i#6745: Fix timestamp gap in delayed tracing (DynamoRIO#6746)

Fixes a timestamp gap between the first and second timestamps in the
trace caused when -trace_after_instrs is used.

Adds a unit test that reuses the existing window_test.cpp to reproduce
the bug and fails without the fix.

Fixes: DynamoRIO#6745

clients/drcachesim/tests/window_test.cpp

@@ -90,6 +90,8 @@ post_process()
         std::cerr << "Failed to create output dir";
         assert(false);
     }
+    // TODO i#6847: This decomposes only the first window trace. We should check
+    // all window traces.
     std::string dir_err = dir.initialize(raw_dir, outdir);
     assert(dir_err.empty());
     raw2trace_t raw2trace(dir.modfile_bytes_, dir.in_files_, dir.out_files_,
@@ -114,13 +116,12 @@ post_process()
 }
 
 static std::string
-gather_trace()
+gather_trace(const std::string &drmemtrace_args)
 {
     // Set -trace_for_instrs and -retrace_every_instrs in such a way that the
     // sleep introduced in the app is big enough to cross window boundaries.
-    std::string dr_ops(
-        "-stderr_mask 0xc -client_lib ';;-offline -offline -trace_after_instrs 1000 "
-        "-trace_for_instrs 2500 -retrace_every_instrs 1000");
+    std::string dr_ops("-stderr_mask 0xc -client_lib ';;-offline ");
+    dr_ops += drmemtrace_args;
     if (!my_setenv("DYNAMORIO_OPTIONS", dr_ops.c_str()))
         std::cerr << "failed to set env var!\n";
     dr_app_setup();
@@ -136,7 +137,7 @@ gather_trace()
 int
 test_main(int argc, const char *argv[])
 {
-    std::string dir = gather_trace();
+    std::string dir = gather_trace(std::string(argv[1]));
     void *dr_context = dr_standalone_init();
     scheduler_t scheduler;
     std::vector<scheduler_t::input_workload_t> sched_inputs;
@@ -159,7 +160,7 @@ test_main(int argc, const char *argv[])
         assert(status == scheduler_t::STATUS_OK);
         if (memref.marker.type == TRACE_TYPE_MARKER &&
             memref.marker.marker_type == TRACE_MARKER_TYPE_TIMESTAMP) {
-            // Looks at the gap between the current and the previous timestamps
+            // Looks at the gap between the first and second timestamps
             // and checks if it's less than the sleep added between windows in
             // the test app. This ensures that a large gap in wall-clock time
             // introduced during window-tracing doesn't result in timestamps so

clients/drcachesim/tracer/instr_counter.cpp

@@ -129,9 +129,10 @@ hit_instr_count_threshold(app_pc next_pc)
         return;
     }
     if (op_trace_after_instrs.get_value() > 0 &&
-        !reached_trace_after_instrs.load(std::memory_order_acquire))
+        !reached_trace_after_instrs.load(std::memory_order_acquire)) {
         NOTIFY(0, "Hit delay threshold: enabling tracing.\n");
-    else {
+        retrace_start_timestamp.store(instru_t::get_timestamp());
+    } else {
         NOTIFY(0, "Hit retrace threshold: enabling tracing for window #%zd.\n",
                tracing_window.load(std::memory_order_acquire));
         retrace_start_timestamp.store(instru_t::get_timestamp());

clients/drcachesim/tracer/output.cpp

@@ -1059,7 +1059,7 @@ process_and_output_buffer(void *drcontext, bool skip_size_cap)
         instru->clamp_unit_header_timestamp(data->buf_base + stamp_offs, min_timestamp);
     }
 
-    if (has_tracing_windows()) {
+    if (has_tracing_windows() || op_trace_after_instrs.get_value() > 0) {
         min_timestamp = retrace_start_timestamp.load(std::memory_order_acquire);
         instru->clamp_unit_header_timestamp(data->buf_base + stamp_offs, min_timestamp);
     }

suite/tests/CMakeLists.txt

@@ -4437,12 +4437,24 @@ if (BUILD_CLIENTS)
       set(tool.drcacheoff.burst_traceopts_nodr ON)
       set(tool.drcacheoff.burst_traceopts_nopost ON)
       torunonly_drcacheoff(burst_traceopts tool.drcacheoff.burst_traceopts "" "" "")
+
       set(tool.drcacheoff.windows-timestamps_nodr ON)
       set(tool.drcacheoff.windows-timestamps_nopost ON)
-      torunonly_drcacheoff(windows-timestamps tool.drcacheoff.windows-timestamps "" "" "")
-      set(tool.drcacheoff.windows-timestamps-expectbase "offline-windows-timestamps")
+      torunonly_drcacheoff(windows-timestamps tool.drcacheoff.windows-timestamps
+        "" "" "-trace_after_instrs 1000 -trace_for_instrs 2500 -retrace_every_instrs 1000")
       set(tool.drcacheoff.windows-timestamps_timeout 120)
 
+      set(tool.drcacheoff.delay-ts_nodr ON)
+      set(tool.drcacheoff.delay-ts_nopost ON)
+      # -subdir_prefix should match the test name to allow the precmd to cleanup
+      # traces from previous runs of the test. For this test, the created trace
+      # path is very close to the max length allowed by Windows, so we abbreviate
+      # the test name a tad.
+      torunonly_drcacheoff(delay-ts tool.drcacheoff.windows-timestamps "" ""
+        "-trace_after_instrs 10000 -subdir_prefix drmemtrace.tool.drcacheoff.delay-ts")
+      set(tool.drcacheoff.delay-ts_expectbase "offline-windows-timestamps")
+      set(tool.drcacheoff.delay-ts_timeout 120)
+
       if (LINUX) # Futex is Linux-only.
         set(tool.drcacheoff.burst_futex_nodr ON)
         set(tool.drcacheoff.burst_futex_nopost ON)
@@ -6304,6 +6316,7 @@ if (UNIX AND X86 AND CPU_AMD AND NOT DR_HOST_X64)
     code_api|tool.drcacheoff.warmup-pthreads-windows-split
     code_api|tool.drcacheoff.windows-split
     code_api|tool.drcacheoff.windows-timestamps
+    code_api|tool.drcacheoff.delay-ts
     code_api|tool.drcachesim.coherence
     code_api|tool.drcachesim.delay-global
     code_api|tool.drcachesim.filter-d