From 090125a283932d5ee251f2bc633ab1cc39685ca4 Mon Sep 17 00:00:00 2001 From: Horst Schirmeier Date: Tue, 15 Oct 2013 13:00:32 +0200 Subject: [PATCH 1/5] Revert "generic-tracing: fix lossage of first event" This reverts commit 036e340bd9322f94a1e6b16048309645245d514a. Problems with this one were: - Broken event timings. m_prevtime wasn't reset to m_curtime in TracingPlugin::handleSingleIP(), resulting in a large deltatime being recorded for the second event, too. This effectively doubled the experiment's start time. - Code repetition (copy/pasted for special handling of first event), making planned changes (advanced tracing for IP events) more difficult. - Unnecessary additional tracing-plugin interface method. Change-Id: I4b74d1a3f4563aabe6626399f9b30a2171b4c285 --- src/experiments/generic-tracing/experiment.cc | 4 --- src/plugins/tracing/TracingPlugin.cc | 36 +++---------------- src/plugins/tracing/TracingPlugin.hpp | 15 +------- 3 files changed, 5 insertions(+), 50 deletions(-) diff --git a/src/experiments/generic-tracing/experiment.cc b/src/experiments/generic-tracing/experiment.cc index 553a9056..0d57f049 100644 --- a/src/experiments/generic-tracing/experiment.cc +++ b/src/experiments/generic-tracing/experiment.cc @@ -209,10 +209,6 @@ bool GenericTracing::run() // this must be done *after* configuring the plugin: simulator.addFlow(&tp); - // In order to not loose the IP event at the beginning of the - // trace, we have to handle the IP event manually - tp.handleSingleIP(l_start_symbol); - //////////////////////////////////////////////////////////////// // STEP 2: continue to the save point, and save state if (start_symbol != save_symbol) { diff --git a/src/plugins/tracing/TracingPlugin.cc b/src/plugins/tracing/TracingPlugin.cc index 12ee464c..482413f8 100644 --- a/src/plugins/tracing/TracingPlugin.cc +++ b/src/plugins/tracing/TracingPlugin.cc @@ -1,7 +1,6 @@ #include #include -#include "sal/SALConfig.hpp" #include "sal/SALInst.hpp" #include "sal/Register.hpp" #include "sal/Memory.hpp" @@ -11,34 +10,6 @@ using namespace std; using namespace fail; -void TracingPlugin::handleSingleIP(const BPListener &bp) { - address_t ip = bp.getTriggerInstructionPointer(); - if (m_ipMap && !m_ipMap->isMatching(ip)) { - return; - } - - m_curtime = simulator.getTimerTicks(); - simtime_diff_t deltatime = m_curtime - m_prevtime; - - if (m_os) - *m_os << "[Tracing] IP " << hex << ip << "\n"; - - if (m_protoStreamFile) { - Trace_Event e; - e.set_ip(ip); - // only store deltas != 0 - if (deltatime != 0) { - e.set_time_delta(deltatime); - } - if (!ps) { - ps = new ProtoOStream (m_protoStreamFile); - } - - ps->writeMessage(&e); - } -} - - bool TracingPlugin::run() { MemoryManager& mm = simulator.getMemoryManager(); @@ -62,13 +33,14 @@ bool TracingPlugin::run() // the first event gets an absolute time stamp, all others a delta to their // predecessor + simtime_t prevtime = 0, curtime; simtime_diff_t deltatime; while (true) { ev = simulator.resume(); - m_curtime = simulator.getTimerTicks(); - deltatime = m_curtime - m_prevtime; + curtime = simulator.getTimerTicks(); + deltatime = curtime - prevtime; if (ev == &ev_step) { simulator.addListener(&ev_step); @@ -150,7 +122,7 @@ bool TracingPlugin::run() // do this only if the last delta was written // (no, e.g., memory map mismatch) - m_prevtime = m_curtime; + prevtime = curtime; } return true; diff --git a/src/plugins/tracing/TracingPlugin.hpp b/src/plugins/tracing/TracingPlugin.hpp index de9bb026..e8cec478 100644 --- a/src/plugins/tracing/TracingPlugin.hpp +++ b/src/plugins/tracing/TracingPlugin.hpp @@ -7,8 +7,6 @@ #include "util/ProtoStream.hpp" #include "efw/ExperimentFlow.hpp" #include "config/FailConfig.hpp" -#include "sal/Listener.hpp" - #include "TracePlugin.pb.h" @@ -50,14 +48,10 @@ private: std::ostream *m_os; //!< ostream to write human-readable trace into fail::ProtoOStream *ps; - fail::simtime_t m_prevtime; - fail::simtime_t m_curtime; - public: TracingPlugin(bool full_trace = false) : m_memMap(0), m_ipMap(0), m_memonly(false), m_iponly(false), - m_full_trace(full_trace), m_protoStreamFile(0), m_os(0), - m_prevtime(0) { } + m_full_trace(full_trace), m_protoStreamFile(0), m_os(0) { } bool run(); /** * Restricts tracing to memory addresses listed in this MemoryMap. An @@ -94,13 +88,6 @@ public: * ProtoStream file to trace into (trace.proto instance) */ void setTraceFile(std::ostream *os) { m_protoStreamFile = os; } - - /** - * Handles a single IP event. This is important for starting the - * tracing process after triggering a breakpoint. Just pass on the - * breakpoint - */ - void handleSingleIP(const fail::BPListener &bp); }; #endif // __TRACING_PLUGIN_HPP__ From 3dc752cd091974be3fd5606fcf4c65e565486eae Mon Sep 17 00:00:00 2001 From: Horst Schirmeier Date: Tue, 15 Oct 2013 16:15:56 +0200 Subject: [PATCH 2/5] tracing: fix loss of first dynamic instruction When starting the tracing plugin (simulator.addFlow()), at the moment the *current* dynamic instruction (e.g., the one the start symbol points to) is skipped, and tracing commences with the second instruction. This change records an additional instruction event at the trace begin. Note that this change affects all tracing-plugin users. The first event gets recorded when starting the plugin (simulator.addFlow()). This avoids compatibility/off-by-one issues when recording traces with the generic-tracing experiment vs. with custom experiments. Change-Id: Ic24e17a68b8a44edad3be994e9edd6d6712bfda1 --- src/plugins/tracing/TracingPlugin.cc | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/src/plugins/tracing/TracingPlugin.cc b/src/plugins/tracing/TracingPlugin.cc index 482413f8..ff0dae1c 100644 --- a/src/plugins/tracing/TracingPlugin.cc +++ b/src/plugins/tracing/TracingPlugin.cc @@ -16,11 +16,10 @@ bool TracingPlugin::run() MemAccessListener ev_mem(ANY_ADDR); BPSingleListener ev_step(ANY_ADDR); - BaseListener *ev; + BaseListener *ev = 0; + + // ev_step is added in the first loop iteration - if (m_iponly || !m_memonly) { - simulator.addListener(&ev_step); - } if (m_memonly || !m_iponly) { simulator.addListener(&ev_mem); } @@ -36,16 +35,17 @@ bool TracingPlugin::run() simtime_t prevtime = 0, curtime; simtime_diff_t deltatime; - while (true) { - ev = simulator.resume(); + bool first = true; + while (true) { curtime = simulator.getTimerTicks(); deltatime = curtime - prevtime; - if (ev == &ev_step) { + if (ev == &ev_step || (first && (m_iponly || !m_memonly))) { + first = false; simulator.addListener(&ev_step); + address_t ip = simulator.getCPU(0).getInstructionPointer(); - address_t ip = ev_step.getTriggerInstructionPointer(); if (m_ipMap && !m_ipMap->isMatching(ip)) { continue; } @@ -115,7 +115,7 @@ bool TracingPlugin::run() ps->writeMessage(&e); } - } else { + } else if (!first) { if (m_os) *m_os << "[Tracing] SOMETHING IS SERIOUSLY WRONG\n"; } @@ -123,6 +123,8 @@ bool TracingPlugin::run() // do this only if the last delta was written // (no, e.g., memory map mismatch) prevtime = curtime; + + ev = simulator.resume(); } return true; From 22b9646b803c7bd7b3c01bf31d5b7470d451cb24 Mon Sep 17 00:00:00 2001 From: Horst Schirmeier Date: Wed, 18 Sep 2013 15:35:38 +0200 Subject: [PATCH 3/5] import-trace: dynamic instruction off-by-one Richard noticed that instr2 values are off by one when done with the MemoryImporter vs. with his own importer. The core problem is that the dynamic instruction counter in the Importer base class (Importer::copy_to_database, instruction_count_t instr) gets increased *after* reporting an IP event to the importer implementation; this has the side-effect that memory access events have a +1 dynamic instruction count offset with regard to the IP event of the instruction they belong to. Bottom line: IP events and all memory events belonging to that instruction should have the same dynamic instruction number. Christian argued for the numbers starting with 0, which, as a side effect, relativizes the repercussions of the change introduced in the previous commit, as the new "first" event gets the sequence number 0 now. - All experiments and importers only dealing with memory accesses (MemoryImporter) are affected by this change: The dynamic instruction count now starts with 0 instead of 1. Together with the previous commit, the only change is one additional dynamic instruction at position 0. Note that existing trace files do not have this additional instruction, which shifts all trace positions by 1. - All importers that process *only* IP events (InstructionImporter, RandomJumpImporter, RegisterImporter) won't see any difference. Commit 036e340, though, introduced a +1 offset. - Experiments that use these instruction counts for navigating to the target instruction must be checked to properly deal with the dynamic instruction #0 (no forwarding necessary). All dynamic instruction offsetting should now work uniformly for both memory accesses and all other fault models. To be sure everything works in order, sanity-check the current absolute instruction pointer right before fault injection. Change-Id: I3f509f1b47836fa78fd029a7bb7c36c878912d97 --- tools/import-trace/Importer.cc | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/tools/import-trace/Importer.cc b/tools/import-trace/Importer.cc index accc562f..ab02e53e 100644 --- a/tools/import-trace/Importer.cc +++ b/tools/import-trace/Importer.cc @@ -66,6 +66,8 @@ bool Importer::copy_to_database(fail::ProtoIStream &ps) { // instruction counter within trace instruction_count_t instr = 0; + // instruction counter new memory access events belong to + instruction_count_t instr_memaccess = 0; // the currently processed event Trace_Event ev; @@ -92,6 +94,7 @@ bool Importer::copy_to_database(fail::ProtoIStream &ps) { LOG << "error: instruction_count_t overflow, aborting at instr=" << instr << std::endl; return false; } + /* Another instruction was executed, handle it in the subclass */ if (!handle_ip_event(curtime, instr, ev)) { @@ -99,10 +102,12 @@ bool Importer::copy_to_database(fail::ProtoIStream &ps) { return false; } + // all subsequent mem access events belong to this dynamic instr + instr_memaccess = instr; instr++; } else { - if (!handle_mem_event(curtime, instr, ev)) { - LOG << "error: handle_mem_event() failed at instr=" << instr << std::endl; + if (!handle_mem_event(curtime, instr_memaccess, ev)) { + LOG << "error: handle_mem_event() failed at instr=" << instr_memaccess << std::endl; return false; } } From 64034e29b4bf4f047706d69064dcde26ea790f9b Mon Sep 17 00:00:00 2001 From: Horst Schirmeier Date: Thu, 17 Oct 2013 19:07:08 +0200 Subject: [PATCH 4/5] tracing: bugfix: advance prevtime only if delta was recorded This change implements what the source-code comment already promised but didn't keep: As we only record time deltas instead of absolute time values, prevtime must not be overwritten unless the current delta was really added to the trace. This has caused timing information to be stored incorrectly if certain events were skipped (e.g., because they didn't match the memory map configured by the user). Change-Id: Id40271d117dd91b1122136c62329d64174f304b0 --- src/plugins/tracing/TracingPlugin.cc | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/plugins/tracing/TracingPlugin.cc b/src/plugins/tracing/TracingPlugin.cc index ff0dae1c..7dbb4f0e 100644 --- a/src/plugins/tracing/TracingPlugin.cc +++ b/src/plugins/tracing/TracingPlugin.cc @@ -58,6 +58,10 @@ bool TracingPlugin::run() // only store deltas != 0 if (deltatime != 0) { e.set_time_delta(deltatime); + + // do this only if the last delta was written + // (no, e.g., memory map mismatch) + prevtime = curtime; } ps->writeMessage(&e); } @@ -88,6 +92,10 @@ bool TracingPlugin::run() // only store deltas != 0 if (deltatime != 0) { e.set_time_delta(deltatime); + + // do this only if the last delta was written + // (no, e.g., memory map mismatch) + prevtime = curtime; } /* When we're doing a full trace, we log more data in @@ -120,10 +128,6 @@ bool TracingPlugin::run() *m_os << "[Tracing] SOMETHING IS SERIOUSLY WRONG\n"; } - // do this only if the last delta was written - // (no, e.g., memory map mismatch) - prevtime = curtime; - ev = simulator.resume(); } From f2d0919553e8af6b1d24c1530acae3bdc3f2aa0f Mon Sep 17 00:00:00 2001 From: Horst Schirmeier Date: Thu, 17 Oct 2013 19:03:27 +0200 Subject: [PATCH 5/5] tracing: simplify confusing iponly/memonly configuration The internal m_iponly / m_memonly bools are a bit hackish; especially it's unclear what should happen if both are set. The m_tracetype enum now encompasses all possible configurations, while the plugin's user interface remains unchanged. Change-Id: Ibdd872b5cc5781836428b27bfb2db3825700e671 --- src/plugins/tracing/TracingPlugin.cc | 4 ++-- src/plugins/tracing/TracingPlugin.hpp | 10 +++++----- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/plugins/tracing/TracingPlugin.cc b/src/plugins/tracing/TracingPlugin.cc index 7dbb4f0e..cfc69d33 100644 --- a/src/plugins/tracing/TracingPlugin.cc +++ b/src/plugins/tracing/TracingPlugin.cc @@ -20,7 +20,7 @@ bool TracingPlugin::run() // ev_step is added in the first loop iteration - if (m_memonly || !m_iponly) { + if (m_tracetype | TRACE_MEM) { simulator.addListener(&ev_mem); } if(m_protoStreamFile) { @@ -41,7 +41,7 @@ bool TracingPlugin::run() curtime = simulator.getTimerTicks(); deltatime = curtime - prevtime; - if (ev == &ev_step || (first && (m_iponly || !m_memonly))) { + if (ev == &ev_step || (first && (m_tracetype | TRACE_IP))) { first = false; simulator.addListener(&ev_step); address_t ip = simulator.getCPU(0).getInstructionPointer(); diff --git a/src/plugins/tracing/TracingPlugin.hpp b/src/plugins/tracing/TracingPlugin.hpp index e8cec478..1004e949 100644 --- a/src/plugins/tracing/TracingPlugin.hpp +++ b/src/plugins/tracing/TracingPlugin.hpp @@ -40,8 +40,8 @@ class TracingPlugin : public fail::ExperimentFlow private: fail::MemoryMap *m_memMap; //!< address restriction for memory accesses fail::MemoryMap *m_ipMap; //!< instruction address restriction - bool m_memonly; //!< log instructions only if they are memory accesses - bool m_iponly; //!< log instruction addresses only + //! trace nothing / instructions / mem accesses / both (can be bitwise ORed) + enum { TRACE_NONE = 0, TRACE_IP, TRACE_MEM, TRACE_BOTH } m_tracetype; bool m_full_trace; //!< do a full trace (more information for the events) std::ostream *m_protoStreamFile; @@ -50,7 +50,7 @@ private: public: TracingPlugin(bool full_trace = false) - : m_memMap(0), m_ipMap(0), m_memonly(false), m_iponly(false), + : m_memMap(0), m_ipMap(0), m_tracetype(TRACE_BOTH), m_full_trace(full_trace), m_protoStreamFile(0), m_os(0) { } bool run(); /** @@ -71,11 +71,11 @@ public: * conducted a memory access. Defaults to false: All instructions are * logged. */ - void setLogMemOnly(bool memonly) { m_memonly = memonly; } + void setLogMemOnly(bool memonly = true) { m_tracetype = memonly ? TRACE_MEM : TRACE_BOTH; } /** * If invoked with iponly=true, only instruction addresses are logged. */ - void setLogIPOnly(bool iponly) { m_iponly = iponly; } + void setLogIPOnly(bool iponly = true) { m_tracetype = iponly ? TRACE_IP : TRACE_BOTH; } /** * If invoked with fulltrace=true, a extended (full) trace is done. */