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

// Copyright 2014 The Bazel Authors. All rights reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//    http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package com.google.devtools.build.lib.runtime;

import com.google.common.base.Joiner;
import com.google.common.collect.ImmutableList;
import com.google.common.eventbus.EventBus;
import com.google.common.eventbus.Subscribe;
import com.google.devtools.build.lib.actions.ActionKeyContext;
import com.google.devtools.build.lib.actions.ActionResultReceivedEvent;
import com.google.devtools.build.lib.buildeventstream.BuildToolLogs;
import com.google.devtools.build.lib.buildtool.BuildRequest;
import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent;
import com.google.devtools.build.lib.buildtool.buildevent.ExecutionStartingEvent;
import com.google.devtools.build.lib.clock.BlazeClock;
import com.google.devtools.build.lib.events.Event;
import com.google.devtools.build.lib.events.Reporter;
import com.google.devtools.build.lib.exec.ExecutionOptions;
import com.google.devtools.build.lib.exec.ExecutorBuilder;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
import com.google.devtools.build.lib.util.Pair;
import com.google.protobuf.ByteString;
import java.time.Duration;
import java.util.ArrayList;
import java.util.List;
import java.util.logging.Logger;

/**
 * Blaze module for the build summary message that reports various stats to the user.
 */
public class BuildSummaryStatsModule extends BlazeModule {

  private static final Logger logger = Logger.getLogger(BuildSummaryStatsModule.class.getName());

  private ActionKeyContext actionKeyContext;
  private SimpleCriticalPathComputer criticalPathComputer;
  private EventBus eventBus;
  private Reporter reporter;
  private boolean enabled;
  private boolean discardActions;

  private SpawnStats spawnStats;

  @Override
  public void beforeCommand(CommandEnvironment env) {
    this.reporter = env.getReporter();
    this.eventBus = env.getEventBus();
    this.actionKeyContext = env.getSkyframeExecutor().getActionKeyContext();
    this.spawnStats = new SpawnStats();
    eventBus.register(this);
  }

  @Override
  public void afterCommand() {
    this.criticalPathComputer = null;
    this.eventBus = null;
    this.reporter = null;
    this.spawnStats = null;
  }

  @Override
  public void executorInit(CommandEnvironment env, BuildRequest request, ExecutorBuilder builder) {
    enabled = env.getOptions().getOptions(ExecutionOptions.class).enableCriticalPathProfiling;
    discardActions = !env.getSkyframeExecutor().tracksStateForIncrementality();
  }

  @Subscribe
  public void executionPhaseStarting(ExecutionStartingEvent event) {
    if (enabled) {
      criticalPathComputer =
          new SimpleCriticalPathComputer(actionKeyContext, BlazeClock.instance(), discardActions);
      eventBus.register(criticalPathComputer);
    }
  }

  @Subscribe
  public void actionResultReceived(ActionResultReceivedEvent event) {
    spawnStats.countActionResult(event.getActionResult());
  }

  @Subscribe
  public void buildComplete(BuildCompleteEvent event) {
    try {
      // We might want to make this conditional on a flag; it can sometimes be a bit of a nuisance.
      List<Pair<String, ByteString>> statistics = new ArrayList<>();
      List<String> items = new ArrayList<>();
      items.add(String.format("Elapsed time: %.3fs", event.getResult().getElapsedSeconds()));
      statistics.add(Pair.of("elapsed time", ByteString.copyFromUtf8(
          String.format("%f", event.getResult().getElapsedSeconds()))));

      if (criticalPathComputer != null) {
        Profiler.instance().startTask(ProfilerTask.CRITICAL_PATH, "Critical path");
        AggregatedCriticalPath<SimpleCriticalPathComponent> criticalPath =
            criticalPathComputer.aggregate();
        items.add(criticalPath.toStringSummary());
        statistics.add(Pair.of("critical path", ByteString.copyFromUtf8(criticalPath.toString())));
        logger.info(criticalPath.toString());
        logger.info(
            "Slowest actions:\n  "
                + Joiner.on("\n  ").join(criticalPathComputer.getSlowestComponents()));
        // We reverse the critical path because the profiler expect events ordered by the time
        // when the actions were executed while critical path computation is stored in the reverse
        // way.
        for (SimpleCriticalPathComponent stat : criticalPath.components().reverse()) {
          Profiler.instance()
              .logSimpleTaskDuration(
                  stat.getStartNanos(),
                  Duration.ofNanos(stat.getElapsedTimeNanos()),
                  ProfilerTask.CRITICAL_PATH_COMPONENT,
                  stat.prettyPrintAction());
        }
        Profiler.instance().completeTask(ProfilerTask.CRITICAL_PATH);
      }

      reporter.handle(Event.info(Joiner.on(", ").join(items)));

      String spawnSummary = spawnStats.getSummary();
      reporter.handle(Event.info(spawnSummary));
      statistics.add(Pair.of("process stats", ByteString.copyFromUtf8(spawnSummary)));

      reporter.post(new BuildToolLogs(statistics, ImmutableList.of()));
    } finally {
      criticalPathComputer = null;
    }
  }
}