[Driver] Add option -fproc-stat-report

[sepavloff]

Summary

The new option -fproc-stat-info=<file> can be used to generate report
about used memory and execution tile of each stage of compilation.
Documentation for this option can be found in UserManual.rst. The
option can be used in parallel builds.

[aganea]

clang/docs/UsersManual.rst

770

Please add a header to the output .CSV, specifying the units of measure where relevant.

786

Why not just -fproc-stat-report in this case?

787

I think it is better if the units are specified along (and locale-formatted, if possible):

clang-11: output=/tmp/foo-123456.o  total=84,000 ms  user=76,000 ms  mem=87,496 kb

clang/include/clang/Driver/Job.h

144

mutable Optional<llvm::sys::ProcessStatistics> ProcStat; and then you won't need .isSet().

clang/lib/Driver/Driver.cpp

3942

There is a large piece of code in the if statement, I would add curly brackets:
if (!StatReportFile.empty()) { ... }

3944

Use Optional<> like state above, then the condition changes to:
if (ProcStat)

and then usage below becomes:
<< ", total=" << ProcStat->TotalTime.count()

3946

if (StatReportFile.equals("-") || StatReportFile.empty()) {

[MaskRay]

clang/docs/UsersManual.rst

786

It can save an Option..

787

Sorry, I tend to disagree with the argument for decimal separators and locale differences. They make behaviors divergent and make the output difficult to parse by a script. (Scripts may have to use LANG=C clang -fproc-stat-report=- to cancel the locale effect)

[aganea]

clang/docs/UsersManual.rst

786

I was thinking in terms of user experience, I find it a bit awkward. If you want stdin, you say mytool < file, if you want stdout you say mytool and pipe the output down the line. Is there a need to state the output when we're not writing to a file?

There is a precedent for this, other tools like xray have llvm-xray account %s -o -, but it's there for completness, you could just say llvm-xray account %s.

787

In my sense, CSV or YAML are for machine parsing, TXT is for human consumption. A script should not parse a human-targetted output.
Maybe an option is missing here to set the format? Again xray has -f=text or -f=csv.

[sepavloff]

clang/docs/UsersManual.rst

770

CSV was chosen because such file is a simple union of records. It is convenient if multiple processes write to it. A process locks the file, writes to it and unlock it.

If header is required, thing get more complicated. A process locks file, then moves to the end and get current position. If it is the beginning of the file, this process if the first writer, so it writes header. Then it writes line of data and unlock file.

On the other hand, CSV file is proposed for parsing by scripts. Does such complication really makes sense?

786

Agree, it looks awkward. I will add variant without value.

787

I don't think an option for output format is needed here (but it could be useful if we supported JSON in addition to CSV). However the proposed format indeed is more readable. I am going to change printing accordingly, but without locale specifics. For users of this feature C locale is convenient.

[aganea]

clang/docs/UsersManual.rst

770

Thanks for the explanation! Yes, it would be more complicated indeed if locking is required. Let's forget the header if it's not practical.

However that raises a question: is it up to the user/build system to delete the log file on startup? Otherwise each build would indefintely append, you wouldn't know where your last build started in the log? How do you address that currently?

787

Sounds good!

[sepavloff]

Updated patch

• added variant of the option without file, it is used to print statistics on stdout.
• Updated file locking mechanism.
• Updated test and documentation accordingly.

[tschuett]

clang/lib/Driver/Driver.cpp

87

https://llvm.org/docs/CodingStandards.html#include-iostream-is-forbidden

[sepavloff]

clang/docs/UsersManual.rst

770

However that raises a question: is it up to the user/build system to delete the log file on startup? Otherwise each build would indefintely append, you wouldn't know where your last build started in the log? How do you address that currently?

Yes, the log file is only appended. Users need to delete it if they want it contains results of one run only. However this feature is also used to collect statistics. User runs the same build several times and average needed metric for the same output file.

[sepavloff]

Updated patch

[sepavloff]

clang/lib/Driver/Driver.cpp

87

Thank you for the catch!

3944

Indeed, changed accordingly.

[aganea]

clang/lib/Driver/Driver.cpp

3946

In the case where !ProcStat, I am wondering if we shouldn't emit zero values, in the report file at least. Otherwise if an invocation fails, it won't be there in the report and we might wonder why. Emitting 0 might indicate that something went wrong.

3978

If the goal is to report accurate information, maybe it's worth looping here a bit in case of an error, to give the chance to other clang.exe instances to release the file lock? What do you think? (same for tryToLock)

[sepavloff]

clang/lib/Driver/Driver.cpp

3946

The feature allows getting statistics using conventional tools like make. In this case the absence of numbers for a particular file is not an issue, maybe the file has already been built. If something goes wrong, clang must handle it in Compilation::ExecuteCommand and react properly. The fact of failed invocation would be handled by build tool. For the purpose of monitoring performance numbers it is more convenient to record successful compilations only.

3978

Actually this method makes blocking request and waits infinitely.

There is long discussion of how this lock helper must be implemented: https://reviews.llvm.org/D79066. Finally the variant with timeout was removed, only blocking one remained. The method has prefix try because it requires handling result value.

If you think the name or interface might be better, you can participate in the discussion in D79066, that patch isn't committed yet.

[aganea]

clang/lib/Driver/Driver.cpp

3946

Ok, thanks for clarifying! Could you please do an early exit here? ie.

if (!ProcStat)
  return;

3978

Thanks!

In the same way as above, I think the code will read better if it did early exits. Also, I don't think you need handleAllErrors, you could replace it with toString and report the error code the user:

if (EC)
  return;
auto L=OS.tryToLock();
if (!L) {
  llvm::errs() ... << toString(L.takeError());
  return;
}
OS << Buffer;

[sepavloff]

Updated patch according to reviewer's notes

[sepavloff]

Updated patch

[sepavloff]

clang/lib/Driver/Driver.cpp

3978

It becomes better. Thanks!

[aganea]

Thanks again for the changes @sepavloff! Looks good to me!
You might wait a bit before commiting, if there are further comments.

clang/lib/Driver/Driver.cpp

3971

Please note that I've just moved this function to llvm::sys::printArg, you will need to update before commit.

[sepavloff]

Thank you @aganea !

[tschuett]

Could you add quotation marks around the executable name to make the CSV file easier to parse?

[sepavloff]

In D78903#2397845, @tschuett wrote:

Could you add quotation marks around the executable name to make the CSV file easier to parse?

Implemented: rG9faedb2d7146.

[tschuett]

Thanks!

[ZarkoCA]

clang/test/Driver/report-stat.c

1

Hi @sepavloff, is it possible to add -fintegrated-as to the clang invocation?

As it is, the test fails on our AIX target because we don't use the integrated assembler by default.

[ZarkoCA]

clang/test/Driver/report-stat.c

1

fyi, I added the option in 979bcbd3a6f7ea784f2098ad4cf613fbd6b09e38

clang/docs/UsersManual.rst

 
 2. Some source locations are not displayed correctly. The front end has
    a more detailed source location tracking than the locations included
    in the debug info (e.g., the front end can locate code inside macro
    expansions). However, the locations used by `-Rpass` are
    translated from debug annotations. That translation can be lossy,
    which results in some remarks having no location information.
 
+Options to Emit Resource Consumption Reports
+--------------------------------------------
+
+These are options that report execution time and consumed memory of different
+compilations steps.
+
+.. option:: -fproc-stat-report=
+
+  This option requests driver to print used memory and execution time of each
+  compilation step. The ``clang`` driver during execution calls different tools,
+  like compiler, assembler, linker etc. With this option the driver reports
+  total execution time, the execution time spent in user mode and peak memory
+  usage of each the called tool. Value of the option specifies where the report
+  is sent to. If it specifies a regular file, the data are saved to this file in
+  CSV format:
+
+.. code-block:: console
+
+   $ clang -fproc-stat-report=abc foo.c
+   $ cat abc
+   clang-11,"/tmp/foo-123456.o",92000,84000,87536
+   ld,"a.out",900,8000,53568
+
+  The data on each row represent:
+  
+  * file name of the tool executable,
+  * output file name in quotes,
+  * total execution time in microseconds,
+  * execution time in user mode in microseconds,
+  * peak memory usage in Kb.
+  
+  It is possible to specify this option without any value. In this case statistics
+  is printed on standard output in human readable format:
+  
+.. code-block:: console
+
+  $ clang -fproc-stat-report foo.c
+  clang-11: output=/tmp/foo-855a8e.o, total=68.000 ms, user=60.000 ms, mem=86920 Kb
+  ld: output=a.out, total=8.000 ms, user=4.000 ms, mem=52320 Kb
+  
+  The report file specified in the option is locked for write, so this option
+  can be used to collect statistics in parallel builds. The report file is not
+  cleared, new data is appended to it, thus making posible to accumulate build
+  statistics.
+
 Other Options
 -------------
 Clang options that don't fit neatly into other categories.
 
 .. option:: -fgnuc-version=
 
   This flag controls the value of ``__GNUC__`` and related macros. This flag
   does not enable or disable any GCC extensions implemented in Clang. Setting

clang/include/clang/Driver/Job.h

class Command {
 
   /// String storage if we need to create a new argument to specify a response
   /// file
   std::string ResponseFileFlag;
 
   /// See Command::setEnvironment
   std::vector<const char *> Environment;
 
+  /// Information on executable run provided by OS.
+  mutable Optional<llvm::sys::ProcessStatistics> ProcStat;
+
   /// When a response file is needed, we try to put most arguments in an
   /// exclusive file, while others remains as regular command line arguments.
   /// This functions fills a vector with the regular command line arguments,
   /// argv, excluding the ones passed in a response file.
   void buildArgvForResponseFile(llvm::SmallVectorImpl<const char *> &Out) const;
 
   /// Encodes an array of C strings into a single string separated by whitespace.
   /// This function will also put in quotes arguments that have whitespaces and
public:
   const llvm::opt::ArgStringList &getInputFilenames() const {
     return InputFilenames;
   }
 
   const std::vector<std::string> &getOutputFilenames() const {
     return OutputFilenames;
   }
 
+  Optional<llvm::sys::ProcessStatistics> getProcessStatistics() const {
+    return ProcStat;
+  }
+
 protected:
   /// Optionally print the filenames to be compiled
   void PrintFileNames() const;
 };
 
 /// Use the CC1 tool callback when available, to avoid creating a new process
 class CC1Command : public Command {
 public:

clang/include/clang/Driver/Options.td

def ftime_trace : Flag<["-"], "ftime-trace">, Group<f_Group>,
   DocBrief<[{
 Turn on time profiler. Generates JSON file based on output filename. Results
 can be analyzed with chrome://tracing or `Speedscope App
 <https://www.speedscope.app>`_ for flamegraph visualization.}]>,
   Flags<[CC1Option, CoreOption]>;
 def ftime_trace_granularity_EQ : Joined<["-"], "ftime-trace-granularity=">, Group<f_Group>,
   HelpText<"Minimum time granularity (in microseconds) traced by time profiler">,
   Flags<[CC1Option, CoreOption]>;
+def fproc_stat_report : Joined<["-"], "fproc-stat-report">, Group<f_Group>,
+  HelpText<"Print subprocess statistics">;
+def fproc_stat_report_EQ : Joined<["-"], "fproc-stat-report=">, Group<f_Group>,
+  HelpText<"Save subprocess statistics to the given file">;
 def ftlsmodel_EQ : Joined<["-"], "ftls-model=">, Group<f_Group>, Flags<[CC1Option]>;
 def ftrapv : Flag<["-"], "ftrapv">, Group<f_Group>, Flags<[CC1Option]>,
   HelpText<"Trap on integer overflow">;
 def ftrapv_handler_EQ : Joined<["-"], "ftrapv-handler=">, Group<f_Group>,
   MetaVarName<"<function name>">,
   HelpText<"Specify the function to be called on overflow">;
 def ftrapv_handler : Separate<["-"], "ftrapv-handler">, Group<f_Group>, Flags<[CC1Option]>;
 def ftrap_function_EQ : Joined<["-"], "ftrap-function=">, Group<f_Group>, Flags<[CC1Option]>,

clang/lib/Driver/Driver.cpp

 #include "llvm/Support/Path.h"
 #include "llvm/Support/PrettyStackTrace.h"
 #include "llvm/Support/Process.h"
 #include "llvm/Support/Program.h"
 #include "llvm/Support/StringSaver.h"
 #include "llvm/Support/TargetRegistry.h"
 #include "llvm/Support/VirtualFileSystem.h"
 #include "llvm/Support/raw_ostream.h"
 #include <map>
 #include <memory>
 #include <utility>
 #if LLVM_ON_UNIX
 #include <unistd.h> // getpid
 #endif
 
 using namespace clang::driver;
 using namespace clang;
for (Action *A : C.getActions()) {
     BuildJobsForAction(C, A, &C.getDefaultToolChain(),
                        /*BoundArch*/ StringRef(),
                        /*AtTopLevel*/ true,
                        /*MultipleArchs*/ ArchNames.size() > 1,
                        /*LinkingOutput*/ LinkingOutput, CachedResults,
                        /*TargetDeviceOffloadKind*/ Action::OFK_None);
   }
 
-  // If we have more than one job, then disable integrated-cc1 for now.
-  if (C.getJobs().size() > 1)
+  StringRef StatReportFile;
+  bool PrintProcessStat = false;
+  if (const Arg *A = C.getArgs().getLastArg(options::OPT_fproc_stat_report_EQ))
+    StatReportFile = A->getValue();
+  if (C.getArgs().hasArg(options::OPT_fproc_stat_report))
+    PrintProcessStat = true;
+
+  // If we have more than one job, then disable integrated-cc1 for now. Do this
+  // also when we need to report process execution statistics.
+  if (C.getJobs().size() > 1 || !StatReportFile.empty() || PrintProcessStat)
     for (auto &J : C.getJobs())
       J.InProcess = false;
 
+  if (!StatReportFile.empty() || PrintProcessStat) {
+    C.setPostCallback([=](const Command &Cmd, int Res) {
+      Optional<llvm::sys::ProcessStatistics> ProcStat =
+          Cmd.getProcessStatistics();
+      if (!ProcStat)
+        return;
+      if (PrintProcessStat) {
+        using namespace llvm;
+        // Human readable output.
+        outs() << sys::path::filename(Cmd.getExecutable()) << ": "
+               << "output=";
+        if (Cmd.getOutputFilenames().empty())
+          outs() << "\"\"";
+        else
+          outs() << Cmd.getOutputFilenames().front();
+        outs() << ", total="
+               << format("%.3f", ProcStat->TotalTime.count() / 1000.) << " ms"
+               << ", user="
+               << format("%.3f", ProcStat->UserTime.count() / 1000.) << " ms"
+               << ", mem=" << ProcStat->PeakMemory << " Kb\n";
+      }
+      if (!StatReportFile.empty()) {
+        // CSV format.
+        std::string Buffer;
+        llvm::raw_string_ostream Out(Buffer);
+        Out << llvm::sys::path::filename(Cmd.getExecutable()) << ',';
+        if (Cmd.getOutputFilenames().empty())
+          Out << "\"\"";
+        else
+          llvm::sys::printArg(Out, Cmd.getOutputFilenames().front(), true);
+        Out << ',' << ProcStat->TotalTime.count() << ','
+            << ProcStat->UserTime.count() << ',' << ProcStat->PeakMemory
+            << '\n';
+        Out.flush();
+        std::error_code EC;
+        llvm::raw_fd_ostream OS(StatReportFile, EC, llvm::sys::fs::OF_Append);
+        if (EC)
+          return;
+        auto L = OS.lock();
+        if (!L) {
+          llvm::errs() << "ERROR: Cannot lock file " << StatReportFile << ": "
+                       << toString(L.takeError()) << "\n";
+          return;
+        }
+        OS << Buffer;
+      }
+    });
+  }
+
   // If the user passed -Qunused-arguments or there were errors, don't warn
   // about any unused arguments.
   if (Diags.hasErrorOccurred() ||
       C.getArgs().hasArg(options::OPT_Qunused_arguments))
     return;
 
   // Claim -### here.
   (void)C.getArgs().hasArg(options::OPT__HASH_HASH_HASH);

clang/lib/Driver/Job.cpp

if (!Environment.empty()) {
     assert(Environment.back() == nullptr &&
            "Environment vector should be null-terminated by now");
     ArgvVectorStorage = llvm::toStringRefArray(Environment.data());
     Env = makeArrayRef(ArgvVectorStorage);
   }
 
   auto Args = llvm::toStringRefArray(Argv.data());
   return llvm::sys::ExecuteAndWait(Executable, Args, Env, Redirects,
-                                   /*secondsToWait*/ 0,
-                                   /*memoryLimit*/ 0, ErrMsg, ExecutionFailed);
+                                   /*secondsToWait*/ 0, /*memoryLimit*/ 0,
+                                   ErrMsg, ExecutionFailed, &ProcStat);
 }
 
 CC1Command::CC1Command(const Action &Source, const Tool &Creator,
                        ResponseFileSupport ResponseSupport,
                        const char *Executable,
                        const llvm::opt::ArgStringList &Arguments,
                        ArrayRef<InputInfo> Inputs, ArrayRef<InputInfo> Outputs)
     : Command(Source, Creator, ResponseSupport, Executable, Arguments, Inputs,

clang/test/Driver/report-stat.c

+// RUN: %clang -c -fproc-stat-report %s | FileCheck %s
+// CHECK: clang{{.*}}: output={{.*}}.o, total={{[0-9.]+}} ms, user={{[0-9.]+}} ms, mem={{[0-9]+}} Kb
+
+// RUN: %clang -c -fproc-stat-report=%t %s
+// RUN: cat %t | FileCheck --check-prefix=CSV %s
+// CSV: clang{{.*}},"{{.*}}.o",{{[0-9]+}},{{[0-9]+}},{{[0-9]+}}