cmake: add command line options to output script profiling data

For users of CMake who want to optimize their scripts if they take a
while to run, this commit adds the ability to output profiling data.

To enable this output, it adds the two command line parameters
to select the output path and format.

This commit adds the first profiling format of type ``google-trace``,
which is the output is a JSON file containing Duration events as per the
Google Trace Format specification:

https://docs.google.com/document/d/1CvAClvFfyA5R-
PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#

Help/manual/cmake.1.rst

@@ -356,6 +356,20 @@ Options
  in :variable:`CMAKE_SOURCE_DIR` and :variable:`CMAKE_BINARY_DIR`.
  This flag tells CMake to warn about other files as well.
 
+``--profiling-output=<path>``
+ Used in conjuction with ``--profiling-format`` to output to a given path.
+
+``--profiling-format=<file>``
+ Enable the output of profiling data of CMake script in the given format.
+
+ This can aid performance analysis of CMake scripts executed. Third party
+ applications should be used to process the output into human readable format.
+
+ Currently supported values are:
+ ``google-trace`` Outputs in Google Trace Format, which can be parsed by the
+ about:tracing tab of Google Chrome or using a plugin for a tool like Trace
+ Compass.
+
 .. _`Build Tool Mode`:
 
 Build a Project

Help/release/dev/profiling.rst

@@ -0,0 +1,9 @@
+cmake-profiling
+---------------
+
+* Add support for profiling of CMake scripts through the parameters
+  ``--profiling-output`` and ``--profiling-format``. These options can
+  be used by users to gain insight into the performance of their scripts.
+
+  The first supported output format is ``google-trace`` which is a format
+  supported by Google Chrome's ``about:tracing`` tab.

Source/CMakeLists.txt

