Skip to content

Commit 2e3c900

Browse files
derekbrueningderekbruening
authored
i#7725: Correct slight negative times in drmemtraces (#7726)
Adds correction of a negative time of 1us, which we observe coming from Linux kernel timestamps. Adds a stat to track the count of such corrections. Adds a unit test. Tested on a larger trace with a real negative timestamp. Before: ``` 6034640 4065585: W0.T3500618 <marker: timestamp 13408459038349822> 6034641 4065585: W0.T3500618 <marker: W0.T3500618 on core 4194> 6034642 4065585: W0.T3500618 <marker: timestamp 13408459038349821> 6034643 4065585: W0.T3500618 <marker: W0.T3500618 on core 4194> ``` After: ``` 6034640 4065585: W0.T3500618 <marker: timestamp 13408459038349822> 6034641 4065585: W0.T3500618 <marker: W0.T3500618 on core 4194> 6034642 4065585: W0.T3500618 <marker: timestamp 13408459038349822> 6034643 4065585: W0.T3500618 <marker: W0.T3500618 on core 4194> ``` Fixes #7725
1 parent d2cf4f1 commit 2e3c900

3 files changed

Lines changed: 156 additions & 1 deletion

File tree

‎clients/drcachesim/tests/raw2trace_unit_tests.cpp‎

Lines changed: 127 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3877,6 +3877,131 @@ test_syscall_injection(void *drcontext)
38773877
check_entry(entries, idx, TRACE_TYPE_THREAD_EXIT, -1) &&
38783878
check_entry(entries, idx, TRACE_TYPE_FOOTER, -1));
38793879
}
3880+
bool
3881+
test_negative_timestamps(void *drcontext)
3882+
{
3883+
std::cerr << "\n===============\nTesting negative timestamps\n";
3884+
{
3885+
// Test timestamp handling thresholds.
3886+
instrlist_t *ilist = instrlist_create(drcontext);
3887+
constexpr uint64_t TIME_A = 100;
3888+
constexpr uint64_t TIME_B = 110;
3889+
constexpr uint64_t TIME_C = 108; // Negative but beyond threshold.
3890+
constexpr uint64_t TIME_D = 111;
3891+
constexpr uint64_t TIME_E = 110; // Negative and under threshold.
3892+
3893+
std::vector<offline_entry_t> raw;
3894+
raw.push_back(make_header());
3895+
raw.push_back(make_tid());
3896+
raw.push_back(make_pid());
3897+
raw.push_back(make_line_size());
3898+
raw.push_back(make_timestamp(TIME_A));
3899+
raw.push_back(make_timestamp(TIME_B));
3900+
raw.push_back(make_timestamp(TIME_C));
3901+
raw.push_back(make_timestamp(TIME_D));
3902+
raw.push_back(make_timestamp(TIME_E));
3903+
raw.push_back(make_exit());
3904+
3905+
std::vector<uint64_t> stats;
3906+
std::vector<trace_entry_t> entries;
3907+
if (!run_raw2trace(drcontext, raw, ilist, entries, &stats))
3908+
return false;
3909+
int idx = 0;
3910+
if (!(stats[RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED] == 1 &&
3911+
check_entry(entries, idx, TRACE_TYPE_HEADER, -1) &&
3912+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_VERSION) &&
3913+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FILETYPE) &&
3914+
check_entry(entries, idx, TRACE_TYPE_THREAD, -1) &&
3915+
check_entry(entries, idx, TRACE_TYPE_PID, -1) &&
3916+
check_entry(entries, idx, TRACE_TYPE_MARKER,
3917+
TRACE_MARKER_TYPE_CACHE_LINE_SIZE) &&
3918+
check_entry(entries, idx, TRACE_TYPE_MARKER,
3919+
TRACE_MARKER_TYPE_CHUNK_INSTR_COUNT) &&
3920+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3921+
TIME_A) &&
3922+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3923+
TIME_B) &&
3924+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3925+
// Remains negative.
3926+
TIME_C) &&
3927+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3928+
TIME_D) &&
3929+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3930+
// Corrected.
3931+
TIME_D) &&
3932+
check_entry(entries, idx, TRACE_TYPE_THREAD_EXIT, -1) &&
3933+
check_entry(entries, idx, TRACE_TYPE_FOOTER, -1)))
3934+
return false;
3935+
}
3936+
{
3937+
// Test timestamp handling with blocks of instrs.
3938+
instrlist_t *ilist = instrlist_create(drcontext);
3939+
instr_t *nop = XINST_CREATE_nop(drcontext);
3940+
instr_t *move =
3941+
XINST_CREATE_move(drcontext, opnd_create_reg(REG1), opnd_create_reg(REG2));
3942+
instrlist_append(ilist, nop);
3943+
instrlist_append(ilist, move);
3944+
size_t offs_nop = 0;
3945+
size_t offs_move = offs_nop + instr_length(drcontext, nop);
3946+
3947+
constexpr uint64_t TIME_A = 100;
3948+
constexpr uint64_t TIME_B = 110;
3949+
constexpr uint64_t TIME_C = 109; // Negative, under threshold.
3950+
constexpr uint64_t TIME_D = 111;
3951+
3952+
std::vector<offline_entry_t> raw;
3953+
raw.push_back(make_header());
3954+
raw.push_back(make_tid());
3955+
raw.push_back(make_pid());
3956+
raw.push_back(make_line_size());
3957+
raw.push_back(make_timestamp(TIME_A));
3958+
raw.push_back(make_core());
3959+
raw.push_back(make_block(offs_move, /*instr_count=*/1));
3960+
raw.push_back(make_timestamp(TIME_B));
3961+
raw.push_back(make_core());
3962+
raw.push_back(make_block(offs_move, /*instr_count=*/1));
3963+
raw.push_back(make_timestamp(TIME_C));
3964+
raw.push_back(make_core());
3965+
raw.push_back(make_timestamp(TIME_D));
3966+
raw.push_back(make_core());
3967+
raw.push_back(make_exit());
3968+
3969+
std::vector<uint64_t> stats;
3970+
std::vector<trace_entry_t> entries;
3971+
if (!run_raw2trace(drcontext, raw, ilist, entries, &stats))
3972+
return false;
3973+
int idx = 0;
3974+
return (
3975+
stats[RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED] == 1 &&
3976+
check_entry(entries, idx, TRACE_TYPE_HEADER, -1) &&
3977+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_VERSION) &&
3978+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FILETYPE) &&
3979+
check_entry(entries, idx, TRACE_TYPE_THREAD, -1) &&
3980+
check_entry(entries, idx, TRACE_TYPE_PID, -1) &&
3981+
check_entry(entries, idx, TRACE_TYPE_MARKER,
3982+
TRACE_MARKER_TYPE_CACHE_LINE_SIZE) &&
3983+
check_entry(entries, idx, TRACE_TYPE_MARKER,
3984+
TRACE_MARKER_TYPE_CHUNK_INSTR_COUNT) &&
3985+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3986+
TIME_A) &&
3987+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) &&
3988+
check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) &&
3989+
check_entry(entries, idx, TRACE_TYPE_INSTR, -1) &&
3990+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3991+
TIME_B) &&
3992+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) &&
3993+
check_entry(entries, idx, TRACE_TYPE_INSTR, -1) &&
3994+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3995+
// Ensure corrected from C to B:
3996+
TIME_B) &&
3997+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) &&
3998+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP,
3999+
TIME_D) &&
4000+
check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) &&
4001+
check_entry(entries, idx, TRACE_TYPE_THREAD_EXIT, -1) &&
4002+
check_entry(entries, idx, TRACE_TYPE_FOOTER, -1));
4003+
}
4004+
}
38804005

