i#5538 memtrace seek, part 11: Fix omitted header problems (#5840)

Fixes a bug where reader_t's detection of duplicated timestamp,cpuid
headers at the start of a chunk assumed single-threaded mode.  We
switch to using a simple per-tid chunk footer trigger.

Adds a test to view_test via a new serial mock which takes in
trace_entry_t and allows testing of the interleaving code.  Tests both
proper chunk header elision as well as replicating the bug where
elision should not happen.

Fixes problems revealed in the drcacheoff.skip test by this change:
do not increment the ref count for the
hidden markers at the start of a chunk when skipping in a zipfile as
well as in raw2trace.

The test revealed a separate bug in the view tool where the version
and filetype ordinals, for delaying, were not updated on new threads.
That is fixed here as well as otherwise the new tests fail.

Issue: #5538

clients/drcachesim/CMakeLists.txt

@@ -1,5 +1,5 @@
 # **********************************************************
-# Copyright (c) 2015-2022 Google, Inc.    All rights reserved.
+# Copyright (c) 2015-2023 Google, Inc.    All rights reserved.
 # **********************************************************
 
 # Redistribution and use in source and binary forms, with or without
@@ -699,7 +699,7 @@ if (BUILD_TESTS)
     add_test(NAME tool.drcachesim.invariant_checker_test
              COMMAND tool.drcachesim.invariant_checker_test)
 
-    add_executable(tool.drcacheoff.view_test tests/view_test.cpp)
+    add_executable(tool.drcacheoff.view_test tests/view_test.cpp reader/file_reader.cpp)
     configure_DynamoRIO_standalone(tool.drcacheoff.view_test)
     add_win32_flags(tool.drcacheoff.view_test)
     target_link_libraries(tool.drcacheoff.view_test drmemtrace_view drmemtrace_raw2trace)

clients/drcachesim/reader/file_reader.h

