Add spawn process times

17 files changed, 46 insertions, 23 deletions

diff --git a/internal/git/catfile/catfile.go b/internal/git/catfile/catfile.go
index 3020c07b7..ab30390ec 100644
--- a/internal/git/catfile/catfile.go
+++ b/internal/git/catfile/catfile.go
@@ -35,7 +35,7 @@ func CatFile(ctx context.Context, repoPath string, handler Handler) error {
 	if err != nil {
 		return grpc.Errorf(codes.Internal, "CatFile: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 	defer stdinWriter.Close()
 	defer stdinReader.Close()
 
diff --git a/internal/helper/command.go b/internal/helper/command.go
index 4d9107251..229d4ff50 100644
--- a/internal/helper/command.go
+++ b/internal/helper/command.go
@@ -8,6 +8,7 @@ import (
 	"os/exec"
 	"strings"
 	"syscall"
+	"time"
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 
@@ -21,6 +22,7 @@ import (
 type Command struct {
 	io.Reader
 	*exec.Cmd
+	startTime time.Time
 }
 
 // GitPath returns the path to the `git` binary. See `SetGitPath` for details
@@ -39,8 +41,8 @@ func GitPath() string {
 
 // Kill cleans the subprocess group of the command. Callers should defer a call
 // to kill after they get the command from NewCommand
-func (c *Command) Kill() {
-	CleanUpProcessGroup(c.Cmd)
+func (c *Command) Kill(ctx context.Context) {
+	c.CleanUpProcessGroup(ctx)
 }
 
 // GitCommandReader creates a git Command with the given args
@@ -55,7 +57,7 @@ func NewCommand(ctx context.Context, cmd *exec.Cmd, stdin io.Reader, stdout, std
 		"args": cmd.Args,
 	}).Info("spawn")
 
-	command := &Command{Cmd: cmd}
+	command := &Command{Cmd: cmd, startTime: time.Now()}
 
 	// Explicitly set the environment for the command
 	cmd.Env = []string{
@@ -108,7 +110,8 @@ func NewCommand(ctx context.Context, cmd *exec.Cmd, stdin io.Reader, stdout, std
 
 // CleanUpProcessGroup will send a SIGTERM signal to the process group
 // belonging to the `cmd` process
-func CleanUpProcessGroup(cmd *exec.Cmd) {
+func (c *Command) CleanUpProcessGroup(ctx context.Context) {
+	cmd := c.Cmd
 	if cmd == nil {
 		return
 	}
@@ -120,7 +123,27 @@ func CleanUpProcessGroup(cmd *exec.Cmd) {
 	}
 
 	// reap our child process
-	cmd.Wait()
+	err := cmd.Wait()
+
+	exitCode := 0
+	if err != nil {
+		if exitStatus, ok := ExitStatus(err); ok {
+			exitCode = exitStatus
+		}
+	}
+
+	systemTime := cmd.ProcessState.SystemTime()
+	userTime := cmd.ProcessState.UserTime()
+	totalTime := time.Now().Sub(c.startTime)
+
+	grpc_logrus.Extract(ctx).WithFields(log.Fields{
+		"path":                   cmd.Path,
+		"args":                   cmd.Args,
+		"command.exitCode":       exitCode,
+		"command.system_time_ms": systemTime.Seconds() * 1000,
+		"command.user_time_ms":   userTime.Seconds() * 1000,
+		"command.total_time_ms":  totalTime.Seconds() * 1000,
+	}).Info("spawn complete")
 }
 
 // ExitStatus will return the exit-code from an error
diff --git a/internal/helper/repo.go b/internal/helper/repo.go
index 33b51d924..6d126a321 100644
--- a/internal/helper/repo.go
+++ b/internal/helper/repo.go
@@ -91,7 +91,7 @@ func IsValidRef(ctx context.Context, path, ref string) bool {
 	if err != nil {
 		return false
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 	cmd.Stdout, cmd.Stderr, cmd.Stdin = nil, nil, nil
 
 	return cmd.Wait() == nil
diff --git a/internal/service/blob/get_blob.go b/internal/service/blob/get_blob.go
index 82445f37e..1ab7dd111 100644
--- a/internal/service/blob/get_blob.go
+++ b/internal/service/blob/get_blob.go
@@ -33,7 +33,7 @@ func (s *server) GetBlob(in *pb.GetBlobRequest, stream pb.BlobService_GetBlobSer
 	if err != nil {
 		return grpc.Errorf(codes.Internal, "GetBlob: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 	defer stdinWriter.Close()
 	defer stdinReader.Close()
 
diff --git a/internal/service/commit/commits_helper.go b/internal/service/commit/commits_helper.go
index 38e711cbb..edcb15a7c 100644
--- a/internal/service/commit/commits_helper.go
+++ b/internal/service/commit/commits_helper.go
@@ -68,7 +68,7 @@ func gitLog(ctx context.Context, sender lines.Sender, repo *pb.Repository, revis
 	if err != nil {
 		return err
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	split := lines.ScanWithDelimiter([]byte("\x00"))
 	if err := lines.Send(cmd, sender, split); err != nil {
diff --git a/internal/service/commit/count_commits.go b/internal/service/commit/count_commits.go
index 91790ef85..23be1c0e4 100644
--- a/internal/service/commit/count_commits.go
+++ b/internal/service/commit/count_commits.go
@@ -43,7 +43,7 @@ func (s *server) CountCommits(ctx context.Context, in *pb.CountCommitsRequest) (
 	if err != nil {
 		return nil, grpc.Errorf(codes.Internal, "CountCommits: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	var count int64
 	countStr, readAllErr := ioutil.ReadAll(cmd)
diff --git a/internal/service/commit/isancestor.go b/internal/service/commit/isancestor.go
index fac30d74d..f3c43ae54 100644
--- a/internal/service/commit/isancestor.go
+++ b/internal/service/commit/isancestor.go
@@ -44,7 +44,7 @@ func commitIsAncestorName(ctx context.Context, path, ancestorID, childID string)
 	if err != nil {
 		return false, grpc.Errorf(codes.Internal, err.Error())
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	return cmd.Wait() == nil, nil
 }
diff --git a/internal/service/commit/list_files.go b/internal/service/commit/list_files.go
index c6559117e..8de257a15 100644
--- a/internal/service/commit/list_files.go
+++ b/internal/service/commit/list_files.go
@@ -38,7 +38,7 @@ func (s *server) ListFiles(in *pb.ListFilesRequest, stream pb.CommitService_List
 	if err != nil {
 		return grpc.Errorf(codes.Internal, err.Error())
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 
 	scanner := lines.ScanWithDelimiter([]byte{'\x00'})
 
diff --git a/internal/service/commit/raw_blame.go b/internal/service/commit/raw_blame.go
index 0ec329d91..6b767fe0c 100644
--- a/internal/service/commit/raw_blame.go
+++ b/internal/service/commit/raw_blame.go
@@ -32,7 +32,7 @@ func (s *server) RawBlame(in *pb.RawBlameRequest, stream pb.CommitService_RawBla
 	if err != nil {
 		return grpc.Errorf(codes.Internal, "RawBlame: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	sw := streamio.NewWriter(func(p []byte) error {
 		return stream.Send(&pb.RawBlameResponse{Data: p})
diff --git a/internal/service/diff/commit.go b/internal/service/diff/commit.go
index 20f965478..5bd0d6e06 100644
--- a/internal/service/diff/commit.go
+++ b/internal/service/diff/commit.go
@@ -218,7 +218,7 @@ func eachDiff(ctx context.Context, rpc string, cmdArgs []string, limits diff.Lim
 	if err != nil {
 		return grpc.Errorf(codes.Internal, "%s: cmd: %v", rpc, err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	diffParser := diff.NewDiffParser(cmd, limits)
 
diff --git a/internal/service/ref/refname.go b/internal/service/ref/refname.go
index c9a3df5f4..baec276f0 100644
--- a/internal/service/ref/refname.go
+++ b/internal/service/ref/refname.go
@@ -45,7 +45,7 @@ func findRefName(ctx context.Context, path, commitID, prefix string) (string, er
 	if err != nil {
 		return "", err
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	scanner := bufio.NewScanner(cmd)
 	scanner.Scan()
diff --git a/internal/service/ref/refs.go b/internal/service/ref/refs.go
index 949c042b4..a82a6f980 100644
--- a/internal/service/ref/refs.go
+++ b/internal/service/ref/refs.go
@@ -55,7 +55,7 @@ func findRefs(ctx context.Context, writer lines.Sender, repo *pb.Repository, pat
 	if err != nil {
 		return err
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	if err := lines.Send(cmd, writer, opts.splitter); err != nil {
 		return err
@@ -91,7 +91,7 @@ func _findBranchNames(ctx context.Context, repoPath string) ([][]byte, error) {
 	if err != nil {
 		return nil, err
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	scanner := bufio.NewScanner(cmd)
 	for scanner.Scan() {
@@ -115,7 +115,7 @@ func _headReference(ctx context.Context, repoPath string) ([]byte, error) {
 	if err != nil {
 		return nil, err
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	scanner := bufio.NewScanner(cmd)
 	scanner.Scan()
diff --git a/internal/service/smarthttp/inforefs.go b/internal/service/smarthttp/inforefs.go
index 864926327..16ff06c18 100644
--- a/internal/service/smarthttp/inforefs.go
+++ b/internal/service/smarthttp/inforefs.go
@@ -43,7 +43,7 @@ func handleInfoRefs(ctx context.Context, service string, repo *pb.Repository, w
 	if err != nil {
 		return grpc.Errorf(codes.Internal, "GetInfoRefs: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(ctx)
 
 	if err := pktLine(w, fmt.Sprintf("# service=git-%s\n", service)); err != nil {
 		return grpc.Errorf(codes.Internal, "GetInfoRefs: pktLine: %v", err)
diff --git a/internal/service/smarthttp/receive_pack.go b/internal/service/smarthttp/receive_pack.go
index 04d7470a3..8904a7aab 100644
--- a/internal/service/smarthttp/receive_pack.go
+++ b/internal/service/smarthttp/receive_pack.go
@@ -54,7 +54,7 @@ func (s *server) PostReceivePack(stream pb.SmartHTTPService_PostReceivePackServe
 	if err != nil {
 		return grpc.Errorf(codes.Unavailable, "PostReceivePack: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 
 	if err := cmd.Wait(); err != nil {
 		return grpc.Errorf(codes.Unavailable, "PostReceivePack: cmd wait for %v: %v", cmd.Args, err)
diff --git a/internal/service/smarthttp/upload_pack.go b/internal/service/smarthttp/upload_pack.go
index 0690a8e05..dda573198 100644
--- a/internal/service/smarthttp/upload_pack.go
+++ b/internal/service/smarthttp/upload_pack.go
@@ -65,7 +65,7 @@ func (s *server) PostUploadPack(stream pb.SmartHTTPService_PostUploadPackServer)
 	if err != nil {
 		return grpc.Errorf(codes.Unavailable, "PostUploadPack: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 
 	if err := cmd.Wait(); err != nil {
 		pw.Close() // ensure scanDeepen returns
diff --git a/internal/service/ssh/receive_pack.go b/internal/service/ssh/receive_pack.go
index f47e0c4ab..38565bb47 100644
--- a/internal/service/ssh/receive_pack.go
+++ b/internal/service/ssh/receive_pack.go
@@ -58,7 +58,7 @@ func (s *server) SSHReceivePack(stream pb.SSHService_SSHReceivePackServer) error
 	if err != nil {
 		return grpc.Errorf(codes.Unavailable, "SSHReceivePack: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 
 	if err := cmd.Wait(); err != nil {
 		if status, ok := helper.ExitStatus(err); ok {
diff --git a/internal/service/ssh/upload_pack.go b/internal/service/ssh/upload_pack.go
index 19549a2a4..09bb34f12 100644
--- a/internal/service/ssh/upload_pack.go
+++ b/internal/service/ssh/upload_pack.go
@@ -52,7 +52,7 @@ func (s *server) SSHUploadPack(stream pb.SSHService_SSHUploadPackServer) error {
 	if err != nil {
 		return grpc.Errorf(codes.Unavailable, "SSHUploadPack: cmd: %v", err)
 	}
-	defer cmd.Kill()
+	defer cmd.Kill(stream.Context())
 
 	if err := cmd.Wait(); err != nil {
 		if status, ok := helper.ExitStatus(err); ok {