From 3af401bcd7ea203d52249e5ea94bdc43363743c0 Mon Sep 17 00:00:00 2001 From: Abhinav Anil Sharma Date: Fri, 14 Jun 2024 16:22:03 -0400 Subject: [PATCH] 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 | 13 +++++++------ clients/drcachesim/tracer/instr_counter.cpp | 5 +++-- clients/drcachesim/tracer/output.cpp | 2 +- suite/tests/CMakeLists.txt | 17 +++++++++++++++-- 4 files changed, 26 insertions(+), 11 deletions(-) diff --git a/clients/drcachesim/tests/window_test.cpp b/clients/drcachesim/tests/window_test.cpp index 2404cd0e19f..fdbc8fc7829 100644 --- a/clients/drcachesim/tests/window_test.cpp +++ b/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 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 diff --git a/clients/drcachesim/tracer/instr_counter.cpp b/clients/drcachesim/tracer/instr_counter.cpp index 43d7b0d0e2f..737e897bb58 100644 --- a/clients/drcachesim/tracer/instr_counter.cpp +++ b/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()); diff --git a/clients/drcachesim/tracer/output.cpp b/clients/drcachesim/tracer/output.cpp index 64d4d120fd0..2462a3b59b0 100644 --- a/clients/drcachesim/tracer/output.cpp +++ b/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); } diff --git a/suite/tests/CMakeLists.txt b/suite/tests/CMakeLists.txt index 49169a319fd..a99f233399f 100644 --- a/suite/tests/CMakeLists.txt +++ b/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