@@ -354,6 +354,7 @@ set(SRCS
   cmMakefileTargetGenerator.cxx
   cmMakefileExecutableTargetGenerator.cxx
   cmMakefileLibraryTargetGenerator.cxx
+  cmMakefileProfilingData.cxx
   cmMakefileUtilityTargetGenerator.cxx
   cmMessageType.h
   cmMessenger.cxx

Source/cmMakefile.cxx

@@ -60,6 +60,7 @@
 #include "cmake.h"
 
 #ifndef CMAKE_BOOTSTRAP
+#  include "cmMakefileProfilingData.h"
 #  include "cmVariableWatch.h"
 #endif
 
@@ -372,19 +373,30 @@ void cmMakefile::PrintCommandTrace(const cmListFileFunction& lff) const
 class cmMakefileCall
 {
 public:
-  cmMakefileCall(cmMakefile* mf, cmCommandContext const& cc,
+  cmMakefileCall(cmMakefile* mf, cmListFileFunction const& lff,
                  cmExecutionStatus& status)
     : Makefile(mf)
   {
     cmListFileContext const& lfc = cmListFileContext::FromCommandContext(
-      cc, this->Makefile->StateSnapshot.GetExecutionListFile());
+      lff, this->Makefile->StateSnapshot.GetExecutionListFile());
     this->Makefile->Backtrace = this->Makefile->Backtrace.Push(lfc);
     ++this->Makefile->RecursionDepth;
     this->Makefile->ExecutionStatusStack.push_back(&status);
+#if !defined(CMAKE_BOOTSTRAP)
+    if (this->Makefile->GetCMakeInstance()->IsProfilingEnabled()) {
+      this->Makefile->GetCMakeInstance()->GetProfilingOutput().StartEntry(lff,
+                                                                          lfc);
+    }
+#endif
   }
 
   ~cmMakefileCall()
   {
+#if !defined(CMAKE_BOOTSTRAP)
+    if (this->Makefile->GetCMakeInstance()->IsProfilingEnabled()) {
+      this->Makefile->GetCMakeInstance()->GetProfilingOutput().StopEntry();
+    }
+#endif
     this->Makefile->ExecutionStatusStack.pop_back();
     --this->Makefile->RecursionDepth;
     this->Makefile->Backtrace = this->Makefile->Backtrace.Pop();

Source/cmMakefileProfilingData.cxx

@@ -0,0 +1,113 @@
+/* Distributed under the OSI-approved BSD 3-Clause License.  See accompanying
+   file Copyright.txt or https://cmake.org/licensing for details.  */
+#include "cmMakefileProfilingData.h"
+
+#include <chrono>
+#include <cstdint>
+#include <stdexcept>
+#include <vector>
+
+#include "cmsys/FStream.hxx"
+#include "cmsys/SystemInformation.hxx"
+
+#include "cm_jsoncpp_value.h"
+#include "cm_jsoncpp_writer.h"
+
+#include "cmListFileCache.h"
+#include "cmStringAlgorithms.h"
+#include "cmSystemTools.h"
+
+cmMakefileProfilingData::cmMakefileProfilingData(
+  const std::string& profileStream)
+{
+  std::ios::openmode omode = std::ios::out | std::ios::trunc;
+  this->ProfileStream.open(profileStream.c_str(), omode);
+  Json::StreamWriterBuilder wbuilder;
+  this->JsonWriter =
+    std::unique_ptr<Json::StreamWriter>(wbuilder.newStreamWriter());
+  if (!this->ProfileStream.good()) {
+    throw std::runtime_error(std::string("Unable to open: ") + profileStream);
+  }
+
+  this->ProfileStream << "[";
+};
+
+cmMakefileProfilingData::~cmMakefileProfilingData() noexcept
+{
+  if (this->ProfileStream.good()) {
+    try {
+      this->ProfileStream << "]";
+      this->ProfileStream.close();
+    } catch (...) {
+      cmSystemTools::Error("Error writing profiling output!");
+    }
+  }
+}
+
+void cmMakefileProfilingData::StartEntry(const cmListFileFunction& lff,
+                                         cmListFileContext const& lfc)
+{
+  /* Do not try again if we previously failed to write to output. */
+  if (!this->ProfileStream.good()) {
+    return;
+  }
+
+  try {
+    if (this->ProfileStream.tellp() > 1) {
+      this->ProfileStream << ",";
+    }
+    cmsys::SystemInformation info;
+    Json::Value v;
+    v["ph"] = "B";
+    v["name"] = lff.Name.Original;
+    v["cat"] = "cmake";
+    v["ts"] = uint64_t(std::chrono::duration_cast<std::chrono::microseconds>(
+                         std::chrono::steady_clock::now().time_since_epoch())
+                         .count());
+    v["pid"] = static_cast<int>(info.GetProcessId());
+    v["tid"] = 0;
+    Json::Value argsValue;
+    if (!lff.Arguments.empty()) {
+      std::string args;
+      for (const auto& a : lff.Arguments) {
+        args += (args.empty() ? "" : " ") + a.Value;
+      }
+      argsValue["functionArgs"] = args;
+    }
+    argsValue["location"] = lfc.FilePath + ":" + std::to_string(lfc.Line);
+    v["args"] = argsValue;
+
+    this->JsonWriter->write(v, &this->ProfileStream);
+  } catch (std::ios_base::failure& fail) {
+    cmSystemTools::Error(
+      cmStrCat("Failed to write to profiling output: ", fail.what()));
+  } catch (...) {
+    cmSystemTools::Error("Error writing profiling output!");
+  }
+}
+
+void cmMakefileProfilingData::StopEntry()
+{
+  /* Do not try again if we previously failed to write to output. */
+  if (!this->ProfileStream.good()) {
+    return;
+  }
+
+  try {
+    this->ProfileStream << ",";
+    cmsys::SystemInformation info;
+    Json::Value v;
+    v["ph"] = "E";
+    v["ts"] = uint64_t(std::chrono::duration_cast<std::chrono::microseconds>(
+                         std::chrono::steady_clock::now().time_since_epoch())
+                         .count());
+    v["pid"] = static_cast<int>(info.GetProcessId());
+    v["tid"] = 0;
+    this->JsonWriter->write(v, &this->ProfileStream);
+  } catch (std::ios_base::failure& fail) {
+    cmSystemTools::Error(
+      cmStrCat("Failed to write to profiling output:", fail.what()));
+  } catch (...) {
+    cmSystemTools::Error("Error writing profiling output!");
+  }
+}

Source/cmMakefileProfilingData.h

@@ -0,0 +1,29 @@
+/* Distributed under the OSI-approved BSD 3-Clause License.  See accompanying
+   file Copyright.txt or https://cmake.org/licensing for details.  */
+#ifndef cmMakefileProfilingData_h
+#define cmMakefileProfilingData_h
+#include <memory>
+#include <string>
+
+#include "cmsys/FStream.hxx"
+
+namespace Json {
+class StreamWriter;
+}
+
+class cmListFileContext;
+struct cmListFileFunction;
+
+class cmMakefileProfilingData
+{
+public:
+  cmMakefileProfilingData(const std::string&);
+  ~cmMakefileProfilingData() noexcept;
+  void StartEntry(const cmListFileFunction& lff, cmListFileContext const& lfc);
+  void StopEntry();
+
+private:
+  cmsys::ofstream ProfileStream;
+  std::unique_ptr<Json::StreamWriter> JsonWriter;
+};
+#endif

Source/cmake.cxx

@@ -9,6 +9,7 @@
 #include <initializer_list>
 #include <iostream>
 #include <sstream>
+#include <stdexcept>
 #include <utility>
 
 #include <cm/memory>
@@ -39,6 +40,9 @@
 #include "cmLinkLineComputer.h"
 #include "cmLocalGenerator.h"
 #include "cmMakefile.h"
+#if !defined(CMAKE_BOOTSTRAP)
+#  include "cmMakefileProfilingData.h"
+#endif
 #include "cmMessenger.h"
 #include "cmState.h"
 #include "cmStateDirectory.h"
@@ -613,6 +617,10 @@ void cmake::SetArgs(const std::vector<std::string>& args)
 {
   bool haveToolset = false;
   bool havePlatform = false;
+#if !defined(CMAKE_BOOTSTRAP)
+  std::string profilingFormat;
+  std::string profilingOutput;
+#endif
   for (unsigned int i = 1; i < args.size(); ++i) {
     std::string const& arg = args[i];
     if (arg.find("-H", 0) == 0 || arg.find("-S", 0) == 0) {
@@ -839,6 +847,20 @@ void cmake::SetArgs(const std::vector<std::string>& args)
         return;
       }
       this->SetGlobalGenerator(std::move(gen));
+#if !defined(CMAKE_BOOTSTRAP)
+    } else if (arg.find("--profiling-format", 0) == 0) {
+      profilingFormat = arg.substr(strlen("--profiling-format="));
+      if (profilingFormat.empty()) {
+        cmSystemTools::Error("No format specified for --profiling-format");
+      }
+    } else if (arg.find("--profiling-output", 0) == 0) {
+      profilingOutput = arg.substr(strlen("--profiling-output="));
+      profilingOutput = cmSystemTools::CollapseFullPath(profilingOutput);
+      cmSystemTools::ConvertToUnixSlashes(profilingOutput);
+      if (profilingOutput.empty()) {
+        cmSystemTools::Error("No path specified for --profiling-output");
+      }
+#endif
     }
     // no option assume it is the path to the source or an existing build
     else {
@@ -856,6 +878,29 @@ void cmake::SetArgs(const std::vector<std::string>& args)
     }
   }
 
+#if !defined(CMAKE_BOOTSTRAP)
+  if (!profilingOutput.empty() || !profilingFormat.empty()) {
+    if (profilingOutput.empty()) {
+      cmSystemTools::Error(
+        "--profiling-format specified but no --profiling-output!");
+      return;
+    }
+    if (profilingFormat == "google-trace") {
+      try {
+        this->ProfilingOutput =
+          cm::make_unique<cmMakefileProfilingData>(profilingOutput);
+      } catch (std::runtime_error& e) {
+        cmSystemTools::Error(
+          cmStrCat("Could not start profiling: ", e.what()));
+        return;
+      }
+    } else {
+      cmSystemTools::Error("Invalid format specified for --profiling-format");
+      return;
+    }
+  }
+#endif
+
   const bool haveSourceDir = !this->GetHomeDirectory().empty();
   const bool haveBinaryDir = !this->GetHomeOutputDirectory().empty();
 
@@ -2952,3 +2997,15 @@ void cmake::SetDeprecatedWarningsAsErrors(bool b)
                       " and functions.",
                       cmStateEnums::INTERNAL);
 }
+
+#if !defined(CMAKE_BOOTSTRAP)
+cmMakefileProfilingData& cmake::GetProfilingOutput()
+{
+  return *(this->ProfilingOutput);
+}
+
+bool cmake::IsProfilingEnabled() const
+{
+  return static_cast<bool>(this->ProfilingOutput);
+}
+#endif

Source/cmake.h

@@ -34,6 +34,9 @@ class cmFileTimeCache;
 class cmGlobalGenerator;
 class cmGlobalGeneratorFactory;
 class cmMakefile;
+#if !defined(CMAKE_BOOTSTRAP)
+class cmMakefileProfilingData;
+#endif
 class cmMessenger;
 class cmVariableWatch;
 struct cmDocumentationEntry;
@@ -549,6 +552,11 @@ public:
 
   bool GetRegenerateDuringBuild() const { return this->RegenerateDuringBuild; }
 
+#if !defined(CMAKE_BOOTSTRAP)
+  cmMakefileProfilingData& GetProfilingOutput();
+  bool IsProfilingEnabled() const;
+#endif
+
 protected:
   void RunCheckForUnusedVariables();
   int HandleDeleteCacheVariables(const std::string& var);
@@ -657,6 +665,10 @@ private:
 
   void AppendGlobalGeneratorsDocumentation(std::vector<cmDocumentationEntry>&);
   void AppendExtraGeneratorsDocumentation(std::vector<cmDocumentationEntry>&);
+
+#if !defined(CMAKE_BOOTSTRAP)
+  std::unique_ptr<cmMakefileProfilingData> ProfilingOutput;
+#endif
 };
 
 #define CMAKE_STANDARD_OPTIONS_TABLE                                          \

