commit c070221c787c65fbedec456cfa7bd77811d4937c
author twerth <twerth@google.com> Tue Oct 02 05:01:45 2018 -0700
committer Copybara-Service <copybara-piper@google.com> Tue Oct 02 05:03:34 2018 -0700
tree f1f8a411cbd5836de822e3a63e91d249fc523d0e
parent 5f312dd1678878fb7563eae0cd184f2270346352

Improve profiling of times spent in client.

- Make launch time an event with duration.
- Add extraction time to the profile.
- Add wait times (both in client and server) to the profile.

RELNOTES: None
PiperOrigin-RevId: 215369415

src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java

diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java
index 8b4015c..21bb06d 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java
@@ -271,7 +271,12 @@
     // the afterCommand call in the finally block below.
     Path profilePath =
         runtime.initProfiler(
-            storedEventHandler, workspace, commonOptions, env.getCommandId(), execStartTimeNanos);
+            storedEventHandler,
+            workspace,
+            commonOptions,
+            env.getCommandId(),
+            execStartTimeNanos,
+            waitTimeInMs);
     if (commonOptions.postProfileStartedEvent) {
       storedEventHandler.post(new ProfilerStartedEvent(profilePath));
     }

src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java

diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
index 57dc16f..637b196 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
@@ -270,7 +270,8 @@
       BlazeWorkspace workspace,
       CommonCommandOptions options,
       UUID buildID,
-      long execStartTimeNanos) {
+      long execStartTimeNanos,
+      long waitTimeInMs) {
     OutputStream out = null;
     boolean recordFullProfilerData = false;
     ProfiledTaskKinds profiledTasks = ProfiledTaskKinds.NONE;
@@ -324,11 +325,34 @@
         // the launcher. We're setting the INIT phase marker so that it follows immediately the
         // LAUNCH phase.
         long startupTimeNanos = options.startupTime * 1000000L;
+        long waitTimeNanos = waitTimeInMs * 1000000L;
+        long clientStartTimeNanos = execStartTimeNanos - startupTimeNanos - waitTimeNanos;
         profiler.logSimpleTaskDuration(
-            execStartTimeNanos - startupTimeNanos,
-            Duration.ZERO,
+            clientStartTimeNanos,
+            Duration.ofNanos(startupTimeNanos),
             ProfilerTask.PHASE,
             ProfilePhase.LAUNCH.description);
+        if (options.extractDataTime > 0) {
+          profiler.logSimpleTaskDuration(
+              clientStartTimeNanos,
+              Duration.ofMillis(options.extractDataTime),
+              ProfilerTask.PHASE,
+              "Extracting Bazel binary");
+        }
+        if (options.waitTime > 0) {
+          profiler.logSimpleTaskDuration(
+              clientStartTimeNanos,
+              Duration.ofMillis(options.waitTime),
+              ProfilerTask.PHASE,
+              "Blocking on busy Bazel server (in client)");
+        }
+        if (waitTimeInMs > 0) {
+          profiler.logSimpleTaskDuration(
+              clientStartTimeNanos + startupTimeNanos,
+              Duration.ofMillis(waitTimeInMs),
+              ProfilerTask.PHASE,
+              "Blocking on busy Bazel server (in server)");
+        }
         profiler.logSimpleTaskDuration(
             execStartTimeNanos, Duration.ZERO, ProfilerTask.PHASE, ProfilePhase.INIT.description);
       }