core/sal: interface for backend-specific notion of time

This adds an interface for a backend-specific notion of time, e.g. CPU
cycles since simulator start, and a concrete implementation for the
Bochs backend.  This is needed to record CPU idle times (e.g., HLT
instruction), and for target backends capable of more timing-accurate
execution.

This change also modifies the tracing plugin to add the time to all
trace events.

Change-Id: I93ac1d54c07f32b0b8f84f333417741d8e9c8288

src/core/comm/TracePlugin.proto

@@ -18,6 +18,10 @@ message Trace_Event_Extended {
 
 message Trace_Event {
 	required uint64 ip = 1;
+	// backend-specific notion of time since last event, counted, e.g., in
+	// CPU cycles; needed to record CPU idle times (e.g., HLT instruction),
+	// and for target backends capable of timing-accurate execution
+	optional int64 time_delta = 6;
 	optional uint64 memaddr = 2;
 	optional uint32 width = 3;
 	enum AccessType {

src/core/sal/SALConfig.hpp

@@ -27,6 +27,11 @@ typedef uint8_t          byte_t;      //!< 8 bit type for memory access (read or
 typedef uint32_t         regwidth_t;  //!< type of register width [bits]
 typedef register_data_t  regdata_t;   //!< type of register data
 typedef timer_t          timer_id_t;  //!< type of timer IDs
+//! backend-specific notion of time, e.g. CPU cycles or nanoseconds
+//! (move this to backend-specific headers when necessary)
+typedef uint64_t         simtime_t;
+//! backend-specific notion of time difference
+typedef int64_t          simtime_diff_t;
 
 // Note: The following flags are defined in SALConfig.cc.
 

src/core/sal/SimulatorController.hpp

@@ -237,6 +237,18 @@ public:
 	 * @param pfl the experiment flow to be activated
 	 */
 	void toggle(ExperimentFlow* pfl) { m_Flows.toggle(pfl); }
+	/**
+	 * Retrieves the current backend time, in a backend-specific format.
+	 * @note FIXME Consider making this pure virtual.
+	 * @see SimulatorController::getTimerTicksPerSecond()
+	 */
+	virtual simtime_t getTimerTicks() { return 0; }
+	/**
+	 * Retrieves the backend-specific number of timer ticks per second.
+	 * @note FIXME Consider making this pure virtual.
+	 * @see SimulatorController::getTimerTicks()
+	 */
+	virtual simtime_t getTimerTicksPerSecond() { return 0; }
 };
 
 } // end-of-namespace: fail

src/core/sal/bochs/BochsController.hpp

@@ -150,6 +150,8 @@ public:
 	 * @see The uses SimulatorController::getCPU().
 	 */
 	ConcreteCPU& detectCPU(BX_CPU_C* pCPU) const;
+	virtual simtime_t getTimerTicks() { return bx_pc_system.time_ticks(); }
+	virtual simtime_t getTimerTicksPerSecond() { return bx_pc_system.time_ticks() / bx_pc_system.time_usec(); /* imprecise hack */ }
 };
 
 } // end-of-namespace: fail

src/plugins/tracing/TracingPlugin.cc

@@ -38,10 +38,17 @@ bool TracingPlugin::run()
 	for (unsigned i = 0; i < sizeof(ids)/sizeof(*ids); ++i)
 		regs[i] = simulator.getCPU(0).getRegister(ids[i]);
 
+	// 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();
 
+		curtime = simulator.getTimerTicks();
+		deltatime = curtime - prevtime;
+
 		if (ev == &ev_step) {
 			simulator.addListener(&ev_step);
 
@@ -55,6 +62,10 @@ bool TracingPlugin::run()
 			if (m_protoStreamFile) {
 				Trace_Event e;
 				e.set_ip(ip);
+				// only store deltas != 0
+				if (deltatime != 0) {
+					e.set_time_delta(deltatime);
+				}
 				ps->writeMessage(&e);
 			}
 		} else if (ev == &ev_mem) {
@@ -81,6 +92,10 @@ bool TracingPlugin::run()
 				e.set_accesstype(
 				  (ev_mem.getTriggerAccessType() & MemAccessEvent::MEM_READ) ?
 				  e.READ : e.WRITE);
+				// only store deltas != 0
+				if (deltatime != 0) {
+					e.set_time_delta(deltatime);
+				}
 
 				/* When we're doing a full trace, we log more data in
 				   the case of a memory event */
@@ -110,6 +125,10 @@ bool TracingPlugin::run()
 			if (m_os)
 				*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;
 	}
 
 	return true;

tools/dump-trace/dump-trace.py

@@ -28,6 +28,8 @@ except IOError:
     print sys.argv[1] + ": Could not open file."
     sys.exit(-1)
 
+acctime = 0
+
 while True:
     # Read trace length
     try:
@@ -45,18 +47,23 @@ while True:
     # print trace_event
 
     # More compact dump for traces:
+    if trace_event.HasField("time_delta"):
+        acctime += trace_event.time_delta
+    # As time_delta fields are omitted where the delta is 0, every event
+    # implicitly has a timestamp.
+    time = " t={0}".format(acctime)
     if not trace_event.HasField("memaddr"):
-        print "IP {0:x}".format(trace_event.ip)
+        print "IP {0:x}{1}".format(trace_event.ip, time)
     else:
         ext = ""
         if trace_event.HasField("trace_ext"):
-            ext = "DATA {0:x}".format(trace_event.trace_ext.data)
+            ext = " DATA {0:x}".format(trace_event.trace_ext.data)
             for reg in trace_event.trace_ext.registers:
                 ext += " REG: {0} *{1:x}={2:x}".format(reg.id, reg.value, reg.value_deref)
             if len(trace_event.trace_ext.stack) > 0:
                 ext += " STACK: " + "".join(["%x"%x for x in trace_event.trace_ext.stack])
-        print "MEM {0} {1:x} width {2:d} IP {3:x} {4}".format(
+        print "MEM {0} {1:x} width {2:d} IP {3:x}{4}{5}".format(
         "R" if trace_event.accesstype == trace_event.READ else "W",
-        trace_event.memaddr, trace_event.width, trace_event.ip, ext)
+        trace_event.memaddr, trace_event.width, trace_event.ip, ext, time)
 
 f.close()