instrumentation: Add Google trace output

Add a feature to parse snippets into a trace file compatible with the
Google Trace Event Format.

Fixes: #26674

Help/command/cmake_instrumentation.rst

@@ -78,7 +78,7 @@ equivalent JSON query file.
     API_VERSION 1
     DATA_VERSION 1
     HOOKS postGenerate preCMakeBuild postCMakeBuild
-    OPTIONS staticSystemInformation dynamicSystemInformation
+    OPTIONS staticSystemInformation dynamicSystemInformation trace
     CALLBACK ${CMAKE_COMMAND} -P /path/to/handle_data.cmake
     CALLBACK ${CMAKE_COMMAND} -P /path/to/handle_data_2.cmake
     CUSTOM_CONTENT myString STRING string
@@ -94,7 +94,7 @@ equivalent JSON query file.
       "postGenerate", "preCMakeBuild", "postCMakeBuild"
     ],
     "options": [
-      "staticSystemInformation", "dynamicSystemInformation"
+      "staticSystemInformation", "dynamicSystemInformation", "trace"
     ],
     "callbacks": [
       "/path/to/cmake -P /path/to/handle_data.cmake"

Help/manual/cmake-instrumentation.7.rst

@@ -162,6 +162,12 @@ subdirectories:
   A subset of the collected data, containing any
   :ref:`cmake_instrumentation Configure Content` files.
 
+``data/trace/``
+  A subset of the collected data, containing the `Google Trace File`_ created
+  from the most recent `Indexing`_. Unlike other data files, the most recent
+  trace file remains even after `Indexing`_ occurs and all `Callbacks`_ are
+  executed, until the next time `Indexing`_ occurs.
+
 ``cdash/``
   Holds temporary files used internally to generate XML content to be submitted
   to CDash.
@@ -231,6 +237,10 @@ key is required, but all other fields are optional.
       CDash. Equivalent to having the
       :envvar:`CTEST_USE_VERBOSE_INSTRUMENTATION` environment variable enabled.
 
+    ``trace``
+      Enables generation of a `Google Trace File`_ during `Indexing`_ to
+      visualize data from the `v1 Snippet Files <v1 Snippet File_>`_ collected.
+
 The ``callbacks`` listed will be invoked during the specified hooks
 *at a minimum*. When there are multiple query files, the ``callbacks``,
 ``hooks`` and ``options`` between them will be merged. Therefore, if any query
@@ -258,7 +268,8 @@ Example:
     "options": [
       "staticSystemInformation",
       "dynamicSystemInformation",
-      "cdashSubmit"
+      "cdashSubmit",
+      "trace"
     ]
   }
 
@@ -270,11 +281,12 @@ files created since the previous indexing. The commands
 ``/usr/bin/cmake -P callback.cmake arg index-<timestamp>.json`` will be executed
 in that order. The index file will contain the ``staticSystemInformation`` data
 and each snippet file listed in the index will contain the
-``dynamicSystemInformation`` data. Once both callbacks have completed, the index
-file and all snippet files listed by it will be deleted from the project build
-tree. The instrumentation data will be present in the XML files submitted to
-CDash, but with truncated command strings because ``cdashVerbose`` was not
-enabled.
+``dynamicSystemInformation`` data. Additionally, the index file will contain
+the path to the generated `Google Trace File`_. Once both callbacks have completed,
+the index file and data files listed by it (including snippet files, but not
+the trace file) will be deleted from the project build tree. The instrumentation
+data will be present in the XML files submitted to CDash, but with truncated
+command strings because ``cdashVerbose`` was not enabled.
 
 .. _`cmake-instrumentation Data v1`:
 
@@ -285,10 +297,10 @@ Data version specifies the contents of the output files generated by the CMake
 instrumentation API as part of the `Data Collection`_ and `Indexing`_. A new
 version number will be created whenever previously included data is removed or
 reformatted such that scripts written to parse this data may become
-incompatible with the new format. There are two types of data files generated:
-the `v1 Snippet File`_ and `v1 Index File`_. When using the `API v1`_, these
-files live in ``<build>/.cmake/instrumentation/v1/data/`` under the project
-build tree.
+incompatible with the new format. There are three types of data files generated:
+the `v1 Snippet File`_, the `v1 Index File`_, and the `Google Trace File`_.
+When using the `API v1`_, these files live in
+``<build>/.cmake/instrumentation/v1/data/`` under the project build tree.
 
 .. _`cmake-instrumentation v1 Snippet File`:
 
@@ -460,6 +472,11 @@ occurs and deleted after any user-specified `Callbacks`_ are executed.
   generated since the previous index file was created. The file paths are
   relative to ``dataDir``.
 