@@ -1,5 +1,5 @@
 /* **********************************************************
- * Copyright (c) 2016-2022 Google, Inc.  All rights reserved.
+ * Copyright (c) 2016-2023 Google, Inc.  All rights reserved.
  * **********************************************************/
 
 /*
@@ -361,10 +361,12 @@ template <typename T> class file_reader_t : public reader_t {
         return true;
     }
 
+    // Protected for access by mock_file_reader_t.
+    std::vector<T> input_files_;
+
 private:
     std::string input_path_;
     std::vector<std::string> input_path_list_;
-    std::vector<T> input_files_;
     trace_entry_t entry_copy_;
     // The current thread we're processing is "index".  If it's set to input_files_.size()
     // that means we need to pick a new thread.

clients/drcachesim/reader/reader.cpp

@@ -1,5 +1,5 @@
 /* **********************************************************
- * Copyright (c) 2016-2022 Google, Inc.  All rights reserved.
+ * Copyright (c) 2016-2023 Google, Inc.  All rights reserved.
  * **********************************************************/
 
 /*
@@ -262,21 +262,19 @@ reader_t::process_input_entry()
         // and use them to start post-seek iteration.
         if (chunk_instr_count_ > 0 &&
             cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_TIMESTAMP &&
-            cur_instr_count_ / chunk_instr_count_ !=
-                last_timestamp_instr_count_ / chunk_instr_count_) {
+            skip_chunk_header_.find(cur_tid_) != skip_chunk_header_.end()) {
             VPRINT(this, 2, "skipping start-of-chunk dup timestamp\n");
-            skip_next_cpu_ = true;
-        } else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_CPU_ID &&
-                   skip_next_cpu_) {
+        } else if (chunk_instr_count_ > 0 &&
+                   cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_CPU_ID &&
+                   skip_chunk_header_.find(cur_tid_) != skip_chunk_header_.end()) {
             VPRINT(this, 2, "skipping start-of-chunk dup cpu\n");
-            skip_next_cpu_ = false;
+            skip_chunk_header_.erase(cur_tid_);
         } else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_RECORD_ORDINAL) {
             // Not exposed to tools.
         } else {
             have_memref = true;
         }
         if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_TIMESTAMP) {
-            last_timestamp_instr_count_ = cur_instr_count_;
             // Today, a skipped memref is just a duplicate of one that we've
             // already seen, so this condition is not really needed. But to
             // be future-proof, we want to avoid looking at timestamps that
@@ -295,6 +293,8 @@ reader_t::process_input_entry()
             page_size_ = cur_ref_.marker.marker_value;
         else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_CHUNK_INSTR_COUNT)
             chunk_instr_count_ = cur_ref_.marker.marker_value;
+        else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_CHUNK_FOOTER)
+            skip_chunk_header_.insert(cur_tid_);
         break;
     default:
         ERRMSG("Unknown trace entry type %s (%d)\n", trace_type_names[input_entry_->type],
@@ -305,14 +305,16 @@ reader_t::process_input_entry()
     }
     if (have_memref) {
         if (suppress_ref_count_ > 0) {
-            VPRINT(this, 4, "suppressing %" PRIu64 " ref counts\n", suppress_ref_count_);
+            VPRINT(this, 4, "suppressing %" PRIu64 " ref counts @%" PRIu64 "\n",
+                   suppress_ref_count_, cur_ref_count_);
             --suppress_ref_count_;
         } else {
             if (suppress_ref_count_ == 0) {
                 // Ensure get_record_ordinal() ignores it.
                 suppress_ref_count_ = -1;
             }
             ++cur_ref_count_;
+            VPRINT(this, 5, "ref count is now @%" PRIu64 "\n", cur_ref_count_);
         }
     }
     return have_memref;

clients/drcachesim/reader/reader.h

@@ -1,5 +1,5 @@
 /* **********************************************************
- * Copyright (c) 2015-2022 Google, Inc.  All rights reserved.
+ * Copyright (c) 2015-2023 Google, Inc.  All rights reserved.
  * **********************************************************/
 
 /*
@@ -40,6 +40,7 @@
 #include <assert.h>
 #include <iterator>
 #include <unordered_map>
+#include <unordered_set>
 // For exporting we avoid "../common" and rely on -I.
 #include "memref.h"
 #include "memtrace_stream.h"
@@ -204,7 +205,7 @@ class reader_t : public std::iterator<std::input_iterator_tag, memref_t>,
     uint64_t cur_ref_count_ = 0;
     int64_t suppress_ref_count_ = -1;
     uint64_t cur_instr_count_ = 0;
-    uint64_t last_timestamp_instr_count_ = 0;
+    std::unordered_set<memref_tid_t> skip_chunk_header_;
     uint64_t last_timestamp_ = 0;
     trace_entry_t *input_entry_ = nullptr;
     // Remember top-level headers for the memtrace_stream_t interface.
@@ -228,7 +229,6 @@ class reader_t : public std::iterator<std::input_iterator_tag, memref_t>,
     addr_t prev_instr_addr_ = 0;
     int bundle_idx_ = 0;
     std::unordered_map<memref_tid_t, memref_pid_t> tid2pid_;
-    bool skip_next_cpu_ = false;
     bool expect_no_encodings_ = true;
     encoding_info_t last_encoding_;
     std::unordered_map<addr_t, encoding_info_t> encodings_;

clients/drcachesim/reader/zipfile_file_reader.cpp

@@ -1,5 +1,5 @@
 /* **********************************************************
- * Copyright (c) 2017-2022 Google, Inc.  All rights reserved.
+ * Copyright (c) 2017-2023 Google, Inc.  All rights reserved.
  * **********************************************************/
 
 /*
@@ -187,6 +187,7 @@ file_reader_t<zipfile_reader_t>::skip_thread_instructions(size_t thread_index,
         zipfile->cur_buf = zipfile->max_buf;
     }
     // We have to linearly walk the last mile.
+    bool prev_was_record_ord = false;
     while (cur_instr_count_ < stop_count_) { // End condition is never reached.
         if (!read_next_thread_entry(thread_index, &entry_copy_, eof))
             return false;
@@ -197,16 +198,26 @@ file_reader_t<zipfile_reader_t>::skip_thread_instructions(size_t thread_index,
             type_is_instr(static_cast<trace_type_t>(entry_copy_.type)))
             break;
         // To examine the produced memrefs we'd have to have the base reader
-        // expose these hidden entries.  It is simpler for use to read the
+        // expose these hidden entries.  It is simpler for us to read the
         // trace_entry_t directly prior to processing by the base class.
         if (entry_copy_.type == TRACE_TYPE_MARKER) {
-            if (entry_copy_.size == TRACE_MARKER_TYPE_RECORD_ORDINAL)
+            if (entry_copy_.size == TRACE_MARKER_TYPE_RECORD_ORDINAL) {
                 cur_ref_count_ = entry_copy_.addr;
-            else if (entry_copy_.size == TRACE_MARKER_TYPE_TIMESTAMP)
+                prev_was_record_ord = true;
+                VPRINT(this, 4, "Found record ordinal marker: new ord %" PRIu64 "\n",
+                       cur_ref_count_);
+            } else if (entry_copy_.size == TRACE_MARKER_TYPE_TIMESTAMP) {
                 timestamp = entry_copy_;
-            else if (entry_copy_.size == TRACE_MARKER_TYPE_CPU_ID)
+                if (prev_was_record_ord)
+                    --cur_ref_count_;
+            } else if (entry_copy_.size == TRACE_MARKER_TYPE_CPU_ID) {
                 cpu = entry_copy_;
-        }
+                if (prev_was_record_ord)
+                    --cur_ref_count_;
+            } else
+                prev_was_record_ord = false;
+        } else
+            prev_was_record_ord = false;
         // Update core state.
         input_entry_ = &entry_copy_;
         process_input_entry();

clients/drcachesim/tests/offline-skip.expect

@@ -1,17 +1,17 @@
 Output format:
 <record#> <instr#>: T<tid> <record details>
 ------------------------------------------------------------
-        0       63: T1384871 <marker: timestamp 13313186810097539>
-        0       63: T1384871 <marker: tid 1384871 on core 9>
-       92       64: T1384871 ifetch       4 byte(s) @ 0x0000000000401028 48 83 eb 01          sub    $0x0000000000000001 %rbx -> %rbx
-       93       65: T1384871 ifetch       4 byte(s) @ 0x000000000040102c 48 83 fb 00          cmp    %rbx $0x0000000000000000
-       94       66: T1384871 ifetch       2 byte(s) @ 0x0000000000401030 75 d9                jnz    $0x000000000040100b
-       95       67: T1384871 ifetch       7 byte(s) @ 0x000000000040100b 48 c7 c7 01 00 00 00 mov    $0x0000000000000001 -> %rdi
-       96       68: T1384871 ifetch       8 byte(s) @ 0x0000000000401012 48 8d 34 25 00 20 40 lea    0x00402000 -> %rsi
-       96       68: T1384871                                             00
-       97       69: T1384871 ifetch       7 byte(s) @ 0x000000000040101a 48 c7 c2 0d 00 00 00 mov    $0x000000000000000d -> %rdx
-       98       70: T1384871 ifetch       5 byte(s) @ 0x0000000000401021 b8 01 00 00 00       mov    $0x00000001 -> %eax
-       99       71: T1384871 ifetch       2 byte(s) @ 0x0000000000401026 0f 05                syscall  -> %rcx %r11
+        0       63: T296231 <marker: timestamp 13319413770947393>
+        0       63: T296231 <marker: tid 296231 on core 10>
+       90       64: T296231 ifetch       4 byte(s) @ 0x0000000000401028 48 83 eb 01          sub    $0x0000000000000001 %rbx -> %rbx
+       91       65: T296231 ifetch       4 byte(s) @ 0x000000000040102c 48 83 fb 00          cmp    %rbx $0x0000000000000000
+       92       66: T296231 ifetch       2 byte(s) @ 0x0000000000401030 75 d9                jnz    $0x000000000040100b
+       93       67: T296231 ifetch       7 byte(s) @ 0x000000000040100b 48 c7 c7 01 00 00 00 mov    $0x0000000000000001 -> %rdi
+       94       68: T296231 ifetch       8 byte(s) @ 0x0000000000401012 48 8d 34 25 00 20 40 lea    0x00402000 -> %rsi
+       94       68: T296231                                             00
+       95       69: T296231 ifetch       7 byte(s) @ 0x000000000040101a 48 c7 c2 0d 00 00 00 mov    $0x000000000000000d -> %rdx
+       96       70: T296231 ifetch       5 byte(s) @ 0x0000000000401021 b8 01 00 00 00       mov    $0x00000001 -> %eax
+       97       71: T296231 ifetch       2 byte(s) @ 0x0000000000401026 0f 05                syscall  -> %rcx %r11
 View tool results:
               8 : total instructions