diff --git a/clients/drcachesim/reader/reader.cpp b/clients/drcachesim/reader/reader.cpp index 93489f6c631..78bb35ecb55 100644 --- a/clients/drcachesim/reader/reader.cpp +++ b/clients/drcachesim/reader/reader.cpp @@ -347,7 +347,9 @@ reader_t::process_input_entry() if (first_timestamp_ == 0) first_timestamp_ = last_timestamp_; } - } else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_VERSION) + } else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_CPU_ID) + last_cpuid_ = cur_ref_.marker.marker_value; + else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_VERSION) version_ = cur_ref_.marker.marker_value; else if (cur_ref_.marker.marker_type == TRACE_MARKER_TYPE_FILETYPE) { filetype_ = cur_ref_.marker.marker_value; @@ -464,6 +466,11 @@ reader_t::skip_instructions_with_timestamp(uint64_t stop_instruction_count) timestamp.addr = static_cast(last_timestamp_); } trace_entry_t cpu = {}; + if (last_cpuid_ != 0) { + cpu.type = TRACE_TYPE_MARKER; + cpu.size = TRACE_MARKER_TYPE_CPU_ID; + cpu.addr = static_cast(last_cpuid_); + } trace_entry_t next_instr = {}; bool prev_was_record_ord = false; bool found_real_timestamp = false; diff --git a/clients/drcachesim/reader/reader.h b/clients/drcachesim/reader/reader.h index a10f614d848..21febd1fe75 100644 --- a/clients/drcachesim/reader/reader.h +++ b/clients/drcachesim/reader/reader.h @@ -254,6 +254,7 @@ class reader_t : public std::iterator, uint64_t last_timestamp_ = 0; uint64_t first_timestamp_ = 0; trace_entry_t *input_entry_ = nullptr; + uint64_t last_cpuid_ = 0; // Remember top-level headers for the memtrace_stream_t interface. uint64_t version_ = 0; uint64_t filetype_ = 0; diff --git a/clients/drcachesim/scheduler/scheduler.cpp b/clients/drcachesim/scheduler/scheduler.cpp index fc90a723ac9..73ae84bd76b 100644 --- a/clients/drcachesim/scheduler/scheduler.cpp +++ b/clients/drcachesim/scheduler/scheduler.cpp @@ -264,6 +264,15 @@ scheduler_tmpl_t::record_type_is_marker(memref_t record, return true; } +template <> +bool +scheduler_tmpl_t::record_type_is_non_marker_header(memref_t record) +{ + // Non-marker trace_entry_t headers turn into markers or are + // hidden, so there are none in a memref_t stream. + return false; +} + template <> bool scheduler_tmpl_t::record_type_is_timestamp(memref_t record, @@ -438,6 +447,15 @@ scheduler_tmpl_t::record_type_is_marker( return true; } +template <> +bool +scheduler_tmpl_t::record_type_is_non_marker_header( + trace_entry_t record) +{ + return record.type == TRACE_TYPE_HEADER || record.type == TRACE_TYPE_THREAD || + record.type == TRACE_TYPE_PID; +} + template <> bool scheduler_tmpl_t::record_type_is_instr_boundary( @@ -1643,15 +1661,46 @@ scheduler_tmpl_t::read_switch_sequences() template bool scheduler_tmpl_t::process_next_initial_record( - input_info_t &input, RecordType record, bool found_filetype, bool found_timestamp) + input_info_t &input, RecordType record, bool &found_filetype, bool &found_timestamp) { - // TODO i#6822: Always look ahead until the first instruction, looking - // for threads that start out with an exit from an UNSCHEDULE or DIRECT - // syscall so we can have them start out unscheduled: though we can't - // easily know whether there was a timeout unless we read way ahead past - // signal handlers until the syscall exits to look for -ETIMEDOUT. - // Should we have raw2trace look for that? - return !(found_filetype && found_timestamp); + // We want to identify threads that should start out unscheduled as + // we attached in the middle of an _UNSCHEDULE system call. + // That marker *before* any instruction indicates the initial + // exit from such a syscall (the markers anywhere else are added on + // entry to a syscall, after the syscall instruction fetch record). + trace_marker_type_t marker_type; + uintptr_t marker_value; + if (record_type_is_invalid(record)) // Sentinel on first call. + return true; // Keep reading. + if (record_type_is_non_marker_header(record)) + return true; // Keep reading. + if (!record_type_is_marker(record, marker_type, marker_value)) { + VPRINT(this, 3, "Stopping initial readahead at non-marker\n"); + return false; // Stop reading. + } + uintptr_t timestamp; + if (marker_type == TRACE_MARKER_TYPE_FILETYPE) { + found_filetype = true; + VPRINT(this, 2, "Input %d filetype %zu\n", input.index, marker_value); + } else if (record_type_is_timestamp(record, timestamp)) { + if (!found_timestamp) { + // next_timestamp must be the first timestamp, even when we read ahead. + input.next_timestamp = timestamp; + found_timestamp = true; + } else { + // Stop at a 2nd timestamp to avoid interval count issues. + VPRINT(this, 3, "Stopping initial readahead at 2nd timestamp\n"); + return false; + } + } else if (marker_type == TRACE_MARKER_TYPE_SYSCALL_UNSCHEDULE) { + if (options_.honor_direct_switches) { + input.unscheduled = true; + // Ignore this marker during regular processing. + input.skip_next_unscheduled = true; + } + return false; // Stop reading. + } + return true; // Keep reading. } template @@ -1679,16 +1728,6 @@ scheduler_tmpl_t::get_initial_input_content( // the non-consuming queue loop vs the consuming and queue-pushback // reader loop. for (const auto &record : input.queue) { - trace_marker_type_t marker_type; - uintptr_t marker_value; - if (record_type_is_marker(record, marker_type, marker_value) && - marker_type == TRACE_MARKER_TYPE_FILETYPE) { - found_filetype = true; - VPRINT(this, 2, "Input %zu filetype %zu from queue\n", i, - marker_value); - } - if (record_type_is_timestamp(record, input.next_timestamp)) - found_timestamp = true; if (!process_next_initial_record(input, record, found_filetype, found_timestamp)) break; @@ -1705,15 +1744,11 @@ scheduler_tmpl_t::get_initial_input_content( } while (*input.reader != *input.reader_end) { RecordType record = **input.reader; + if (record_type_is_instr(record)) { + ++input.instrs_pre_read; + } trace_marker_type_t marker_type; uintptr_t marker_value; - if (record_type_is_marker(record, marker_type, marker_value) && - marker_type == TRACE_MARKER_TYPE_FILETYPE) { - found_filetype = true; - VPRINT(this, 2, "Input %zu filetype %zu\n", i, marker_value); - } - if (record_type_is_timestamp(record, input.next_timestamp)) - found_timestamp = true; if (!process_next_initial_record(input, record, found_filetype, found_timestamp)) break; @@ -1941,7 +1976,7 @@ scheduler_tmpl_t::get_input_record_ordinal( if (index < 0) return 0; uint64_t ord = inputs_[index].reader->get_record_ordinal(); - if (inputs_[index].reader->get_instruction_ordinal() == 0) { + if (get_instr_ordinal(inputs_[index]) == 0) { // Account for get_initial_input_content() readahead for filetype/timestamp. // If this gets any more complex, the scheduler stream should track its // own counts for every input and just ignore the input stream's tracking. @@ -1950,6 +1985,17 @@ scheduler_tmpl_t::get_input_record_ordinal( return ord; } +template +uint64_t +scheduler_tmpl_t::get_instr_ordinal(input_info_t &input) +{ + uint64_t reader_cur = input.reader->get_instruction_ordinal(); + assert(reader_cur >= static_cast(input.instrs_pre_read)); + VPRINT(this, 5, "get_instr_ordinal: %" PRId64 " - %d\n", reader_cur, + input.instrs_pre_read); + return reader_cur - input.instrs_pre_read; +} + template uint64_t scheduler_tmpl_t::get_input_first_timestamp( @@ -1961,7 +2007,7 @@ scheduler_tmpl_t::get_input_first_timestamp( if (index < 0) return 0; uint64_t res = inputs_[index].reader->get_first_timestamp(); - if (inputs_[index].reader->get_instruction_ordinal() == 0 && + if (get_instr_ordinal(inputs_[index]) == 0 && (!inputs_[index].queue.empty() || inputs_[index].cur_from_queue)) { // Account for get_initial_input_content() readahead for filetype/timestamp. res = 0; @@ -1980,7 +2026,7 @@ scheduler_tmpl_t::get_input_last_timestamp( if (index < 0) return 0; uint64_t res = inputs_[index].reader->get_last_timestamp(); - if (inputs_[index].reader->get_instruction_ordinal() == 0 && + if (get_instr_ordinal(inputs_[index]) == 0 && (!inputs_[index].queue.empty() || inputs_[index].cur_from_queue)) { // Account for get_initial_input_content() readahead for filetype/timestamp. res = 0; @@ -1993,7 +2039,8 @@ typename scheduler_tmpl_t::stream_status_t scheduler_tmpl_t::advance_region_of_interest( output_ordinal_t output, RecordType &record, input_info_t &input) { - uint64_t cur_instr = input.reader->get_instruction_ordinal(); + uint64_t cur_instr = get_instr_ordinal(input); + uint64_t cur_reader_instr = input.reader->get_instruction_ordinal(); assert(input.cur_region >= 0 && input.cur_region < static_cast(input.regions_of_interest.size())); auto &cur_range = input.regions_of_interest[input.cur_region]; @@ -2047,8 +2094,11 @@ scheduler_tmpl_t::advance_region_of_interest( if (input.in_cur_region && cur_instr >= cur_range.start_instruction - 1) return sched_type_t::STATUS_OK; - VPRINT(this, 2, "skipping from %" PRIu64 " to %" PRIu64 " instrs for ROI\n", - cur_instr, cur_range.start_instruction); + VPRINT(this, 2, + "skipping from %" PRIu64 " to %" PRIu64 " instrs (%" PRIu64 + " in reader) for ROI\n", + cur_instr, cur_range.start_instruction, + cur_range.start_instruction - cur_reader_instr - 1); if (options_.schedule_record_ostream != nullptr) { sched_type_t::stream_status_t status = close_schedule_segment(output, input); if (status != sched_type_t::STATUS_OK) @@ -2062,7 +2112,13 @@ scheduler_tmpl_t::advance_region_of_interest( if (status != sched_type_t::STATUS_OK) return status; } - return skip_instructions(output, input, cur_range.start_instruction - cur_instr - 1); + if (cur_range.start_instruction < cur_reader_instr) { + // We do not support skipping without skipping over the pre-read: we would + // need to extract from the queue. + return sched_type_t::STATUS_INVALID; + } + return skip_instructions(output, input, + cur_range.start_instruction - cur_reader_instr - 1); } template @@ -2101,6 +2157,13 @@ scheduler_tmpl_t::skip_instructions(output_ordinal_t out !record_type_is_encoding(input.queue.front()))); clear_input_queue(input); input.reader->skip_instructions(skip_amount); + VPRINT(this, 3, "skip_instructions: input=%d amount=%" PRIu64 "\n", input.index, + skip_amount); + if (input.instrs_pre_read > 0) { + // We do not support skipping without skipping over the pre-read: we would + // need to extract from the queue. + input.instrs_pre_read = 0; + } if (*input.reader == *input.reader_end) { mark_input_eof(input); // Raise error because the input region is out of bounds, unless the max @@ -2186,9 +2249,6 @@ scheduler_tmpl_t::record_schedule_segment( outputs_[output].record.emplace_back(type, input, start_instruction, stop_instruction, timestamp); // The stop is typically updated later in close_schedule_segment(). - if (type == schedule_record_t::DEFAULT) { - inputs_[input].recorded_in_schedule = true; - } return sched_type_t::STATUS_OK; } @@ -2217,7 +2277,7 @@ scheduler_tmpl_t::close_schedule_segment(output_ordinal_ outputs_[output].record.back().timestamp); return sched_type_t::STATUS_OK; } - uint64_t instr_ord = input.reader->get_instruction_ordinal(); + uint64_t instr_ord = get_instr_ordinal(input); if (input.at_eof || *input.reader == *input.reader_end) { // The end is exclusive, so use the max int value. instr_ord = std::numeric_limits::max(); @@ -2499,16 +2559,7 @@ scheduler_tmpl_t::set_cur_input(output_ordinal_t output, inputs_[input].prev_time_in_quantum = outputs_[output].cur_time; if (options_.schedule_record_ostream != nullptr) { - uint64_t instr_ord = inputs_[input].reader->get_instruction_ordinal(); - if (!inputs_[input].recorded_in_schedule && instr_ord == 1) { - // Due to differing reader->init() vs initial set_cur_input() orderings - // we can have an initial value of 1 for non-initial input streams - // with few markers; we reset to 0 for such cases. - VPRINT(this, 3, - "set_cur_input: adjusting instr_ord from 1 to 0 for input=%d\n", - input); - instr_ord = 0; - } + uint64_t instr_ord = get_instr_ordinal(inputs_[input]); VPRINT(this, 3, "set_cur_input: recording input=%d start=%" PRId64 "\n", input, instr_ord); sched_type_t::stream_status_t status = @@ -2544,20 +2595,18 @@ scheduler_tmpl_t::pick_next_input_as_previously( VPRINT(this, 5, "pick_next_input_as_previously[%d]: next replay segment in=%d (@%" PRId64 ") type=%d start=%" PRId64 " end=%" PRId64 "\n", - output, index, inputs_[index].reader->get_instruction_ordinal(), segment.type, + output, index, get_instr_ordinal(inputs_[index]), segment.type, segment.value.start_instruction, segment.stop_instruction); { std::lock_guard lock(*inputs_[index].lock); - if (inputs_[index].reader->get_instruction_ordinal() > - segment.value.start_instruction) { + if (get_instr_ordinal(inputs_[index]) > segment.value.start_instruction) { VPRINT(this, 1, "WARNING: next_record[%d]: input %d wants instr #%" PRId64 " but it is already at #%" PRId64 "\n", output, index, segment.value.start_instruction, - inputs_[index].reader->get_instruction_ordinal()); + get_instr_ordinal(inputs_[index])); } - if (inputs_[index].reader->get_instruction_ordinal() < - segment.value.start_instruction && + if (get_instr_ordinal(inputs_[index]) < segment.value.start_instruction && // Don't wait for an ROI that starts at the beginning. segment.value.start_instruction > 1 && // The output may have begun in the wait state. @@ -2628,14 +2677,14 @@ scheduler_tmpl_t::pick_next_input_as_previously( return sched_type_t::STATUS_SKIPPED; } else if (segment.type == schedule_record_t::SKIP) { std::lock_guard lock(*inputs_[index].lock); - uint64_t cur_instr = inputs_[index].reader->get_instruction_ordinal(); + uint64_t cur_reader_instr = inputs_[index].reader->get_instruction_ordinal(); VPRINT(this, 2, "next_record[%d]: skipping from %" PRId64 " to %" PRId64 " in %d for schedule\n", - output, cur_instr, segment.stop_instruction, index); - auto status = - skip_instructions(output, inputs_[index], - segment.stop_instruction - cur_instr - 1 /*exclusive*/); + output, cur_reader_instr, segment.stop_instruction, index); + auto status = skip_instructions(output, inputs_[index], + segment.stop_instruction - cur_reader_instr - + 1 /*exclusive*/); // Increment the region to get window id markers with ordinals. inputs_[index].cur_region++; if (status != sched_type_t::STATUS_SKIPPED) @@ -2702,8 +2751,7 @@ scheduler_tmpl_t::pick_next_input(output_ordinal_t outpu : 2, "next_record[%d]: replay segment in=%d (@%" PRId64 ") type=%d start=%" PRId64 " end=%" PRId64 "\n", - output, input, - inputs_[input].reader->get_instruction_ordinal(), + output, input, get_instr_ordinal(inputs_[input]), segment.type, segment.value.start_instruction, segment.stop_instruction); } @@ -3134,7 +3182,9 @@ scheduler_tmpl_t::next_record(output_ordinal_t output, } VPRINT(this, 5, "next_record[%d]: candidate record from %d (@%" PRId64 "): ", output, - input->index, input->reader->get_instruction_ordinal()); + input->index, get_instr_ordinal(*input)); + if (input->instrs_pre_read > 0 && record_type_is_instr(record)) + --input->instrs_pre_read; VDO(this, 5, print_record(record);); bool need_new_input = false; bool preempt = false; @@ -3170,7 +3220,7 @@ scheduler_tmpl_t::next_record(output_ordinal_t output, // (as just mentioned, it is easier to have a seemingly-redundant entry // to get into the trace reading loop and then do something like a skip // from the start rather than adding logic into the setup code). - if (input->reader->get_instruction_ordinal() >= stop && + if (get_instr_ordinal(*input) >= stop && (!input->cur_from_queue || (start == 0 && stop == 0))) { VPRINT(this, 5, "next_record[%d]: need new input: at end of segment in=%d " diff --git a/clients/drcachesim/scheduler/scheduler.h b/clients/drcachesim/scheduler/scheduler.h index d92a7f8eeb4..82bd489a361 100644 --- a/clients/drcachesim/scheduler/scheduler.h +++ b/clients/drcachesim/scheduler/scheduler.h @@ -1251,7 +1251,7 @@ template class scheduler_tmpl_t { bool at_eof = false; uintptr_t next_timestamp = 0; uint64_t instrs_in_quantum = 0; - bool recorded_in_schedule = false; + int instrs_pre_read = 0; // This is a per-workload value, stored in each input for convenience. uint64_t base_timestamp = 0; // This equals 'options_.deps == DEPENDENCY_TIMESTAMPS', stored here for @@ -1464,7 +1464,7 @@ template class scheduler_tmpl_t { // the two bool parameters are what the return value should be based on. virtual bool process_next_initial_record(input_info_t &input, RecordType record, - bool found_filetype, bool found_timestamp); + bool &found_filetype, bool &found_timestamp); // Opens up all the readers for each file in 'path' which may be a directory. // Returns a map of the thread id of each file to its index in inputs_. @@ -1612,6 +1612,11 @@ template class scheduler_tmpl_t { bool record_type_is_marker(RecordType record, trace_marker_type_t &type, uintptr_t &value); + // Returns false for memref_t; for trace_entry_t returns true for the _HEADER, + // _THREAD, and _PID record types. + bool + record_type_is_non_marker_header(RecordType record); + // If the given record is a timestamp, returns true and its fields. bool record_type_is_timestamp(RecordType record, uintptr_t &value); @@ -1691,6 +1696,11 @@ template class scheduler_tmpl_t { uint64_t get_input_record_ordinal(output_ordinal_t output); + // Returns the input instruction ordinal taking into account queued records. + // The caller must hold the input's lock. + uint64_t + get_instr_ordinal(input_info_t &input); + // Returns the first timestamp for the current input stream interface for the // 'output_ordinal'-th output stream. uint64_t diff --git a/clients/drcachesim/tests/scheduler_unit_tests.cpp b/clients/drcachesim/tests/scheduler_unit_tests.cpp index 554715e42e4..056e34d7652 100644 --- a/clients/drcachesim/tests/scheduler_unit_tests.cpp +++ b/clients/drcachesim/tests/scheduler_unit_tests.cpp @@ -3512,10 +3512,11 @@ test_replay_as_traced_from_file(const char *testdir) static const char *const SCHED_STRING = "Core #0: 1257602 \nCore #1: 1257600 \n" "Core #2: 1257599 => 1257604 @ <366987,87875,13331862029895453> " - // The ordinal is really 1 ("<1,0,0>") but with the scheduler's readahead - // it becomes 2; easier to just check for that as trying to avoid readahead - // causes other problems (i#xxxx). - "(<366986,87875,13331862029895453> => <2,0,0>) \n" + // The ordinal is really 1 ("<1,0,0>") but with the scheduler's readahead we have + // more records and a timestamp; easier to just check for that as trying to avoid + // readahead causes other problems. Maybe the scheduler should have mediator + // getters for the record and timestamp that hide the readahead. + "(<366986,87875,13331862029895453> => <6,0,13331862029900572>) \n" "Core #3: 1257596 \nCore #4: 1257603 \nCore #5: 1257601 \nCore #6: 1257598 \n"; static constexpr int NUM_OUTPUTS = 7; // Matches the actual trace's core footprint. scheduler_t scheduler; @@ -4423,6 +4424,123 @@ test_unscheduled_fallback() } } +static void +test_unscheduled_initially() +{ + std::cerr << "\n----------------\nTesting initially-unscheduled threads\n"; + static constexpr int NUM_OUTPUTS = 1; + static constexpr int BLOCK_LATENCY = 100; + static constexpr double BLOCK_SCALE = 1. / (BLOCK_LATENCY); + static constexpr uint64_t BLOCK_TIME_MAX = 500; + static constexpr memref_tid_t TID_BASE = 100; + static constexpr memref_tid_t TID_A = TID_BASE + 0; + static constexpr memref_tid_t TID_B = TID_BASE + 1; + std::vector refs_A = { + make_thread(TID_A), + make_pid(1), + make_version(TRACE_ENTRY_VERSION), + // A has the earliest timestamp and would start. + make_timestamp(1001), + make_marker(TRACE_MARKER_TYPE_CPU_ID, 0), + // A starts out unscheduled though. + make_marker(TRACE_MARKER_TYPE_SYSCALL_UNSCHEDULE, 0), + make_timestamp(4202), + // B makes us scheduled again. + make_instr(/*pc=*/102), + make_exit(TID_A), + }; + std::vector refs_B = { + make_thread(TID_B), + make_pid(1), + make_version(TRACE_ENTRY_VERSION), + // B runs 2nd by timestamp. + make_timestamp(3001), + make_marker(TRACE_MARKER_TYPE_CPU_ID, 0), + make_instr(/*pc=*/200), + make_timestamp(3002), + make_marker(TRACE_MARKER_TYPE_CPU_ID, 0), + // B makes a long-latency blocking syscall, testing whether + // A is really unscheduled. + make_marker(TRACE_MARKER_TYPE_SYSCALL, 999), + make_marker(TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 0), + make_timestamp(7002), + make_instr(/*pc=*/201), + // B makes A no longer unscheduled. + make_marker(TRACE_MARKER_TYPE_SYSCALL, 999), + make_marker(TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 0), + make_marker(TRACE_MARKER_TYPE_SYSCALL_SCHEDULE, TID_A), + make_timestamp(7021), + make_instr(/*pc=*/202), + make_exit(TID_B), + }; + { + // Test the defaults with direct switches enabled. + std::vector readers; + readers.emplace_back(std::unique_ptr(new mock_reader_t(refs_A)), + std::unique_ptr(new mock_reader_t()), TID_A); + readers.emplace_back(std::unique_ptr(new mock_reader_t(refs_B)), + std::unique_ptr(new mock_reader_t()), TID_B); + // We have an idle period while B is blocked and A unscheduled. + static const char *const CORE0_SCHED_STRING = + "...B.....________________________________________B....B......A."; + + std::vector sched_inputs; + sched_inputs.emplace_back(std::move(readers)); + scheduler_t::scheduler_options_t sched_ops(scheduler_t::MAP_TO_ANY_OUTPUT, + scheduler_t::DEPENDENCY_TIMESTAMPS, + scheduler_t::SCHEDULER_DEFAULTS, + /*verbosity=*/3); + sched_ops.quantum_unit = scheduler_t::QUANTUM_TIME; + sched_ops.blocking_switch_threshold = BLOCK_LATENCY; + sched_ops.block_time_scale = BLOCK_SCALE; + sched_ops.block_time_max = BLOCK_TIME_MAX; + scheduler_t scheduler; + if (scheduler.init(sched_inputs, NUM_OUTPUTS, std::move(sched_ops)) != + scheduler_t::STATUS_SUCCESS) + assert(false); + std::vector sched_as_string = + run_lockstep_simulation(scheduler, NUM_OUTPUTS, TID_BASE, /*send_time=*/true); + for (int i = 0; i < NUM_OUTPUTS; i++) { + std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n"; + } + assert(sched_as_string[0] == CORE0_SCHED_STRING); + } + { + // Test disabling direct switches. + std::vector readers; + readers.emplace_back(std::unique_ptr(new mock_reader_t(refs_A)), + std::unique_ptr(new mock_reader_t()), TID_A); + readers.emplace_back(std::unique_ptr(new mock_reader_t(refs_B)), + std::unique_ptr(new mock_reader_t()), TID_B); + // A runs first as it being unscheduled is ignored. + static const char *const CORE0_SCHED_STRING = + ".....A....B.....________________________________________B....B."; + + std::vector sched_inputs; + sched_inputs.emplace_back(std::move(readers)); + scheduler_t::scheduler_options_t sched_ops(scheduler_t::MAP_TO_ANY_OUTPUT, + scheduler_t::DEPENDENCY_TIMESTAMPS, + scheduler_t::SCHEDULER_DEFAULTS, + /*verbosity=*/3); + // We use our mock's time==instruction count for a deterministic result. + sched_ops.quantum_unit = scheduler_t::QUANTUM_TIME; + sched_ops.blocking_switch_threshold = BLOCK_LATENCY; + sched_ops.block_time_scale = BLOCK_SCALE; + sched_ops.block_time_max = BLOCK_TIME_MAX; + sched_ops.honor_direct_switches = false; + scheduler_t scheduler; + if (scheduler.init(sched_inputs, NUM_OUTPUTS, std::move(sched_ops)) != + scheduler_t::STATUS_SUCCESS) + assert(false); + std::vector sched_as_string = + run_lockstep_simulation(scheduler, NUM_OUTPUTS, TID_BASE, /*send_time=*/true); + for (int i = 0; i < NUM_OUTPUTS; i++) { + std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n"; + } + assert(sched_as_string[0] == CORE0_SCHED_STRING); + } +} + static void test_kernel_switch_sequences() { @@ -4935,6 +5053,7 @@ test_main(int argc, const char *argv[]) test_direct_switch(); test_unscheduled(); test_unscheduled_fallback(); + test_unscheduled_initially(); test_kernel_switch_sequences(); test_random_schedule(); test_record_scheduler(); diff --git a/clients/drcachesim/tracer/raw2trace.cpp b/clients/drcachesim/tracer/raw2trace.cpp index 9386f080465..d553088f376 100644 --- a/clients/drcachesim/tracer/raw2trace.cpp +++ b/clients/drcachesim/tracer/raw2trace.cpp @@ -748,9 +748,7 @@ raw2trace_t::process_offline_entry(raw2trace_thread_data_t *tdata, return false; trace_marker_type_t marker_type = static_cast(in_entry->extended.valueB); - buf += trace_metadata_writer_t::write_marker(buf, marker_type, marker_val); - if (!process_marker_additionally(tdata, marker_type, marker_val, buf, - flush_decode_cache)) + if (!process_marker(tdata, marker_type, marker_val, buf, flush_decode_cache)) return false; // If there is currently a delayed branch that has not been emitted yet, // delay most markers since intra-block markers can cause issues with @@ -836,11 +834,21 @@ raw2trace_t::process_offline_entry(raw2trace_thread_data_t *tdata, } bool -raw2trace_t::process_marker_additionally(raw2trace_thread_data_t *tdata, - trace_marker_type_t marker_type, - uintptr_t marker_val, byte *&buf, - DR_PARAM_OUT bool *flush_decode_cache) -{ +raw2trace_t::process_marker(raw2trace_thread_data_t *tdata, + trace_marker_type_t marker_type, uintptr_t marker_val, + byte *&buf, DR_PARAM_OUT bool *flush_decode_cache) +{ + if (marker_type == TRACE_MARKER_TYPE_TIMESTAMP) { + uint64 stamp = static_cast(marker_val); + VPRINT(2, "Thread %u timestamp 0x" ZHEX64_FORMAT_STRING "\n", + static_cast(tdata->tid), stamp); + accumulate_to_statistic(tdata, RAW2TRACE_STAT_EARLIEST_TRACE_TIMESTAMP, stamp); + accumulate_to_statistic(tdata, RAW2TRACE_STAT_LATEST_TRACE_TIMESTAMP, stamp); + tdata->last_timestamp_ = stamp; + buf += trace_metadata_writer_t::write_timestamp(buf, marker_val); + return true; + } + buf += trace_metadata_writer_t::write_marker(buf, marker_type, marker_val); if (marker_type == TRACE_MARKER_TYPE_KERNEL_EVENT) { log(4, "Signal/exception between bbs\n"); // An rseq side exit may next hit a signal which is then the @@ -1293,16 +1301,17 @@ raw2trace_t::process_next_thread_buffer(raw2trace_thread_data_t *tdata, // when it calls get_next_entry() on its own. offline_entry_t entry = *in_entry; if (entry.timestamp.type == OFFLINE_TYPE_TIMESTAMP) { - VPRINT(2, "Thread %u timestamp 0x" ZHEX64_FORMAT_STRING "\n", - (uint)tdata->tid, (uint64)entry.timestamp.usec); - accumulate_to_statistic(tdata, RAW2TRACE_STAT_EARLIEST_TRACE_TIMESTAMP, - static_cast(entry.timestamp.usec)); - accumulate_to_statistic(tdata, RAW2TRACE_STAT_LATEST_TRACE_TIMESTAMP, - static_cast(entry.timestamp.usec)); - byte *buf = buf_base + - trace_metadata_writer_t::write_timestamp(buf_base, - (uintptr_t)entry.timestamp.usec); - tdata->last_timestamp_ = entry.timestamp.usec; + // Give subclasses a chance for further action on a timestamp by + // putting our processing as thought it were a marker at the raw level. + bool flush_decode_cache = false; + byte *buf = buf_base; + uintptr_t value = static_cast(entry.timestamp.usec); + if (!process_marker(tdata, TRACE_MARKER_TYPE_TIMESTAMP, value, buf, + &flush_decode_cache)) { + return false; + } + if (flush_decode_cache) + decode_cache_[tdata->worker].clear(); if ((uint)(buf - buf_base) >= WRITE_BUFFER_SIZE) { tdata->error = "Too many entries"; return false; diff --git a/clients/drcachesim/tracer/raw2trace.h b/clients/drcachesim/tracer/raw2trace.h index 01cca6465f0..f5522636706 100644 --- a/clients/drcachesim/tracer/raw2trace.h +++ b/clients/drcachesim/tracer/raw2trace.h @@ -1101,14 +1101,14 @@ class raw2trace_t { DR_PARAM_OUT bool *flush_decode_cache); /** - * Performs any additional actions for the marker "marker_type" with value - * "marker_val", beyond writing out a marker record. New records can be written to - * "buf". Returns whether successful. + * Performs processing actions for the marker "marker_type" with value + * "marker_val", including writing out a marker record. Further records can also + * be written to "buf". Returns whether successful. */ virtual bool - process_marker_additionally(raw2trace_thread_data_t *tdata, - trace_marker_type_t marker_type, uintptr_t marker_val, - byte *&buf, DR_PARAM_OUT bool *flush_decode_cache); + process_marker(raw2trace_thread_data_t *tdata, trace_marker_type_t marker_type, + uintptr_t marker_val, byte *&buf, + DR_PARAM_OUT bool *flush_decode_cache); /** * Read the header of a thread, by calling get_next_entry() successively to * populate the header values. The timestamp field is populated only