[lldb][trace] Add a basic function call dump [3] - Add a JSON dumper

[wallace]

Summary

The JSON dumper is very minimalistic. It pretty much only shows the
delimiting instruction IDs of every segment, so that further queries to
the SBCursor can be used to make sense of the data. It's main purpose is
to be serialized somewhat cheaply.

I also renamed untracedSegment to untracedPrefixSegment, in case in the
future we add an untracedSuffixSegment. In any case, this new name is
more explicit, which I like.

[jj10306]

nice! using this in conjunction with trace cursor we'll be able to produce some nice visualizations - lgtm

lldb/include/lldb/Target/TraceDumper.h

public:
   ///       call. More on this later.
   ///     - Abruptly due to end of trace. In this case, we weren't able to trace
   ///     the end of this function call.
   ///     - Simply a return higher in the callstack.
   ///
   ///   In terms of implementation details, as segment can be represented with
   ///   the beginning and ending instruction IDs from the instruction trace.
   ///
-  ///  UntracedSegment:
+  ///  UntracedPrefixSegment:
   ///   It might happen that we didn't trace the beginning of a function and we
   ///   saw it for the first time as part of a return. As a way to signal these
-  ///   cases, we have a placeholder UntracedSegment class that completes the
+  ///   cases, we have a placeholder UntracedPrefixSegment class that completes the
   ///   callgraph.
   ///
   ///  Example:
   ///   We might have this piece of execution:
   ///
   ///     main() [offset 0x00 to 0x20] [traced instruction ids 1 to 4]
   ///       foo()  [offset 0x00 to 0x80] [traced instruction ids 5 to 20] # main
   ///       invoked foo
   ///     main() [offset 0x24 to 0x40] [traced instruction ids 21 to 30]
   ///
   ///   In this case, our function main invokes foo. We have 3 segments: main
   ///   [offset 0x00 to 0x20], foo() [offset 0x00 to 0x80], and main() [offset
   ///   0x24 to 0x40]. We also have the instruction ids from the corresponding
   ///   linear instruction trace for each segment.
   ///
   ///   But what if we started tracing since the middle of foo? Then we'd have
   ///   an incomplete trace
   ///
   ///       foo() [offset 0x30 to 0x80] [traced instruction ids 1 to 10]
   ///     main() [offset 0x24 to 0x40] [traced instruction ids 11 to 20]
   ///
   ///   Notice that we changed the instruction ids because this is a new trace.
   ///   Here, in order to have a somewhat complete tree with good traversal
-  ///   capabilities, we can create an UntracedSegment to signal the portion of
+  ///   capabilities, we can create an UntracedPrefixSegment to signal the portion of
   ///   main() that we didn't trace. We don't know if this segment was in fact
   ///   multiple segments with many function calls. We'll never know. The
   ///   resulting tree looks like the following:
   ///
   ///     main() [untraced]
   ///       foo() [offset 0x30 to 0x80] [traced instruction ids 1 to 10]
   ///     main() [offset 0x24 to 0x40] [traced instruction ids 11 to 20]
   ///
   ///   And in pseudo-code:
   ///
   ///     FunctionCall [
-  ///       UntracedSegment {
+  ///       UntracedPrefixSegment {
   ///         symbol: main()
   ///         nestedCall: FunctionCall [ # this untraced segment has a nested
   ///         call
   ///           TracedSegment {
   ///             symbol: foo()
   ///             fromInstructionId: 1
   ///             toInstructionId: 10
   ///             nestedCall: none # this doesn't have a nested call
private:
       /// The symbol information of the delimiting instructions
       /// \{
       SymbolInfo m_first_symbol_info;
       SymbolInfo m_last_symbol_info;
       /// \}
       FunctionCall &m_owning_call;
     };
 
