trace: Add time and stack level to JSON output format

Add the timestamp and stack depth of the function call to the JSON trace
output format. This information can be useful for cmake profiling and
call stack inspection (see e.g. https://github.com/volo-zyko/cmake-profile-stats).

Improve unit test to allow for varying set of keys to check in trace lines.

3 files changed, 22 insertions, 7 deletions

diff --git a/Help/manual/cmake.1.rst b/Help/manual/cmake.1.rst
index 4315f0a..44b1f2f 100644
--- a/Help/manual/cmake.1.rst
+++ b/Help/manual/cmake.1.rst
@@ -279,7 +279,9 @@ Options
          "file": "/full/path/to/the/CMake/file.txt",
          "line": 0,
          "cmd": "add_executable",
-         "args": ["foo", "bar"]
+         "args": ["foo", "bar"],
+         "time": 1579512535.9687231,
+         "frame": 2
        }
 
      The members are:
@@ -288,8 +290,8 @@ Options
        The full path to the CMake source file where the function
        was called.
 
-      ``line``
-       The line in `file` of the function call.
+     ``line``
+       The line in ``file`` of the function call.
 
      ``cmd``
        The name of the function that was called.
@@ -297,6 +299,12 @@ Options
      ``args``
        A string list of all function parameters.
 
+     ``time``
+       Timestamp (seconds since epoch) of the function call.
+
+     ``frame``
+       Stack frame depth of the function that was called.
+
      Additionally, the first JSON document outputted contains the
      ``version`` key for the current major and minor version of the
 
diff --git a/Source/cmMakefile.cxx b/Source/cmMakefile.cxx
index dc741d3..1d1e895 100644
--- a/Source/cmMakefile.cxx
+++ b/Source/cmMakefile.cxx
@@ -340,6 +340,9 @@ void cmMakefile::PrintCommandTrace(const cmListFileFunction& lff) const
       for (std::string const& arg : args) {
         val["args"].append(arg);
       }
+      val["time"] = cmSystemTools::GetTime();
+      val["frame"] =
+        static_cast<std::uint64_t>(this->ExecutionStatusStack.size());
       msg << Json::writeString(builder, val);
 #endif
       break;
diff --git a/Tests/RunCMake/CommandLine/trace-json-v1-check.py b/Tests/RunCMake/CommandLine/trace-json-v1-check.py
index 14febaf..e617b76 100755
--- a/Tests/RunCMake/CommandLine/trace-json-v1-check.py
+++ b/Tests/RunCMake/CommandLine/trace-json-v1-check.py
@@ -46,6 +46,7 @@ required_traces = [
     {
         'args': msg_args,
         'cmd': 'message',
+        'frame': 3 if expand else 2
     },
 ]
 
@@ -59,14 +60,17 @@ with open(trace_file, 'r') as fp:
 
     for i in fp.readlines():
         line = json.loads(i)
-        assert sorted(line.keys()) == ['args', 'cmd', 'file', 'line']
+        assert sorted(line.keys()) == ['args', 'cmd', 'file', 'frame', 'line', 'time']
         assert isinstance(line['args'], list)
         assert isinstance(line['cmd'], unicode)
         assert isinstance(line['file'], unicode)
+        assert isinstance(line['frame'], int)
         assert isinstance(line['line'], int)
+        assert isinstance(line['time'], float)
 
         for j in required_traces:
-            if j['cmd'] == line['cmd'] and j['args'] == line['args']:
-                j['found'] = True
+            # Compare the subset of required keys with line
+            if {k: line[k] for k in j} == j:
+                required_traces.remove(j)
 
-assert all([x.get('found', False) == True for x in required_traces])
+assert not required_traces