38814006
int
38824007
test_main(int argc, const char *argv[])
@@ -3900,7 +4025,8 @@ test_main(int argc, const char *argv[])
39004025
!test_branch_decoration(drcontext) ||
39014026
!test_stats_timestamp_instr_count(drcontext) ||
39024027
!test_is_maybe_blocking_syscall(drcontext) || !test_ifiltered(drcontext) ||
3903-
!test_asynchronous_signal(drcontext) || !test_syscall_injection(drcontext))
4028+
!test_asynchronous_signal(drcontext) || !test_syscall_injection(drcontext) ||
4029+
!test_negative_timestamps(drcontext))
39044030
return 1;
39054031
return 0;
39064032
}

‎clients/drcachesim/tracer/raw2trace.cpp‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -496,6 +496,25 @@ raw2trace_t::process_marker(raw2trace_thread_data_t *tdata,
496496
uint64 stamp = static_cast<uint64>(marker_val);
497497
VPRINT(2, "Thread %u timestamp 0x" ZHEX64_FORMAT_STRING "\n",
498498
static_cast<uint>(tdata->tid), stamp);
499+
if (stamp < tdata->last_timestamp_) {
500+
// We see time values out of the Linux kernel go backward.
501+
// If we see at most 1us difference we assume it's innocuous
502+
// and we correct it, to avoid invariant problems later.
503+
// If a subclass overrides process_marker() and acts before us, they'll
504+
// see the old one, but the difference is minimal and if it really matters
505+
// they'll have to arrange to run after our code.
506+
constexpr int64 NEGATIVE_TIME_CORRECT_THREHSOLD_US = 1;
507+
if (tdata->last_timestamp_ - stamp <= NEGATIVE_TIME_CORRECT_THREHSOLD_US) {
508+
stamp = tdata->last_timestamp_;
509+
marker_val = static_cast<uintptr_t>(stamp);
510+
accumulate_to_statistic(tdata, RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED,
511+
1);
512+
VPRINT(2,
513+
"Thread %u negative time corrected: using timestamp "
514+
"0x" ZHEX64_FORMAT_STRING "\n",
515+
static_cast<uint>(tdata->tid), stamp);
516+
}
517+
}
499518
accumulate_to_statistic(tdata, RAW2TRACE_STAT_EARLIEST_TRACE_TIMESTAMP, stamp);
500519
accumulate_to_statistic(tdata, RAW2TRACE_STAT_LATEST_TRACE_TIMESTAMP, stamp);
501520
tdata->last_timestamp_ = stamp;
@@ -1297,6 +1316,7 @@ raw2trace_t::do_conversion()
12971316
syscall_traces_conversion_empty_ +=
12981317
thread_data_[i]->syscall_traces_conversion_empty;
12991318
syscall_traces_injected_ += thread_data_[i]->syscall_traces_injected;
1319+
negative_times_corrected_ += thread_data_[i]->negative_times_corrected;
13001320
}
13011321
} else {
13021322
// The files can be converted concurrently.
@@ -1329,6 +1349,7 @@ raw2trace_t::do_conversion()
13291349
tdata->syscall_traces_non_fatal_decoding_error_count;
13301350
syscall_traces_conversion_empty_ += tdata->syscall_traces_conversion_empty;
13311351
syscall_traces_injected_ += tdata->syscall_traces_injected;
1352+
negative_times_corrected_ += tdata->negative_times_corrected;
13321353
}
13331354
}
13341355
error = aggregate_and_write_schedule_files();
@@ -3653,6 +3674,9 @@ raw2trace_t::accumulate_to_statistic(raw2trace_thread_data_t *tdata,
36533674
case RAW2TRACE_STAT_SYSCALL_TRACES_INJECTED:
36543675
tdata->syscall_traces_injected += value;
36553676
break;
3677+
case RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED:
3678+
tdata->negative_times_corrected += value;
3679+
break;
36563680
case RAW2TRACE_STAT_MAX:
36573681
default: DR_ASSERT(false);
36583682
}
@@ -3679,6 +3703,7 @@ raw2trace_t::get_statistic(raw2trace_statistic_t stat)
36793703
case RAW2TRACE_STAT_SYSCALL_TRACES_CONVERSION_EMPTY:
36803704
return syscall_traces_conversion_empty_;
36813705
case RAW2TRACE_STAT_SYSCALL_TRACES_INJECTED: return syscall_traces_injected_;
3706+
case RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED: return negative_times_corrected_;
36823707
case RAW2TRACE_STAT_MAX:
36833708
default: DR_ASSERT(false); return 0;
36843709
}