-    class UntracedSegment {
+    class UntracedPrefixSegment {
     public:
       /// Note: Untraced segments can only exist if have also seen a traced
       /// segment of the same function call. Thus, we can use those traced
       /// segments if we want symbol information and such.
 
-      UntracedSegment(FunctionCallUP &&nested_call)
+      UntracedPrefixSegment(FunctionCallUP &&nested_call)
           : m_nested_call(std::move(nested_call)) {}
 
       const FunctionCall &GetNestedCall() const;
 
     private:
-      UntracedSegment(const UntracedSegment &) = delete;
-      UntracedSegment &operator=(UntracedSegment const &);
+      UntracedPrefixSegment(const UntracedPrefixSegment &) = delete;
+      UntracedPrefixSegment &operator=(UntracedPrefixSegment const &);
       FunctionCallUP m_nested_call;
     };
 
     /// Create a new function call given an instruction. This will also create a
     /// segment for that instruction.
     ///
     /// \param[in] cursor_sp
     ///   A cursor pointing to the first instruction of that function call.
public:
     const std::deque<TracedSegment> &GetTracedSegments() const;
 
     /// \return
     ///   A non-const reference to the most-recent traced segment.
     TracedSegment &GetLastTracedSegment();
 
     /// Create an untraced segment for this call that jumps to the provided
     /// nested call.
-    void SetUntracedSegment(FunctionCallUP &&nested_call);
+    void SetUntracedPrefixSegment(FunctionCallUP &&nested_call);
 
     /// \return
-    ///   A optional to the untraced segment of this call.
-    const llvm::Optional<UntracedSegment> &GetUntracedSegment() const;
+    ///   A optional to the untraced prefix segment of this call.
+    const llvm::Optional<UntracedPrefixSegment> &GetUntracedPrefixSegment() const;
 
     /// \return
     ///   A pointer to the parent call. It may be \b nullptr.
     FunctionCall *GetParentCall() const;
 
     void SetParentCall(FunctionCall &parent_call);
 
   private:
     /// An optional untraced segment that precedes all the traced segments.
-    llvm::Optional<UntracedSegment> m_untraced_segment;
+    llvm::Optional<UntracedPrefixSegment> m_untraced_prefix_segment;
     /// The traced segments in order. We used a deque to prevent moving these
     /// objects when appending to the list, which would happen with vector.
     std::deque<TracedSegment> m_traced_segments;
     /// The parent call, which might be null. Useful for reconstructing
     /// callstacks.
     FunctionCall *m_parent_call = nullptr;
     /// Whether this call represents a list of consecutive errors.
     bool m_is_error;
   };
 
   /// Interface used to abstract away the format in which the instruction
   /// information will be dumped.
   class OutputWriter {
   public:
     virtual ~OutputWriter() = default;
 
     /// Notify this writer that the cursor ran out of data.
     virtual void NoMoreData() {}
 
     /// Dump a trace item (instruction, error or event).
     virtual void TraceItem(const TraceItem &item) = 0;
 
     /// Dump a function call forest.
-    virtual void FunctionCallForest(const std::vector<FunctionCallUP> &forest) {
-    }
+    virtual void
+    FunctionCallForest(const std::vector<FunctionCallUP> &forest) = 0;
   };
 
   /// Create a instruction dumper for the cursor.
   ///
   /// \param[in] cursor
   ///     The cursor whose instructions will be dumped.
   ///
   /// \param[in] s

lldb/source/Commands/CommandObjectThread.cpp

Status SetOptionValue(uint32_t option_idx, llvm::StringRef option_arg,
       const int short_option = m_getopt_table[option_idx].val;
 
       switch (short_option) {
       case 'j': {
         m_dumper_options.json = true;
         break;
       }
       case 'J': {
+        m_dumper_options.json = true;
         m_dumper_options.pretty_print_json = true;
         break;
       }
       case 'F': {
         m_output_file.emplace(option_arg);
         break;
       }
       default:
if (!cursor_or_error) {
       result.AppendError(llvm::toString(cursor_or_error.takeError()));
       return false;
     }
     TraceCursorSP &cursor_sp = *cursor_or_error;
 
     llvm::Optional<StreamFile> out_file;
     if (m_options.m_output_file) {
       out_file.emplace(m_options.m_output_file->GetPath().c_str(),
-                       File::eOpenOptionWriteOnly | File::eOpenOptionCanCreate,
-                       lldb::eFilePermissionsFileDefault);
+                       File::eOpenOptionWriteOnly | File::eOpenOptionCanCreate);
     }
 
     m_options.m_dumper_options.forwards = true;
 
     TraceDumper dumper(std::move(cursor_sp),
                        out_file ? *out_file : result.GetOutputStream(),
                        m_options.m_dumper_options);
 
if (m_options.m_dumper_options.id &&
         !cursor_sp->HasId(*m_options.m_dumper_options.id)) {
       result.AppendError("invalid instruction id\n");
       return false;
     }
 
     llvm::Optional<StreamFile> out_file;
     if (m_options.m_output_file) {
       out_file.emplace(m_options.m_output_file->GetPath().c_str(),
-                       File::eOpenOptionWriteOnly | File::eOpenOptionCanCreate,
-                       lldb::eFilePermissionsFileDefault);
+                       File::eOpenOptionWriteOnly | File::eOpenOptionCanCreate);
     }
 
     if (m_options.m_continue && !m_last_id) {
       // We need to stop processing data when we already ran out of instructions
       // in a previous command. We can fake this by setting the cursor past the
       // end of the trace.
       cursor_sp->Seek(1, lldb::eTraceCursorSeekTypeEnd);
     }

