Run 'pstree' if ninja_log hasn't updated recently

This doesn't catch all the possible causes of timeouts,
(like if Ninja is only partially stuck or if Kati is stuck)
but it should clarify some causes of stuckness

Bug: 62065855
Test: m -j showcommands NINJA_HEARTBEAT_INTERVAL=500ms
Change-Id: I73a792ae91873b19d7b336166a2d47f37c549906

2 files changed, 87 insertions, 7 deletions

diff --git a/ui/build/exec.go b/ui/build/exec.go
index c8c5c9a5..79310dc2 100644
--- a/ui/build/exec.go
+++ b/ui/build/exec.go
@@ -30,6 +30,9 @@ type Cmd struct {
 	ctx    Context
 	config Config
 	name   string
+
+	// doneChannel closes to signal the command's termination
+	doneChannel chan bool
 }
 
 func Command(ctx Context, config Config, name string, executable string, args ...string) *Cmd {
@@ -38,9 +41,10 @@ func Command(ctx Context, config Config, name string, executable string, args ..
 		Environment: config.Environment().Copy(),
 		Sandbox:     noSandbox,
 
-		ctx:    ctx,
-		config: config,
-		name:   name,
+		ctx:         ctx,
+		config:      config,
+		name:        name,
+		doneChannel: make(chan bool),
 	}
 
 	return ret
@@ -57,6 +61,10 @@ func (c *Cmd) prepare() {
 	c.ctx.Verboseln(c.Path, c.Args)
 }
 
+func (c *Cmd) teardown() {
+	close(c.doneChannel)
+}
+
 func (c *Cmd) Start() error {
 	c.prepare()
 	return c.Cmd.Start()
@@ -64,17 +72,23 @@ func (c *Cmd) Start() error {
 
 func (c *Cmd) Run() error {
 	c.prepare()
-	return c.Cmd.Run()
+	defer c.teardown()
+	err := c.Cmd.Run()
+	return err
 }
 
 func (c *Cmd) Output() ([]byte, error) {
 	c.prepare()
-	return c.Cmd.Output()
+	defer c.teardown()
+	bytes, err := c.Cmd.Output()
+	return bytes, err
 }
 
 func (c *Cmd) CombinedOutput() ([]byte, error) {
 	c.prepare()
-	return c.Cmd.CombinedOutput()
+	defer c.teardown()
+	bytes, err := c.Cmd.CombinedOutput()
+	return bytes, err
 }
 
 // StartOrFatal is equivalent to Start, but handles the error with a call to ctx.Fatal
@@ -119,3 +133,13 @@ func (c *Cmd) CombinedOutputOrFatal() []byte {
 	c.reportError(err)
 	return ret
 }
+
+// Done() tells whether this command has finished executing
+func (c *Cmd) Done() bool {
+	select {
+	case <-c.doneChannel:
+		return true
+	default:
+		return false
+	}
+}
diff --git a/ui/build/ninja.go b/ui/build/ninja.go
index 5787a00f..22771e7b 100644
--- a/ui/build/ninja.go
+++ b/ui/build/ninja.go
@@ -15,6 +15,8 @@
 package build
 
 import (
+	"fmt"
+	"os"
 	"path/filepath"
 	"strconv"
 	"strings"
@@ -69,7 +71,61 @@ func runNinja(ctx Context, config Config) {
 	cmd.Stdin = ctx.Stdin()
 	cmd.Stdout = ctx.Stdout()
 	cmd.Stderr = ctx.Stderr()
+	logPath := filepath.Join(config.OutDir(), ".ninja_log")
+	ninjaHeartbeatDuration := time.Minute * 5
+	if overrideText, ok := cmd.Environment.Get("NINJA_HEARTBEAT_INTERVAL"); ok {
+		// For example, "1m"
+		overrideDuration, err := time.ParseDuration(overrideText)
+		if err == nil && overrideDuration.Seconds() > 0 {
+			ninjaHeartbeatDuration = overrideDuration
+		}
+	}
+	// Poll the ninja log for updates; if it isn't updated enough, then we want to show some diagnostics
+	checker := &statusChecker{}
+	go func() {
+		for !cmd.Done() {
+			checker.check(ctx, config, logPath)
+			time.Sleep(ninjaHeartbeatDuration)
+		}
+	}()
+
 	startTime := time.Now()
-	defer ctx.ImportNinjaLog(filepath.Join(config.OutDir(), ".ninja_log"), startTime)
+	defer ctx.ImportNinjaLog(logPath, startTime)
+
 	cmd.RunOrFatal()
 }
+
+type statusChecker struct {
+	prevTime time.Time
+}
+
+func (c *statusChecker) check(ctx Context, config Config, pathToCheck string) {
+	info, err := os.Stat(pathToCheck)
+	var newTime time.Time
+	if err == nil {
+		newTime = info.ModTime()
+	}
+	if newTime == c.prevTime {
+		// ninja may be stuck
+		dumpStucknessDiagnostics(ctx, config, pathToCheck, newTime)
+	}
+	c.prevTime = newTime
+}
+
+// dumpStucknessDiagnostics gets called when it is suspected that Ninja is stuck and we want to output some diagnostics
+func dumpStucknessDiagnostics(ctx Context, config Config, statusPath string, lastUpdated time.Time) {
+
+	ctx.Verbosef("ninja may be stuck; last update to %v was %v. dumping process tree...", statusPath, lastUpdated)
+
+	// The "pstree" command doesn't exist on Mac, but "pstree" on Linux gives more convenient output than "ps"
+	// So, we try pstree first, and ps second
+	pstreeCommandText := fmt.Sprintf("pstree -pal %v", os.Getpid())
+	psCommandText := "ps -ef"
+	commandText := pstreeCommandText + " || " + psCommandText
+
+	cmd := Command(ctx, config, "dump process tree", "bash", "-c", commandText)
+	output := cmd.CombinedOutputOrFatal()
+	ctx.Verbose(string(output))
+
+	ctx.Printf("done\n")
+}