Add logging for stats on finished commands
Includes the exit code, real time, user time, system time, and maxrss.
Test: m nothing; check out/soong.log
Change-Id: I93dea9fc1c7fb892150e16e11cae09f2372f4429
diff --git a/ui/build/exec.go b/ui/build/exec.go
index e435c53..053bbae 100644
--- a/ui/build/exec.go
+++ b/ui/build/exec.go
@@ -19,6 +19,8 @@
"io"
"os/exec"
"strings"
+ "syscall"
+ "time"
)
// Cmd is a wrapper of os/exec.Cmd that integrates with the build context for
@@ -33,6 +35,8 @@
ctx Context
config Config
name string
+
+ started time.Time
}
func Command(ctx Context, config Config, name string, executable string, args ...string) *Cmd {
@@ -57,7 +61,20 @@
c.wrapSandbox()
}
- c.ctx.Verboseln(c.Path, c.Args)
+ c.ctx.Verbosef("%q executing %q %v\n", c.name, c.Path, c.Args)
+ c.started = time.Now()
+}
+
+func (c *Cmd) report() {
+ if c.Cmd.ProcessState != nil {
+ rusage := c.Cmd.ProcessState.SysUsage().(*syscall.Rusage)
+ c.ctx.Verbosef("%q finished with exit code %d (%s real, %s user, %s system, %dMB maxrss)",
+ c.name, c.Cmd.ProcessState.ExitCode(),
+ time.Since(c.started).Round(time.Millisecond),
+ c.Cmd.ProcessState.UserTime().Round(time.Millisecond),
+ c.Cmd.ProcessState.SystemTime().Round(time.Millisecond),
+ rusage.Maxrss/1024)
+ }
}
func (c *Cmd) Start() error {
@@ -68,21 +85,30 @@
func (c *Cmd) Run() error {
c.prepare()
err := c.Cmd.Run()
+ c.report()
return err
}
func (c *Cmd) Output() ([]byte, error) {
c.prepare()
bytes, err := c.Cmd.Output()
+ c.report()
return bytes, err
}
func (c *Cmd) CombinedOutput() ([]byte, error) {
c.prepare()
bytes, err := c.Cmd.CombinedOutput()
+ c.report()
return bytes, err
}
+func (c *Cmd) Wait() error {
+ err := c.Cmd.Wait()
+ c.report()
+ return err
+}
+
// StartOrFatal is equivalent to Start, but handles the error with a call to ctx.Fatal
func (c *Cmd) StartOrFatal() {
if err := c.Start(); err != nil {