i#3995 irregular window tracing: last window bug fix #7448

edeiana · 2025-04-09T07:28:10Z

When a workload executed more than DELAY_FOREVER_THRESHOLD
(= 1024^3) instructions after the last window specified in
-trace_instr_intervals_file, the tracing of an unwanted, infinite "trace"
window triggered.

This happened because the last "no trace" window that we create
(not the user), was set to DELAY_FOREVER_THRESHOLD instead
of the larger value UINT64_MAX, which we assume is a large enough
value to stop tracing for the remaining of the execution of the traced
program. This last window exists to stop the tracing after the last,
user-defined window set in -trace_instr_intervals_file (reminder:
if the user wants to trace the end of the execution, the last window
in the file has to be large enough to cover the end of the workload
execution).

Tested manually, as a new binary that executes at least
DELAY_FOREVER_THRESHOLD instructions takes way more than
90 seconds to run a tool like basic_counts, which we normally use
to count windows (by looking at its output).

The reason code_api|tool.drcachesim.irregular-windows-simple
passed is that the test binary traced (simple_app) executes
~100k instructions, which is way less than
DELAY_FOREVER_THRESHOLD instructions, so the last "no trace"
window of DELAY_FOREVER_THRESHOLD was large enough to
not trigger a new, infinite "trace" window.

Adds a check for user-defined instruction intervals with a
duration of 0. They are meaningless, so we ignore them and
print a NOTIFY message letting the user know.

Adds a NOTIFY message when user-defined instruction intervals
overlap (in which case, they are merged).

Issue #3995

When a workload executed more than `DELAY_FOREVER_THRESHOLD` (= 1024^3) instructions after the last window specified in `-trace_instr_intervals_file`, the tracing of a new, infinite "trace" window triggered. This happened because the last "no trace" window that we create (not the user), was set to `DELAY_FOREVER_THRESHOLD` instead of `0`. This last window exists to stop the tracing after the last, user-defined window set in `-trace_instr_intervals_file` (reminder: if the user wants to trace the end of the execution, the last window in the file has to be large enough to cover the end of the workload execution). Although a bit counter-intuitive, a "no trace" window of `0` (in terms of instructions), actually means: don't start a new tracing window. Tested manually, as a new binary that executes at least `DELAY_FOREVER_THRESHOLD` instructions takes way more than 90 seconds to run a tool like `basic_counts`, which we normally use to count windows (by looking at its output). The reason `code_api|tool.drcachesim.irregular-windows-simple` passed is that the test binary traced (`simple_app`) executes way less than DELAY_FOREVER_THRESHOLD instructions (~100k instructions), so the last "no trace" window was large enough to not trigger a new, infinite "trace" window. Issue #3995

abhinav92003 · 2025-04-10T23:19:07Z

Apologies, I missed this before. Reviewing it now.

abhinav92003

I was a bit confused by some existing windows related logic. Would help to add more comments in code by the window-related functions.

abhinav92003 · 2025-04-10T23:24:24Z

clients/drcachesim/tracer/instr_counter.cpp

@@ -550,9 +550,9 @@ compute_irregular_trace_windows(std::vector<instr_interval_t> &instr_intervals)
    // must have a duration long enough to cover the end of the program.
    irregular_window_ptr =
        (irregular_window_t *)dr_global_alloc(sizeof(irregular_window_t));


