[tests] [trace] Add a more comprehensive test for `thread trace export ctf` command

[jj10306]

Summary

Follow up on https://reviews.llvm.org/D105741

• Add new test that exhaustively checks the output file's content
• Fix typos in documentation and other minor fixes

[wallace]

Thank you, this is much more understandable

lldb/docs/htr.rst

1

I'd be good to put these documentation files next in source/Plugins/TraceExporter/docs so that the documentation can live next to the source code. It'll give more visibility to this doc

lldb/source/Plugins/TraceExporter/common/TraceHTR.cpp

393–394

a little comment explaining what "ph", "X", "dur" mean would be good. Also that in the absence of timestamps "ts" is just an index. You can repeat the comments you have in the test, btw

450

explain why the duration is the num of instructions in the case of no timestamps

467

in your devserver you can run
"arc lint"
and it will fix all these formatting issues for you

[wallace]

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

79–80

you don't need this. Whenever the test runs, all previous data will be wiped out

[jj10306]

• move documentation to plugin directory
• remove unnecessary checks in tests and remove test that wasn't testing anything different than the others
• nits

[wallace]

lldb/source/Plugins/TraceExporter/common/TraceHTR.cpp

394–419

use // style comments, as mentioned here https://llvm.org/docs/CodingStandards.html#comment-formatting

450–457

same here

[jj10306]

• fix comment style

[jj10306]

lint + comments

lldb/source/Plugins/TraceExporter/common/TraceHTR.h

public:
   /// \param[in] num_instructions
   ///     The total number of instructions in the block.
   ///
   /// \param[in] func_calls
   ///     The map of a function name to the number of times it is called from
   ///     the block.
   HTRBlockMetadata(lldb::addr_t first_instruction_load_address,
                    size_t num_instructions,
-                   llvm::DenseMap<ConstString, size_t> &func_calls)
+                   llvm::DenseMap<ConstString, size_t> &&func_calls)
       : m_first_instruction_load_address(first_instruction_load_address),
         m_num_instructions(num_instructions), m_func_calls(func_calls) {}
 
   /// Merge two \a HTRBlockMetadata in place.
   ///
   /// \param[in][out] merged_metadata
   ///     Metadata that metadata_to_merge will be merged into.
   ///

lldb/source/Plugins/TraceExporter/common/TraceHTR.cpp