+``trace``:
+  Contains the path to the `Google Trace File`_. This includes data from all
+  corresponding ``snippets`` in the index file. The file path is relative to
+  ``dataDir``. Only included when enabled by the `v1 Query Files`_.
+
 ``staticSystemInformation``
   Specifies the static information collected about the host machine
   CMake is being run from. Only included when enabled by the `v1 Query Files`_.
@@ -502,5 +519,49 @@ Example:
       "ctest-<hash>-<timestamp>.json",
       "test-<hash>-<timestamp>.json",
       "test-<hash>-<timestamp>.json",
-    ]
+    ],
+    "trace": "trace/trace-<timestamp>.json"
   }
+
+Google Trace File
+-----------------
+
+Trace files follow the `Google Trace Event Format`_. They include data from
+all `v1 Snippet File`_ listed in the current index file. These files remain
+in the build tree even after `Indexing`_ occurs and all `Callbacks`_ are
+executed, until the next time `Indexing`_ occurs.
+
+Trace files are stored in the ``JSON Array Format``, where each
+`v1 Snippet File`_ corresponds to a single trace event object. Each trace
+event contains the following data:
+
+  ``name``
+  A descriptive name generated by CMake based on the given snippet data.
+
+  ``cat``
+  The ``role`` from the `v1 Snippet File`_.
+
+  ``ph``
+  Currently, always ``"X"`` to represent ``Complete Events``.
+
+  ``ts``
+  The ``timeStart`` from the `v1 Snippet File`_, converted from milliseconds to
+  microseconds.
+
+  ``dur``
+  The ``duration`` from the `v1 Snippet File`_, converted from milliseconds to
+  microseconds.
+
+  ``pid``
+  Unused (always zero).
+
+  ``tid``
+  An integer ranging from zero to the number of concurrent jobs with which the
+  processes being indexed ran. This is a synthetic ID calculated by CMake
+  based on the ``ts`` and ``dur`` of all snippet files being indexed in
+  order to produce a more useful visualization of the process concurrency.
+
+  ``args``
+  Contains all data from the `v1 Snippet File`_ corresponding to this trace event.
+
+.. _`Google Trace Event Format`: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview

Source/cmInstrumentation.cxx

@@ -1,5 +1,6 @@
 #include "cmInstrumentation.h"
 
+#include <algorithm>
 #include <chrono>
 #include <ctime>
 #include <iomanip>
@@ -10,12 +11,14 @@
 #include <cm/memory>
 #include <cm/optional>
 
+#include <cm3p/json/reader.h>
+#include <cm3p/json/version.h>
 #include <cm3p/json/writer.h>
 #include <cm3p/uv.h>
 
 #include "cmsys/Directory.hxx"
 #include "cmsys/FStream.hxx"
-#include <cmsys/SystemInformation.hxx>
+#include "cmsys/SystemInformation.hxx"
 
 #include "cmCryptoHash.h"
 #include "cmExperimental.h"
@@ -225,22 +228,54 @@ void cmInstrumentation::WriteCustomContent()
   }
 }
 