Source/cmakemain.cxx

@@ -93,6 +93,12 @@ const char* cmDocumentationOptions[][2] = {
   { "--check-system-vars",
     "Find problems with variable usage in system "
     "files." },
+#  if !defined(CMAKE_BOOTSTRAP)
+  { "--profiling-format=<fmt>", "Output data for profiling CMake scripts." },
+  { "--profiling-output=<file>",
+    "Select an output path for the profiling data enabled through "
+    "--profiling-format." },
+#  endif
   { nullptr, nullptr }
 };
 

Tests/RunCMake/CommandLine/ProfilingTest-check.cmake

@@ -0,0 +1,18 @@
+if (NOT EXISTS ${ProfilingTestOutput})
+  set(RunCMake_TEST_FAILED "Expected ${ProfilingTestOutput} to exists")
+endif()
+
+file(READ "${ProfilingTestOutput}" JSON_HEADER LIMIT 2)
+if (NOT JSON_HEADER MATCHES "^\\[{")
+  set(RunCMake_TEST_FAILED "Expected valid JSON start")
+  return()
+endif()
+
+file(SIZE "${ProfilingTestOutput}" OUTPUT_SIZE)
+math(EXPR END_OFFSET "${OUTPUT_SIZE} -2 ")
+
+file(READ "${ProfilingTestOutput}" JSON_TRAILER OFFSET ${END_OFFSET})
+if (NOT JSON_TRAILER MATCHES "^}]$")
+  set(RunCMake_TEST_FAILED "Expected valid JSON end")
+  return()
+endif()