What about other uses of DELAY_FOREVER_THRESHOLD? I see instr_count_threshold() still returns that when current_no_trace_for_instrs == 0 (which IIUC will be true after the last window with this PR's change).

My understanding is that instr_count_threshold() is used to differentiate between counting modes.
If it returns > DELAY_EXACT_THRESHOLD (like when current_no_trace_for_instrs == 0, which causes it to return DELAY_FOREVER_THRESHOLD), then the tracer adds to the global instruction count instr_count every DELAY_COUNTDOWN_UNIT.
Otherwise, when instr_count_threshold() returns a small "no_trace" window (like in the case of a "proper", user-defined window), then the tracer adds directly to the global instruction count.

However, what actually blocks the creation of the unwanted window is has_instr_count_threshold_to_enable_tracing(), which returns false when current_no_trace_for_instrs == 0.
Hence we return here: https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L190, before instr_count_threshold() or the creation of a new tracing window below.

if it returns > DELAY_EXACT_THRESHOLD (like when current_no_trace_for_instrs == 0, which causes it to return DELAY_FOREVER_THRESHOLD),

I didn't understand this statement. In your example does it return DELAY_EXACT_THRESHOLD or >DELAY_EXACT_THRESHOLD?

Even if other logic prevents its use, it seems weird to leave DELAY_FOREVER_THRESHOLD in there: it sounds like it still signifies "trace forever" for some cases, which I thought we don't want anymore.

I didn't understand this statement. In your example does it return DELAY_EXACT_THRESHOLD or >DELAY_EXACT_THRESHOLD?

The previous behavior (which caused the bug), would have instr_count_threshold() return DELAY_FOREVER_THRESHOLD (which is > DELAY_EXACT_THRESHOLD) for the last "no trace" window.
So, we'd enter the if statement at https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L196 and not start a tracing window (like we expect) only until the program executed at least DELAY_FOREVER_THRESHOLD instructions, which is not that much, it's "only" 1024^3 (~1 billion instructions).
So, despite the name DELAY_FOREVER_THRESHOLD, we wouldn't delay tracing forever, we would delay only for ~1 billion instructions and then start tracing again.
I got confused by the name as well, but DELAY_FOREVER_THRESHOLD should have never been used as a value for a "no trace" window in the first place.
Looking at the comments of DELAY_EXACT_THRESHOLD and DELAY_FOREVER_THRESHOLD, these are used for counting modes: local vs global (https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L77).

Even if other logic prevents its use, it seems weird to leave DELAY_FOREVER_THRESHOLD in there: it sounds like it still signifies "trace forever" for some cases, which I thought we don't want anymore.

Is the suggestion to change the name of this constant because misleading?

I got confused by the name as well, but DELAY_FOREVER_THRESHOLD should have never been used as a value for a "no trace" window in the first place.
Looking at the comments of DELAY_EXACT_THRESHOLD and DELAY_FOREVER_THRESHOLD, these are used for counting modes: local vs global (https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L77).
Is the suggestion to change the name of this constant because misleading?

Indeed the name is confusing. Renaming would help.

abhinav92003 · 2025-04-10T23:25:22Z

clients/drcachesim/tracer/instr_counter.cpp

-    irregular_window_ptr->no_trace_for_instrs = DELAY_FOREVER_THRESHOLD;
+    // This results in has_instr_count_threshold_to_enable_tracing() returning 0, which
+    // in turns makes hit_instr_count_threshold() return without creating a new window.
+    irregular_window_ptr->no_trace_for_instrs = 0;


Would it be any simpler to use UINT64_MAX? Or would that make instrumentation more difficult as loading that into a register takes more instructions?

We could, that's definitely a large enough value.
I don't think loading UINT64_MAX into a register would take more instructions (in general).
Do you mean that part of the instrumentation the tracer adds involves adding instructions to load the value of a "no_trace" window into a register and that might be more instructions than what we would have for smaller values? (I am not sure about this, but it would be DR dependent, so "fixable").

My view is: it's nice to have a value that indicates an infinite "no_trace" window (like 0 is today), rather than a very large value like UINT64_MAX.
However, I do agree that 0 is a bit misleading and can be interpreted in the opposite way as: the "no_trace" window is null, start a new "trace" window immediately.
Also, in the future, we might want to use the window tracing mechanism to shard long traces, so in that case we would like to have a null "no_trace" window to avoid gaps in between.
Maybe we can revisit this when (or if) we decide to use window tracing as additional sharding method?

See instrlist_insert_mov_immed_ptrsz which may use a different number of instructions on aarch64 depending on the size of the imm.

However, I do agree that 0 is a bit misleading and can be interpreted in the opposite way as: the "no_trace" window is null, start a new "trace" window immediately.

I agree that it is misleading. Indeed even today, the very first window may have a start value of zero (signifying immediate start of tracing).

See instrlist_insert_mov_immed_ptrsz which may use a different number of instructions on aarch64 depending on the size of the imm.

Got it, thanks!

I agree that it is misleading.

Using UINT64_MAX. It's a performance penalty, but it's only for one value, one time (last window). Clarity in the code is more beneficial IMHO.

It's a performance penalty, but it's only for one value, one time (last window). Clarity in the code is more beneficial IMHO.

Oh so that value is not loaded for some repeated inlined comparison in the instrumented block? Ok.

Right, the value loaded in the register comes from instr_count_threshold(), which depends on what window we're at. Only the last no-trace window will have UINT64_MAX. (xref: https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L331).

Note that the user can still purposely make a no-trace window large enough to trigger a more-than-one-instruction move to a register, but there is nothing we can do about that.

clients/drcachesim/tracer/instr_counter.cpp

Add NOTIFY messages about changes in the intervals (merged intervals).

clients/drcachesim/tracer/instr_counter.cpp

abhinav92003 · 2025-04-14T20:52:46Z

clients/drcachesim/tracer/instr_counter.cpp

-    irregular_window_ptr->no_trace_for_instrs = DELAY_FOREVER_THRESHOLD;
+    // This results in has_instr_count_threshold_to_enable_tracing() returning 0, which
+    // in turns makes hit_instr_count_threshold() return without creating a new window.
+    irregular_window_ptr->no_trace_for_instrs = 0;


See instrlist_insert_mov_immed_ptrsz which may use a different number of instructions on aarch64 depending on the size of the imm.

However, I do agree that 0 is a bit misleading and can be interpreted in the opposite way as: the "no_trace" window is null, start a new "trace" window immediately.

I agree that it is misleading. Indeed even today, the very first window may have a start value of zero (signifying immediate start of tracing).

clients/drcachesim/tracer/instr_counter.cpp

abhinav92003 · 2025-04-14T21:07:48Z

clients/drcachesim/tracer/instr_counter.cpp

@@ -550,9 +550,9 @@ compute_irregular_trace_windows(std::vector<instr_interval_t> &instr_intervals)
    // must have a duration long enough to cover the end of the program.
    irregular_window_ptr =
        (irregular_window_t *)dr_global_alloc(sizeof(irregular_window_t));


if it returns > DELAY_EXACT_THRESHOLD (like when current_no_trace_for_instrs == 0, which causes it to return DELAY_FOREVER_THRESHOLD),

I didn't understand this statement. In your example does it return DELAY_EXACT_THRESHOLD or >DELAY_EXACT_THRESHOLD?

Even if other logic prevents its use, it seems weird to leave DELAY_FOREVER_THRESHOLD in there: it sounds like it still signifies "trace forever" for some cases, which I thought we don't want anymore.

edeiana · 2025-05-02T22:48:01Z

clients/drcachesim/tracer/instr_counter.cpp

+                   "Instruction interval starting at %" PRIu64 " has duration of 0. "
+                   "Removing interval.\n",
+                   start);
+            continue;