-std::string cmInstrumentation::GetLatestContentFile()
+std::string cmInstrumentation::GetLatestFile(std::string const& dataSubdir)
 {
-  std::string contentFile;
-  if (cmSystemTools::FileExists(
-        cmStrCat(this->timingDirv1, "/data/content"))) {
+  std::string fullDir = cmStrCat(this->timingDirv1, "/data/", dataSubdir);
+  std::string latestFile;
+  if (cmSystemTools::FileExists(fullDir)) {
     cmsys::Directory d;
-    if (d.Load(cmStrCat(this->timingDirv1, "/data/content"))) {
+    if (d.Load(fullDir)) {
       for (unsigned int i = 0; i < d.GetNumberOfFiles(); i++) {
         std::string fname = d.GetFileName(i);
-        if (fname != "." && fname != ".." && fname > contentFile) {
-          contentFile = fname;
+        if (fname != "." && fname != ".." && fname > latestFile) {
+          latestFile = fname;
+        }
+      }
+    }
+  }
+  return latestFile;
+}
+
+void cmInstrumentation::RemoveOldFiles(std::string const& dataSubdir)
+{
+  std::string const dataSubdirPath =
+    cmStrCat(this->timingDirv1, "/data/", dataSubdir);
+  if (cmSystemTools::FileExists(dataSubdirPath)) {
+    std::string latestFile = this->GetLatestFile(dataSubdir);
+    cmsys::Directory d;
+    if (d.Load(dataSubdirPath)) {
+      for (unsigned int i = 0; i < d.GetNumberOfFiles(); i++) {
+        std::string fname = d.GetFileName(i);
+        std::string fpath = d.GetFilePath(i);
+        if (fname != "." && fname != ".." && fname < latestFile) {
+          if (dataSubdir == "trace") {
+            // Check if this trace file shares a name with any existing index
+            // files, in which case it is listed by that index file and a
+            // callback is running, so we shouldn't delete it yet.
+            std::string index = "index-";
+            std::string json = ".json";
+            std::string timestamp = fname.substr(
+              index.size(), fname.size() - index.size() - json.size() - 1);
+            if (cmSystemTools::FileExists(cmStrCat(
+                  this->timingDirv1, "/data/index-", timestamp, ".json"))) {
+              continue;
+            }
+          }
+          cmSystemTools::RemoveFile(fpath);
         }
       }
     }
   }
-  return contentFile;
 }
 
 void cmInstrumentation::ClearGeneratedQueries()
@@ -281,9 +316,9 @@ int cmInstrumentation::CollectTimingData(cmInstrumentationQuery::Hook hook)
 
   // Touch index file immediately to claim snippets
   std::string const& directory = cmStrCat(this->timingDirv1, "/data");
-  std::string const& file_name =
-    cmStrCat("index-", ComputeSuffixTime(), ".json");
-  std::string index_path = cmStrCat(directory, '/', file_name);
+  std::string suffix_time = ComputeSuffixTime();
+  std::string const& index_name = cmStrCat("index-", suffix_time, ".json");
+  std::string index_path = cmStrCat(directory, '/', index_name);
   cmSystemTools::Touch(index_path, true);
 
   // Gather Snippets
@@ -295,7 +330,7 @@ int cmInstrumentation::CollectTimingData(cmInstrumentationQuery::Hook hook)
     for (unsigned int i = 0; i < d.GetNumberOfFiles(); i++) {
       std::string fpath = d.GetFilePath(i);
       std::string fname = d.GetFile(i);
-      if (fname.rfind('.', 0) == 0 || fname == file_name ||
+      if (fname.rfind('.', 0) == 0 || fname == index_name ||
           d.FileIsDirectory(i)) {
         continue;
       }
@@ -336,7 +371,16 @@ int cmInstrumentation::CollectTimingData(cmInstrumentationQuery::Hook hook)
       }
     }
   }
-  this->WriteInstrumentationJson(index, "data", file_name);
+
+  // Parse snippets into the Google trace file
+  if (this->HasOption(cmInstrumentationQuery::Option::Trace)) {
+    std::string trace_name = cmStrCat("trace-", suffix_time, ".json");
+    this->WriteTraceFile(index, trace_name);
+    index["trace"] = "trace/" + trace_name;
+  }
+
+  // Write index file
+  this->WriteInstrumentationJson(index, "data", index_name);
 
   // Execute callbacks
   for (auto& cb : this->callbacks) {
@@ -356,25 +400,9 @@ int cmInstrumentation::CollectTimingData(cmInstrumentationQuery::Hook hook)
   }
   cmSystemTools::RemoveFile(index_path);
 
-  // Delete old content files
-  std::string const contentDir = cmStrCat(this->timingDirv1, "/data/content");
-  if (cmSystemTools::FileExists(contentDir)) {
-    std::string latestContent = this->GetLatestContentFile();
-    if (d.Load(contentDir)) {
-      for (unsigned int i = 0; i < d.GetNumberOfFiles(); i++) {
-        std::string fname = d.GetFileName(i);
-        std::string fpath = d.GetFilePath(i);
-        if (fname != "." && fname != ".." && fname != latestContent) {
-          int compare;
-          cmSystemTools::FileTimeCompare(
-            cmStrCat(contentDir, '/', latestContent), fpath, &compare);
-          if (compare == 1) {
-            cmSystemTools::RemoveFile(fpath);
-          }
-        }
-      }
-    }
-  }
+  // Delete old content and trace files
+  this->RemoveOldFiles("content");
+  this->RemoveOldFiles("trace");
 
   return 0;
 }
@@ -453,6 +481,27 @@ void cmInstrumentation::InsertTimingData(
   root["duration"] = static_cast<Json::Value::UInt64>(duration);
 }
 
+Json::Value cmInstrumentation::ReadJsonSnippet(std::string const& directory,
+                                               std::string const& file_name)
+{
+  Json::CharReaderBuilder builder;
+  builder["collectComments"] = false;
+  cmsys::ifstream ftmp(cmStrCat(directory, '/', file_name).c_str());
+  Json::Value snippetData;
+  builder["collectComments"] = false;
+
+  if (!Json::parseFromStream(builder, ftmp, &snippetData, nullptr)) {
+#if JSONCPP_VERSION_HEXA < 0x01070300
+    snippetData = Json::Value::null;
+#else
+    snippetData = Json::Value::nullSingleton();
+#endif
+  }
+
+  ftmp.close();
+  return snippetData;
+}
+
 void cmInstrumentation::WriteInstrumentationJson(Json::Value& root,
                                                  std::string const& subdir,
                                                  std::string const& file_name)
@@ -620,7 +669,7 @@ int cmInstrumentation::InstrumentCommand(
   root["workingDir"] = cmSystemTools::GetLogicalWorkingDirectory();
 
   // Add custom configure content
-  std::string contentFile = this->GetLatestContentFile();
+  std::string contentFile = this->GetLatestFile("content");
   if (!contentFile.empty()) {
     root["configureContent"] = cmStrCat("content/", contentFile);
   }
@@ -859,3 +908,93 @@ void cmInstrumentation::PrepareDataForCDash(std::string const& data_dir,
     }
   }
 }