HTRBlockMetadata HTRInstructionLayer::GetMetadataByIndex(size_t index) const {
   llvm::DenseMap<ConstString, size_t> func_calls;
 
   auto func_name_it = m_call_isns.find(instruction_load_address);
   if (func_name_it != m_call_isns.end()) {
     if (llvm::Optional<ConstString> func_name = func_name_it->second) {
       func_calls[*func_name] = 1;
     }
   }
-  return {instruction_load_address, 1, func_calls};
+  return {instruction_load_address, 1, std::move(func_calls)};
 }
 
 size_t HTRInstructionLayer::GetNumUnits() const {
   return m_instruction_trace.size();
 }
 
 HTRBlockMetadata HTRBlockLayer::GetMetadataByIndex(size_t index) const {
   size_t block_id = m_block_id_trace[index];
for (size_t i = 0; i < htr.GetInstructionLayer().GetInstructionTrace().size();
     lldb::addr_t load_address = metadata.GetFirstInstructionLoadAddress();
 
     std::string display_name;
 
     std::stringstream stream;
     stream << "0x" << std::hex << load_address;
     std::string load_address_hex_string(stream.str());
     display_name.assign(load_address_hex_string);
 
-    layers_as_json.emplace_back(llvm::json::Object{
-        {"name", display_name},
-        {"ph", "B"},
-        {"ts", (int64_t)i},
+    /*
+    name: load address of the first instruction of the block and the name
+    of the most frequently called function from the block (if applicable)
 
-        {"pid", (int64_t)layer_id},
-        {"tid", (int64_t)layer_id},
-    });
+    ph: the event type - 'X' for Complete events (see link to documentation
+    below)
+
+
+    Since trace timestamps aren't yet supported in HTR, the ts (timestamp) is
+    based on the instruction's offset in the trace and the dur (duration) is 1
+    since this layer contains single instructions. Using the instruction offset
+    and a duration of 1 oversimplifies the true timing information of the trace,
+    nonetheless, these approximate timestamps/durations provide an
+    clear visualization of the trace.
+
+    ts: offset from the beginning of the trace for the first instruction in the
+    block
+
+    dur: 1 since this layer contains single instructions.
 
+    pid: the ID of the HTR layer the blocks belong to
+
+    See
+    https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.j75x71ritcoy
+    for documentation on the Trace Event Format
+    */
     layers_as_json.emplace_back(llvm::json::Object{
-        {"ph", "E"},
-        {"ts", (int64_t)i + 1},
+        {"name", display_name},
+        {"ph", "X"},
+        {"ts", (int64_t)i},
+        {"dur", 1},
         {"pid", (int64_t)layer_id},
-        {"tid", (int64_t)layer_id},
     });
   }
 
   for (const auto &layer : htr.GetBlockLayers()) {
     size_t start_ts = 0;
     std::vector<size_t> block_id_trace = layer->GetBlockIdTrace();
     for (size_t i = 0; i < block_id_trace.size(); i++) {
       size_t id = block_id_trace[i];
       // Guranteed that this ID is valid, so safe to dereference here.
       HTRBlock block = *layer->GetBlockById(id);
       llvm::json::Value block_json = toJSON(block);
       size_t layer_id = layer->GetLayerId();
 
       HTRBlockMetadata metadata = block.GetMetadata();
 
-      size_t end_ts = start_ts + metadata.GetNumInstructions();
-
       llvm::Optional<llvm::StringRef> most_freq_func =
           metadata.GetMostFrequentlyCalledFunction();
       std::stringstream stream;
       stream << "0x" << std::hex << metadata.GetFirstInstructionLoadAddress();
       std::string offset_hex_string(stream.str());
       std::string display_name =
           most_freq_func ? offset_hex_string + ": " + most_freq_func->str()
                          : offset_hex_string;
 
+      /*
+      Since trace timestamps aren't yet supported in HTR, the ts (timestamp) and
+      dur (duration) are based on the block's offset in the trace and number of
+      instructions in the block, respectively. Using the block offset and the
+      number of instructions oversimplifies the true timing information of the
+      trace, nonetheless, these approximate timestamps/durations provide an
+      understandable visualization of the trace.
+      */
+      auto duration = metadata.GetNumInstructions();
       layers_as_json.emplace_back(llvm::json::Object{
           {"name", display_name},
-          {"ph", "B"},
+          {"ph", "X"},
           {"ts", (int64_t)start_ts},
+          {"dur", (int64_t)duration},
           {"pid", (int64_t)layer_id},
-          {"tid", (int64_t)layer_id},
-      });
-
-      layers_as_json.emplace_back(llvm::json::Object{
-          {"ph", "E"},
-          {"ts", (int64_t)end_ts},
-          {"pid", (int64_t)layer_id},
-          {"tid", (int64_t)layer_id},
           {"args", block_json},
       });
-      start_ts = end_ts;
+      start_ts += duration;
     }
   }
   return layers_as_json;
 }
 
 llvm::json::Value lldb_private::toJSON(const HTRBlock &block) {
   return llvm::json::Value(
       llvm::json::Object{{"Metadata", block.GetMetadata()}});

lldb/source/Plugins/TraceExporter/docs/htr.rst

 Hierarchical Trace Representation (HTR)
 ======================================
 The humongous amount of data processor traces like the ones obtained with Intel PT contain is not digestible to humans in its raw form. Given this, it is useful to summarize these massive traces by extracting useful information. Hierarchical Trace Representation (HTR) is the way lldb represents a summarized trace internally. HTR efficiently stores trace data and allows the trace data to be transformed in a way akin to compiler passes.
 
 Concepts
 --------
 **Block:** One or more contiguous units of the trace. At minimum, the unit of a trace is the load address of an instruction.
 
 **Block Metadata:** Metadata associated with each *block*. For processor traces, some metadata examples are the number of instructions in the block or information on what functions are called in the block.
 
 **Layer:** The representation of trace data between passes. For Intel PT there are two types of layers:
 
- **Instruction Layer:** Composed of the oad addresses of the instructions in the trace. In an effort to save space, 
+ **Instruction Layer:** Composed of the load addresses of the instructions in the trace. In an effort to save space, 
  metadata is only stored for instructions that are of interest, not every instruction in the trace. HTR contains a 
  single instruction layer.
 
  **Block Layer:** Composed of blocks - a block in *layer n* refers to a sequence of blocks in *layer n - 1*. A block in 
  *layer 1* refers to a sequence of instructions in *layer 0* (the instruction layer). Metadata is stored for each block in 
  a block layer. HTR contains one or more block layers.
 
 **Pass:** A transformation applied to a *layer* that generates a new *layer* that is a more summarized, consolidated representation of the trace data.
-A pass merges instructions/blocks based on its specific purpose - for example, a pass designed to summarize a processor trace by function calls would merge all the blocks of a function into a single block representing the entire function.l
+A pass merges instructions/blocks based on its specific purpose - for example, a pass designed to summarize a processor trace by function calls would merge all the blocks of a function into a single block representing the entire function.
 
 The image below illusrates the transformation of a trace's representation (HTR)
 
 .. image:: media/htr-example.png
 
+
 Passes
 ------
 A *pass* is applied to a *layer* to extract useful information (summarization) and compress the trace representation into a new *layer*. The idea is to have a series of passes where each pass specializes in extracting certain information about the trace. Some examples of potential passes include: identifying functions, identifying loops, or a more general purpose such as identifying long sequences of instructions that are repeated (i.e. Basic Super Block). Below you will find a description of each pass currently implemented in lldb.
 
 **Basic Super Block Reduction**
 
 A “basic super block” is the longest sequence of blocks that always occur in the same order. (The concept is akin to “Basic Block'' in compiler theory, but refers to dynamic occurrences rather than CFG nodes).
 

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

def testErrorMessages(self):
         # Now we check the output when there's a running target without a trace
         self.expect("b main")
         self.expect("run")
 
         self.expect(f"thread trace export ctf --file {ctf_test_file}",
             substrs=["error: Process is not being traced"],
             error=True)
 
-    def testExportCreatesFile(self):
+
+    def testHtrBasicSuperBlockPassFullCheck(self):
+        '''
+        Test the BasicSuperBlock pass of HTR.
+
+        This test uses a very small trace so that the expected output is digestible and
+        it's possible to manually verify the behavior of the algorithm.
+
+        This test exhaustively checks that each entry
+        in the output JSON is equal to the expected value.
+
+        '''
+
         self.expect("trace load -v " +
             os.path.join(self.getSourceDir(), "intelpt-trace", "trace.json"),
             substrs=["intel-pt"])
 
         ctf_test_file = self.getBuildArtifact("ctf-test.json")
 
-        if os.path.exists(ctf_test_file):
-            remove_file(ctf_test_file)
         self.expect(f"thread trace export ctf --file {ctf_test_file}")
         self.assertTrue(os.path.exists(ctf_test_file))
 
+        with open(ctf_test_file) as f:
+            data = json.load(f)
 
-    def testHtrBasicSuperBlockPass(self):
         '''
-        Test the BasicSuperBlock pass of HTR
+        The expected JSON contained by "ctf-test.json"
+
+        dur: number of instructions in the block
+
+        name: load address of the first instruction of the block and the
+        name of the most frequently called function from the block (if applicable)
+
+        ph: 'X' for Complete events (see link to documentation below)
+
+        pid: the ID of the HTR layer the blocks belong to
+
+        ts: offset from the beginning of the trace for the first instruction in the block
+
+        See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.j75x71ritcoy
+        for documentation on the Trace Event Format
+        '''
+        # Comments on the right indicate if a block is a "head" and/or "tail"
+        # See BasicSuperBlockMerge in TraceHTR.h for a description of the algorithm
+        expected = [
+            {"dur":1,"name":"0x400511","ph":"X","pid":0,"ts":0},
+            {"dur":1,"name":"0x400518","ph":"X","pid":0,"ts":1},
+            {"dur":1,"name":"0x40051f","ph":"X","pid":0,"ts":2},
+            {"dur":1,"name":"0x400529","ph":"X","pid":0,"ts":3}, # head
+            {"dur":1,"name":"0x40052d","ph":"X","pid":0,"ts":4}, # tail
+            {"dur":1,"name":"0x400521","ph":"X","pid":0,"ts":5},
+            {"dur":1,"name":"0x400525","ph":"X","pid":0,"ts":6},
+            {"dur":1,"name":"0x400529","ph":"X","pid":0,"ts":7}, # head
+            {"dur":1,"name":"0x40052d","ph":"X","pid":0,"ts":8}, # tail
+            {"dur":1,"name":"0x400521","ph":"X","pid":0,"ts":9},
+            {"dur":1,"name":"0x400525","ph":"X","pid":0,"ts":10},
+            {"dur":1,"name":"0x400529","ph":"X","pid":0,"ts":11}, # head
+            {"dur":1,"name":"0x40052d","ph":"X","pid":0,"ts":12}, # tail
+            {"dur":1,"name":"0x400521","ph":"X","pid":0,"ts":13},
+            {"dur":1,"name":"0x400525","ph":"X","pid":0,"ts":14},
+            {"dur":1,"name":"0x400529","ph":"X","pid":0,"ts":15}, # head
+            {"dur":1,"name":"0x40052d","ph":"X","pid":0,"ts":16}, # tail
+            {"dur":1,"name":"0x400521","ph":"X","pid":0,"ts":17},
+            {"dur":1,"name":"0x400525","ph":"X","pid":0,"ts":18},
+            {"dur":1,"name":"0x400529","ph":"X","pid":0,"ts":19}, # head
+            {"dur":1,"name":"0x40052d","ph":"X","pid":0,"ts":20}, # tail
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":3}},"dur":3,"name":"0x400511","ph":"X","pid":1,"ts":0},
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400529","ph":"X","pid":1,"ts":3}, # head, tail
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400521","ph":"X","pid":1,"ts":5},
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400529","ph":"X","pid":1,"ts":7}, # head, tail
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400521","ph":"X","pid":1,"ts":9},
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400529","ph":"X","pid":1,"ts":11}, # head, tail
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400521","ph":"X","pid":1,"ts":13},
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400529","ph":"X","pid":1,"ts":15}, # head, tail
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400521","ph":"X","pid":1,"ts":17},
+            {"args":{"Metadata":{"Functions":[],"Number of Instructions":2}},"dur":2,"name":"0x400529","ph":"X","pid":1,"ts":19} # head, tail
+        ]
+
+        # Check that the length of the expected JSON array is equal to the actual
+        self.assertTrue(len(data) == len(expected))
+        for i in range(len(data)):
+            # Check each individual JSON object in "ctf-test.json" against the expected value above
+            self.assertTrue(data[i] == expected[i])
+
+    def testHtrBasicSuperBlockPassSequenceCheck(self):
+        '''
+        Test the BasicSuperBlock pass of HTR.
+
+        This test exports a modest sized trace and only checks that a particular sequence of blocks are
+        expected, see `testHtrBasicSuperBlockPassFullCheck` for a more "exhaustive" test.
 
         TODO: Once the "trace save" command is implemented, gather Intel PT
         trace of this program and load it like the other tests instead of
         manually executing the commands to trace the program.
         '''
         self.expect(f"target create {os.path.join(self.getSourceDir(), 'intelpt-trace', 'export_ctf_test_program.out')}")
         self.expect("b main")
         self.expect("r")
         self.expect("b exit")
         self.expect("thread trace start")
         self.expect("c")
 
         ctf_test_file = self.getBuildArtifact("ctf-test.json")
 
-        if os.path.exists(ctf_test_file):
-            remove_file(ctf_test_file)
         self.expect(f"thread trace export ctf --file {ctf_test_file}")
         self.assertTrue(os.path.exists(ctf_test_file))
 
 
         with open(ctf_test_file) as f:
             data = json.load(f)
 
         num_units_by_layer = defaultdict(int)
         index_of_first_layer_1_block = None
         for i, event in enumerate(data):
             layer_id = event.get('pid')
+            self.assertTrue(layer_id is not None)
             if layer_id == 1 and index_of_first_layer_1_block is None:
                 index_of_first_layer_1_block = i
-            if layer_id is not None and event['ph'] == 'B':
-                num_units_by_layer[layer_id] += 1
 
-        # Check that there are two layers
-        self.assertTrue(0 in num_units_by_layer and 1 in num_units_by_layer)
-        # Check that each layer has the correct total number of blocks
-        self.assertTrue(num_units_by_layer[0] == 1630)
-        self.assertTrue(num_units_by_layer[1] == 383)
-
+        # Check that there are only two layers and that the layer IDs are correct
+        # Check that layer IDs are correct
+        self.assertTrue(len(num_units_by_layer) == 2 and 0 in num_units_by_layer and 1 in num_units_by_layer)
 
+        # The expected block names for the first 7 blocks of layer 1
         expected_block_names = [
                 '0x4005f0',
                 '0x4005fe',
                 '0x400606: iterative_handle_request_by_id(int, int)',
                 '0x4005a7',
                 '0x4005af',
                 '0x4005b9: fast_handle_request(int)',
                 '0x4005d5: log_response(int)',
         ]
-        # There are two events per block, a beginning and an end. This means we must increment data_index by 2, so we only encounter the beginning event of each block.
+
         data_index = index_of_first_layer_1_block
-        expected_index = 0
-        while expected_index < len(expected_block_names):
-            self.assertTrue(data[data_index]['name'] == expected_block_names[expected_index])
-            self.assertTrue(data[data_index]['name'] == expected_block_names[expected_index])
-            data_index += 2
-            expected_index += 1
+        for i in range(len(expected_block_names)):
+            self.assertTrue(data[data_index + i]['name'] == expected_block_names[i])