Exemple #1
0
  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 graphTime = execPhase.getTotalDurationNanos(ProfilerTask.ACTION_GRAPH);
    long execTime = execPhase.getPhaseDurationNanos() - graphTime;

    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, "Action dependency map creation", TimeUtilities.prettyTime(graphTime));
    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());
  }
Exemple #2
0
  private void printCriticalPath(String title, CriticalPathEntry path) {
    lnPrintf("%s (%s):", title, TimeUtilities.prettyTime(path.cumulativeDuration));

    boolean isComponent = path.isComponent();
    if (isComponent) {
      lnPrintf("%6s %11s %8s   %s", "Id", "Time", "Percentage", "Description");
    } else {
      lnPrintf("%6s %11s %8s %8s   %s", "Id", "Time", "Share", "Critical", "Description");
    }

    long totalPathTime = path.cumulativeDuration;

    for (CriticalPathEntry pathEntry : criticalPathStats.getMiddlemanFilteredPath(path)) {
      String desc = pathEntry.task.getDescription().replace(':', ' ');
      if (isComponent) {
        lnPrintf(
            "%6d %11s %8s   %s",
            pathEntry.task.id,
            TimeUtilities.prettyTime(pathEntry.duration),
            prettyPercentage((double) pathEntry.duration / totalPathTime),
            desc);
      } else {
        lnPrintf(
            "%6d %11s %8s %8s   %s",
            pathEntry.task.id,
            TimeUtilities.prettyTime(pathEntry.duration),
            prettyPercentage((double) pathEntry.duration / totalPathTime),
            prettyPercentage((double) pathEntry.getCriticalTime() / totalPathTime),
            desc);
      }
    }
    MiddleManStatistics middleMan = MiddleManStatistics.create(path);
    if (middleMan.count > 0) {
      if (isComponent) {
        lnPrintf(
            "       %11s %8s   [%d middleman actions]",
            TimeUtilities.prettyTime(middleMan.duration),
            prettyPercentage((double) middleMan.duration / totalPathTime),
            middleMan.count);
      } else {
        lnPrintf(
            "       %11s %8s %8s   [%d middleman actions]",
            TimeUtilities.prettyTime(middleMan.duration),
            prettyPercentage((double) middleMan.duration / totalPathTime),
            prettyPercentage((double) middleMan.criticalTime / totalPathTime),
            middleMan.count);
      }
    }
  }
Exemple #3
0
 /**
  * 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();
 }
  void printCriticalPathTimingBreakdown(
      CriticalPathEntry totalPath, CriticalPathEntry optimalPath) {
    lnPrint(totalPath.task.type);

    lnPrintf(
        TWO_COLUMN_FORMAT,
        "Worker thread scheduling delays",
        TimeUtilities.prettyTime(criticalPathStats.getWorkerWaitTime()));
    lnPrintf(
        TWO_COLUMN_FORMAT,
        "Main thread scheduling delays",
        TimeUtilities.prettyTime(criticalPathStats.getMainThreadWaitTime()));

    printLn();
    lnPrint("Critical path time:");

    long totalTime = totalPath.cumulativeDuration;
    lnPrintf(
        "%-37s %10s (%s of execution time)",
        "Actual time",
        TimeUtilities.prettyTime(totalTime),
        prettyPercentage((double) totalTime / executionTime));

    long optimalTime = optimalPath.cumulativeDuration;
    lnPrintf(
        "%-37s %10s (%s of execution time)",
        "Time excluding scheduling delays",
        TimeUtilities.prettyTime(optimalTime),
        prettyPercentage((double) optimalTime / executionTime));

    printLn();
    // Artificial critical path if we ignore all the time spent in all tasks,
    // except time directly attributed to the ACTION tasks.
    lnPrint("Time related to:");

    for (Pair<String, Double> relativePathDuration : criticalPathStats) {
      lnPrintf(
          TWO_COLUMN_FORMAT,
          relativePathDuration.first,
          prettyPercentage(relativePathDuration.second));
    }
  }
Exemple #5
0
 /**
  * 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)));
   }
 }
Exemple #6
0
  /** 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());
    }
  }
Exemple #7
0
  /**
   * 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();
  }
  private void printCriticalPath(String title, CriticalPathEntry path) {
    lnPrintf("%s (%s):", title, TimeUtilities.prettyTime(path.cumulativeDuration));

    boolean isComponent = path.isComponent();
    if (isComponent) {
      lnPrintf("%6s %11s %8s   %s", "Id", "Time", "Percentage", "Description");
    } else {
      lnPrintf("%6s %11s %8s %8s   %s", "Id", "Time", "Share", "Critical", "Description");
    }

    long totalPathTime = path.cumulativeDuration;
    int middlemanCount = 0;
    long middlemanDuration = 0L;
    long middlemanCritTime = 0L;

    for (; path != null; path = path.next) {
      if (path.task.id < 0) {
        // Ignore fake actions.
        continue;
      } else if (path.task.getDescription().startsWith(MiddlemanAction.MIDDLEMAN_MNEMONIC + " ")
          || path.task.getDescription().startsWith("TargetCompletionMiddleman")) {
        // Aggregate middleman actions.
        middlemanCount++;
        middlemanDuration += path.duration;
        middlemanCritTime += path.getCriticalTime();
      } else {
        String desc = path.task.getDescription().replace(':', ' ');
        if (isComponent) {
          lnPrintf(
              "%6d %11s %8s   %s",
              path.task.id,
              TimeUtilities.prettyTime(path.duration),
              prettyPercentage((double) path.duration / totalPathTime),
              desc);
        } else {
          lnPrintf(
              "%6d %11s %8s %8s   %s",
              path.task.id,
              TimeUtilities.prettyTime(path.duration),
              prettyPercentage((double) path.duration / totalPathTime),
              prettyPercentage((double) path.getCriticalTime() / totalPathTime),
              desc);
        }
      }
    }
    if (middlemanCount > 0) {
      if (isComponent) {
        lnPrintf(
            "       %11s %8s   [%d middleman actions]",
            TimeUtilities.prettyTime(middlemanDuration),
            prettyPercentage((double) middlemanDuration / totalPathTime),
            middlemanCount);
      } else {
        lnPrintf(
            "       %11s %8s %8s   [%d middleman actions]",
            TimeUtilities.prettyTime(middlemanDuration),
            prettyPercentage((double) middlemanDuration / totalPathTime),
            prettyPercentage((double) middlemanCritTime / totalPathTime),
            middlemanCount);
      }
    }
  }