+
+void cmInstrumentation::WriteTraceFile(Json::Value const& index,
+                                       std::string const& trace_name)
+{
+  std::string const& directory = cmStrCat(this->timingDirv1, "/data");
+  std::vector<Json::Value> snippets = std::vector<Json::Value>();
+  for (auto const& f : index["snippets"]) {
+    Json::Value snippetData = this->ReadJsonSnippet(directory, f.asString());
+    snippets.push_back(snippetData);
+  }
+  // Reverse-sort snippets by timeEnd (timeStart + duration) as a
+  // prerequisite for AssignTargetToTraceThread().
+  std::sort(snippets.begin(), snippets.end(),
+            [](Json::Value snippetA, Json::Value snippetB) {
+              uint64_t timeEndA = snippetA["timeStart"].asUInt64() +
+                snippetA["duration"].asUInt64();
+              uint64_t timeEndB = snippetB["timeStart"].asUInt64() +
+                snippetB["duration"].asUInt64();
+              return timeEndA > timeEndB;
+            });
+
+  Json::Value trace = Json::arrayValue;
+  std::vector<uint64_t> workers = std::vector<uint64_t>();
+  for (auto const& snippetData : snippets) {
+    this->AppendTraceEvent(trace, workers, snippetData);
+  }
+
+  this->WriteInstrumentationJson(trace, "data/trace", trace_name);
+}
+
+void cmInstrumentation::AppendTraceEvent(Json::Value& trace,
+                                         std::vector<uint64_t>& workers,
+                                         Json::Value const& snippetData)
+{
+  Json::Value snippetTraceEvent;
+
+  // Provide a useful trace event name depending on what data is available
+  // from the snippet.
+  std::string name = snippetData["role"].asString();
+  if (snippetData["role"] == "compile") {
+    name = cmStrCat("compile: ", snippetData["source"].asString());
+  } else if (snippetData["role"] == "link") {
+    name = cmStrCat("link: ", snippetData["target"].asString());
+  } else if (snippetData["role"] == "custom" ||
+             snippetData["role"] == "install") {
+    name = snippetData["command"].asString();
+  } else if (snippetData["role"] == "test") {
+    name = cmStrCat("test: ", snippetData["testName"].asString());
+  }
+  snippetTraceEvent["name"] = name;
+
+  snippetTraceEvent["cat"] = snippetData["role"];
+  snippetTraceEvent["ph"] = "X";
+  snippetTraceEvent["args"] = snippetData;
+
+  // Time in the Trace Event Format is stored in microseconds
+  // but the snippet files store time in milliseconds.
+  snippetTraceEvent["ts"] = snippetData["timeStart"].asUInt64() * 1000;
+  snippetTraceEvent["dur"] = snippetData["duration"].asUInt64() * 1000;
+
+  // Assign an arbitrary PID, since this data isn't useful for the
+  // visualization in our case.
+  snippetTraceEvent["pid"] = 0;
+  // Assign TID of 0 for snippets which will have other snippet data
+  // visualized "underneath" them. (For others, start from 1.)
+  if (snippetData["role"] == "build" || snippetData["role"] == "cmakeBuild" ||
+      snippetData["role"] == "ctest" ||
+      snippetData["role"] == "cmakeInstall") {
+    snippetTraceEvent["tid"] = 0;
+  } else {
+    snippetTraceEvent["tid"] = static_cast<Json::Value::UInt64>(
+      AssignTargetToTraceThread(workers, snippetData["timeStart"].asUInt64(),
+                                snippetData["duration"].asUInt64()));
+  }
+
+  trace.append(snippetTraceEvent);
+}
+
+size_t cmInstrumentation::AssignTargetToTraceThread(
+  std::vector<uint64_t>& workers, uint64_t timeStart, uint64_t duration)
+{
+  for (size_t i = 0; i < workers.size(); i++) {
+    if (workers[i] >= timeStart + duration) {
+      workers[i] = timeStart;
+      return i + 1;
+    }
+  }
+  workers.push_back(timeStart);
+  return workers.size();
+}

Source/cmInstrumentation.h

@@ -15,6 +15,7 @@
 #include <cm/optional>
 
 #include <cm3p/json/value.h>
+#include <stddef.h>
 
 #include "cmFileLock.h"
 #ifndef CMAKE_BOOTSTRAP
