i#2039 trace trim, part 4: Clamp timestamps (#5704)

Moves the timestamp+cpu headers to be added at buffer creation time
instead of at buffer output time.

Makes instru_t::frozen_timestamp_ use release-acquire semantics and
sets it for -align_endpoints at detach time.

Adds a 'minimum timestamp' recorded at post-attach time.  At buffer
output time, we examine the buffer's timestamp and if it was from
before the minimum, we replace it with the minimum.

Tested on a large app where these changes result in much tighter
timestamps matching the burst period.

This also directly fixes #5537 which pointed out that the timestamps
being at buffer output time is contradicted by the documentation.

Issue: #2039, #5537
Fixes #5537

clients/drcachesim/tracer/instru.h

@@ -38,6 +38,7 @@
 
 #include <stdint.h>
 #include <string.h>
+#include <atomic>
 #include "dr_api.h"
 #include "drvector.h"
 #include "trace_entry.h"
@@ -179,6 +180,7 @@ class instru_t {
         , disable_optimizations_(disable_opts)
         , instr_size_(instruction_size)
     {
+        frozen_timestamp_.store(0, std::memory_order_release);
     }
     virtual ~instru_t()
     {
@@ -221,10 +223,15 @@ class instru_t {
     // This is a per-buffer-writeout header.
     virtual int
     append_unit_header(byte *buf_ptr, thread_id_t tid, ptr_int_t window) = 0;
+    // The entry at buf_ptr must be a timestamp.
+    // If the timestamp value is < min_timestamp, replaces it with min_timestamp
+    // and returns true; else returns false.
+    virtual bool
+    refresh_unit_header_timestamp(byte *buf_ptr, uint64 min_timestamp) = 0;
     virtual void
     set_frozen_timestamp(uint64 timestamp)
     {
-        frozen_timestamp_ = timestamp;
+        frozen_timestamp_.store(timestamp, std::memory_order_release);
     }
 
     // These insert inlined code to add an entry into the trace buffer.
@@ -292,8 +299,8 @@ class instru_t {
     drvector_t *reg_vector_;
     bool disable_optimizations_;
     // Stores a timestamp to use for all future unit headers.  This is meant for
-    // avoiding time gaps for max-limit scenarios (i#5021).
-    uint64 frozen_timestamp_ = 0;
+    // avoiding time gaps for -align_endpoints or max-limit scenarios (i#5021).
+    std::atomic<uint64> frozen_timestamp_;
 
 private:
     instru_t()
@@ -339,6 +346,8 @@ class online_instru_t : public instru_t {
     append_thread_header(byte *buf_ptr, thread_id_t tid, offline_file_type_t file_type);
     int
     append_unit_header(byte *buf_ptr, thread_id_t tid, ptr_int_t window) override;
+    bool
+    refresh_unit_header_timestamp(byte *buf_ptr, uint64 min_timestamp) override;
 
     int
     instrument_memref(void *drcontext, void *bb_field, instrlist_t *ilist, instr_t *where,
@@ -420,6 +429,8 @@ class offline_instru_t : public instru_t {
     append_thread_header(byte *buf_ptr, thread_id_t tid, offline_file_type_t file_type);
     int
     append_unit_header(byte *buf_ptr, thread_id_t tid, ptr_int_t window) override;
+    bool
+    refresh_unit_header_timestamp(byte *buf_ptr, uint64 min_timestamp) override;
 
     int
     instrument_memref(void *drcontext, void *bb_field, instrlist_t *ilist, instr_t *where,

clients/drcachesim/tracer/instru_offline.cpp

@@ -397,15 +397,27 @@ offline_instru_t::append_unit_header(byte *buf_ptr, thread_id_t tid, ptr_int_t w
     byte *new_buf = buf_ptr;
     offline_entry_t *entry = (offline_entry_t *)new_buf;
     entry->timestamp.type = OFFLINE_TYPE_TIMESTAMP;
-    entry->timestamp.usec =
-        frozen_timestamp_ != 0 ? frozen_timestamp_ : instru_t::get_timestamp();
+    uint64 frozen = frozen_timestamp_.load(std::memory_order_acquire);
+    entry->timestamp.usec = frozen != 0 ? frozen : instru_t::get_timestamp();
     new_buf += sizeof(*entry);
     if (window >= 0)
         new_buf += append_marker(new_buf, TRACE_MARKER_TYPE_WINDOW_ID, (uintptr_t)window);
     new_buf += append_marker(new_buf, TRACE_MARKER_TYPE_CPU_ID, instru_t::get_cpu_id());
     return (int)(new_buf - buf_ptr);
 }
 
+bool
+offline_instru_t::refresh_unit_header_timestamp(byte *buf_ptr, uint64 min_timestamp)
+{
+    offline_entry_t *stamp = reinterpret_cast<offline_entry_t *>(buf_ptr);
+    DR_ASSERT(stamp->timestamp.type == OFFLINE_TYPE_TIMESTAMP);
+    if (stamp->timestamp.usec < min_timestamp) {
+        stamp->timestamp.usec = min_timestamp;
+        return true;
+    }
+    return false;
+}
+
 int
 offline_instru_t::insert_save_entry(void *drcontext, instrlist_t *ilist, instr_t *where,
                                     reg_id_t reg_ptr, reg_id_t scratch, int adjust,

clients/drcachesim/tracer/instru_online.cpp

@@ -185,17 +185,30 @@ online_instru_t::append_unit_header(byte *buf_ptr, thread_id_t tid, intptr_t win
 {
     byte *new_buf = buf_ptr;
     new_buf += append_tid(new_buf, tid);
-    new_buf += append_marker(new_buf, TRACE_MARKER_TYPE_TIMESTAMP,
-                             // Truncated to 32 bits for 32-bit: we live with it.
-                             static_cast<uintptr_t>(frozen_timestamp_ != 0
-                                                        ? frozen_timestamp_
-                                                        : instru_t::get_timestamp()));
+    uint64 frozen = frozen_timestamp_.load(std::memory_order_acquire);
+    new_buf += append_marker(
+        new_buf, TRACE_MARKER_TYPE_TIMESTAMP,
+        // Truncated to 32 bits for 32-bit: we live with it.
+        static_cast<uintptr_t>(frozen != 0 ? frozen : instru_t::get_timestamp()));
     if (window >= 0)
         new_buf += append_marker(new_buf, TRACE_MARKER_TYPE_WINDOW_ID, (uintptr_t)window);
     new_buf += append_marker(new_buf, TRACE_MARKER_TYPE_CPU_ID, instru_t::get_cpu_id());
     return (int)(new_buf - buf_ptr);
 }
 
+bool
+online_instru_t::refresh_unit_header_timestamp(byte *buf_ptr, uint64 min_timestamp)
+{
+    trace_entry_t *stamp = reinterpret_cast<trace_entry_t *>(buf_ptr);
+    DR_ASSERT(stamp->type == TRACE_TYPE_MARKER &&
+              stamp->size == TRACE_MARKER_TYPE_TIMESTAMP);
+    if (stamp->addr < min_timestamp) {
+        stamp->addr = static_cast<uintptr_t>(min_timestamp);
+        return true;
+    }
+    return false;
+}
+
 void
 online_instru_t::insert_save_immed(void *drcontext, instrlist_t *ilist, instr_t *where,
                                    reg_id_t base, reg_id_t scratch, ptr_int_t immed,

clients/drcachesim/tracer/output.cpp

@@ -445,6 +445,9 @@ open_new_thread_file(void *drcontext, ptr_int_t window_num)
     return opened_new_file;
 }
 
+/* Appends just the thread header (not the unit/buffer header).
+ * Returns the size of the added thread header.
+ */
 static size_t
 prepend_offline_thread_header(void *drcontext)
 {
@@ -453,7 +456,7 @@ prepend_offline_thread_header(void *drcontext)
     per_thread_t *data = (per_thread_t *)drmgr_get_tls_field(drcontext, tls_idx);
     size_t size = reinterpret_cast<offline_instru_t *>(instru)->append_thread_header(
         data->buf_base, dr_get_thread_id(drcontext), get_file_type());
-    BUF_PTR(data->seg_base) = data->buf_base + size + buf_hdr_slots_size;
+    BUF_PTR(data->seg_base) = data->buf_base + size;
     data->has_thread_header = true;
     return size;
 }
@@ -547,10 +550,13 @@ write_trace_data(void *drcontext, byte *towrite_start, byte *towrite_end,
 }
 
 // Should only be called when the trace buffer is empty.
-static void
+// For a new window, appends the thread headers, but not the unit headers;
+// returns true if that happens else returns false.
+static bool
 set_local_window(void *drcontext, ptr_int_t value)
 {
     per_thread_t *data = (per_thread_t *)drmgr_get_tls_field(drcontext, tls_idx);
+    bool prepended = false;
     NOTIFY(3, "%s: T%d %zd (old: %zd)\n", __FUNCTION__, dr_get_thread_id(drcontext),
            value, get_local_window(data));
     if (op_offline.get_value()) {
@@ -586,6 +592,7 @@ set_local_window(void *drcontext, ptr_int_t value)
                     data->init_header_size = header_size;
                 else
                     DR_ASSERT(header_size == data->init_header_size);
+                prepended = true;
             }
             // We delay opening the next window's file to avoid an empty final file.
             // The initial file is opened at thread init.
@@ -594,6 +601,7 @@ set_local_window(void *drcontext, ptr_int_t value)
         }
     }
     *(ptr_int_t *)TLS_SLOT(data->seg_base, MEMTRACE_TLS_OFFS_WINDOW) = value;
+    return prepended;
 }
 
 static void
@@ -674,22 +682,6 @@ is_ok_to_split_before(trace_type_t type)
         op_L0I_filter.get_value();
 }
 
-static size_t
-add_buffer_header(void *drcontext, per_thread_t *data, byte *buf_base)
-{
-    size_t header_size = 0;
-    // For online we already wrote the thread header but for offline it is in
-    // the first buffer, so skip over it.
-    if (data->has_thread_header && op_offline.get_value())
-        header_size = data->init_header_size;
-    data->has_thread_header = false;
-    // The initial slots are left empty for the header, which we add here.
-    header_size +=
-        append_unit_header(drcontext, buf_base + header_size, dr_get_thread_id(drcontext),
-                           get_local_window(data));
-    return header_size;
-}
-
 static uint
 output_buffer(void *drcontext, per_thread_t *data, byte *buf_base, byte *buf_ptr,
               size_t header_size)
@@ -811,9 +803,12 @@ process_entry_for_physaddr(void *drcontext, per_thread_t *data, size_t header_si
             ASSERT(size == data->init_header_size, "inconsistent header");
             *skip = data->init_header_size;
             v2p_ptr += size;
-            header_size += size;
         }
-        v2p_ptr += add_buffer_header(drcontext, data, v2p_ptr);
+        // With timestamps at buffer start, we want to use the same timestamp+cpu
+        // to avoid out-of-order times.
+        memcpy(v2p_ptr, data->buf_base + header_size - buf_hdr_slots_size,
+               buf_hdr_slots_size);
+        v2p_ptr += buf_hdr_slots_size;
         *emitted = true;
     }
     if (v2p_ptr + 2 * instru->sizeof_entry() - data->v2p_buf >=
@@ -822,7 +817,9 @@ process_entry_for_physaddr(void *drcontext, per_thread_t *data, size_t header_si
         data->num_phys_markers +=
             output_buffer(drcontext, data, data->v2p_buf, v2p_ptr, header_size);
         v2p_ptr = data->v2p_buf;
-        v2p_ptr += add_buffer_header(drcontext, data, v2p_ptr);
+        memcpy(v2p_ptr, data->buf_base + header_size - buf_hdr_slots_size,
+               buf_hdr_slots_size);
+        v2p_ptr += buf_hdr_slots_size;
     }
     if (success) {
         v2p_ptr +=
@@ -906,7 +903,6 @@ process_and_output_buffer(void *drcontext, bool skip_size_cap)
     byte *mem_ref, *buf_ptr;
     byte *redzone;
     bool do_write = true;
-    size_t header_size = 0;
     uint current_num_refs = 0;
 
     if (op_offline.get_value() && data->file == INVALID_FILE) {
@@ -916,22 +912,46 @@ process_and_output_buffer(void *drcontext, bool skip_size_cap)
         open_new_thread_file(drcontext, get_local_window(data));
     }
 
+    size_t header_size = buf_hdr_slots_size;
+    // For online we already wrote the thread header but for offline it is in
+    // the first buffer.
+    if (data->has_thread_header && op_offline.get_value())
+        header_size += data->init_header_size;
+    data->has_thread_header = false;
+
+    if (align_attach_detach_endpoints()) {
+        // This is the attach counterpart to instru_t::set_frozen_timestamp(): we place
+        // timestamps at buffer creation, but that can be before we're fully attached.
+        // We update any too-early timestamps to reflect when we actually started
+        // tracing.  (Switching back to timestamps at buffer output is actually
+        // worse as we then have the identical frozen timestamp for all the flushes
+        // during detach, plus they are all on the same cpu too.)
+        size_t stamp_offs =
+            header_size > buf_hdr_slots_size ? header_size - buf_hdr_slots_size : 0;
+        uint64 min_timestamp = attached_timestamp.load(std::memory_order_acquire);
+        instru->refresh_unit_header_timestamp(data->buf_base + stamp_offs, min_timestamp);
+    }
+
     buf_ptr = BUF_PTR(data->seg_base);
     // We may get called with nothing to write: e.g., on a syscall for
     // -L0I_filter and -L0D_filter.
-    if (buf_ptr == data->buf_base + header_size + buf_hdr_slots_size) {
+    if (buf_ptr == data->buf_base + header_size) {
+        ptr_int_t window = -1;
         if (has_tracing_windows()) {
             // If there is no data to write, we do not emit an empty header here
             // unless this thread is exiting (set_local_window will also write out
             // entries on a window change for offline; for online multiple windows
             // may pass with no output at all for an idle thread).
-            set_local_window(drcontext, tracing_window.load(std::memory_order_acquire));
+            window = tracing_window.load(std::memory_order_acquire);
+            if (set_local_window(drcontext, window))
+                header_size = data->init_header_size;
         }
+        // Refresh header.
+        append_unit_header(drcontext, data->buf_base + header_size - buf_hdr_slots_size,
+                           dr_get_thread_id(drcontext), window);
         return;
     }
 
-    header_size = add_buffer_header(drcontext, data, data->buf_base);
-
     bool window_changed = false;
     if (has_tracing_windows() &&
         get_local_window(data) != tracing_window.load(std::memory_order_acquire)) {
@@ -1021,7 +1041,14 @@ process_and_output_buffer(void *drcontext, bool skip_size_cap)
             memset(redzone, -1, buf_ptr - redzone);
         }
     }
-    BUF_PTR(data->seg_base) = data->buf_base + buf_hdr_slots_size;
+    BUF_PTR(data->seg_base) = data->buf_base;
+    ptr_int_t window = -1;
+    if (has_tracing_windows()) {
+        window = tracing_window.load(std::memory_order_acquire);
+        set_local_window(drcontext, window);
+    }
+    BUF_PTR(data->seg_base) += append_unit_header(drcontext, BUF_PTR(data->seg_base),
+                                                  dr_get_thread_id(drcontext), window);
     num_refs_racy += current_num_refs;
     if (op_exit_after_tracing.get_value() > 0 &&
         num_refs_racy > op_exit_after_tracing.get_value()) {
@@ -1038,9 +1065,6 @@ process_and_output_buffer(void *drcontext, bool skip_size_cap)
         }
         dr_mutex_unlock(mutex);
     }
-    if (has_tracing_windows()) {
-        set_local_window(drcontext, tracing_window.load(std::memory_order_acquire));
-    }
 }
 
 void
@@ -1096,6 +1120,9 @@ init_thread_io(void *drcontext)
         } else {
             // set_local_window() called prepend_offline_thread_header().
         }
+        BUF_PTR(data->seg_base) +=
+            append_unit_header(drcontext, BUF_PTR(data->seg_base),
+                               dr_get_thread_id(drcontext), get_local_window(data));
     } else {
         /* pass pid and tid to the simulator to register current thread */
         char buf[MAXIMUM_PATH];
@@ -1106,8 +1133,10 @@ init_thread_io(void *drcontext)
         write_trace_data(drcontext, (byte *)buf, proc_info, get_local_window(data));
 
         /* put buf_base to TLS plus header slots as starting buf_ptr */
-        data->init_header_size = buf_hdr_slots_size;
-        BUF_PTR(data->seg_base) = data->buf_base + buf_hdr_slots_size;
+        data->init_header_size =
+            append_unit_header(drcontext, data->buf_base, dr_get_thread_id(drcontext),
+                               get_local_window(data));
+        BUF_PTR(data->seg_base) = data->buf_base + data->init_header_size;
     }
 }
 

clients/drcachesim/tracer/tracer.cpp

@@ -113,6 +113,8 @@ size_t trace_buf_size;
 size_t redzone_size;
 size_t max_buf_size;
 
+std::atomic<uint64> attached_timestamp;
+
 static drvector_t scratch_reserve_vec;
 
 /* per bb user data during instrumentation */
@@ -413,6 +415,7 @@ event_post_attach()
     DR_ASSERT(attached_midway);
     if (!align_attach_detach_endpoints())
         return;
+    attached_timestamp.store(instru_t::get_timestamp(), std::memory_order_release);
     if (op_trace_after_instrs.get_value() != 0) {
         NOTIFY(1, "Switching to counting mode after attach\n");
         tracing_mode.store(BBDUP_MODE_COUNT, std::memory_order_release);
@@ -427,6 +430,12 @@ event_pre_detach()
 {
     if (align_attach_detach_endpoints()) {
         NOTIFY(1, "Switching to no-tracing mode during detach\n");
+        // Keep all final thread output at the detach timestamp.
+        // With timestamps added at buffer start instead of output we generally do not
+        // add new timestamps during detach, but for a window being closed and the
+        // thread exit in the new window or similar cases it can happen, so we avoid any
+        // possible post-detach timestamp by freezing.
+        instru->set_frozen_timestamp(instru_t::get_timestamp());
         tracing_mode.store(BBDUP_MODE_NOP, std::memory_order_release);
     }
 }

clients/drcachesim/tracer/tracer.h

@@ -153,6 +153,7 @@ is_first_nonlabel(void *drcontext, instr_t *instr);
 extern std::atomic<ptr_int_t> tracing_mode;
 extern std::atomic<ptr_int_t> tracing_window;
 extern bool attached_midway;
+extern std::atomic<uint64> attached_timestamp;
 
 /* We have multiple modes.  While just 2 results in a more efficient dispatch,
  * the power of extra modes justifies the extra overhead.