From 11ec0a8f8ba7b3250e56ebf207efc41bdb1f595b Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 5 Aug 2021 16:42:57 -0700 Subject: [PATCH 1/2] Add more debugging to run_with_timeout Print more messages in run_with_timeout to make it easier to determine which log statements came before the timeout and the on_timeout command. Test: run_with_timeout_test.go Change-Id: I92ad663529fa03d91185ba382654a73f0eba1ab7 --- cmd/run_with_timeout/run_with_timeout.go | 9 ++++++--- cmd/run_with_timeout/run_with_timeout_test.go | 7 +++++-- 2 files changed, 11 insertions(+), 5 deletions(-) diff --git a/cmd/run_with_timeout/run_with_timeout.go b/cmd/run_with_timeout/run_with_timeout.go index f2caaabd9..deaa842e4 100644 --- a/cmd/run_with_timeout/run_with_timeout.go +++ b/cmd/run_with_timeout/run_with_timeout.go @@ -47,7 +47,7 @@ func main() { flag.Parse() if flag.NArg() < 1 { - fmt.Fprintln(os.Stderr, "command is required") + fmt.Fprintf(os.Stderr, "%s: error: command is required\n", os.Args[0]) usage() } @@ -55,9 +55,9 @@ func main() { os.Stdin, os.Stdout, os.Stderr) if err != nil { if exitErr, ok := err.(*exec.ExitError); ok { - fmt.Fprintln(os.Stderr, "process exited with error:", exitErr.Error()) + fmt.Fprintf(os.Stderr, "%s: process exited with error: %s\n", os.Args[0], exitErr.Error()) } else { - fmt.Fprintln(os.Stderr, "error:", err.Error()) + fmt.Fprintf(os.Stderr, "%s: error: %s\n", os.Args[0], err.Error()) } os.Exit(1) } @@ -115,6 +115,7 @@ func runWithTimeout(command string, args []string, timeout time.Duration, onTime if timeout > 0 { timeoutCh = time.After(timeout) } + startTime := time.Now() select { case err := <-waitCh: @@ -126,10 +127,12 @@ func runWithTimeout(command string, args []string, timeout time.Duration, onTime // Continue below. } + fmt.Fprintf(concurrentStderr, "%s: process timed out after %s\n", os.Args[0], time.Since(startTime)) // Process timed out before exiting. defer cmd.Process.Signal(syscall.SIGKILL) if onTimeoutCmdStr != "" { + fmt.Fprintf(concurrentStderr, "%s: running on_timeout command `%s`\n", os.Args[0], onTimeoutCmdStr) onTimeoutCmd := exec.Command("sh", "-c", onTimeoutCmdStr) onTimeoutCmd.Stdin, onTimeoutCmd.Stdout, onTimeoutCmd.Stderr = stdin, concurrentStdout, concurrentStderr onTimeoutCmd.Env = append(os.Environ(), fmt.Sprintf("PID=%d", cmd.Process.Pid)) diff --git a/cmd/run_with_timeout/run_with_timeout_test.go b/cmd/run_with_timeout/run_with_timeout_test.go index aebd33600..ed6ec11e7 100644 --- a/cmd/run_with_timeout/run_with_timeout_test.go +++ b/cmd/run_with_timeout/run_with_timeout_test.go @@ -17,6 +17,7 @@ package main import ( "bytes" "io" + "regexp" "testing" "time" ) @@ -60,7 +61,8 @@ func Test_runWithTimeout(t *testing.T) { args: []string{"-c", "sleep 1 && echo foo"}, timeout: 1 * time.Millisecond, }, - wantErr: true, + wantStderr: ".*: process timed out after .*\n", + wantErr: true, }, { name: "on_timeout command", @@ -71,6 +73,7 @@ func Test_runWithTimeout(t *testing.T) { onTimeoutCmd: "echo bar", }, wantStdout: "bar\n", + wantStderr: ".*: process timed out after .*\n.*: running on_timeout command `echo bar`\n", wantErr: true, }, } @@ -86,7 +89,7 @@ func Test_runWithTimeout(t *testing.T) { if gotStdout := stdout.String(); gotStdout != tt.wantStdout { t.Errorf("runWithTimeout() gotStdout = %v, want %v", gotStdout, tt.wantStdout) } - if gotStderr := stderr.String(); gotStderr != tt.wantStderr { + if gotStderr := stderr.String(); !regexp.MustCompile(tt.wantStderr).MatchString(gotStderr) { t.Errorf("runWithTimeout() gotStderr = %v, want %v", gotStderr, tt.wantStderr) } }) From a832a04db24683228ab60c86fa17cf343168cb70 Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 5 Aug 2021 16:56:18 -0700 Subject: [PATCH 2/2] Revert "Time out and dump stacks from R8 processes after 30 minutes" This reverts commit 29c294b2cfb778b77a1556511ba53414254ddbab. The deadlock in R8 was fixed, and the timeout causes problems when RBE is enabled and the R8 action gets stuck in a queue for 30 minutes. Test: checkbuild Change-Id: Ia0c3826aea3288e9db3bdbd4955e1e16c0a38fe3 --- java/config/config.go | 2 -- java/dex.go | 13 ++----------- 2 files changed, 2 insertions(+), 13 deletions(-) diff --git a/java/config/config.go b/java/config/config.go index 273084c85..30c6f91aa 100644 --- a/java/config/config.go +++ b/java/config/config.go @@ -69,8 +69,6 @@ func init() { pctx.StaticVariable("JavacHeapSize", "2048M") pctx.StaticVariable("JavacHeapFlags", "-J-Xmx${JavacHeapSize}") pctx.StaticVariable("DexFlags", "-JXX:OnError='cat hs_err_pid%p.log' -JXX:CICompilerCount=6 -JXX:+UseDynamicNumberOfGCThreads") - // TODO(b/181095653): remove duplicated flags. - pctx.StaticVariable("DexJavaFlags", "-XX:OnError='cat hs_err_pid%p.log' -XX:CICompilerCount=6 -XX:+UseDynamicNumberOfGCThreads -Xmx2G") pctx.StaticVariable("CommonJdkFlags", strings.Join([]string{ `-Xmaxerrs 9999999`, diff --git a/java/dex.go b/java/dex.go index 6bf0143b1..7898e9dff 100644 --- a/java/dex.go +++ b/java/dex.go @@ -84,11 +84,6 @@ func (d *dexer) effectiveOptimizeEnabled() bool { return BoolDefault(d.dexProperties.Optimize.Enabled, d.dexProperties.Optimize.EnabledByDefault) } -func init() { - pctx.HostBinToolVariable("runWithTimeoutCmd", "run_with_timeout") - pctx.SourcePathVariable("jstackCmd", "${config.JavaToolchain}/jstack") -} - var d8, d8RE = pctx.MultiCommandRemoteStaticRules("d8", blueprint.RuleParams{ Command: `rm -rf "$outDir" && mkdir -p "$outDir" && ` + @@ -122,10 +117,7 @@ var r8, r8RE = pctx.MultiCommandRemoteStaticRules("r8", Command: `rm -rf "$outDir" && mkdir -p "$outDir" && ` + `rm -f "$outDict" && rm -rf "${outUsageDir}" && ` + `mkdir -p $$(dirname ${outUsage}) && ` + - // TODO(b/181095653): remove R8 timeout and go back to config.R8Cmd. - `${runWithTimeoutCmd} -timeout 30m -on_timeout '${jstackCmd} $$PID' -- ` + - `$r8Template${config.JavaCmd} ${config.DexJavaFlags} -cp ${config.R8Jar} ` + - `com.android.tools.r8.compatproguard.CompatProguard -injars $in --output $outDir ` + + `$r8Template${config.R8Cmd} ${config.DexFlags} -injars $in --output $outDir ` + `--no-data-resources ` + `-printmapping ${outDict} ` + `-printusage ${outUsage} ` + @@ -136,10 +128,9 @@ var r8, r8RE = pctx.MultiCommandRemoteStaticRules("r8", `$zipTemplate${config.SoongZipCmd} $zipFlags -o $outDir/classes.dex.jar -C $outDir -f "$outDir/classes*.dex" && ` + `${config.MergeZipsCmd} -D -stripFile "**/*.class" $out $outDir/classes.dex.jar $in`, CommandDeps: []string{ - "${config.R8Jar}", + "${config.R8Cmd}", "${config.SoongZipCmd}", "${config.MergeZipsCmd}", - "${runWithTimeoutCmd}", }, }, map[string]*remoteexec.REParams{ "$r8Template": &remoteexec.REParams{