diff --git a/clients/drcachesim/scheduler/scheduler_impl.cpp b/clients/drcachesim/scheduler/scheduler_impl.cpp index 2eaa1d59c62..00c4b564ba1 100644 --- a/clients/drcachesim/scheduler/scheduler_impl.cpp +++ b/clients/drcachesim/scheduler/scheduler_impl.cpp @@ -278,6 +278,13 @@ scheduler_impl_tmpl_t::record_type_is_instr_boundary( return record_type_is_instr(record); } +template <> +bool +scheduler_impl_tmpl_t::record_type_is_thread_exit(memref_t record) +{ + return record.exit.type == TRACE_TYPE_THREAD_EXIT; +} + template <> bool scheduler_impl_tmpl_t::record_type_is_marker( @@ -556,6 +563,14 @@ scheduler_impl_tmpl_t::record_type_is_instr_boun !record_reader_t::record_is_pre_instr(&prev_record); } +template <> +bool +scheduler_impl_tmpl_t::record_type_is_thread_exit( + trace_entry_t record) +{ + return record.type == TRACE_TYPE_THREAD_EXIT; +} + template <> bool scheduler_impl_tmpl_t::record_type_set_marker_value( @@ -1623,6 +1638,10 @@ scheduler_impl_tmpl_t::read_kernel_sequences( error_string_ += sequence_type + " marker values mismatched"; return sched_type_t::STATUS_ERROR_INVALID_PARAMETER; } + if (sequence[sequence_key].empty()) { + error_string_ += sequence_type + " sequence empty"; + return sched_type_t::STATUS_ERROR_INVALID_PARAMETER; + } VPRINT(this, 1, "Read %zu kernel %s records for key %d\n", sequence[sequence_key].size(), sequence_type.c_str(), sequence_key); sequence_key = INVALID_SEQ_KEY; @@ -1791,6 +1810,83 @@ scheduler_impl_tmpl_t::get_initial_input_content( return sched_type_t::STATUS_SUCCESS; } +template +typename scheduler_tmpl_t::stream_status_t +scheduler_impl_tmpl_t::inject_pending_syscall_sequence( + output_ordinal_t output, input_info_t *input, RecordType &record) +{ + assert(!input->in_syscall_injection); + assert(input->to_inject_syscall != input_info_t::INJECT_NONE); + if (!record_type_is_invalid(record)) { + // May be invalid if we're at input eof, in which case we do not need to + // save it. + input->queue.push_front(record); + } + int syscall_num = input->to_inject_syscall; + input->to_inject_syscall = input_info_t::INJECT_NONE; + assert(syscall_sequence_.find(syscall_num) != syscall_sequence_.end()); + stream_status_t res = inject_kernel_sequence(syscall_sequence_[syscall_num], input); + if (res != stream_status_t::STATUS_OK) + return res; + ++outputs_[output] + .stats[memtrace_stream_t::SCHED_STAT_KERNEL_SYSCALL_SEQUENCE_INJECTIONS]; + VPRINT(this, 3, "Inserted %zu syscall records for syscall %d to %d.%d\n", + syscall_sequence_[syscall_num].size(), syscall_num, input->workload, + input->index); + + // Return the first injected record. + assert(!input->queue.empty()); + record = input->queue.front(); + input->queue.pop_front(); + input->cur_from_queue = true; + input->in_syscall_injection = true; + return stream_status_t::STATUS_OK; +} + +template +typename scheduler_tmpl_t::stream_status_t +scheduler_impl_tmpl_t::maybe_inject_pending_syscall_sequence( + output_ordinal_t output, input_info_t *input, RecordType &record) +{ + if (input->to_inject_syscall == input_info_t::INJECT_NONE) + return stream_status_t::STATUS_OK; + + trace_marker_type_t marker_type; + uintptr_t marker_value_unused; + uintptr_t timestamp_unused; + bool is_marker = record_type_is_marker(record, marker_type, marker_value_unused); + bool is_injection_point = false; + if ( + // For syscalls not specified in -record_syscall, which do not have + // the func_id-func_retval markers. + record_type_is_timestamp(record, timestamp_unused) || + // For syscalls that did not have a post-event because the trace ended. + record_type_is_thread_exit(record) || + // For syscalls interrupted by a signal and did not have a post-syscall + // event. + (is_marker && marker_type == TRACE_MARKER_TYPE_KERNEL_EVENT)) { + is_injection_point = true; + } else if (is_marker && marker_type == TRACE_MARKER_TYPE_FUNC_ID) { + if (!input->saw_first_func_id_marker_after_syscall) { + // XXX i#7482: If we allow recording zero args for syscalls in + // -record_syscall, we would need to update this logic. + input->saw_first_func_id_marker_after_syscall = true; + } else { + // For syscalls specified in -record_syscall, for which we inject + // after the func_id-func_arg markers (if any) but before the + // func_id-func_retval markers. + is_injection_point = true; + } + } + if (is_injection_point) { + stream_status_t res = inject_pending_syscall_sequence(output, input, record); + if (res != stream_status_t::STATUS_OK) + return res; + input->saw_first_func_id_marker_after_syscall = false; + } + return stream_status_t::STATUS_OK; +} + template typename scheduler_tmpl_t::stream_status_t scheduler_impl_tmpl_t::inject_kernel_sequence( @@ -1804,8 +1900,7 @@ scheduler_impl_tmpl_t::inject_kernel_sequence( // not affect input stream ordinals. // XXX: These will appear before the top headers of a new thread which is slightly // odd to have regular records with the new tid before the top headers. - if (sequence.empty()) - return stream_status_t::STATUS_EOF; + assert(!sequence.empty()); bool saw_any_instr = false; bool set_branch_target_marker = false; trace_marker_type_t marker_type; @@ -2072,6 +2167,10 @@ scheduler_impl_tmpl_t::get_input_record_ordinal( // own counts for every input and just ignore the input stream's tracking. ord -= inputs_[index].queue.size() + (inputs_[index].cur_from_queue ? 1 : 0); } + if (inputs_[index].in_syscall_injection) { + // We readahead by one record when injecting syscalls. + --ord; + } return ord; } @@ -2732,6 +2831,7 @@ scheduler_impl_tmpl_t::next_record(output_ordinal_t outp input_info_t *&input, uint64_t cur_time) { + record = create_invalid_record(); // We do not enforce a globally increasing time to avoid the synchronization cost; we // do return an error on a time smaller than an input's current start time when we // check for quantum end. @@ -2830,7 +2930,14 @@ scheduler_impl_tmpl_t::next_record(output_ordinal_t outp } else { input->needs_advance = true; } - if (input->at_eof || *input->reader == *input->reader_end) { + bool input_at_eof = input->at_eof || *input->reader == *input->reader_end; + if (input_at_eof && input->to_inject_syscall != input_info_t::INJECT_NONE) { + // The input's at eof but we have a syscall trace yet to be injected. + stream_status_t res = + inject_pending_syscall_sequence(output, input, record); + if (res != stream_status_t::STATUS_OK) + return res; + } else if (input_at_eof) { if (!input->at_eof) { stream_status_t status = mark_input_eof(*input); if (status != sched_type_t::STATUS_OK) @@ -2853,6 +2960,22 @@ scheduler_impl_tmpl_t::next_record(output_ordinal_t outp record = **input->reader; } } + + stream_status_t res = + maybe_inject_pending_syscall_sequence(output, input, record); + if (res != stream_status_t::STATUS_OK) + return res; + + // Check whether all syscall injected records have been passed along + // to the caller. + trace_marker_type_t marker_type; + uintptr_t marker_value_unused; + if (input->in_syscall_injection && + record_type_is_marker(outputs_[output].last_record, marker_type, + marker_value_unused) && + marker_type == TRACE_MARKER_TYPE_SYSCALL_TRACE_END) { + input->in_syscall_injection = false; + } VPRINT(this, 5, "next_record[%d]: candidate record from %d (@%" PRId64 "): ", output, input->index, get_instr_ordinal(*input)); @@ -2868,8 +2991,8 @@ scheduler_impl_tmpl_t::next_record(output_ordinal_t outp bool preempt = false; uint64_t blocked_time = 0; uint64_t prev_time_in_quantum = input->prev_time_in_quantum; - stream_status_t res = check_for_input_switch( - output, record, input, cur_time, need_new_input, preempt, blocked_time); + res = check_for_input_switch(output, record, input, cur_time, need_new_input, + preempt, blocked_time); if (res != sched_type_t::STATUS_OK && res != sched_type_t::STATUS_SKIPPED) return res; if (need_new_input) { @@ -2988,18 +3111,11 @@ scheduler_impl_tmpl_t::finalize_next_record( marker_type == TRACE_MARKER_TYPE_SYSCALL && syscall_sequence_.find(static_cast(marker_value)) != syscall_sequence_.end()) { - int syscall_num = static_cast(marker_value); - stream_status_t res = - inject_kernel_sequence(syscall_sequence_[syscall_num], input); - if (res == stream_status_t::STATUS_OK) { - ++outputs_[output].stats - [memtrace_stream_t::SCHED_STAT_KERNEL_SYSCALL_SEQUENCE_INJECTIONS]; - VPRINT(this, 3, "Inserted %zu syscall records for syscall %d to %d.%d\n", - syscall_sequence_[syscall_num].size(), syscall_num, input->workload, - input->index); - } else if (res != stream_status_t::STATUS_EOF) { - return res; - } + assert(!input->in_syscall_injection); + // The actual injection of the syscall trace happens later at the intended + // point between the syscall function tracing markers. + input->to_inject_syscall = static_cast(marker_value); + input->saw_first_func_id_marker_after_syscall = false; } else if (record_type_is_instr(record, &instr_pc, &instr_size)) { input->last_pc_fallthrough = instr_pc + instr_size; } diff --git a/clients/drcachesim/scheduler/scheduler_impl.h b/clients/drcachesim/scheduler/scheduler_impl.h index a137647ea0e..3429d188a81 100644 --- a/clients/drcachesim/scheduler/scheduler_impl.h +++ b/clients/drcachesim/scheduler/scheduler_impl.h @@ -198,6 +198,8 @@ template class scheduler_impl_tmpl_t std::deque queue; bool cur_from_queue; addr_t last_pc_fallthrough = 0; + // Whether we're in the middle of returning injected syscall records. + bool in_syscall_injection = false; std::set binding; int priority = 0; @@ -262,6 +264,11 @@ template class scheduler_impl_tmpl_t // Causes the next unscheduled entry to abort. bool skip_next_unscheduled = false; uint64_t last_run_time = 0; + int to_inject_syscall = INJECT_NONE; + bool saw_first_func_id_marker_after_syscall = false; + + // Sentinel value for to_inject_syscall. + static constexpr int INJECT_NONE = -1; }; // XXX i#6831: Should this live entirely inside the dynamic subclass? @@ -874,6 +881,9 @@ template class scheduler_impl_tmpl_t bool record_type_is_instr_boundary(RecordType record, RecordType prev_record); + bool + record_type_is_thread_exit(RecordType record); + // Creates the marker we insert between regions of interest. RecordType create_region_separator_marker(memref_tid_t tid, uintptr_t value); @@ -893,9 +903,23 @@ template class scheduler_impl_tmpl_t void update_next_record(output_ordinal_t output, RecordType &record); + // Performs the actual injection of the kernel sequence. stream_status_t inject_kernel_sequence(std::vector &sequence, input_info_t *input); + // Performs the actual injection of a kernel syscall sequence, using + // inject_kernel_sequence as helper. + stream_status_t + inject_pending_syscall_sequence(output_ordinal_t output, input_info_t *input, + RecordType &record); + + // Checks whether we're at a suitable injection point for a yet to be injected + // syscall sequence, and performs the injection using + // inject_pending_syscall_sequence as helper. + stream_status_t + maybe_inject_pending_syscall_sequence(output_ordinal_t output, input_info_t *input, + RecordType &record); + // Actions that must be taken only when we know for sure that the given record // is going to be the next record for some output stream. stream_status_t diff --git a/clients/drcachesim/tests/allasm-repstr-basic-counts.templatex b/clients/drcachesim/tests/allasm-repstr-basic-counts.templatex index 82e836da1d7..c0e5ec96069 100644 --- a/clients/drcachesim/tests/allasm-repstr-basic-counts.templatex +++ b/clients/drcachesim/tests/allasm-repstr-basic-counts.templatex @@ -11,8 +11,8 @@ Adios world! ---- ---- Basic counts tool results: Total counts: - 103 total \(fetched\) instructions - 31 total unique \(fetched\) instructions + 110 total \(fetched\) instructions + 38 total unique \(fetched\) instructions 4 total non-fetched instructions 0 total prefetches 7 total data loads @@ -20,7 +20,7 @@ Total counts: 0 total icache flushes 0 total dcache flushes 1 total threads - 48 total timestamp \+ cpuid markers + 56 total timestamp \+ cpuid markers 0 total idle markers 0 total wait markers 0 total kernel transfer markers @@ -30,20 +30,20 @@ Total counts: 0 total function return value markers 0 total physical address \+ virtual address marker pairs 0 total physical address unavailable markers - 12 total system call number markers + 14 total system call number markers 0 total blocking system call markers 4 total other markers - 107 total encodings + 114 total encodings Thread [0-9]* counts: - 103 \(fetched\) instructions - 31 unique \(fetched\) instructions + 110 \(fetched\) instructions + 38 unique \(fetched\) instructions 4 non-fetched instructions 0 prefetches 7 data loads 5 data stores 0 icache flushes 0 dcache flushes - 48 timestamp \+ cpuid markers + 56 timestamp \+ cpuid markers 0 idle markers 0 wait markers 0 kernel transfer markers @@ -53,7 +53,7 @@ Thread [0-9]* counts: 0 function return value markers 0 physical address \+ virtual address marker pairs 0 physical address unavailable markers - 12 system call number markers + 14 system call number markers 0 blocking system call markers 4 other markers - 107 encodings + 114 encodings diff --git a/clients/drcachesim/tests/allasm_repstr.asm b/clients/drcachesim/tests/allasm_repstr.asm index ff28005a23e..b9e30bd9ba6 100644 --- a/clients/drcachesim/tests/allasm_repstr.asm +++ b/clients/drcachesim/tests/allasm_repstr.asm @@ -1,5 +1,5 @@ /* ********************************************************** - * Copyright (c) 2021-2023 Google, Inc. All rights reserved. + * Copyright (c) 2021-2025 Google, Inc. All rights reserved. * **********************************************************/ /* @@ -53,6 +53,17 @@ _start: cld rep movsb + // Make a getpid syscall, which is a non-blocking one. + mov eax, 39 // SYS_getpid + syscall + + // Make a membarrier syscall, which is a blocking one. + mov rdi, 0 // MEMBARRIER_CMD_QUERY + mov rsi, 0 // flags + mov rdx, 0 // cpuid + mov eax, 324 // SYS_membarrier + syscall + // Test page-spanning accesses. lea rcx, page_str // Somehow the GNU assembler 2.38 is adding the load size (4 here) to diff --git a/clients/drcachesim/tests/burst_syscall_inject.cpp b/clients/drcachesim/tests/burst_syscall_inject.cpp index 532b8abcf45..b87f318e18b 100644 --- a/clients/drcachesim/tests/burst_syscall_inject.cpp +++ b/clients/drcachesim/tests/burst_syscall_inject.cpp @@ -68,13 +68,13 @@ namespace dynamorio { namespace drmemtrace { -#define PC_SYSCALL_GETPID 0xdeadbe00 +#define PC_SYSCALL_MEMBARRIER 0xdeadbe00 #define PC_SYSCALL_GETTID 0x8badf000 #define READ_MEMADDR_GETTID 0xdecafbad #define REP_MOVS_COUNT 1024 #define SYSCALL_INSTR_COUNT 2 -static instr_t *instrs_in_getpid[SYSCALL_INSTR_COUNT]; +static instr_t *instrs_in_membarrier[SYSCALL_INSTR_COUNT]; static instr_t *instrs_in_gettid[SYSCALL_INSTR_COUNT]; #define FATAL_ERROR(msg, ...) \ @@ -84,8 +84,17 @@ static instr_t *instrs_in_gettid[SYSCALL_INSTR_COUNT]; exit(1); \ } while (0) +static int +do_membarrier(void) +{ + // MEMBARRIER_CMD_QUERY is always supported, and returns + // a non-zero result. + return syscall(SYS_membarrier, /*MEMBARRIER_CMD_QUERY*/ 0, + /*flags=*/0, /*cpuid=*/0); +} + static pid_t -gettid(void) +do_gettid(void) { return syscall(SYS_gettid); } @@ -93,8 +102,11 @@ gettid(void) static int do_some_syscalls() { - getpid(); - gettid(); + // Considered as a "maybe blocking" syscall by raw2trace. + do_membarrier(); + // Considered as a regular non-blocking syscall by raw2trace; we also + // specify it in -record_syscall for this test. + do_gettid(); // Make some failing sigaction syscalls, which we record such that // syscall_mix will count the failure codes. @@ -215,31 +227,32 @@ write_system_call_template(void *dr_context) write_header_entries(writer); - // Write the trace template for SYS_getpid. + // Write the trace template for SYS_membarrier. write_trace_entry( writer, - test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYS_getpid)); + test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYS_membarrier)); // Just a random instruction. - instrs_in_getpid[0] = XINST_CREATE_nop(dr_context); - write_instr_entry(dr_context, writer, instrs_in_getpid[0], - reinterpret_cast(PC_SYSCALL_GETPID)); + instrs_in_membarrier[0] = XINST_CREATE_nop(dr_context); + write_instr_entry(dr_context, writer, instrs_in_membarrier[0], + reinterpret_cast(PC_SYSCALL_MEMBARRIER)); constexpr uintptr_t SOME_VAL = 0xf00d; #ifdef X86 - instrs_in_getpid[1] = INSTR_CREATE_sysret(dr_context); + instrs_in_membarrier[1] = INSTR_CREATE_sysret(dr_context); #elif defined(AARCHXX) - instrs_in_getpid[1] = INSTR_CREATE_eret(dr_context); + instrs_in_membarrier[1] = INSTR_CREATE_eret(dr_context); #endif // The value doesn't really matter as it will be replaced during trace injection. write_trace_entry(writer, test_util::make_marker(TRACE_MARKER_TYPE_BRANCH_TARGET, SOME_VAL)); write_instr_entry( - dr_context, writer, instrs_in_getpid[1], - reinterpret_cast(PC_SYSCALL_GETPID + - instr_length(dr_context, instrs_in_getpid[0])), + dr_context, writer, instrs_in_membarrier[1], + reinterpret_cast(PC_SYSCALL_MEMBARRIER + + instr_length(dr_context, instrs_in_membarrier[0])), TRACE_TYPE_INSTR_INDIRECT_JUMP); write_trace_entry( - writer, test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYS_getpid)); + writer, + test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYS_membarrier)); // Write the trace template for SYS_gettid. write_trace_entry( @@ -351,7 +364,10 @@ gather_trace() { std::cerr << "Collecting a trace...\n"; std::string ops = "-stderr_mask 0xc -client_lib ';;-offline -record_syscall " + - std::to_string(SYS_rt_sigaction) + "|4"; + // TODO i#7482: Specifying 0 args for any syscall to -record_syscall crashes. + // We specify 1 arg for gettid just to get around this, which is okay for this + // test as we'd like some func_arg markers. + std::to_string(SYS_rt_sigaction) + "|4&" + std::to_string(SYS_gettid) + "|1"; if (setenv("DYNAMORIO_OPTIONS", ops.c_str(), 1 /*override*/) != 0) std::cerr << "failed to set env var!\n"; dr_app_setup(); @@ -399,15 +415,22 @@ look_for_syscall_trace(void *dr_context, std::string trace_dir) } auto *stream = scheduler.get_stream(0); memref_t memref; - int getpid_instr_found = 0; + int membarrier_instr_found = 0; int gettid_instr_found = 0; - int getpid_instr_len = 0; + int membarrier_instr_len = 0; int gettid_instr_len = 0; - bool found_gettid_read = false; bool have_syscall_trace_type = false; + // Non-sentinel only when we're actually between the syscall_trace_start and + // syscall_trace_end markers. int syscall_trace_num = -1; + // Non-sentinel only when we've seen a syscall marker without any intervening + // instr or any marker except the allowed ones till now. int prev_syscall_num_marker = -1; + // Always holds the last seen syscall number. + int last_syscall = -1; + bool saw_aux_syscall_markers_for_membarrier = false; + bool saw_aux_syscall_markers_for_gettid = false; for (scheduler_t::stream_status_t status = stream->next_record(memref); status != scheduler_t::STATUS_EOF; status = stream->next_record(memref)) { assert(status == scheduler_t::STATUS_OK); @@ -436,7 +459,38 @@ look_for_syscall_trace(void *dr_context, std::string trace_dir) case TRACE_MARKER_TYPE_SYSCALL_TRACE_END: syscall_trace_num = -1; break; case TRACE_MARKER_TYPE_SYSCALL: prev_syscall_num_marker = memref.marker.marker_value; + last_syscall = prev_syscall_num_marker; break; + case TRACE_MARKER_TYPE_FUNC_RETVAL: + if (last_syscall == SYS_gettid && gettid_instr_found == 0) { + std::cerr << "gettid trace not injected before func_retval marker."; + return false; + } else if (last_syscall == SYS_membarrier) { + std::cerr << "Did not expect func_retval marker for membarrier."; + return false; + } + break; + case TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL: + case TRACE_MARKER_TYPE_FUNC_ARG: + if (last_syscall == SYS_gettid) { + if (gettid_instr_found > 0) { + std::cerr << "Found func_arg marker or maybe_blocking marker " + << "after the gettid trace."; + return false; + } + saw_aux_syscall_markers_for_gettid = true; + } else if (last_syscall == SYS_membarrier) { + if (membarrier_instr_found > 0) { + std::cerr << "Found func_arg marker or maybe_blocking marker " + << "after the membarrier trace."; + return false; + } + saw_aux_syscall_markers_for_membarrier = true; + } + case TRACE_MARKER_TYPE_FUNC_ID: + // The above markers are expected to be seen between the syscall + // marker and the injected trace, so we preserve prev_syscall_num_marker. + prev_syscall_num_marker = prev_syscall_num_marker_saved; } continue; } @@ -480,23 +534,24 @@ look_for_syscall_trace(void *dr_context, std::string trace_dir) } } break; - case SYS_getpid: + case SYS_membarrier: if (is_instr) { - assert(getpid_instr_found < SYSCALL_INSTR_COUNT); - if (memref.instr.addr != PC_SYSCALL_GETPID + getpid_instr_len) { + assert(membarrier_instr_found < SYSCALL_INSTR_COUNT); + if (memref.instr.addr != PC_SYSCALL_MEMBARRIER + membarrier_instr_len) { std::cerr << "Found incorrect addr (" << std::hex << memref.instr.addr - << " vs expected " << PC_SYSCALL_GETPID + getpid_instr_len - << std::dec << ") for getpid trace instr.\n"; + << " vs expected " + << PC_SYSCALL_MEMBARRIER + membarrier_instr_len << std::dec + << ") for membarrier trace instr.\n"; return false; } if (!check_instr_same(dr_context, memref, - instrs_in_getpid[getpid_instr_found])) { + instrs_in_membarrier[membarrier_instr_found])) { return false; } - getpid_instr_len += memref.instr.size; - ++getpid_instr_found; + membarrier_instr_len += memref.instr.size; + ++membarrier_instr_found; } else { - std::cerr << "Found unexpected data memref in getpid trace\n"; + std::cerr << "Found unexpected data memref in membarrier trace\n"; return false; } break; @@ -506,10 +561,16 @@ look_for_syscall_trace(void *dr_context, std::string trace_dir) std::cerr << "Trace did not have the expected file type\n"; } else if (gettid_instr_found != SYSCALL_INSTR_COUNT) { std::cerr << "Did not find all instrs in gettid trace\n"; - } else if (getpid_instr_found != SYSCALL_INSTR_COUNT) { - std::cerr << "Did not find all instrs in getpid trace\n"; + } else if (membarrier_instr_found != SYSCALL_INSTR_COUNT) { + std::cerr << "Did not find all instrs in membarrier trace\n"; } else if (!found_gettid_read) { std::cerr << "Did not find read data memref in gettid trace\n"; + } else if (!saw_aux_syscall_markers_for_membarrier) { + std::cerr << "Did not see any auxillary syscall markers for membarrier. " + << "Ensure test is setup properly\n"; + } else if (!saw_aux_syscall_markers_for_gettid) { + std::cerr << "Did not see any auxillary syscall markers for gettid. " + << "Ensure test is setup properly\n"; } else { return true; } @@ -564,7 +625,8 @@ write_system_call_template_with_repstr(void *dr_context) TRACE_TYPE_INSTR_INDIRECT_JUMP); write_trace_entry( - writer, test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYS_getpid)); + writer, + test_util::make_marker(TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYS_membarrier)); write_footer_entries(writer); @@ -650,7 +712,7 @@ test_trace_templates(void *dr_context) /*expected_injected_syscall_count=*/2, ""); bool success = look_for_syscall_trace(dr_context, trace_dir); for (int i = 0; i < SYSCALL_INSTR_COUNT; ++i) { - instr_destroy(dr_context, instrs_in_getpid[i]); + instr_destroy(dr_context, instrs_in_membarrier[i]); instr_destroy(dr_context, instrs_in_gettid[i]); } if (!success) { diff --git a/clients/drcachesim/tests/invariant_checker_test.cpp b/clients/drcachesim/tests/invariant_checker_test.cpp index beb8902a03c..dbc0755570a 100644 --- a/clients/drcachesim/tests/invariant_checker_test.cpp +++ b/clients/drcachesim/tests/invariant_checker_test.cpp @@ -3327,12 +3327,28 @@ check_kernel_syscall_trace(void) { gen_marker(TID_A, TRACE_MARKER_TYPE_VERSION, TRACE_ENTRY_VERSION_BRANCH_INFO), nullptr }, - { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, FILE_TYPE_FULL_SYSCALL_TRACE), + { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, + FILE_TYPE_FULL_SYSCALL_TRACE | + OFFLINE_FILE_TYPE_BLOCKING_SYSCALLS), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_CACHE_LINE_SIZE, 64), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_PAGE_SIZE, 4096), nullptr }, { gen_instr(TID_A), sys }, { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL, 42), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_ARG, 1), nullptr }, + + // These markers may be added based on the syscall's func tracing markers. + // All of them are not present at the same time in a real trace. + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_UNSCHEDULE, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_SCHEDULE, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_ARG_TIMEOUT, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_DIRECT_THREAD_SWITCH, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, 42), nullptr }, { gen_instr(TID_A), move }, { gen_instr(TID_A), load }, @@ -3342,6 +3358,12 @@ check_kernel_syscall_trace(void) { gen_marker(TID_A, TRACE_MARKER_TYPE_BRANCH_TARGET, 0), post_sys }, { gen_instr_type(TRACE_TYPE_INSTR_INDIRECT_JUMP, TID_A), sys_return }, { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_RETVAL, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_FAILED, 42), nullptr }, { gen_instr(TID_A), post_sys }, { gen_exit(TID_A), nullptr } }; @@ -3349,6 +3371,124 @@ check_kernel_syscall_trace(void) if (!run_checker(memrefs, false)) res = false; } + // Syscall trace injected before func_arg marker. + { + std::vector memref_setup = { + { gen_marker(TID_A, TRACE_MARKER_TYPE_VERSION, + TRACE_ENTRY_VERSION_BRANCH_INFO), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, FILE_TYPE_FULL_SYSCALL_TRACE), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_CACHE_LINE_SIZE, 64), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_PAGE_SIZE, 4096), nullptr }, + { gen_instr(TID_A), sys }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL, 42), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, 42), nullptr }, + { gen_instr(TID_A), move }, + { gen_instr(TID_A), load }, + { gen_data(TID_A, /*load=*/true, /*addr=*/0x1234, /*size=*/4), nullptr }, + // add_encodings_to_memrefs removes this from the memref list and adds it + // to memref_t.instr.indirect_branch_target instead for the following instr. + { gen_marker(TID_A, TRACE_MARKER_TYPE_BRANCH_TARGET, 0), post_sys }, + { gen_instr_type(TRACE_TYPE_INSTR_INDIRECT_JUMP, TID_A), sys_return }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_ARG, 1), nullptr }, + { gen_instr(TID_A), post_sys }, + { gen_exit(TID_A), nullptr } + }; + auto memrefs = add_encodings_to_memrefs(ilist, memref_setup, BASE_ADDR); + if (!run_checker(memrefs, true, + { "Found unexpected func_arg or syscall marker after injected " + "syscall trace", + /*tid=*/TID_A, + /*ref_ordinal=*/14, /*last_timestamp=*/0, + /*instrs_since_last_timestamp=*/4 }, + "Failed to detect func_arg marker after injected syscall trace")) + res = false; + } + // Syscall trace injected before syscall_schedule marker. + { + std::vector memref_setup = { + { gen_marker(TID_A, TRACE_MARKER_TYPE_VERSION, + TRACE_ENTRY_VERSION_BRANCH_INFO), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, FILE_TYPE_FULL_SYSCALL_TRACE), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_CACHE_LINE_SIZE, 64), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_PAGE_SIZE, 4096), nullptr }, + { gen_instr(TID_A), sys }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL, 42), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, 42), nullptr }, + { gen_instr(TID_A), move }, + { gen_instr(TID_A), load }, + { gen_data(TID_A, /*load=*/true, /*addr=*/0x1234, /*size=*/4), nullptr }, + // add_encodings_to_memrefs removes this from the memref list and adds it + // to memref_t.instr.indirect_branch_target instead for the following instr. + { gen_marker(TID_A, TRACE_MARKER_TYPE_BRANCH_TARGET, 0), post_sys }, + { gen_instr_type(TRACE_TYPE_INSTR_INDIRECT_JUMP, TID_A), sys_return }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, 42), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_SCHEDULE, 1), nullptr }, + { gen_instr(TID_A), post_sys }, + { gen_exit(TID_A), nullptr } + }; + auto memrefs = add_encodings_to_memrefs(ilist, memref_setup, BASE_ADDR); + if (!run_checker(memrefs, true, + { "Found unexpected func_arg or syscall marker after injected " + "syscall trace", + /*tid=*/TID_A, + /*ref_ordinal=*/13, /*last_timestamp=*/0, + /*instrs_since_last_timestamp=*/4 }, + "Failed to detect func_arg marker after injected syscall trace")) + res = false; + } + // Syscall trace injected after func_retval marker. + { + std::vector memref_setup = { + { gen_marker(TID_A, TRACE_MARKER_TYPE_VERSION, + TRACE_ENTRY_VERSION_BRANCH_INFO), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, FILE_TYPE_FULL_SYSCALL_TRACE), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_CACHE_LINE_SIZE, 64), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_PAGE_SIZE, 4096), nullptr }, + { gen_instr(TID_A), sys }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_ARG, 1), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_RETVAL, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, 42), nullptr }, + { gen_instr(TID_A), move }, + { gen_instr(TID_A), load }, + { gen_data(TID_A, /*load=*/true, /*addr=*/0x1234, /*size=*/4), nullptr }, + // add_encodings_to_memrefs removes this from the memref list and adds it + // to memref_t.instr.indirect_branch_target instead for the following instr. + { gen_marker(TID_A, TRACE_MARKER_TYPE_BRANCH_TARGET, 0), post_sys }, + { gen_instr_type(TRACE_TYPE_INSTR_INDIRECT_JUMP, TID_A), sys_return }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, 42), nullptr }, + { gen_instr(TID_A), post_sys }, + { gen_exit(TID_A), nullptr } + }; + auto memrefs = add_encodings_to_memrefs(ilist, memref_setup, BASE_ADDR); + if (!run_checker(memrefs, true, + { "System call trace found without prior syscall marker or " + "unexpected intervening records", + /*tid=*/TID_A, + /*ref_ordinal=*/11, /*last_timestamp=*/0, + /*instrs_since_last_timestamp=*/1 }, + "Failed to detect func_retval marker before injected trace")) + res = false; + } // Missing indirect branch target at the syscall trace end. { std::vector memref_setup = { @@ -3462,12 +3602,20 @@ check_kernel_syscall_trace(void) { gen_marker(TID_A, TRACE_MARKER_TYPE_VERSION, TRACE_ENTRY_VERSION_BRANCH_INFO), nullptr }, - { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, FILE_TYPE_FULL_SYSCALL_TRACE), + { gen_marker(TID_A, TRACE_MARKER_TYPE_FILETYPE, + FILE_TYPE_FULL_SYSCALL_TRACE | + OFFLINE_FILE_TYPE_BLOCKING_SYSCALLS), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_CACHE_LINE_SIZE, 64), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_PAGE_SIZE, 4096), nullptr }, { gen_instr(TID_A), sys }, { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL, 42), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_ARG, 1), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, 42), nullptr }, { gen_instr(TID_A), move }, { gen_instr(TID_A), load }, @@ -3477,6 +3625,12 @@ check_kernel_syscall_trace(void) { gen_marker(TID_A, TRACE_MARKER_TYPE_BRANCH_TARGET, 0), post_sys }, { gen_instr_type(TRACE_TYPE_INSTR_INDIRECT_JUMP, TID_A), sys_return }, { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, 42), nullptr }, + { gen_marker( + TID_A, TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + 42), + nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_FUNC_RETVAL, 1), nullptr }, + { gen_marker(TID_A, TRACE_MARKER_TYPE_SYSCALL_FAILED, 42), nullptr }, { gen_marker(TID_A, TRACE_MARKER_TYPE_KERNEL_EVENT, 0), post_sys }, { gen_instr(TID_A), move }, { gen_marker(TID_A, TRACE_MARKER_TYPE_KERNEL_XFER, 0), load }, @@ -3915,7 +4069,8 @@ check_kernel_syscall_trace(void) }; auto memrefs = add_encodings_to_memrefs(ilist, memref_setup, BASE_ADDR); if (!run_checker(memrefs, true, - { "System call trace found without prior syscall marker", + { "System call trace found without prior syscall marker or " + "unexpected intervening records", /*tid=*/TID_A, /*ref_ordinal=*/7, /*last_timestamp=*/0, /*instrs_since_last_timestamp=*/1 }, diff --git a/clients/drcachesim/tests/mock_syscall_sequences.x64 b/clients/drcachesim/tests/mock_syscall_sequences.x64 index 4d6b783e67d..35ac5d8f141 100644 Binary files a/clients/drcachesim/tests/mock_syscall_sequences.x64 and b/clients/drcachesim/tests/mock_syscall_sequences.x64 differ diff --git a/clients/drcachesim/tests/offline-allasm-dyn-inject-invariants.templatex b/clients/drcachesim/tests/offline-allasm-dyn-inject-invariants.templatex new file mode 100644 index 00000000000..51b8f96eab9 --- /dev/null +++ b/clients/drcachesim/tests/offline-allasm-dyn-inject-invariants.templatex @@ -0,0 +1,11 @@ +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Trace invariant checks passed diff --git a/clients/drcachesim/tests/offline-allasm-dyn-inject-view.templatex b/clients/drcachesim/tests/offline-allasm-dyn-inject-view.templatex new file mode 100644 index 00000000000..e0d1706c594 --- /dev/null +++ b/clients/drcachesim/tests/offline-allasm-dyn-inject-view.templatex @@ -0,0 +1,67 @@ +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +Adios world! +.* + 34 13: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 35 13: .* + 36 13: .* + 37 13: .* + 37 13: .* + 37 13: .* ifetch 1 byte\(s\) @ 0x00000000deadbe00 90 nop + 37 13: .* ifetch 2 byte\(s\) @ 0x00000000deadbe01 0f 07 sysret \(target .*\) + 37 13: .* + 38 13: .* +.* + 44 18: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 45 18: .* + 46 18: .* + 47 18: .* + 48 18: .* + 48 18: .* + 48 18: .* ifetch 1 byte\(s\) @ 0x00000000deadbe00 90 nop + 48 18: .* ifetch 2 byte\(s\) @ 0x00000000deadbe01 0f 07 sysret \(target .*\) + 48 18: .* + 49 18: .* +.* + 61 27: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 62 27: .* + 63 27: .* + 64 27: .* + 65 27: .* + 66 27: .* + 67 27: .* + 68 27: .* + 69 27: .* + 69 27: .* + 69 27: .* ifetch 1 byte\(s\) @ 0x00000000deadbe00 90 nop + 69 27: .* ifetch 2 byte\(s\) @ 0x00000000deadbe01 0f 07 sysret \(target .*\) + 69 27: .* + 70 27: .* + 71 27: .* + 72 27: .* +.* + 261 107: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 262 107: .* + 263 107: .* + 264 107: .* + 265 107: .* + 266 107: .* + 267 107: .* + 268 107: .* + 269 107: .* + 269 107: .* + 269 107: .* ifetch 1 byte\(s\) @ 0x00000000deadbe00 90 nop + 269 107: .* ifetch 2 byte\(s\) @ 0x00000000deadbe01 0f 07 sysret \(target .*\) + 269 107: .* + 270 107: .* + 271 107: .* + 272 107: .* + 273 107: .* +.* diff --git a/clients/drcachesim/tests/offline-allasm-record-syscall.templatex b/clients/drcachesim/tests/offline-allasm-record-syscall.templatex index face7d3ad32..1f9a374074d 100644 --- a/clients/drcachesim/tests/offline-allasm-record-syscall.templatex +++ b/clients/drcachesim/tests/offline-allasm-record-syscall.templatex @@ -9,26 +9,43 @@ Adios world! Adios world! Adios world! .* - 43 20: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall - 44 20: .* - 45 20: .* - 46 20: .* - 47 20: .* - 48 20: .* - 49 20: .* - 50 20: .* - 51 20: .* - 52 20: .* - 53 20: .* - 54 20: .* + 34 13: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 35 13: .* + 36 13: .* + 37 13: .* + 38 13: .* .* - 246 100: .* - 247 100: .* - 248 100: .* - 249 100: .* - 250 100: .* - 251 100: .* - 252 100: .* - 253 100: .* - 254 100: .* + 44 18: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 45 18: .* + 46 18: .* + 47 18: .* + 48 18: .* + 49 18: .* +.* + 61 27: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 62 27: .* + 63 27: .* + 64 27: .* + 65 27: .* + 66 27: .* + 67 27: .* + 68 27: .* + 69 27: .* + 70 27: .* + 71 27: .* + 72 27: .* +.* + 261 107: .* ifetch 2 byte\(s\) @ 0x.* 0f 05 syscall + 262 107: .* + 263 107: .* + 264 107: .* + 265 107: .* + 266 107: .* + 267 107: .* + 268 107: .* + 269 107: .* + 270 107: .* + 271 107: .* + 272 107: .* + 273 107: .* .* diff --git a/clients/drcachesim/tests/offline-allasm-repstr-basic-counts.templatex b/clients/drcachesim/tests/offline-allasm-repstr-basic-counts.templatex index 79b2495c6a0..a84b246d479 100644 --- a/clients/drcachesim/tests/offline-allasm-repstr-basic-counts.templatex +++ b/clients/drcachesim/tests/offline-allasm-repstr-basic-counts.templatex @@ -10,8 +10,8 @@ Adios world! Adios world! Basic counts tool results: Total counts: - 103 total \(fetched\) instructions - 31 total unique \(fetched\) instructions + 110 total \(fetched\) instructions + 38 total unique \(fetched\) instructions 4 total non-fetched instructions 0 total prefetches 7 total data loads @@ -19,7 +19,7 @@ Total counts: 0 total icache flushes 0 total dcache flushes 1 total threads - 48 total timestamp \+ cpuid markers + 56 total timestamp \+ cpuid markers 0 total idle markers 0 total wait markers 0 total kernel transfer markers @@ -29,20 +29,20 @@ Total counts: 0 total function return value markers 0 total physical address \+ virtual address marker pairs 0 total physical address unavailable markers - 12 total system call number markers - 11 total blocking system call markers + 14 total system call number markers + 12 total blocking system call markers 5 total other markers - 31 total encodings + 38 total encodings Thread [0-9]* counts: - 103 \(fetched\) instructions - 31 unique \(fetched\) instructions + 110 \(fetched\) instructions + 38 unique \(fetched\) instructions 4 non-fetched instructions 0 prefetches 7 data loads 5 data stores 0 icache flushes 0 dcache flushes - 48 timestamp \+ cpuid markers + 56 timestamp \+ cpuid markers 0 idle markers 0 wait markers 0 kernel transfer markers @@ -52,7 +52,7 @@ Thread [0-9]* counts: 0 function return value markers 0 physical address \+ virtual address marker pairs 0 physical address unavailable markers - 12 system call number markers - 11 blocking system call markers + 14 system call number markers + 12 blocking system call markers 5 other markers - 31 encodings + 38 encodings diff --git a/clients/drcachesim/tests/offline-burst_syscall_inject.template b/clients/drcachesim/tests/offline-burst_syscall_inject.template index 3b165fe901b..622b7613bb6 100644 --- a/clients/drcachesim/tests/offline-burst_syscall_inject.template +++ b/clients/drcachesim/tests/offline-burst_syscall_inject.template @@ -20,10 +20,10 @@ Output format: 4 0: W0.T1 5 0: W0.T1 #ifdef X86 - 6 0: W0.T1 + 6 0: W0.T1 7 1: W0.T1 ifetch 1 byte\(s\) @ 0x00000000deadbe00 90 nop 8 2: W0.T1 ifetch 2 byte\(s\) @ 0x00000000deadbe01 0f 07 sysret \(target 0xf00d\) - 9 2: W0.T1 + 9 2: W0.T1 10 2: W0.T1 11 3: W0.T1 ifetch 3 byte\(s\) @ 0x000000008badf000 48 8b 12 mov \(%rdx\), %rdx 12 3: W0.T1 read 8 byte\(s\) @ 0x00000000decafbad by PC 0x000000008badf000 @@ -31,10 +31,10 @@ Output format: 14 4: W0.T1 #else - 6 0: W0.T1 + 6 0: W0.T1 7 1: W0.T1 ifetch 4 byte\(s\) @ 0x00000000deadbe00 d503201f nop 8 2: W0.T1 ifetch 4 byte\(s\) @ 0x00000000deadbe04 d69f03e0 eret \(target 0xf00d\) - 9 2: W0.T1 + 9 2: W0.T1 10 2: W0.T1 11 3: W0.T1 ifetch 4 byte\(s\) @ 0x000000008badf000 f9400084 ldr \(%x4\)\[8byte\] -> %x4 12 3: W0.T1 read 8 byte\(s\) @ 0x00000000decafbad by PC 0x000000008badf000 diff --git a/clients/drcachesim/tests/offline-simple-dyn-inject-invariants.template b/clients/drcachesim/tests/offline-simple-dyn-inject-invariants.template new file mode 100644 index 00000000000..e69de29bb2d diff --git a/clients/drcachesim/tests/offline-windows-asm.templatex b/clients/drcachesim/tests/offline-windows-asm.templatex index ca567c10a08..4de8db38e4f 100644 --- a/clients/drcachesim/tests/offline-windows-asm.templatex +++ b/clients/drcachesim/tests/offline-windows-asm.templatex @@ -1,8 +1,6 @@ Hit delay threshold: enabling tracing. Hit tracing window #0 limit: disabling tracing. -Adios world! Hit retrace threshold: enabling tracing for window #1. -Adios world! Hit tracing window #1 limit: disabling tracing. Adios world! Hit retrace threshold: enabling tracing for window #2. @@ -20,10 +18,14 @@ Adios world! Hit retrace threshold: enabling tracing for window #5. Adios world! Hit tracing window #5 limit: disabling tracing. +Adios world! +Hit retrace threshold: enabling tracing for window #6. +Adios world! +Hit tracing window #6 limit: disabling tracing. Basic counts tool results: Total counts: - 55 total \(fetched\) instructions - 23 total unique \(fetched\) instructions + 57 total \(fetched\) instructions + 25 total unique \(fetched\) instructions 4 total non-fetched instructions 0 total prefetches 7 total data loads @@ -31,7 +33,7 @@ Total counts: 0 total icache flushes 0 total dcache flushes 1 total threads - 36 total timestamp \+ cpuid markers + 42 total timestamp \+ cpuid markers 0 total idle markers 0 total wait markers 0 total kernel transfer markers @@ -41,17 +43,17 @@ Total counts: 0 total function return value markers 0 total physical address \+ virtual address marker pairs 0 total physical address unavailable markers - 6 total system call number markers + 7 total system call number markers 6 total blocking system call markers - 12 total other markers - 23 total encodings -Total windows: 7 + 13 total other markers + 25 total encodings +Total windows: 8 Window #0: - 15 window \(fetched\) instructions - 15 window unique \(fetched\) instructions + 8 window \(fetched\) instructions + 8 window unique \(fetched\) instructions 4 window non-fetched instructions 0 window prefetches - 7 window data loads + 5 window data loads 5 window data stores 0 window icache flushes 0 window dcache flushes @@ -66,10 +68,33 @@ Window #0: 0 window physical address \+ virtual address marker pairs 0 window physical address unavailable markers 1 window system call number markers - 1 window blocking system call markers + 0 window blocking system call markers 6 window other markers - 15 window encodings + 8 window encodings Window #1: + 9 window \(fetched\) instructions + 9 window unique \(fetched\) instructions + 0 window non-fetched instructions + 0 window prefetches + 2 window data loads + 0 window data stores + 0 window icache flushes + 0 window dcache flushes + 6 window timestamp \+ cpuid markers + 0 window idle markers + 0 window wait markers + 0 window kernel transfer markers + 0 window function id markers + 0 window function return address markers + 0 window function argument markers + 0 window function return value markers + 0 window physical address \+ virtual address marker pairs + 0 window physical address unavailable markers + 1 window system call number markers + 1 window blocking system call markers + 1 window other markers + 9 window encodings +Window #2: 8 window \(fetched\) instructions 8 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -92,7 +117,7 @@ Window #1: 1 window blocking system call markers 1 window other markers 3 window encodings -Window #2: +Window #3: 8 window \(fetched\) instructions 8 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -115,7 +140,7 @@ Window #2: 1 window blocking system call markers 1 window other markers 0 window encodings -Window #3: +Window #4: 8 window \(fetched\) instructions 8 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -138,7 +163,7 @@ Window #3: 1 window blocking system call markers 1 window other markers 0 window encodings -Window #4: +Window #5: 8 window \(fetched\) instructions 8 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -161,7 +186,7 @@ Window #4: 1 window blocking system call markers 1 window other markers 0 window encodings -Window #5: +Window #6: 8 window \(fetched\) instructions 8 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -184,7 +209,7 @@ Window #5: 1 window blocking system call markers 1 window other markers 5 window encodings -Window #6: +Window #7: 0 window \(fetched\) instructions 0 window unique \(fetched\) instructions 0 window non-fetched instructions @@ -208,11 +233,11 @@ Window #6: 1 window other markers 0 window encodings Thread [0-9]* counts: - 15 \(fetched\) instructions - 15 unique \(fetched\) instructions + 8 \(fetched\) instructions + 8 unique \(fetched\) instructions 4 non-fetched instructions 0 prefetches - 7 data loads + 5 data loads 5 data stores 0 icache flushes 0 dcache flushes @@ -227,6 +252,6 @@ Thread [0-9]* counts: 0 physical address \+ virtual address marker pairs 0 physical address unavailable markers 1 system call number markers - 1 blocking system call markers + 0 blocking system call markers 6 other markers - 15 encodings + 8 encodings diff --git a/clients/drcachesim/tests/raw2trace_unit_tests.cpp b/clients/drcachesim/tests/raw2trace_unit_tests.cpp index b5f794d8c80..f9c67278a79 100644 --- a/clients/drcachesim/tests/raw2trace_unit_tests.cpp +++ b/clients/drcachesim/tests/raw2trace_unit_tests.cpp @@ -3521,8 +3521,25 @@ test_syscall_injection(void *drcontext) size_t offs_sys = offs_move1 + instr_length(drcontext, move1); size_t offs_move2 = offs_sys + instr_length(drcontext, sys); + // Syscall traces may be injected at different points in the trace: + // A) for syscalls whose args and retval are traced with -record_syscall, the + // trace is injected before the func_id-func_retval markers. + // B) for syscalls that are interrupted by a signal and do not have a post- + // syscall event, the trace is injected just before the kernel_event marker, + // which is also after the func_id-func_arg markers (if any). + // C) for syscalls that are not traced with -record_syscall and are not + // interrupted by a signal, the trace is injected just before the timestamp + // marker after the syscall marker, which is also after the syscall and + // maybe_blocking_syscall marker if any. + // D) if we reach the thread_exit with a pending injection, we inject the trace + // before the thread_exit. + // + // We test each of the above cases below. + // Now we synthesize our raw trace itself, including a valid header sequence. static constexpr int SYSCALL_NUM = 42; // Doesn't really matter. + static constexpr int FUNC_ID_SYSCALL = + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + SYSCALL_NUM; std::vector raw; raw.push_back(make_header()); raw.push_back(make_tid()); @@ -3531,15 +3548,66 @@ test_syscall_injection(void *drcontext) raw.push_back(make_timestamp(1)); raw.push_back(make_core()); raw.push_back(make_block(offs_move1, 1)); + + // ---------- Type (A) ---------- raw.push_back(make_timestamp(2)); raw.push_back(make_core()); raw.push_back(make_block(offs_sys, 1)); + // Entries added by pre-syscall event. raw.push_back(make_timestamp(3)); raw.push_back(make_core()); raw.push_back(make_marker(TRACE_MARKER_TYPE_SYSCALL, SYSCALL_NUM)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_ID, FUNC_ID_SYSCALL)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_ARG, 1)); + // Entries added by post-syscall event. + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_ID, FUNC_ID_SYSCALL)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_RETVAL, 1)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_SYSCALL_FAILED, 0)); raw.push_back(make_timestamp(4)); raw.push_back(make_core()); + // Trace continues after syscall. + raw.push_back(make_block(offs_move2, 1)); + + // ---------- Type (B) ---------- + raw.push_back(make_timestamp(5)); + raw.push_back(make_core()); + raw.push_back(make_block(offs_sys, 1)); + // Entries added by pre-syscall event. + raw.push_back(make_timestamp(6)); + raw.push_back(make_core()); + raw.push_back(make_marker(TRACE_MARKER_TYPE_SYSCALL, SYSCALL_NUM)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_ID, FUNC_ID_SYSCALL)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_FUNC_ARG, 1)); + // Syscall interrupted by signal. + raw.push_back(make_marker(TRACE_MARKER_TYPE_KERNEL_EVENT, offs_sys)); + raw.push_back(make_timestamp(7)); + raw.push_back(make_core()); raw.push_back(make_block(offs_move2, 1)); + raw.push_back(make_marker(TRACE_MARKER_TYPE_KERNEL_XFER, offs_sys)); + + // ---------- Type (C) ---------- + raw.push_back(make_timestamp(8)); + raw.push_back(make_core()); + raw.push_back(make_block(offs_sys, 1)); + // Entries added by pre-syscall event. + raw.push_back(make_timestamp(9)); + raw.push_back(make_core()); + raw.push_back(make_marker(TRACE_MARKER_TYPE_SYSCALL, SYSCALL_NUM)); + // Entries added by post-syscall event. + raw.push_back(make_timestamp(10)); + raw.push_back(make_core()); + // Trace continues after syscall. + raw.push_back(make_block(offs_move2, 1)); + + // ---------- Type (D) ---------- + raw.push_back(make_timestamp(11)); + raw.push_back(make_core()); + raw.push_back(make_block(offs_sys, 1)); + // Entries added by pre-syscall event. + raw.push_back(make_timestamp(12)); + raw.push_back(make_core()); + raw.push_back(make_marker(TRACE_MARKER_TYPE_SYSCALL, SYSCALL_NUM)); + // No post-syscall. raw.push_back(make_exit()); static constexpr memref_tid_t TID_IN_SYSCALL = 1; @@ -3574,8 +3642,8 @@ test_syscall_injection(void *drcontext) return false; int idx = 0; return ( - stats[RAW2TRACE_STAT_SYSCALL_TRACES_INJECTED] == 1 && - stats[RAW2TRACE_STAT_KERNEL_INSTR_COUNT] == 2 && + stats[RAW2TRACE_STAT_SYSCALL_TRACES_INJECTED] == 4 && + stats[RAW2TRACE_STAT_KERNEL_INSTR_COUNT] == 8 && check_entry(entries, idx, TRACE_TYPE_HEADER, -1) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_VERSION) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FILETYPE) && @@ -3589,6 +3657,7 @@ test_syscall_injection(void *drcontext) // The move1 instr. check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && check_entry(entries, idx, TRACE_TYPE_INSTR, -1, offs_move1) && + // ---------- Type (A) ---------- check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 2) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && // The sys instr. @@ -3598,6 +3667,9 @@ test_syscall_injection(void *drcontext) check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, SYSCALL_NUM) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_ID, + FUNC_ID_SYSCALL) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_ARG, 1) && // Injected syscall trace. check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYSCALL_NUM) && @@ -3612,11 +3684,107 @@ test_syscall_injection(void *drcontext) SYSCALL_PC_START + 1) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYSCALL_NUM) && + // Injected syscall trace -- done. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_ID, + FUNC_ID_SYSCALL) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_RETVAL, 1) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_FAILED, + 0) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 4) && check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && // The move2 instr. check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && check_entry(entries, idx, TRACE_TYPE_INSTR, -1, offs_move2) && + + // ---------- Type (B) ---------- + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 5) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + // The sys instr. + check_entry(entries, idx, expected_syscall_instr_type, -1, offs_sys) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 6) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, + SYSCALL_NUM) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_ID, + FUNC_ID_SYSCALL) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_FUNC_ARG, 1) && + // Injected syscall trace. + check_entry(entries, idx, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYSCALL_NUM) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR, -1, SYSCALL_PC_START) && + // Indirect branch at the end of the injected syscall trace that should point to + // the move2 instr. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_BRANCH_TARGET, + offs_move2) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR_INDIRECT_JUMP, -1, + SYSCALL_PC_START + 1) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, + SYSCALL_NUM) && + // Injected syscall trace -- done. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_KERNEL_EVENT, + offs_sys) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 7) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + // The move2 instr. + check_entry(entries, idx, TRACE_TYPE_INSTR, -1, offs_move2) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_KERNEL_XFER, + offs_sys) && + + // ---------- Type (C) ---------- + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 8) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + // The sys instr. + check_entry(entries, idx, expected_syscall_instr_type, -1, offs_sys) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 9) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, + SYSCALL_NUM) && + // Injected syscall trace. + check_entry(entries, idx, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYSCALL_NUM) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR, -1, SYSCALL_PC_START) && + // Indirect branch at the end of the injected syscall trace that should point to + // the move2 instr. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_BRANCH_TARGET, + offs_move2) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR_INDIRECT_JUMP, -1, + SYSCALL_PC_START + 1) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, + SYSCALL_NUM) && + // Injected syscall trace -- done. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 10) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + // The move2 instr. + check_entry(entries, idx, TRACE_TYPE_INSTR, -1, offs_move2) && + + // ---------- Type (D) ---------- + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 11) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + // The sys instr. + check_entry(entries, idx, expected_syscall_instr_type, -1, offs_sys) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, 12) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_CPU_ID) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, + SYSCALL_NUM) && + // Injected syscall trace. + check_entry(entries, idx, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_SYSCALL_TRACE_START, SYSCALL_NUM) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR, -1, SYSCALL_PC_START) && + // Indirect branch at the end of the injected syscall trace that should point to + // the move2 instr. + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_BRANCH_TARGET, + offs_move2) && + check_entry(entries, idx, TRACE_TYPE_ENCODING, -1) && + check_entry(entries, idx, TRACE_TYPE_INSTR_INDIRECT_JUMP, -1, + SYSCALL_PC_START + 1) && + check_entry(entries, idx, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, + SYSCALL_NUM) && + // Injected syscall trace -- done. check_entry(entries, idx, TRACE_TYPE_THREAD_EXIT, -1) && check_entry(entries, idx, TRACE_TYPE_FOOTER, -1)); } diff --git a/clients/drcachesim/tests/scheduler_unit_tests.cpp b/clients/drcachesim/tests/scheduler_unit_tests.cpp index db12b0ae313..02a07605f55 100644 --- a/clients/drcachesim/tests/scheduler_unit_tests.cpp +++ b/clients/drcachesim/tests/scheduler_unit_tests.cpp @@ -6497,17 +6497,22 @@ run_lockstep_simulation_for_kernel_seq(scheduler_t &scheduler, int num_outputs, TRACE_MARKER_TYPE_CONTEXT_SWITCH_START)); assert(outputs[i]->get_record_ordinal() > prev_out_ord[i]); } else if (in_syscall[i]) { + bool is_trace_start = memref.marker.type == TRACE_TYPE_MARKER && + memref.marker.marker_type == TRACE_MARKER_TYPE_SYSCALL_TRACE_START; + bool is_trace_end = memref.marker.type == TRACE_TYPE_MARKER && + memref.marker.marker_type == TRACE_MARKER_TYPE_SYSCALL_TRACE_END; // Test that syscall code is marked synthetic. assert(outputs[i]->is_record_synthetic()); // Test that it's marked as kernel, unless it's the end marker. - assert( - outputs[i]->is_record_kernel() || - (memref.marker.type == TRACE_TYPE_MARKER && - memref.marker.marker_type == TRACE_MARKER_TYPE_SYSCALL_TRACE_END)); + assert(outputs[i]->is_record_kernel() || is_trace_end); // Test that dynamically injected syscall code doesn't count toward // input ordinals, but does toward output ordinals. assert(outputs[i]->get_input_interface()->get_record_ordinal() == - prev_in_ord[i]); + prev_in_ord[i] || + // We readahead by one record to decide when to inject the + // syscall trace, so the input interface record ordinal will + // be advanced by one at trace start. + is_trace_start); assert(outputs[i]->get_record_ordinal() > prev_out_ord[i]); } else assert(!outputs[i]->is_record_synthetic()); @@ -6529,7 +6534,12 @@ run_lockstep_simulation_for_kernel_seq(scheduler_t &scheduler, int num_outputs, else assert(false && "unknown context switch type"); break; - case TRACE_MARKER_TYPE_SYSCALL: sched_as_string[i] += 's'; break; + case TRACE_MARKER_TYPE_FUNC_ID: + case TRACE_MARKER_TYPE_FUNC_ARG: + case TRACE_MARKER_TYPE_FUNC_RETVAL: sched_as_string[i] += 'F'; break; + case TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL: + case TRACE_MARKER_TYPE_SYSCALL_FAILED: sched_as_string[i] += 's'; break; + case TRACE_MARKER_TYPE_SYSCALL: sched_as_string[i] += 'S'; break; case TRACE_MARKER_TYPE_SYSCALL_TRACE_END: in_syscall[i] = false; ANNOTATE_FALLTHROUGH; @@ -6537,6 +6547,8 @@ run_lockstep_simulation_for_kernel_seq(scheduler_t &scheduler, int num_outputs, sched_as_string[i] += '1' + static_cast(memref.marker.marker_value - syscall_base); break; + case TRACE_MARKER_TYPE_KERNEL_EVENT: + case TRACE_MARKER_TYPE_KERNEL_XFER: sched_as_string[i] += 'k'; break; default: sched_as_string[i] += '?'; break; } } @@ -6820,9 +6832,53 @@ test_kernel_syscall_sequences() inputs.push_back(test_util::make_instr( static_cast(42 * tid + instr_idx * 4), TRACE_TYPE_INSTR, /*size=*/4)); + // Every other instr is a syscall. if (instr_idx % 2 == 0) { + // The markers after the syscall instr are supposed to be bracketed + // by timestamp markers. + bool add_post_timestamp = true; + inputs.push_back(test_util::make_timestamp(TIMESTAMP + instr_idx)); inputs.push_back(test_util::make_marker( TRACE_MARKER_TYPE_SYSCALL, SYSCALL_BASE + (instr_idx / 2) % 2)); + // Every other syscall is a blocking syscall. + if (instr_idx % 4 == 0) { + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, /*value=*/0)); + } + if (instr_idx == 0) { + // Assuming the first syscall was specified in -record_syscall, + // so we'll have additional markers. + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_FUNC_ID, + static_cast( + func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + + SYSCALL_BASE)); + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_FUNC_ARG, /*value=*/10)); + // First syscall on first input was interrupted by a signal, + // so no post-syscall event. + if (input_idx == 0) { + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_KERNEL_EVENT, /*value=*/1)); + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_KERNEL_XFER, /*value=*/1)); + add_post_timestamp = false; + } else { + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_FUNC_ID, + static_cast( + func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + + SYSCALL_BASE)); + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_FUNC_RETVAL, /*value=*/1)); + inputs.push_back(test_util::make_marker( + TRACE_MARKER_TYPE_SYSCALL_FAILED, /*value=*/1)); + } + } + if (add_post_timestamp) { + inputs.push_back( + test_util::make_timestamp(TIMESTAMP + instr_idx + 1)); + } } } inputs.push_back(test_util::make_exit(tid)); @@ -6855,17 +6911,17 @@ test_kernel_syscall_sequences() // The instrs in the injected syscall sequence count towards the #instr // quantum, but no context switch happens in the middle of the syscall seq. assert(sched_as_string[0] == - "Avf0is1ii1,Cvf0is1ii1,Aiis2iii2,Ciis2iii2,Aiis1ii1,Ciis1ii1,Aiis2iii2," - "Ciis2iii2,Aiis1ii1,Ciis1ii1"); + "Avf0i0SsFF1ii1kk,Cvf0i0SsFF1ii1FFs0,Aii0S2iii20,Cii0S2iii20," + "Aii0Ss1ii10,Cii0Ss1ii10,Aii0S2iii20,Cii0S2iii20,Aii0Ss1ii10,Cii0Ss1ii10"); assert(sched_as_string[1] == - "Bvf0is1ii1iis2iii2iis1ii1iis2iii2iis1ii1_____________________________" - "___________"); - + "Bvf0i0SsFF1ii1FFs0ii0S2iii20ii0Ss1ii10ii0S2iii20ii0Ss1ii10______________" + "__________________________________________"); // Zoom in and check the first few syscall sequences on the first output record // by record with value checks. int idx = 0; bool res = true; res = res && + // First thread. check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_VERSION) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, @@ -6874,8 +6930,18 @@ test_kernel_syscall_sequences() check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_INSTR) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, SYSCALL_BASE) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 0) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + + SYSCALL_BASE) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_ARG, 10) && // Syscall_1 trace on first thread. check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, @@ -6886,6 +6952,13 @@ test_kernel_syscall_sequences() check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYSCALL_BASE) && + // Signal interruption on first thread. + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_KERNEL_EVENT, 1) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_KERNEL_XFER, 1) && + + // Second thread. check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_VERSION) && check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, @@ -6894,8 +6967,18 @@ test_kernel_syscall_sequences() check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_INSTR) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, SYSCALL_BASE) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL, 0) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + + SYSCALL_BASE) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_ARG, 10) && // Syscall_1 trace on second thread. check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, @@ -6906,8 +6989,24 @@ test_kernel_syscall_sequences() check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYSCALL_BASE) && + // Post-syscall markers + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_ID, + static_cast(func_trace_t::TRACE_FUNC_ID_SYSCALL_BASE) + + SYSCALL_BASE) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_FUNC_RETVAL, 1) && + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_SYSCALL_FAILED, 1) && + + // Post syscall timestamp. + check_ref(refs[0], idx, TID_BASE + 2, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_INSTR) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_INSTR) && + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, TRACE_MARKER_TYPE_SYSCALL, SYSCALL_BASE + 1) && // Syscall_2 trace on first thread. @@ -6918,7 +7017,11 @@ test_kernel_syscall_sequences() check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_INSTR_INDIRECT_JUMP, TRACE_MARKER_TYPE_RESERVED_END, 42 * TID_BASE + 3 * 4) && check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, - TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYSCALL_BASE + 1); + TRACE_MARKER_TYPE_SYSCALL_TRACE_END, SYSCALL_BASE + 1) && + + // Post syscall timestamp. + check_ref(refs[0], idx, TID_BASE, TRACE_TYPE_MARKER, + TRACE_MARKER_TYPE_TIMESTAMP, TIMESTAMP); assert(res); } { diff --git a/clients/drcachesim/tests/syscall_insertion.templatex b/clients/drcachesim/tests/syscall_insertion.templatex index f771912a2b6..abc037a4597 100644 --- a/clients/drcachesim/tests/syscall_insertion.templatex +++ b/clients/drcachesim/tests/syscall_insertion.templatex @@ -2,8 +2,8 @@ Schedule stats tool results: Total counts: 4 cores .* - 650600 instructions + 650604 instructions .* 0 context switch sequence injections - 12 system call sequence injections + 14 system call sequence injections .* diff --git a/clients/drcachesim/tests/syscall_insertion_core_sharded.templatex b/clients/drcachesim/tests/syscall_insertion_core_sharded.templatex index f771912a2b6..abc037a4597 100644 --- a/clients/drcachesim/tests/syscall_insertion_core_sharded.templatex +++ b/clients/drcachesim/tests/syscall_insertion_core_sharded.templatex @@ -2,8 +2,8 @@ Schedule stats tool results: Total counts: 4 cores .* - 650600 instructions + 650604 instructions .* 0 context switch sequence injections - 12 system call sequence injections + 14 system call sequence injections .* diff --git a/clients/drcachesim/tools/invariant_checker.cpp b/clients/drcachesim/tools/invariant_checker.cpp index 919963f3941..ccf608cf90e 100644 --- a/clients/drcachesim/tools/invariant_checker.cpp +++ b/clients/drcachesim/tools/invariant_checker.cpp @@ -279,6 +279,46 @@ invariant_checker_t::parallel_shard_memref(void *shard_data, const memref_t &mem ++shard->instr_count_; ++shard->instr_count_since_last_timestamp_; } + + // These markers are allowed between the syscall marker and a possible + // syscall trace. + bool prev_was_syscall_marker_saved = shard->prev_was_syscall_marker_; + if (memref.marker.type == TRACE_TYPE_MARKER) { + switch (memref.marker.marker_type) { + // XXX: The following four markers may be added by sub-classes that + // provide their own implementation of raw2trace_t::process_marker. + // raw2trace_t::process_marker may prepend or append these additional + // markers on processing the syscall's TRACE_MARKER_TYPE_FUNC_ARGs. It + // may have been cleaner if the syscall trace were injected before the + // following four, but it gets messy trying to inject the trace between + // the last TRACE_MARKER_TYPE_FUNC_ARG and one of the following added + // by raw2trace_t::process_marker. In any case, the dynamic scheduler + // waits until the next user-space instr before making any scheduling + // decisions, so the order doesn't matter functionally. + case TRACE_MARKER_TYPE_SYSCALL_UNSCHEDULE: + case TRACE_MARKER_TYPE_SYSCALL_SCHEDULE: + case TRACE_MARKER_TYPE_SYSCALL_ARG_TIMEOUT: + case TRACE_MARKER_TYPE_DIRECT_THREAD_SWITCH: + // Marking end of context for the above comment. + case TRACE_MARKER_TYPE_FUNC_ARG: + case TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL: + report_if_false(shard, + !shard->found_syscall_trace_after_last_userspace_instr_, + "Found unexpected func_arg or syscall marker after injected " + "syscall trace"); + break; + case TRACE_MARKER_TYPE_FUNC_ID: + // This may be present both before and after the injected syscall trace, + // from the pre- and post-syscall callback. + break; + default: + // Remaining markers are not allowed to intervene TRACE_MARKER_TYPE_SYSCALL + // and a possible TRACE_MARKER_TYPE_SYSCALL_TRACE_START. + // Also lets us detect syscall traces that were injected too late (after a + // marker not on the list above, like syscall_failed). + shard->prev_was_syscall_marker_ = false; + } + } if (dynamic_syscall_trace_injection_ && (shard->between_kernel_syscall_trace_markers_ || (memref.marker.type == TRACE_TYPE_MARKER && @@ -309,8 +349,6 @@ invariant_checker_t::parallel_shard_memref(void *shard_data, const memref_t &mem shard->stream->get_instruction_ordinal(), "Stream instr ordinal inaccurate"); } - bool prev_was_syscall_marker_saved = shard->prev_was_syscall_marker_; - shard->prev_was_syscall_marker_ = false; #ifdef UNIX if (has_annotations_) { // Check conditions specific to the signal_invariants app, where it @@ -541,9 +579,6 @@ invariant_checker_t::parallel_shard_memref(void *shard_data, const memref_t &mem if (memref.marker.type == TRACE_TYPE_MARKER && memref.marker.marker_type == TRACE_MARKER_TYPE_MAYBE_BLOCKING_SYSCALL) { shard->found_blocking_marker_ = true; - // Re-assign the saved value to the shard state to allow this intervening - // maybe_blocking marker. - shard->prev_was_syscall_marker_ = prev_was_syscall_marker_saved; report_if_false( shard, (shard->prev_entry_.marker.type == TRACE_TYPE_MARKER && @@ -619,7 +654,8 @@ invariant_checker_t::parallel_shard_memref(void *shard_data, const memref_t &mem OFFLINE_FILE_TYPE_KERNEL_SYSCALL_INSTR_ONLY, shard->file_type_)) { report_if_false(shard, prev_was_syscall_marker_saved, - "System call trace found without prior syscall marker"); + "System call trace found without prior syscall marker or " + "unexpected intervening records"); report_if_false(shard, shard->last_syscall_marker_value_ == static_cast(memref.marker.marker_value), diff --git a/clients/drcachesim/tracer/raw2trace.cpp b/clients/drcachesim/tracer/raw2trace.cpp index 329a0d22e87..b84d0e34e1e 100644 --- a/clients/drcachesim/tracer/raw2trace.cpp +++ b/clients/drcachesim/tracer/raw2trace.cpp @@ -394,12 +394,15 @@ raw2trace_t::process_offline_entry(raw2trace_thread_data_t *tdata, // process_next_thread_buffer() so there is no need to have a separate // check for it here. if (marker_type != TRACE_MARKER_TYPE_CPU_ID) { - if (syscall_template_file_reader_ != nullptr && - marker_type == TRACE_MARKER_TYPE_SYSCALL) { - // Also writes out the delayed branches if any. - if (!write_syscall_template(tdata, buf, buf_base, - static_cast(marker_val))) - return false; + if (marker_type == TRACE_MARKER_TYPE_SYSCALL && + syscall_trace_templates_.find(static_cast(marker_val)) != + syscall_trace_templates_.end()) { + assert(tdata->to_inject_syscall_ == + raw2trace_thread_data_t::INJECT_NONE); + // The actual injection of the syscall trace happens later at the + // intended point between the syscall function tracing markers + tdata->to_inject_syscall_ = static_cast(marker_val); + tdata->saw_first_func_id_marker_after_syscall_ = false; } if (delayed_branches_exist(tdata)) { return write_delayed_branches(tdata, buf_base, @@ -919,6 +922,54 @@ raw2trace_t::process_syscall_pt(raw2trace_thread_data_t *tdata, uint64_t syscall } #endif +bool +raw2trace_t::maybe_inject_pending_syscall_sequence(raw2trace_thread_data_t *tdata, + const offline_entry_t &entry, + byte *buf_base) +{ + if (tdata->to_inject_syscall_ == raw2trace_thread_data_t::INJECT_NONE) + return true; + bool is_marker = entry.extended.type == OFFLINE_TYPE_EXTENDED && + entry.extended.ext == OFFLINE_EXT_TYPE_MARKER; + bool is_injection_point = false; + // We inject the syscall trace after all markers added in the + // pre-syscall event. + if ( + // For syscalls not specified in -record_syscall, which do not have + // the func_id-func_retval markers. + entry.timestamp.type == OFFLINE_TYPE_TIMESTAMP || + // For syscalls that did not have a post-event because the trace ended. + (entry.extended.type == OFFLINE_TYPE_EXTENDED && + entry.extended.ext == OFFLINE_EXT_TYPE_FOOTER) || + // For syscalls interrupted by a signal and did not have a post-syscall + // event. + (is_marker && entry.extended.valueB == TRACE_MARKER_TYPE_KERNEL_EVENT)) { + is_injection_point = true; + } else if (is_marker && entry.extended.valueB == TRACE_MARKER_TYPE_FUNC_ID) { + if (!tdata->saw_first_func_id_marker_after_syscall_) { + // XXX i#7482: If we allow recording zero args for syscalls in + // -record_syscall, we would need to update this logic. + tdata->saw_first_func_id_marker_after_syscall_ = true; + } else { + // For syscalls specified in -record_syscall, for which we inject + // just before the func_id-func_retval markers. + is_injection_point = true; + } + } + + byte *buf = buf_base; + // Also writes out the delayed branches if any. + if (is_injection_point) { + if (!write_syscall_template(tdata, buf, + reinterpret_cast(buf_base), + tdata->to_inject_syscall_)) { + return false; + } + tdata->to_inject_syscall_ = raw2trace_thread_data_t::INJECT_NONE; + tdata->saw_first_func_id_marker_after_syscall_ = false; + } + return true; +} bool raw2trace_t::process_next_thread_buffer(raw2trace_thread_data_t *tdata, DR_PARAM_OUT bool *end_of_record) @@ -951,6 +1002,8 @@ raw2trace_t::process_next_thread_buffer(raw2trace_thread_data_t *tdata, // Make a copy to avoid clobbering the entry we pass to process_offline_entry() // when it calls get_next_entry() on its own. offline_entry_t entry = *in_entry; + if (!maybe_inject_pending_syscall_sequence(tdata, entry, buf_base)) + return false; if (entry.timestamp.type == OFFLINE_TYPE_TIMESTAMP) { // Give subclasses a chance for further action on a timestamp by // putting our processing as thought it were a marker at the raw level. diff --git a/clients/drcachesim/tracer/raw2trace.h b/clients/drcachesim/tracer/raw2trace.h index a6457e1982f..4373983f0c4 100644 --- a/clients/drcachesim/tracer/raw2trace.h +++ b/clients/drcachesim/tracer/raw2trace.h @@ -751,6 +751,8 @@ class raw2trace_t { addr_t rseq_commit_pc_ = 0; addr_t rseq_start_pc_ = 0; addr_t rseq_end_pc_ = 0; + int to_inject_syscall_ = INJECT_NONE; + bool saw_first_func_id_marker_after_syscall_ = false; std::vector rseq_buffer_; int rseq_commit_idx_ = -1; // Index into rseq_buffer_. std::vector rseq_branch_targets_; @@ -762,6 +764,9 @@ class raw2trace_t { bool pt_metadata_processed = false; pt2ir_t pt2ir; #endif + + // Sentinel value for to_inject_syscall. + static constexpr int INJECT_NONE = -1; }; #ifdef BUILD_PT_POST_PROCESSOR @@ -881,6 +886,10 @@ class raw2trace_t { process_next_thread_buffer(raw2trace_thread_data_t *tdata, DR_PARAM_OUT bool *end_of_record); + bool + maybe_inject_pending_syscall_sequence(raw2trace_thread_data_t *tdata, + const offline_entry_t &entry, byte *buf_base); + std::string aggregate_and_write_schedule_files(); diff --git a/suite/tests/CMakeLists.txt b/suite/tests/CMakeLists.txt index f36dab1e5a8..3ea5956934c 100644 --- a/suite/tests/CMakeLists.txt +++ b/suite/tests/CMakeLists.txt @@ -4036,6 +4036,9 @@ if (BUILD_CLIENTS) "-tool basic_counts" "") endif () + set(syscall_file + "${PROJECT_SOURCE_DIR}/clients/drcachesim/tests/mock_syscall_sequences.x64") + if (X86 AND X64) # We only bother with a sample trace for x86_64. # We test with a fixed trace file so we can test exact numeric results. set(small_trace_file @@ -4115,9 +4118,6 @@ if (BUILD_CLIENTS) "") set(tool.switch_file_invariants_rawtemp ON) # no preprocessor - set(syscall_file - "${PROJECT_SOURCE_DIR}/clients/drcachesim/tests/mock_syscall_sequences.x64") - torunonly_simtool(syscall_insertion ${ci_shared_app} "-indir ${thread_trace_dir} ${thread_trace_scale} -tool schedule_stats -sched_syscall_file ${syscall_file}" "") @@ -4895,6 +4895,12 @@ if (BUILD_CLIENTS) # Test -record_syscall on SYS_write == #1 with 3 args. torunonly_drcacheoff(allasm-record-syscall allasm_repstr "-record_syscall 1|3" "@-tool@view" "") + + torunonly_drcacheoff(allasm-dyn-inject-view allasm_repstr + "-record_syscall 1|3" "@-sched_syscall_file@${syscall_file}@-tool@view" "") + + torunonly_drcacheoff(allasm-dyn-inject-invariants allasm_repstr + "-record_syscall 1|3" "@-sched_syscall_file@${syscall_file}@-tool@invariant_checker" "") endif (UNIX AND X86 AND X64) torunonly_drcacheoff(invariant_checker ${ci_shared_app}