i#6745: Fix timestamp gap in delayed tracing (#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: #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