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

Walter Erquinigo · Walter Erquinigo · commit ef28c78350db · 2021-08-11T20:50:10.000-07:00
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 Reviewed By: wallace Original Author: jj10306 Differential Revision: https://reviews.llvm.org/D107674
diff --git a/lldb/source/Plugins/TraceExporter/common/TraceHTR.cpp b/lldb/source/Plugins/TraceExporter/common/TraceHTR.cpp
@@ -112,7 +112,7 @@ HTRBlockMetadata HTRInstructionLayer::GetMetadataByIndex(size_t index) const {
       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 {
@@ -391,20 +391,35 @@ llvm::json::Value lldb_private::toJSON(const TraceHTR &htr) {
     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},
     });
   }
 
@@ -420,8 +435,6 @@ llvm::json::Value lldb_private::toJSON(const TraceHTR &htr) {
 
       HTRBlockMetadata metadata = block.GetMetadata();
 
-      size_t end_ts = start_ts + metadata.GetNumInstructions();
-
       llvm::Optional<llvm::StringRef> most_freq_func =
           metadata.GetMostFrequentlyCalledFunction();
       std::stringstream stream;
@@ -431,22 +444,23 @@ llvm::json::Value lldb_private::toJSON(const TraceHTR &htr) {
           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;
diff --git a/lldb/source/Plugins/TraceExporter/common/TraceHTR.h b/lldb/source/Plugins/TraceExporter/common/TraceHTR.h
@@ -35,7 +35,7 @@ class HTRBlockMetadata {
   ///     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) {}
 
diff --git a/lldb/source/Plugins/TraceExporter/docs/htr.rst b/lldb/source/Plugins/TraceExporter/docs/htr.rst
@@ -10,7 +10,7 @@ Concepts
 
 **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.
 
@@ -19,12 +19,13 @@ Concepts
  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.
diff --git a/lldb/test/API/commands/trace/TestTraceExport.py b/lldb/test/API/commands/trace/TestTraceExport.py
@@ -34,22 +34,96 @@ def testErrorMessages(self):
             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
@@ -64,8 +138,6 @@ def testHtrBasicSuperBlockPass(self):
 
         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))
 
@@ -77,18 +149,16 @@ def testHtrBasicSuperBlockPass(self):
         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)
+            num_units_by_layer[layer_id] += 1
 
+        # 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',
@@ -98,12 +168,8 @@ def testHtrBasicSuperBlockPass(self):
                 '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])
 
