From f1e63855b08e366dc9d3bf1d3394a8f5c77ab3a6 Mon Sep 17 00:00:00 2001 From: Walter Erquinigo Date: Sat, 15 Oct 2022 18:52:22 -0700 Subject: [PATCH] [lldb][trace] Add a basic function call dump [3] - Add a JSON dumper 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. Differential Revision: https://reviews.llvm.org/D136034 --- lldb/include/lldb/Target/TraceDumper.h | 28 +-- lldb/source/Commands/CommandObjectThread.cpp | 7 +- lldb/source/Target/TraceDumper.cpp | 57 ++++- .../trace/TestTraceDumpFunctionCalls.py | 220 +++++++++++++++++- 4 files changed, 282 insertions(+), 30 deletions(-) diff --git a/lldb/include/lldb/Target/TraceDumper.h b/lldb/include/lldb/Target/TraceDumper.h index bcbe8e525197..59f887878888 100644 --- a/lldb/include/lldb/Target/TraceDumper.h +++ b/lldb/include/lldb/Target/TraceDumper.h @@ -92,10 +92,10 @@ public: /// 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: @@ -119,7 +119,7 @@ public: /// /// 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: @@ -131,7 +131,7 @@ public: /// And in pseudo-code: /// /// FunctionCall [ - /// UntracedSegment { + /// UntracedPrefixSegment { /// symbol: main() /// nestedCall: FunctionCall [ # this untraced segment has a nested /// call @@ -289,20 +289,20 @@ public: 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; }; @@ -346,11 +346,11 @@ public: /// 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 &GetUntracedSegment() const; + /// A optional to the untraced prefix segment of this call. + const llvm::Optional &GetUntracedPrefixSegment() const; /// \return /// A pointer to the parent call. It may be \b nullptr. @@ -360,7 +360,7 @@ public: private: /// An optional untraced segment that precedes all the traced segments. - llvm::Optional m_untraced_segment; + llvm::Optional 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 m_traced_segments; @@ -384,8 +384,8 @@ public: virtual void TraceItem(const TraceItem &item) = 0; /// Dump a function call forest. - virtual void FunctionCallForest(const std::vector &forest) { - } + virtual void + FunctionCallForest(const std::vector &forest) = 0; }; /// Create a instruction dumper for the cursor. diff --git a/lldb/source/Commands/CommandObjectThread.cpp b/lldb/source/Commands/CommandObjectThread.cpp index f7a571db7f13..414acfb23ef9 100644 --- a/lldb/source/Commands/CommandObjectThread.cpp +++ b/lldb/source/Commands/CommandObjectThread.cpp @@ -2132,6 +2132,7 @@ public: break; } case 'J': { + m_dumper_options.json = true; m_dumper_options.pretty_print_json = true; break; } @@ -2198,8 +2199,7 @@ protected: llvm::Optional 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; @@ -2395,8 +2395,7 @@ protected: llvm::Optional 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) { diff --git a/lldb/source/Target/TraceDumper.cpp b/lldb/source/Target/TraceDumper.cpp index 2dbcb49ccaef..7a5214d7cff0 100644 --- a/lldb/source/Target/TraceDumper.cpp +++ b/lldb/source/Target/TraceDumper.cpp @@ -247,13 +247,13 @@ private: } 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(); } @@ -314,6 +314,43 @@ public: ~OutputWriterJSON() { m_j.arrayEnd(); } + void FunctionCallForest( + const std::vector &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) { @@ -597,7 +634,7 @@ TraceDumper::FunctionCall::TracedSegment::GetLastInstructionSymbolInfo() const { } const TraceDumper::FunctionCall & -TraceDumper::FunctionCall::UntracedSegment::GetNestedCall() const { +TraceDumper::FunctionCall::UntracedPrefixSegment::GetNestedCall() const { return *m_nested_call; } @@ -631,14 +668,14 @@ TraceDumper::FunctionCall::GetLastTracedSegment() { return m_traced_segments.back(); } -const Optional & -TraceDumper::FunctionCall::GetUntracedSegment() const { - return m_untraced_segment; +const Optional & +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 { @@ -694,8 +731,8 @@ static TraceDumper::FunctionCall &AppendReturnedInstructionToFunctionCallForest( // one that will contain the new instruction in its first traced segment. TraceDumper::FunctionCallUP new_root = std::make_unique(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)); diff --git a/lldb/test/API/commands/trace/TestTraceDumpFunctionCalls.py b/lldb/test/API/commands/trace/TestTraceDumpFunctionCalls.py index 70f8edbf0daf..d37920bc719b 100644 --- a/lldb/test/API/commands/trace/TestTraceDumpFunctionCalls.py +++ b/lldb/test/API/commands/trace/TestTraceDumpFunctionCalls.py @@ -10,8 +10,20 @@ class TestTraceDumpInfo(TraceIntelPTTestCaseBase): 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", @@ -34,6 +46,26 @@ m.out`foo() + 65 at multi_thread.cpp:12:21 to 12:21 [4, 19524] [call tree #1] [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 @@ -43,6 +75,26 @@ m.out`bar() + 30 at multi_thread.cpp:19:3 to 20:6 [5, 61831] [call tree #1] [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 @@ -58,6 +110,42 @@ a.out`main + 8 at inline.cpp:15:7 to 16:14 [1, 5] 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 @@ -73,6 +161,38 @@ a.out`main 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 @@ -107,3 +227,99 @@ a.out`main + 55 at main.cpp:14 to 16:0 [21, 25] 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" + } + ] + } +]'''])