@@ -62,7 +63,7 @@ public:
                       std::vector<std::vector<std::string>> const& callback);
   void AddCustomContent(std::string const& name, Json::Value const& contents);
   void WriteCustomContent();
-  std::string GetLatestContentFile();
+  std::string GetLatestFile(std::string const& dataSubdir);
   void ClearGeneratedQueries();
   int CollectTimingData(cmInstrumentationQuery::Hook hook);
   int SpawnBuildDaemon();
@@ -74,6 +75,8 @@ public:
   std::string const& GetCDashDir();
 
 private:
+  Json::Value ReadJsonSnippet(std::string const& directory,
+                              std::string const& file_name);
   void WriteInstrumentationJson(Json::Value& index,
                                 std::string const& directory,
                                 std::string const& file_name);
@@ -90,6 +93,12 @@ private:
   static std::string ComputeSuffixTime();
   void PrepareDataForCDash(std::string const& data_dir,
                            std::string const& index_path);
+  void RemoveOldFiles(std::string const& dataSubdir);
+  void WriteTraceFile(Json::Value const& index, std::string const& trace_name);
+  void AppendTraceEvent(Json::Value& trace, std::vector<uint64_t>& workers,
+                        Json::Value const& snippetData);
+  size_t AssignTargetToTraceThread(std::vector<uint64_t>& workers,
+                                   uint64_t timeStart, uint64_t duration);
   std::string binaryDir;
   std::string timingDirv1;
   std::string userTimingDirv1;

Source/cmInstrumentationQuery.cxx

@@ -17,7 +17,7 @@
 
 std::vector<std::string> const cmInstrumentationQuery::OptionString{
   "staticSystemInformation", "dynamicSystemInformation", "cdashSubmit",
-  "cdashVerbose"
+  "cdashVerbose", "trace"
 };
 std::vector<std::string> const cmInstrumentationQuery::HookString{
   "postGenerate",  "preBuild",        "postBuild",

Source/cmInstrumentationQuery.h

@@ -17,7 +17,8 @@ public:
     StaticSystemInformation,
     DynamicSystemInformation,
     CDashSubmit,
-    CDashVerbose
+    CDashVerbose,
+    Trace
   };
   static std::vector<std::string> const OptionString;
 

Tests/RunCMake/Instrumentation/RunCMakeTest.cmake

@@ -16,6 +16,7 @@ function(instrument test)
     "COPY_QUERIES_GENERATED"
     "STATIC_QUERY"
     "DYNAMIC_QUERY"
+    "TRACE_QUERY"
     "MANUAL_HOOK"
     "PRESERVE_DATA"
     "NO_CONFIGURE"
@@ -39,7 +40,11 @@ function(instrument test)
   if (ARGS_STATIC_QUERY)
     set(static_query_hook_arg 1)
   endif()
-  set(GET_HOOK "\\\"${CMAKE_COMMAND}\\\" -P \\\"${RunCMake_SOURCE_DIR}/hook.cmake\\\" ${static_query_hook_arg}")
+  set(trace_query_hook_arg 0)
+  if (ARGS_TRACE_QUERY)
+    set(trace_query_hook_arg 1)
+  endif()
+  set(GET_HOOK "\\\"${CMAKE_COMMAND}\\\" -P \\\"${RunCMake_SOURCE_DIR}/hook.cmake\\\" ${static_query_hook_arg} ${trace_query_hook_arg}")
 
   # Load query JSON and cmake (with cmake_instrumentation(...)) files
   set(query ${query_dir}/${test}.json.in)