The main changes from the last review are:

Using UINT64_MAX instead of 0 for the last "no trace" window we add.

Added a NOTIFY message if the user-defined instruction intervals contain intervals of duration == 0 (we skip it).

Added a NOTIFY message when we merge overlapping intervals.

Please update the PR description.

abhinav92003 · 2025-05-09T16:51:43Z

clients/drcachesim/tracer/instr_counter.cpp

        uint64 end = interval.start + interval.duration;
        instr_interval_t &last_interval = instr_intervals_merged.back();
        uint64 last_end = last_interval.start + last_interval.duration;
        if (interval.start <= last_end) {
            uint64 max_end = last_end > end ? last_end : end;
            last_interval.duration = max_end - last_interval.start;
+            NOTIFY(0,
+                   "Instruction interval starting at %" PRIu64 " has been merged with "


Maybe make this log more concise by denoting intervals as [start, end].

abhinav92003 · 2025-05-09T16:56:07Z

clients/drcachesim/tracer/instr_counter.cpp

+                   "Instruction interval starting at %" PRIu64 " has duration of 0. "
+                   "Removing interval.\n",
+                   start);
+            continue;


Please update the PR description.

abhinav92003 · 2025-05-09T16:58:06Z

clients/drcachesim/tracer/instr_counter.cpp

-    irregular_window_ptr->no_trace_for_instrs = DELAY_FOREVER_THRESHOLD;
+    // This results in has_instr_count_threshold_to_enable_tracing() returning 0, which
+    // in turns makes hit_instr_count_threshold() return without creating a new window.
+    irregular_window_ptr->no_trace_for_instrs = 0;


It's a performance penalty, but it's only for one value, one time (last window). Clarity in the code is more beneficial IMHO.

Oh so that value is not loaded for some repeated inlined comparison in the instrumented block? Ok.

abhinav92003 · 2025-05-09T16:59:33Z

clients/drcachesim/tracer/instr_counter.cpp

@@ -550,9 +550,9 @@ compute_irregular_trace_windows(std::vector<instr_interval_t> &instr_intervals)
    // must have a duration long enough to cover the end of the program.
    irregular_window_ptr =
        (irregular_window_t *)dr_global_alloc(sizeof(irregular_window_t));


I got confused by the name as well, but DELAY_FOREVER_THRESHOLD should have never been used as a value for a "no trace" window in the first place.
Looking at the comments of DELAY_EXACT_THRESHOLD and DELAY_FOREVER_THRESHOLD, these are used for counting modes: local vs global (https://github.com/DynamoRIO/dynamorio/blob/master/clients/drcachesim/tracer/instr_counter.cpp#L77).
Is the suggestion to change the name of this constant because misleading?

Indeed the name is confusing. Renaming would help.

abhinav92003 · 2025-05-09T17:07:40Z

clients/drcachesim/tracer/instr_counter.cpp

@@ -41,6 +41,7 @@
 #include <stddef.h>


Before submitting, maybe we should test this on a large app to make sure everything is WAI.

edeiana requested a review from abhinav92003 April 9, 2025 07:29

abhinav92003 reviewed Apr 10, 2025

View reviewed changes

edeiana added 2 commits April 12, 2025 17:37

Add additional check for instr inteval with duration = 0.

8f039e6

Add NOTIFY messages about changes in the intervals (merged intervals).

Add clarifying comment to has_instr_count_threshold_to_enable_tracing().

f6dc8a1

abhinav92003 requested changes Apr 14, 2025

View reviewed changes

edeiana added 4 commits May 2, 2025 10:55

Using UINT64_MAX instead of 0 as no-trace window.

dcec71e

Fixed string formatting.

a8f7b69

Added inttypes.h .

32afadd

Fixed comment.

c4a6928

edeiana commented May 2, 2025

View reviewed changes

edeiana requested a review from abhinav92003 May 2, 2025 22:51

abhinav92003 approved these changes May 9, 2025

View reviewed changes

i#3995 irregular window tracing: last window bug fix #7448

Are you sure you want to change the base?

i#3995 irregular window tracing: last window bug fix #7448

Uh oh!

Conversation

edeiana commented Apr 9, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

abhinav92003 commented Apr 10, 2025

Uh oh!

abhinav92003 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edeiana Apr 12, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edeiana May 2, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edeiana May 2, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edeiana May 2, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

edeiana commented Apr 9, 2025 •

edited

Loading

edeiana Apr 12, 2025 •

edited

Loading

edeiana May 2, 2025 •

edited

Loading

edeiana May 2, 2025 •

edited

Loading

edeiana May 2, 2025 •

edited

Loading