lldb/source/Target/TraceDumper.cpp

if (!module_name)
       m_s << "(none)";
     else if (!sc.function && !sc.symbol)
       m_s << module_name << "`(none)";
     else
       m_s << module_name << "`" << sc.GetFunctionName().AsCString();
   }
 
   void DumpFunctionCallTree(const TraceDumper::FunctionCall &function_call) {
-    if (function_call.GetUntracedSegment()) {
+    if (function_call.GetUntracedPrefixSegment()) {
       m_s.Indent();
       DumpUntracedContext(function_call);
       m_s << "\n";
 
       m_s.IndentMore();
-      DumpFunctionCallTree(function_call.GetUntracedSegment()->GetNestedCall());
+      DumpFunctionCallTree(function_call.GetUntracedPrefixSegment()->GetNestedCall());
       m_s.IndentLess();
     }
 
     for (const TraceDumper::FunctionCall::TracedSegment &segment :
          function_call.GetTracedSegments()) {
       m_s.Indent();
       DumpSegmentContext(segment);
       m_s.Format("  [{0}, {1}]\n", segment.GetFirstInstructionID(),
OutputWriterJSON(Stream &s, const TraceDumperOptions &options)
       : m_s(s), m_options(options),
         m_j(m_s.AsRawOstream(),
             /*IndentSize=*/options.pretty_print_json ? 2 : 0) {
     m_j.arrayBegin();
   };
 
   ~OutputWriterJSON() { m_j.arrayEnd(); }
 
+  void FunctionCallForest(
+      const std::vector<TraceDumper::FunctionCallUP> &forest) override {
+    for (size_t i = 0; i < forest.size(); i++) {
+      m_j.object([&] { DumpFunctionCallTree(*forest[i]); });
+    }
+  }
+
+  void DumpFunctionCallTree(const TraceDumper::FunctionCall &function_call) {
+    if (function_call.GetUntracedPrefixSegment()) {
+      m_j.attributeObject("untracedPrefixSegment", [&] {
+        m_j.attributeObject("nestedCall", [&] {
+          DumpFunctionCallTree(
+              function_call.GetUntracedPrefixSegment()->GetNestedCall());
+        });
+      });
+    }
+
+    if (!function_call.GetTracedSegments().empty()) {
+      m_j.attributeArray("tracedSegments", [&] {
+        for (const TraceDumper::FunctionCall::TracedSegment &segment :
+             function_call.GetTracedSegments()) {
+          m_j.object([&] {
+            m_j.attribute("firstInstructionId",
+                          std::to_string(segment.GetFirstInstructionID()));
+            m_j.attribute("lastInstructionId",
+                          std::to_string(segment.GetLastInstructionID()));
+            segment.IfNestedCall(
+                [&](const TraceDumper::FunctionCall &nested_call) {
+                  m_j.attributeObject(
+                      "nestedCall", [&] { DumpFunctionCallTree(nested_call); });
+                });
+          });
+        }
+      });
+    }
+  }
+
   void DumpEvent(const TraceDumper::TraceItem &item) {
     m_j.attribute("event", TraceCursor::EventKindToString(*item.event));
     switch (*item.event) {
     case eTraceEventCPUChanged:
       m_j.attribute("cpuId", item.cpu_id);
       break;
     case eTraceEventHWClockTick:
       m_j.attribute("hwClock", item.hw_clock);

 }
 
 const TraceDumper::SymbolInfo &
 TraceDumper::FunctionCall::TracedSegment::GetLastInstructionSymbolInfo() const {
   return m_last_symbol_info;
 }
 
 const TraceDumper::FunctionCall &
-TraceDumper::FunctionCall::UntracedSegment::GetNestedCall() const {
+TraceDumper::FunctionCall::UntracedPrefixSegment::GetNestedCall() const {
   return *m_nested_call;
 }
 
 TraceDumper::FunctionCall::FunctionCall(
     const TraceCursorSP &cursor_sp,
     const TraceDumper::SymbolInfo &symbol_info) {
   m_is_error = cursor_sp->IsError();
   AppendSegment(cursor_sp, symbol_info);
TraceDumper::FunctionCall::GetTracedSegments() const {
   return m_traced_segments;
 }
 
 TraceDumper::FunctionCall::TracedSegment &
 TraceDumper::FunctionCall::GetLastTracedSegment() {
   return m_traced_segments.back();
 }
 
-const Optional<TraceDumper::FunctionCall::UntracedSegment> &
-TraceDumper::FunctionCall::GetUntracedSegment() const {
-  return m_untraced_segment;
+const Optional<TraceDumper::FunctionCall::UntracedPrefixSegment> &
+TraceDumper::FunctionCall::GetUntracedPrefixSegment() const {
+  return m_untraced_prefix_segment;
 }
 
-void TraceDumper::FunctionCall::SetUntracedSegment(
+void TraceDumper::FunctionCall::SetUntracedPrefixSegment(
     TraceDumper::FunctionCallUP &&nested_call) {
-  m_untraced_segment.emplace(std::move(nested_call));
+  m_untraced_prefix_segment.emplace(std::move(nested_call));
 }
 
 TraceDumper::FunctionCall *TraceDumper::FunctionCall::GetParentCall() const {
   return m_parent_call;
 }
 
 void TraceDumper::FunctionCall::SetParentCall(
     TraceDumper::FunctionCall &parent_call) {
if (IsSameInstructionSymbolContext(ancestor->GetSymbolInfo(), symbol_info,
       return *ancestor;
     }
   }
 
   // We didn't find the call we were looking for, so we now create a synthetic
   // one that will contain the new instruction in its first traced segment.
   TraceDumper::FunctionCallUP new_root =
       std::make_unique<TraceDumper::FunctionCall>(cursor_sp, symbol_info);
-  // This new root will own the previous root through an untraced segment.
-  new_root->SetUntracedSegment(std::move(roots.back()));
+  // This new root will own the previous root through an untraced prefix segment.
+  new_root->SetUntracedPrefixSegment(std::move(roots.back()));
   roots.pop_back();
   // We update the roots container to point to the new root
   roots.emplace_back(std::move(new_root));
   return *roots.back();
 }
 
 /// Append an instruction to a function call forest. The new instruction might
 /// be appended to the current segment, to a new nest call, or return to an

lldb/test/API/commands/trace/TestTraceDumpFunctionCalls.py

 from intelpt_testcase import *
 from lldbsuite.test.lldbtest import *
 from lldbsuite.test.decorators import *
 
 class TestTraceDumpInfo(TraceIntelPTTestCaseBase):
     def testDumpSimpleFunctionCalls(self):
       self.expect("trace load -v " +
         os.path.join(self.getSourceDir(), "intelpt-trace", "trace.json"))
 
       self.expect("thread trace dump function-calls 2",
         error=True, substrs=['error: no thread with index: "2"'])
 
-      # We don't support yet JSON
-      self.expect("thread trace dump function-calls 1 -j", substrs=['[]'])
+      self.expect("thread trace dump function-calls 1 -j",
+        substrs=['[{"tracedSegments":[{"firstInstructionId":"1","lastInstructionId":"22"}]}]'])
+
+      self.expect("thread trace dump function-calls 1 -J",
+        substrs=['''[
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "1",
+        "lastInstructionId": "22"
+      }
+    ]
+  }
+]'''])
 
       # We test first some code without function call
       self.expect("thread trace dump function-calls 1",
         substrs=['''thread #1: tid = 3842849
 
 [call tree #0]
 a.out`main + 4 at main.cpp:2 to 4:0  [1, 22]'''])
 
     def testFunctionCallsWithErrors(self):
       self.expect("trace load -v " +
         os.path.join(self.getSourceDir(), "intelpt-multi-core-trace", "trace.json"))
 
       # We expect that tracing errors appear as a different tree
       self.expect("thread trace dump function-calls 2",
         substrs=['''thread #2: tid = 3497496
 
 [call tree #0]
 m.out`foo() + 65 at multi_thread.cpp:12:21 to 12:21  [4, 19524]
 
 [call tree #1]
 <tracing errors>  [19532, 19532]'''])
 
+      self.expect("thread trace dump function-calls 2 -J",
+        substrs=['''[
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "4",
+        "lastInstructionId": "19524"
+      }
+    ]
+  },
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "19532",
+        "lastInstructionId": "19532"
+      }
+    ]
+  }
+]'''])
+
       self.expect("thread trace dump function-calls 3",
         substrs=['''thread #3: tid = 3497497
 
 [call tree #0]
 m.out`bar() + 30 at multi_thread.cpp:19:3 to 20:6  [5, 61831]
 
 [call tree #1]
 <tracing errors>  [61834, 61834]'''])
 
+      self.expect("thread trace dump function-calls 3 -J",
+        substrs=['''[
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "5",
+        "lastInstructionId": "61831"
+      }
+    ]
+  },
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "61834",
+        "lastInstructionId": "61834"
+      }
+    ]
+  }
+]'''])
+
     def testInlineFunctionCalls(self):
       self.expect("file " + os.path.join(self.getSourceDir(), "inline-function", "a.out"))
       self.expect("b main") # we'll trace from the beginning of main
       self.expect("b 17")
       self.expect("r")
       self.expect("thread trace start")
       self.expect("c")
       self.expect("thread trace dump function-calls",
         substrs=['''[call tree #0]
 a.out`main + 8 at inline.cpp:15:7 to 16:14  [1, 5]
   a.out`foo(int) at inline.cpp:8:16 to 9:15  [6, 13]
     a.out`foo(int) + 22 [inlined] mult(int, int) at inline.cpp:2:7 to 5:10  [14, 21]
   a.out`foo(int) + 49 at inline.cpp:9:15 to 12:1  [22, 26]
 a.out`main + 25 at inline.cpp:16:14 to 16:14  [27, 27]'''])
 
+      self.expect("thread trace dump function-calls -J",
+        substrs=['''[
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "1",
+        "lastInstructionId": "5",
+        "nestedCall": {
+          "tracedSegments": [
+            {
+              "firstInstructionId": "6",
+              "lastInstructionId": "13",
+              "nestedCall": {
+                "tracedSegments": [
+                  {
+                    "firstInstructionId": "14",
+                    "lastInstructionId": "21"
+                  }
+                ]
+              }
+            },
+            {
+              "firstInstructionId": "22",
+              "lastInstructionId": "26"
+            }
+          ]
+        }
+      },
+      {
+        "firstInstructionId": "27",
+        "lastInstructionId": "27"
+      }
+    ]
+  }
+]'''])
+
     def testIncompleteInlineFunctionCalls(self):
       self.expect("file " + os.path.join(self.getSourceDir(), "inline-function", "a.out"))
       self.expect("b 4") # we'll trace from the middle of the inline method
       self.expect("b 17")
       self.expect("r")
       self.expect("thread trace start")
       self.expect("c")
       self.expect("thread trace dump function-calls",
         substrs=['''[call tree #0]
 a.out`main
   a.out`foo(int)
     a.out`foo(int) + 36 [inlined] mult(int, int) + 14 at inline.cpp:4:5 to 5:10  [1, 5]
   a.out`foo(int) + 49 at inline.cpp:9:15 to 12:1  [6, 10]
 a.out`main + 25 at inline.cpp:16:14 to 16:14  [11, 11]'''])
 
+      self.expect("thread trace dump function-calls -J",
+        substrs=['''[
+  {
+    "untracedPrefixSegment": {
+      "nestedCall": {
+        "untracedPrefixSegment": {
+          "nestedCall": {
+            "tracedSegments": [
+              {
+                "firstInstructionId": "1",
+                "lastInstructionId": "5"
+              }
+            ]
+          }
+        },
+        "tracedSegments": [
+          {
+            "firstInstructionId": "6",
+            "lastInstructionId": "10"
+          }
+        ]
+      }
+    },
+    "tracedSegments": [
+      {
+        "firstInstructionId": "11",
+        "lastInstructionId": "11"
+      }
+    ]
+  }
+]'''])
+
     def testMultifileFunctionCalls(self):
       # This test is extremely important because it first calls the method foo() which requires going through the dynamic linking.
       # You'll see the entry "a.out`symbol stub for: foo()" which will invoke the ld linker, which will in turn find the actual foo
       # function and eventually invoke it.  However, we don't have the image of the linker in the trace bundle, so we'll see errors
       # because the decoder couldn't find the linker binary! After those failures, the linker will resume right where we return to
       # main after foo() finished.
       # Then, we call foo() again, but because it has already been loaded by the linker, we don't invoke the linker anymore! And
       # we'll see a nice tree without errors in this second invocation. Something interesting happens here. We still have an
a.out`main + 20 at main.cpp:10 to 12:0  [10, 14]
   a.out`main + 34 [inlined] inline_function() at main.cpp:4 to 6:0  [16, 20]
 a.out`main + 55 at main.cpp:14 to 16:0  [21, 25]
   a.out`symbol stub for: foo() to <+0>  [26, 26]
     libfoo.so`foo() at foo.cpp:3 to 4:0  [27, 30]
       libfoo.so`symbol stub for: bar() to <+0>  [31, 31]
         libbar.so`bar() at bar.cpp:1 to 4:0  [32, 40]
     libfoo.so`foo() + 13 at foo.cpp:4 to 6:0  [41, 48]
 a.out`main + 68 at main.cpp:16 to 16:0  [49, 51]'''])
+
+      self.expect("thread trace dump function-calls -J",
+        substrs=['''[
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "1",
+        "lastInstructionId": "1",
+        "nestedCall": {
+          "tracedSegments": [
+            {
+              "firstInstructionId": "3",
+              "lastInstructionId": "5",
+              "nestedCall": {
+                "tracedSegments": [
+                  {
+                    "firstInstructionId": "6",
+                    "lastInstructionId": "7"
+                  }
+                ]
+              }
+            }
+          ]
+        }
+      }
+    ]
+  },
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "8",
+        "lastInstructionId": "8"
+      }
+    ]
+  },
+  {
+    "tracedSegments": [
+      {
+        "firstInstructionId": "10",
+        "lastInstructionId": "14",
+        "nestedCall": {
+          "tracedSegments": [
+            {
+              "firstInstructionId": "16",
+              "lastInstructionId": "20"
+            }
+          ]
+        }
+      },
+      {
+        "firstInstructionId": "21",
+        "lastInstructionId": "25",
+        "nestedCall": {
+          "tracedSegments": [
+            {
+              "firstInstructionId": "26",
+              "lastInstructionId": "26",
+              "nestedCall": {
+                "tracedSegments": [
+                  {
+                    "firstInstructionId": "27",
+                    "lastInstructionId": "30",
+                    "nestedCall": {
+                      "tracedSegments": [
+                        {
+                          "firstInstructionId": "31",
+                          "lastInstructionId": "31",
+                          "nestedCall": {
+                            "tracedSegments": [
+                              {
+                                "firstInstructionId": "32",
+                                "lastInstructionId": "40"
+                              }
+                            ]
+                          }
+                        }
+                      ]
+                    }
+                  },
+                  {
+                    "firstInstructionId": "41",
+                    "lastInstructionId": "48"
+                  }
+                ]
+              }
+            }
+          ]
+        }
+      },
+      {
+        "firstInstructionId": "49",
+        "lastInstructionId": "51"
+      }
+    ]
+  }
+]'''])