@@ -179,6 +184,19 @@ instrument(cmake-command-custom-content
 instrument(cmake-command-custom-content-bad-type NO_WARN)
 instrument(cmake-command-custom-content-bad-content NO_WARN)
 
+# Test Google trace
+instrument(trace-query
+  BUILD INSTALL TEST TRACE_QUERY
+  CHECK_SCRIPT check-generated-queries.cmake
+)
+instrument(cmake-command-trace
+  NO_WARN BUILD INSTALL TEST TRACE_QUERY
+)
+instrument(cmake-command-trace
+  NO_WARN BUILD PRESERVE_DATA
+  CHECK_SCRIPT check-trace-removed.cmake
+)
+
 # Test make/ninja hooks
 if(RunCMake_GENERATOR STREQUAL "MSYS Makefiles")
   # FIXME(#27079): This does not work for MSYS Makefiles.

Tests/RunCMake/Instrumentation/check-data-dir.cmake

@@ -13,7 +13,7 @@ foreach(snippet IN LISTS snippets)
   read_json("${snippet}" contents)
 
   # Verify snippet file is valid
-  verify_snippet("${snippet}" "${contents}")
+  verify_snippet_file("${snippet}" "${contents}")
 
   # Append to list of collected snippet roles
   if (NOT role IN_LIST FOUND_SNIPPETS)

Tests/RunCMake/Instrumentation/check-make-program-hooks.cmake

@@ -10,8 +10,8 @@ macro(hasPostBuildArtifacts)
     set(postBuildRan 1)
   endif()
   if (NOT dataDirClean)
-    file(GLOB snippets "${v1}/data/*")
-    if ("${snippets}" STREQUAL "")
+    file(GLOB data "${v1}/data/*")
+    if ("${data}" STREQUAL "")
       set(dataDirClean 1)
     endif()
   endif()

Tests/RunCMake/Instrumentation/check-trace-removed.cmake

@@ -0,0 +1,11 @@
+include(${CMAKE_CURRENT_LIST_DIR}/json.cmake)
+
+if (NOT IS_DIRECTORY "${v1}/data/trace")
+  add_error("Trace directory ${v1}/data/trace does not exist.")
+endif()
+
+file(GLOB trace_files ${v1}/data/trace/*)
+list(LENGTH trace_files num)
+if (NOT ${num} EQUAL 1)
+  add_error("Found ${num} trace files, expected 1.")
+endif()

Tests/RunCMake/Instrumentation/hook.cmake

@@ -2,12 +2,17 @@ cmake_minimum_required(VERSION 3.30)
 
 include(${CMAKE_CURRENT_LIST_DIR}/json.cmake)
 include(${CMAKE_CURRENT_LIST_DIR}/verify-snippet.cmake)
+include(${CMAKE_CURRENT_LIST_DIR}/verify-trace.cmake)
+
 # Test CALLBACK script. Prints output information and verifies index file
-# Called as: cmake -P hook.cmake [CheckForStaticQuery?] [index.json]
-set(index ${CMAKE_ARGV4})
+# Called as: cmake -P hook.cmake [CheckForStaticQuery?] [CheckForTrace?] [index.json]
+set(index ${CMAKE_ARGV5})
 if (NOT ${CMAKE_ARGV3})
   set(hasStaticInfo "UNEXPECTED")
 endif()
+if (NOT ${CMAKE_ARGV4})
+  set(hasTrace "UNEXPECTED")
+endif()
 read_json("${index}" contents)
 string(JSON hook GET "${contents}" hook)
 
@@ -29,17 +34,60 @@ if (NOT version EQUAL 1)
   add_error("Version must be 1, got: ${version}")
 endif()
 
-string(JSON length LENGTH "${snippets}")
-math(EXPR length "${length}-1")
-foreach(i RANGE ${length})
+string(JSON n_snippets LENGTH "${snippets}")
+
+math(EXPR snippets_range "${n_snippets}-1")
+foreach(i RANGE ${snippets_range})
   string(JSON filename GET "${snippets}" ${i})
   if (NOT EXISTS ${dataDir}/${filename})
     add_error("Listed snippet: ${dataDir}/${filename} does not exist")
   endif()
   read_json(${dataDir}/${filename} snippet_contents)
-  verify_snippet(${dataDir}/${filename} "${snippet_contents}")
+  verify_snippet_file(${dataDir}/${filename} "${snippet_contents}")
 endforeach()
 
+json_has_key("${index}" "${contents}" trace ${hasTrace})
+if (NOT hasTrace STREQUAL UNEXPECTED)
+  if (NOT EXISTS ${dataDir}/${trace})
+    add_error("Listed trace file: ${dataDir}/${trace} does not exist")
+  endif()
+  verify_trace_file_name("${index}" "${trace}")
+  read_json(${dataDir}/${trace} trace_contents)
+  string(JSON n_entries LENGTH "${trace_contents}")
+  if (n_entries EQUAL 0)
+    add_error("Listed trace file: ${dataDir}/${trace} has no entries")
+  endif()
+  if (NOT n_entries EQUAL n_snippets)
+    add_error("Differing number of trace entries (${n_entries}) and snippets (${n_snippets})")
+  endif()
+
+  math(EXPR entries_range "${n_entries}-1")
+  foreach (i RANGE ${entries_range})
+    string(JSON entry GET "${trace_contents}" ${i})
+    verify_trace_entry("${trace}" "${entry}")
+
+    # In addition to validating the data in the trace entry, check that
+    # it is strictly equal to its corresponding snippet data.
+    # Ideally, the args from all trace entries could be checked at once
+    # against the list of snippets from the index file, but the order of
+    # snippets is not preserved in the trace file, so being equal to data from
+    # any snippet file is sufficient.
+    set(args_equals_snippet OFF)
+    string(JSON trace_args GET "${entry}" args)
+    foreach (j RANGE ${entries_range})
+      string(JSON snippet_file GET "${snippets}" ${j})
+      read_json(${dataDir}/${snippet_file} snippet_contents)
+      string(JSON args_equals_snippet EQUAL "${snippet_contents}" "${trace_args}")
+      if (args_equals_snippet)
+        break()
+      endif()
+    endforeach()
+    if (NOT args_equals_snippet)
+      add_error("Trace entry args does not match any snippet data: ${entry}")
+    endif()
+  endforeach()
+endif()
+
 json_has_key("${index}" "${contents}" staticSystemInformation ${hasStaticInfo})
 if (NOT hasStaticInfo STREQUAL UNEXPECTED)
   json_has_key("${index}" "${staticSystemInformation}" OSName ${hasStaticInfo})

Tests/RunCMake/Instrumentation/query/cmake-command-cmake-build.cmake

@@ -3,5 +3,5 @@ cmake_instrumentation(
   API_VERSION 1
   DATA_VERSION 1
   HOOKS preBuild postBuild postCMakeBuild
-  CALLBACK ${CMAKE_COMMAND} -P ${hook_path} 0
+  CALLBACK ${CMAKE_COMMAND} -P ${hook_path} 0 0
 )

Tests/RunCMake/Instrumentation/query/cmake-command-make-program.cmake

@@ -3,5 +3,5 @@ cmake_instrumentation(
   API_VERSION 1
   DATA_VERSION 1
   HOOKS preBuild postBuild
-  CALLBACK ${CMAKE_COMMAND} -P ${hook_path} 0
+  CALLBACK ${CMAKE_COMMAND} -P ${hook_path} 0 0
 )

Tests/RunCMake/Instrumentation/query/cmake-command-trace.cmake

@@ -0,0 +1,8 @@
+file(TO_CMAKE_PATH "${CMAKE_SOURCE_DIR}/../hook.cmake" hook_path)
+cmake_instrumentation(
+  API_VERSION 1
+  DATA_VERSION 1
+  OPTIONS trace
+  HOOKS postBuild postInstall postTest
+  CALLBACK ${CMAKE_COMMAND} -P ${hook_path} 0 1
+)

Tests/RunCMake/Instrumentation/query/cmake-command.cmake

@@ -16,7 +16,7 @@
     API_VERSION 1
     DATA_VERSION 1
     HOOKS postCMakeBuild
-    OPTIONS staticSystemInformation dynamicSystemInformation
+    OPTIONS staticSystemInformation dynamicSystemInformation trace
     CALLBACK ${CMAKE_COMMAND} -E echo callback2
     CALLBACK ${CMAKE_COMMAND} -E echo callback3
   )

Tests/RunCMake/Instrumentation/query/generated/query-2.json.in

@@ -11,7 +11,8 @@
   "options" :
   [
     "staticSystemInformation",
-    "dynamicSystemInformation"
+    "dynamicSystemInformation",
+    "trace"
   ],
   "version": 1
 }

Tests/RunCMake/Instrumentation/query/trace-query.json.in

@@ -0,0 +1,6 @@
+{
+  "version": 1,
+  "options": [
+    "trace"
+  ]
+}

Tests/RunCMake/Instrumentation/verify-snippet.cmake

@@ -65,18 +65,13 @@ function(snippet_valid_timing contents)
   return(PROPAGATE RunCMake_TEST_FAILED ERROR_MESSAGE)
 endfunction()
 
-function(verify_snippet snippet contents)
+function(verify_snippet_data snippet contents)
   snippet_has_fields("${snippet}" "${contents}")
   snippet_valid_timing("${contents}")
   string(JSON version GET "${contents}" version)
   if (NOT version EQUAL 1)
     json_error("${snippet}" "Version must be 1, got: ${version}")
   endif()
-  string(JSON role GET "${contents}" role)
-  get_filename_component(filename "${snippet}" NAME)
-  if (NOT filename MATCHES "^${role}-")
-    json_error("${snippet}" "Role \"${role}\" doesn't match snippet filename")
-  endif()
   string(JSON outputs ERROR_VARIABLE noOutputs GET "${contents}" outputs)
   if (NOT outputs MATCHES NOTFOUND)
     string(JSON outputSizes ERROR_VARIABLE noOutputSizes GET "${contents}" outputSizes)
@@ -88,3 +83,15 @@ function(verify_snippet snippet contents)
   endif()
   return(PROPAGATE ERROR_MESSAGE RunCMake_TEST_FAILED role)
 endfunction()
+
+function(verify_snippet_file snippet contents)
+  verify_snippet_data("${snippet}" "${contents}")
+
+  string(JSON role GET "${contents}" role)
+  get_filename_component(filename "${snippet}" NAME)
+  if (NOT filename MATCHES "^${role}-")
+    json_error("${snippet}" "Role \"${role}\" doesn't match snippet filename")
+  endif()
+
+  return(PROPAGATE ERROR_MESSAGE RunCMake_TEST_FAILED role)
+endfunction()

Tests/RunCMake/Instrumentation/verify-trace.cmake

@@ -0,0 +1,110 @@
+# Performs generic (non-project specific) validation of Trace File Contents
+
+include(${CMAKE_CURRENT_LIST_DIR}/json.cmake)
+include(${CMAKE_CURRENT_LIST_DIR}/verify-snippet.cmake)
+
+function(trace_entry_has_fields trace entry)
+  json_has_key("${trace}" "${entry}" cat)
+  json_has_key("${trace}" "${entry}" dur)
+  json_has_key("${trace}" "${entry}" name)
+  json_has_key("${trace}" "${entry}" ph)
+  json_has_key("${trace}" "${entry}" pid)
+  json_has_key("${trace}" "${entry}" tid)
+  json_has_key("${trace}" "${entry}" ts)
+  json_has_key("${trace}" "${entry}" args)
+
+  return(PROPAGATE RunCMake_TEST_FAILED ERROR_MESSAGE)
+endfunction()
+
+function(trace_valid_entry trace entry)
+  string(JSON ph GET "${entry}" ph)
+  if (NOT ph STREQUAL "X")
+    json_error("${trace}"
+      "Invalid event \'${ph}\' (only complete events \'X\' expected)")
+  endif()
+  string(JSON start GET "${entry}" ts)
+  if (start LESS 0)
+    json_error("${trace}" "Negative time start: ${start}")
+  endif()
+  string(JSON duration GET "${entry}" dur)
+  if (duration LESS 0)
+    json_error("${trace}" "Negative duration: ${duration}")
+  endif()
+  string(JSON pid GET "${entry}" pid)
+  if (NOT pid EQUAL 0)
+    json_error("${trace}" "Invalid PID: ${pid}")
+  endif()
+  string(JSON tid GET "${entry}" tid)
+  if (tid LESS 0)
+    json_error("${trace}" "Invalid TID: ${tid}")
+  endif()
+
+  # Validate "args" as snippet data
+  string(JSON args GET "${entry}" args)
+  verify_snippet_data("${trace}" "${args}")
+
+  # Check the formation of the "name" based on the snippet data
+  string(JSON name GET "${entry}" name)
+  string(JSON cat GET "${entry}" cat)
+  set(error_name OFF)
+  if (cat STREQUAL "compile")
+    string(JSON source GET "${args}" source)
+    if (NOT name STREQUAL "compile: ${source}")
+      set(error_name ON)
+    endif()
+  elseif (cat STREQUAL "link")
+    string(JSON target GET "${args}" target)
+    if (NOT name STREQUAL "link: ${target}")
+      set(error_name ON)
+    endif()
+  elseif (cat STREQUAL "custom" OR cat STREQUAL "install")
+    string(JSON command GET "${args}" command)
+    if (NOT name STREQUAL command)
+      set(error_name ON)
+    endif()
+  elseif (cat STREQUAL "test")
+    string(JSON testName GET "${args}" testName)
+    if (NOT name STREQUAL "test: ${testName}")
+      set(error_name ON)
+    endif()
+  else()
+    string(JSON role GET "${args}" role)
+    if (NOT name STREQUAL role)
+      set(error_name ON)
+    endif()
+  endif()
+  if (error_name)
+    json_error("${trace}" "Invalid name: ${name}")
+  endif()
+
+  return(PROPAGATE ERROR_MESSAGE RunCMake_TEST_FAILED)
+endfunction()
+
+function(verify_trace_entry trace entry)
+  trace_entry_has_fields("${trace}" "${entry}")
+  trace_valid_entry("${trace}" "${entry}")
+  return(PROPAGATE ERROR_MESSAGE RunCMake_TEST_FAILED)
+endfunction()
+
+function(verify_trace_file_name index_file trace_file)
+  cmake_path(GET trace_file FILENAME trace_filename)
+  cmake_path(GET index_file FILENAME index_filename)
+
+  set(timestamp_regex "^(index|trace)-([A-Z0-9\\-]+)\\.json")
+  if ("${trace_filename}" MATCHES "${timestamp_regex}")
+    set(trace_timestamp "${CMAKE_MATCH_2}")
+  else()
+    add_error("Unable to parse timestamp from trace file name: \'${trace_filename}\'")
+  endif()
+  if ("${index_filename}" MATCHES "${timestamp_regex}")
+    set(index_timestamp "${CMAKE_MATCH_2}")
+  else()
+    add_error("Unable to parse timestamp from index file name: \'${index_filename}\'")
+  endif()
+
+  if (NOT "${trace_timestamp}" STREQUAL "${index_timestamp}")
+    add_error("Trace file timestamp \'${trace_filename}\' does not match the index \'${index_file}\'")
+  endif()
+
+  return(PROPAGATE ERROR_MESSAGE RunCMake_TEST_FAILED)
+endfunction()