‎clients/drcachesim/tracer/raw2trace.h‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -124,6 +124,8 @@ typedef enum {
124124
// was recorded.
125125
RAW2TRACE_STAT_SYSCALL_TRACES_CONVERSION_EMPTY,
126126
RAW2TRACE_STAT_SYSCALL_TRACES_INJECTED,
127+
// Count of negative times that were corrected.
128+
RAW2TRACE_STAT_NEGATIVE_TIMES_CORRECTED,
127129
// We add a MAX member so that we can iterate over all stats in unit tests.
128130
RAW2TRACE_STAT_MAX,
129131
} raw2trace_statistic_t;
@@ -729,6 +731,7 @@ class raw2trace_t {
729731
uint64 syscall_traces_non_fatal_decoding_error_count = 0;
730732
uint64 syscall_traces_conversion_empty = 0;
731733
uint64 syscall_traces_injected = 0;
734+
uint64 negative_times_corrected = 0;
732735

733736
uint64 cur_chunk_instr_count = 0;
734737
uint64 cur_chunk_ref_count = 0;
@@ -1006,6 +1009,7 @@ class raw2trace_t {
10061009
uint64 syscall_traces_non_fatal_decoding_error_count_ = 0;
10071010
uint64 syscall_traces_conversion_empty_ = 0;
10081011
uint64 syscall_traces_injected_ = 0;
1012+
uint64 negative_times_corrected_ = 0;
10091013

10101014
std::unique_ptr<module_mapper_t> module_mapper_;
10111015

0 commit comments

Comments
 (0)