Tests/RunCMake/CommandLine/ProfilingTest.cmake

@@ -0,0 +1 @@
+# This file is intentionally left blank

Tests/RunCMake/CommandLine/RunCMakeTest.cmake

@@ -697,3 +697,25 @@ function(run_llvm_rc)
   unset(LLVMRC_RESULT)
 endfunction()
 run_llvm_rc()
+
+set(RunCMake_TEST_OPTIONS --profiling-output=/no/such/file.txt --profiling-format=google-trace)
+run_cmake(profiling-all-params)
+unset(RunCMake_TEST_OPTIONS)
+
+set(RunCMake_TEST_OPTIONS --profiling-output=/no/such/file.txt --profiling-format=invalid-format)
+run_cmake(profiling-invalid-format)
+unset(RunCMake_TEST_OPTIONS)
+
+set(RunCMake_TEST_OPTIONS --profiling-output=/no/such/file.txt)
+run_cmake(profiling-missing-format)
+unset(RunCMake_TEST_OPTIONS)
+
+set(RunCMake_TEST_OPTIONS --profiling-format=google-trace)
+run_cmake(profiling-missing-output)
+unset(RunCMake_TEST_OPTIONS)
+
+set(RunCMake_TEST_BINARY_DIR "${RunCMake_BINARY_DIR}/profiling-test")
+set(ProfilingTestOutput ${RunCMake_TEST_BINARY_DIR}/output.json)
+set(RunCMake_TEST_OPTIONS --profiling-format=google-trace --profiling-output=${ProfilingTestOutput})
+run_cmake(ProfilingTest)
+unset(RunCMake_TEST_OPTIONS)

Tests/RunCMake/CommandLine/profiling-all-params-result.txt

@@ -0,0 +1 @@
+1

Tests/RunCMake/CommandLine/profiling-all-params-stderr.txt

@@ -0,0 +1 @@
+^.*Could not start profiling: Unable to open: /no/such/file.txt$

Tests/RunCMake/CommandLine/profiling-invalid-format-result.txt

@@ -0,0 +1 @@
+1

Tests/RunCMake/CommandLine/profiling-invalid-format-stderr.txt

@@ -0,0 +1 @@
+^.*Invalid format specified for --profiling-format$

Tests/RunCMake/CommandLine/profiling-missing-format-result.txt

@@ -0,0 +1 @@
+1

Tests/RunCMake/CommandLine/profiling-missing-format-stderr.txt

@@ -0,0 +1 @@
+^.*Invalid format specified for --profiling-format$

Tests/RunCMake/CommandLine/profiling-missing-output-result.txt

@@ -0,0 +1 @@
+1

Tests/RunCMake/CommandLine/profiling-missing-output-stderr.txt

@@ -0,0 +1 @@
+^.*--profiling-format specified but no --profiling-output!$