src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java

// Copyright 2015 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.profiler.output;

import com.google.common.base.Optional;
import com.google.devtools.build.lib.profiler.ProfilePhase;
import com.google.devtools.build.lib.profiler.ProfilerTask;
import com.google.devtools.build.lib.profiler.statistics.CriticalPathStatistics;
import com.google.devtools.build.lib.profiler.statistics.PhaseStatistics;
import com.google.devtools.build.lib.profiler.statistics.PhaseSummaryStatistics;
import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics;
import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics.Stat;
import com.google.devtools.build.lib.util.TimeUtilities;

import java.io.PrintStream;
import java.util.Arrays;
import java.util.EnumMap;

import javax.annotation.Nullable;

/**
 * Output {@link PhaseSummaryStatistics}, {@link PhaseStatistics} and {@link PhaseVfsStatistics}
 * in text format.
 */
public final class PhaseText extends TextPrinter {

  private final PhaseSummaryStatistics phaseSummaryStats;
  private final EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics;
  private final Optional<CriticalPathStatistics> criticalPathStatistics;
  private final int vfsStatsLimit;
  private final int missingActionsCount;

  /**
   * @param vfsStatsLimit maximum number of VFS statistics to print, or -1 for no limit.
   */
  public PhaseText(
      PrintStream out,
      PhaseSummaryStatistics phaseSummaryStats,
      EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics,
      Optional<CriticalPathStatistics> critPathStats,
      int missingActionsCount,
      int vfsStatsLimit) {
    super(out);
    this.phaseSummaryStats = phaseSummaryStats;
    this.phaseStatistics = phaseStatistics;
    this.criticalPathStatistics = critPathStats;
    this.missingActionsCount = missingActionsCount;
    this.vfsStatsLimit = vfsStatsLimit;
  }

  public void print() {
    printPhaseSummaryStatistics();

    for (ProfilePhase phase :
        Arrays.asList(ProfilePhase.INIT, ProfilePhase.LOAD, ProfilePhase.ANALYZE)) {
      PhaseStatistics statistics = phaseStatistics.get(phase);
      if (statistics.wasExecuted()) {
        printPhaseStatistics(statistics);
      }
    }
    printExecutionPhaseStatistics();
  }

  /**
   * Print a table for the phase overview with runtime and runtime percentage per phase and total.
   */
  private void printPhaseSummaryStatistics() {
    print("\n=== PHASE SUMMARY INFORMATION ===\n");
    for (ProfilePhase phase : phaseSummaryStats) {
      long phaseDuration = phaseSummaryStats.getDurationNanos(phase);
      double relativeDuration = phaseSummaryStats.getRelativeDuration(phase);
      lnPrintf(
          THREE_COLUMN_FORMAT,
          "Total " + phase.nick + " phase time",
          TimeUtilities.prettyTime(phaseDuration),
          prettyPercentage(relativeDuration));
    }
    lnPrintf(
        THREE_COLUMN_FORMAT,
        "Total run time",
        TimeUtilities.prettyTime(phaseSummaryStats.getTotalDuration()),
        "100.00%");
    printLn();
  }

  /**
   * Prints all statistics from {@link PhaseStatistics} in text form.
   */
  private void printPhaseStatistics(PhaseStatistics stats) {
    lnPrintf("=== %s PHASE INFORMATION ===\n", stats.getProfilePhase().nick.toUpperCase());

    lnPrintf(
        TWO_COLUMN_FORMAT,
        "Total " + stats.getProfilePhase().nick + " phase time",
        TimeUtilities.prettyTime(stats.getPhaseDurationNanos()));
    printLn();

    if (!stats.isEmpty()) {
      printTimingDistribution(stats);
      printLn();
      printVfsStatistics(stats.getVfsStatistics());
    }
  }

  private void printExecutionPhaseStatistics() {
    PhaseStatistics prepPhase = phaseStatistics.get(ProfilePhase.PREPARE);
    PhaseStatistics execPhase = phaseStatistics.get(ProfilePhase.EXECUTE);
    PhaseStatistics finishPhase = phaseStatistics.get(ProfilePhase.FINISH);
    if (!execPhase.wasExecuted()) {
      return;
    }
    lnPrint("=== EXECUTION PHASE INFORMATION ===\n");

    long execTime = execPhase.getPhaseDurationNanos();

    if (prepPhase.wasExecuted()) {
      lnPrintf(
          TWO_COLUMN_FORMAT,
          "Total preparation time",
          TimeUtilities.prettyTime(prepPhase.getPhaseDurationNanos()));
    }
    lnPrintf(
        TWO_COLUMN_FORMAT,
        "Total execution phase time",
        TimeUtilities.prettyTime(execPhase.getPhaseDurationNanos()));
    if (finishPhase.wasExecuted()) {
      lnPrintf(
          TWO_COLUMN_FORMAT,
          "Total time finalizing build",
          TimeUtilities.prettyTime(finishPhase.getPhaseDurationNanos()));
    }
    printLn();
    lnPrintf(TWO_COLUMN_FORMAT, "Actual execution time", TimeUtilities.prettyTime(execTime));

    CriticalPathText criticalPaths = null;
    if (criticalPathStatistics.isPresent()) {
      criticalPaths = new CriticalPathText(out, criticalPathStatistics.get(), execTime);
      criticalPaths.printTimingBreakdown();
      printLn();
    }

    printTimingDistribution(execPhase);
    printLn();

    if (criticalPathStatistics.isPresent()) {
      criticalPaths.printCriticalPaths();
      printLn();
    }

    if (missingActionsCount > 0) {
      lnPrint(missingActionsCount);
      print(
          " action(s) are present in the"
              + " action graph but missing instrumentation data. Most likely the profile file"
              + " has been created during a failed or aborted build.");
      printLn();
    }

    printVfsStatistics(execPhase.getVfsStatistics());
  }

  /**
   * Prints a table of task types and their relative total and average execution time as well as
   * how many tasks of each type there were
   */
  private void printTimingDistribution(PhaseStatistics stats) {
    lnPrint("Total time (across all threads) spent on:");
    lnPrintf("%18s %8s %8s %11s", "Type", "Total", "Count", "Average");
    for (ProfilerTask type : stats) {
      lnPrintf(
          "%18s %8s %8d %11s",
          type.toString(),
          prettyPercentage(stats.getTotalRelativeDuration(type)),
          stats.getCount(type),
          TimeUtilities.prettyTime(stats.getMeanDuration(type)));
    }
  }

  /**
   * Print the time spent on VFS operations on each path. Output is grouped by operation and
   * sorted by descending duration. If multiple of the same VFS operation were logged for the same
   * path, print the total duration.
   */
  private void printVfsStatistics(@Nullable PhaseVfsStatistics stats) {
    if (vfsStatsLimit == 0 || stats == null || stats.isEmpty()) {
      return;
    }

    lnPrint("VFS path statistics:");
    lnPrintf("%15s %10s %10s %s", "Type", "Frequency", "Duration", "Path");
    for (ProfilerTask type : stats) {
      int numPrinted = 0;
      for (Stat stat : stats.getSortedStatistics(type)) {
        if (vfsStatsLimit != -1 && numPrinted++ == vfsStatsLimit) {
          lnPrintf("... %d more ...", stats.getStatisticsCount(type) - vfsStatsLimit);
          break;
        }
        lnPrintf(
            "%15s %10d %10s %s",
            type.name(),
            stat.getCount(),
            TimeUtilities.prettyTime(stat.getDuration()),
            stat.path);
      }
    }
    printLn();
  }
}