tools/import-trace: import timing information + various additions

- Import timing information from traces that were recorded with timing.
- Allow restricting import to a memory map ("vertical" restriction).
- Proper fault-space right-margin handling.
- Cleanups, data-type usage, etc.

Change-Id: I7a49e8e9e49894c458e884bfc234f36b9ba8b130

tools/import-trace/BasicImporter.cc

@@ -1,4 +1,3 @@
-#include <iostream>
 #include "util/Logger.hpp"
 #include "BasicImporter.hpp"
 
@@ -10,6 +9,8 @@ bool BasicImporter::create_database() {
 		"	instr1 int(10) unsigned NOT NULL,"
 		"	instr2 int(10) unsigned NOT NULL,"
 		"	instr2_absolute int(10) unsigned DEFAULT NULL,"
+		"	time1 bigint(10) unsigned NOT NULL,"
+		"	time2 bigint(10) unsigned NOT NULL,"
 		"	data_address int(10) unsigned NOT NULL,"
 		"	width tinyint(3) unsigned NOT NULL,"
 		"	accesstype enum('R','W') NOT NULL,"
@@ -19,13 +20,14 @@ bool BasicImporter::create_database() {
 }
 
 bool BasicImporter::add_trace_event(instruction_count_t begin, instruction_count_t end,
-									const Trace_Event &event, bool is_fake) {
+	fail::simtime_t time_begin, fail::simtime_t time_end,
+	const Trace_Event &event, bool is_fake) {
 
 	static MYSQL_STMT *stmt = 0;
 	if (!stmt) {
-		std::string sql("INSERT INTO trace (variant_id, instr1, instr2, instr2_absolute, data_address, width,"
+		std::string sql("INSERT INTO trace (variant_id, instr1, instr2, instr2_absolute, time1, time2, data_address, width,"
 		                "					accesstype)"
-		                "VALUES (?,?,?,?, ?,?,?)");
+		                "VALUES (?,?,?,?,?,?,?,?,?)");
 		stmt = mysql_stmt_init(db->getHandle());
 		if (mysql_stmt_prepare(stmt, sql.c_str(), sql.length())) {
 			LOG << "query '" << sql << "' failed: " << mysql_error(db->getHandle()) << std::endl;
@@ -33,7 +35,7 @@ bool BasicImporter::add_trace_event(instruction_count_t begin, instruction_count
 		}
 	}
 
-	MYSQL_BIND bind[7];
+	MYSQL_BIND bind[9];
 	my_bool is_null = is_fake;
 	unsigned long accesstype_len = 1;
 	unsigned ip = event.ip();
@@ -42,7 +44,7 @@ bool BasicImporter::add_trace_event(instruction_count_t begin, instruction_count
 	char accesstype = event.accesstype() == event.READ ? 'R' : 'W';
 
 	memset(bind, 0, sizeof(bind));
-	for (int i = 0; i < 7; ++i) {
+	for (unsigned i = 0; i < sizeof(bind)/sizeof(*bind); ++i) {
 		bind[i].buffer_type = MYSQL_TYPE_LONG;
 		bind[i].is_unsigned = 1;
 		switch (i) {
@@ -51,9 +53,15 @@ bool BasicImporter::add_trace_event(instruction_count_t begin, instruction_count
 		case 2: bind[i].buffer = &end; break;
 		case 3: bind[i].buffer = &ip;
 			bind[i].is_null = &is_null; break;
-		case 4: bind[i].buffer = &data_address; break;
+		case 4: bind[i].buffer = &time_begin;
-		case 5: bind[i].buffer = &width; break;
+			bind[i].buffer_type = MYSQL_TYPE_LONGLONG;
-		case 6: bind[i].buffer = &accesstype;
+			break;
+		case 5: bind[i].buffer = &time_end;
+			bind[i].buffer_type = MYSQL_TYPE_LONGLONG;
+			break;
+		case 6: bind[i].buffer = &data_address; break;
+		case 7: bind[i].buffer = &width; break;
+		case 8: bind[i].buffer = &accesstype;
 			bind[i].buffer_type = MYSQL_TYPE_STRING;
 			bind[i].buffer_length = accesstype_len;
 			bind[i].length = &accesstype_len;
@@ -66,10 +74,8 @@ bool BasicImporter::add_trace_event(instruction_count_t begin, instruction_count
 	}
 	if (mysql_stmt_execute(stmt)) {
 		LOG << "mysql_stmt_execute() failed: " << mysql_stmt_error(stmt) << std::endl;
-		LOG << "IP: " << std::hex<< event.ip() << std::endl;
+		LOG << "IP: " << std::hex << event.ip() << std::endl;
 		return false;
 	}
 	return true;
 }
-
-

tools/import-trace/BasicImporter.hpp

@@ -2,12 +2,15 @@
 #define __BASIC_IMPORTER_H__
 
 #include "Importer.hpp"
+#include "util/CommandLine.hpp"
 
 class BasicImporter : public Importer {
 public:
 	virtual bool create_database();
 	bool add_trace_event(instruction_count_t begin,
 						 instruction_count_t end,
+						 fail::simtime_t time_begin,
+						 fail::simtime_t time_end,
 						 const Trace_Event &event,
 						 bool is_fake = false);
 };

tools/import-trace/DCiAOKernelImporter.cc

@@ -92,7 +92,7 @@ bool DCiAOKernelImporter::copy_to_database(fail::ProtoIStream &ps) {
 					// we now have an interval-terminating R/W event to the memaddr
 					// we're currently looking at; the EC is defined by
 					// data_address [last_kernel_leave, read_instr] (instr_absolute)
-					if (!add_trace_event(instr1, instr2, ev)) {
+					if (!add_trace_event(instr1, instr2, 0, 0, ev)) { // FIXME use timing data
 						LOG << "add_trace_event failed" << std::endl;
 						return false;
 					}

tools/import-trace/Importer.cc

@@ -28,36 +28,74 @@ bool Importer::clear_database() {
 }
 
 bool Importer::copy_to_database(fail::ProtoIStream &ps) {
-	unsigned row_count = 0;
+	unsigned row_count = 0, row_count_fake = 0;
 	// map for keeping one "open" EC for every address
-	// (maps injection data address => equivalence class)
+	// (maps injection data address =>
+	// dyn. instruction count / time information for equivalence class left margin)
 	AddrLastaccessMap open_ecs;
 
-	// instruction counter within trace
+	// time the trace started/ended
-	unsigned instr = 0;
+	// For now we just use the min/max occuring timestamp; for "sparse" traces
+	// (e.g., only mem accesses, only a subset of the address space) it might
+	// be a good idea to store this explicitly in the trace file, though.
+	simtime_t time_trace_start = 0, curtime = 0;
 
-	// "rightmost" instr where we did a FI experiment
+	// instruction counter within trace
-	unsigned instr_rightmost = 0;
+	instruction_count_t instr = 0;
 
 	Trace_Event ev;
 
 	while (ps.getNext(&ev)) {
+		if (ev.has_time_delta()) {
+			// record trace start
+			// it suffices to do this once, the events come in sorted
+			if (time_trace_start == 0) {
+				time_trace_start = ev.time_delta();
+				LOG << "trace start time: " << time_trace_start << std::endl;
+			}
+			// curtime also always holds the max time, provided we only get
+			// nonnegative deltas
+			assert(ev.time_delta() >= 0);
+			curtime += ev.time_delta();
+		}
+
 		// instruction events just get counted
 		if (!ev.has_memaddr()) {
 			// new instruction
+			// sanity check for overflow
+			if (instr == (1LL << (sizeof(instr)*8)) - 1) {
+				LOG << "error: instruction_count_t overflow, aborting at instr=" << instr << std::endl;
+				return false;
+			}
 			instr++;
 			continue;
 		}
 
 		address_t from = ev.memaddr(), to = ev.memaddr() + ev.width();
 		// Iterate over all accessed bytes
+		// FIXME Keep complete trace information (access width)?
+		//   advantages: may be used for pruning strategies, complete value would be visible; less DB entries
+		//   disadvantages: may need splitting when width varies, lots of special case handling
+		//   Probably implement this in a separate importer when necessary.
 		for (address_t data_address = from; data_address < to; ++data_address) {
-
+			// skip events outside a possibly supplied memory map
-			int instr1 = open_ecs[data_address]; // defaults to 0 if nonexistent
+			if (m_mm && !m_mm->isMatching(data_address)) {
-			int instr2 = instr; // the current instruction
+				continue;
+			}
+			instruction_count_t instr1 =
+				open_ecs[data_address].dyninstr; // defaults to 0 if nonexistent
+			instruction_count_t instr2 = instr; // the current instruction
+			simtime_t time1 = open_ecs[data_address].time;
+			// defaulting to 0 is not such a good idea, memory reads at the
+			// beginning of the trace would get an unnaturally high weight:
+			if (time1 == 0) {
+				time1 = time_trace_start;
+			}
+			simtime_t time2 = curtime;
 
 			// skip zero-sized intervals: these can occur when an instruction
 			// accesses a memory location more than once (e.g., INC, CMPXCHG)
+			// FIXME: look at timing instead?
 			if (instr1 > instr2) {
 				continue;
 			}
@@ -67,62 +105,77 @@ bool Importer::copy_to_database(fail::ProtoIStream &ps) {
 
 			// we now have an interval-terminating R/W event to the memaddr
 			// we're currently looking at; the EC is defined by
-			// data_address [instr1, instr2] (instr_absolute)
+			// data_address, dynamic instruction start/end, the absolute PC at
-			if (!add_trace_event(instr1, instr2, ev)) {
+			// the end, and time start/end
+			if (!add_trace_event(instr1, instr2, time1, time2, ev)) {
 				LOG << "add_trace_event failed" << std::endl;
 				return false;
 			}
 			row_count ++;
-			if (row_count % 1000 == 0) {
+			if (row_count % 10000 == 0) {
-				LOG << "Imported " << row_count << " traces into the database" << std::endl;
+				LOG << "Inserted " << row_count << " trace events into the database" << std::endl;
-			}
-
-			if (ev.accesstype() == ev.READ) {
-				// FIXME this is broken: we must abort after the rightmost R
-				// and must not allow Ws to find their way into the known
-				// results
-				instr_rightmost = instr2;
 			}
 
 			// next interval must start at next instruction; the aforementioned
 			// skipping mechanism wouldn't work otherwise
 			//lastuse_it->second = instr2 + 1;
-			open_ecs[data_address] = instr2 + 1;
+			open_ecs[data_address].dyninstr = instr2 + 1;
+			open_ecs[data_address].time = time2 + 1;
 		}
 	}
 
-	LOG << "Inserted " << row_count << " traces into the database" << std::endl;
+	// Close all open intervals (right end of the fault-space) with fake trace
+	// event.  This ensures we have a rectangular fault space (important for,
+	// e.g., calculating the total SDC rate), and unknown memory accesses after
+	// the end of the trace are properly taken into account: Either with a
+	// "don't care" (a synthetic memory write at the right margin), or a "care"
+	// (synthetic read), the latter resulting in more experiments to be done.
+	for (AddrLastaccessMap::iterator lastuse_it = open_ecs.begin();
+		lastuse_it != open_ecs.end(); ++lastuse_it) {
 
-	// FIXME
+		Trace_Event fake_ev;
-	// close all open intervals (right end of the fault-space) with fake trace event
+		fake_ev.set_memaddr(lastuse_it->first);
-//		for (AddrLastaccessMap::iterator lastuse_it = open_ecs.begin();
+		fake_ev.set_width(1);
-//			 lastuse_it != open_ecs.end(); ++lastuse_it) {
+		fake_ev.set_accesstype(m_faultspace_rightmargin == 'R' ? fake_ev.READ : fake_ev.WRITE);
-//			address_t data_address = lastuse_it->first;
+
-//			int instr1 = lastuse_it->second;
+		instruction_count_t instr1 = lastuse_it->second.dyninstr;
+		simtime_t time1 = lastuse_it->second.time;
+
+		// Why -1?	In most cases it does not make sense to inject before the
+		// very last instruction, as we won't execute it anymore.  This *only*
+		// makes sense if we also inject into parts of the result vector.  This
+		// is not the case in this experiment, and with -1 we'll get a result
+		// comparable to the non-pruned campaign.
+		instruction_count_t instr2 = instr - 1;
+
+		simtime_t time2 = curtime; // -1?
 
-// #if 0
-//			// Why -1?	In most cases it does not make sense to inject before the
-//			// very last instruction, as we won't execute it anymore.  This *only*
-//			// makes sense if we also inject into parts of the result vector.  This
-//			// is not the case in this experiment, and with -1 we'll get a result
-//			// comparable to the non-pruned campaign.
-//			int instr2 = instr - 1;
 // #else
-//			// EcosKernelTestCampaign only variant: fault space ends with the last FI experiment
+//		// EcosKernelTestCampaign only variant: fault space ends with the last FI experiment
-//			int instr2 = instr_rightmost;
+//		FIXME probably implement this with cmdline parameter FAULTSPACE_CUTOFF
+//		int instr2 = instr_rightmost;
 // #endif
-//			// zero-sized?	skip.
-//			if (instr1 > instr2) {
-//				continue;
-//			}
 
-//			add_trace_event(variant_id, instr1, instr2, 
+		// zero-sized?	skip.
-//				data_address, 1, 'W', 0,
+		// FIXME: look at timing instead?
-//				0, 0, 0, 0, 0, true);
+		if (instr1 > instr2) {
-//		}
+			continue;
+		}
 
-//		fsp.fini();
+		if (!add_trace_event(instr1, instr2, time1, time2, fake_ev, true)) {
+			LOG << "add_trace_event failed" << std::endl;
+			return false;
+		}
+		++row_count_fake;
+	}
+
+	LOG << "trace duration: " << (curtime - time_trace_start) << " ticks" << std::endl;
+	LOG << "Inserted " << row_count << " trace events (+" << row_count_fake
+	    << " fake events) into the database" << std::endl;
+
+	// TODO: (configurable) sanity checks
+	// PC-based fault space rectangular, covered, and non-overlapping?
+	// (same for timing-based fault space?)
 
 	return true;
 }
-

tools/import-trace/Importer.hpp

@@ -7,17 +7,19 @@
 #include "util/ElfReader.hpp"
 #include "sal/SALConfig.hpp"
 #include "util/Database.hpp"
+#include "util/MemoryMap.hpp"
 #include "comm/TracePlugin.pb.h"
 
-
 class Importer {
 protected:
 	int m_variant_id;
 	fail::ElfReader *m_elf;
+	fail::MemoryMap *m_mm;
+	char m_faultspace_rightmargin;
 	fail::Database *db;
 
 public:
-	typedef unsigned instruction_count_t;
+	typedef unsigned instruction_count_t; //!< not big enough for some benchmarks
 
 	bool init(const std::string &variant, const std::string &benchmark, fail::Database *db);
 
@@ -25,12 +27,16 @@ public:
 	virtual bool copy_to_database(fail::ProtoIStream &ps);
 	virtual bool clear_database();
 	virtual bool add_trace_event(instruction_count_t begin, instruction_count_t end,
+								 fail::simtime_t time_begin, fail::simtime_t time_end,
 								 const Trace_Event &event, bool is_fake = false) = 0;
 
 	void set_elf_file(fail::ElfReader *elf) { m_elf = elf; }
+	void set_memorymap(fail::MemoryMap *mm) { m_mm = mm; }
+	void set_faultspace_rightmargin(char accesstype) { m_faultspace_rightmargin = accesstype; }
 protected:
 private:
-	typedef std::map<fail::address_t, instruction_count_t> AddrLastaccessMap;
+	struct leftmargin_info_t { instruction_count_t dyninstr; fail::simtime_t time; };
+	typedef std::map<fail::address_t, leftmargin_info_t> AddrLastaccessMap;
 };
 
 #endif

tools/import-trace/main.cc

@@ -3,6 +3,7 @@
 #include "util/CommandLine.hpp"
 #include "util/Database.hpp"
 #include "util/ElfReader.hpp"
+#include "util/MemoryMap.hpp"
 #include "util/gzstream/gzstream.h"
 #include "util/Logger.hpp"
 #include <fstream>
@@ -49,6 +50,7 @@ int main(int argc, char *argv[]) {
 	std::string trace_file, username, hostname, database, benchmark;
 	std::string variant, importer_args;
 	ElfReader *elf_file = 0;
+	MemoryMap *memorymap = 0;
 
 	// Manually fill the command line option parser
 	CommandLine &cmd = CommandLine::Inst();
@@ -56,23 +58,47 @@ int main(int argc, char *argv[]) {
 		cmd.add_args(argv[i]);
 
 	cmd.addOption("", "", Arg::None, "USAGE: import-trace [options]");
-	CommandLine::option_handle HELP = cmd.addOption("h", "help", Arg::None, "-h/--help\t Print usage and exit");
+	CommandLine::option_handle HELP =
-	CommandLine::option_handle TRACE_FILE	= cmd.addOption("t", "trace-file", Arg::Required,
+		cmd.addOption("h", "help", Arg::None, "-h/--help \tPrint usage and exit");
-															"-t/--trace-file\t File to load the execution trace from\n");
+	CommandLine::option_handle TRACE_FILE =
+		cmd.addOption("t", "trace-file", Arg::Required,
+			"-t/--trace-file \tFile to load the execution trace from\n");
 
 	// setup the database command line options
 	Database::cmdline_setup();
 
-	CommandLine::option_handle VARIANT	 = cmd.addOption("v", "variant", Arg::Required,
+	CommandLine::option_handle VARIANT =
-															"-v/--variant\t Variant label (default: \"none\")");
+		cmd.addOption("v", "variant", Arg::Required,
-	CommandLine::option_handle BENCHMARK = cmd.addOption("b", "benchmark", Arg::Required,
+			"-v/--variant \tVariant label (default: \"none\")");
-														 "-b/--benchmark\t Benchmark label (default: \"none\")\n");
+	CommandLine::option_handle BENCHMARK =
-	CommandLine::option_handle IMPORTER	  = cmd.addOption("i", "importer", Arg::Required,
+		cmd.addOption("b", "benchmark", Arg::Required,
-															"-i/--importer\t Which import method to use (default: BasicImporter)");
+			"-b/--benchmark \tBenchmark label (default: \"none\")\n");
-	CommandLine::option_handle IMPORTER_ARGS	  = cmd.addOption("I", "importer-args", Arg::Required,
+	CommandLine::option_handle IMPORTER =
-															"-I/--importer-args\t Which import method to use (default: "")");
+		cmd.addOption("i", "importer", Arg::Required,
-	CommandLine::option_handle ELF_FILE  = cmd.addOption("e", "elf-file", Arg::Required,
+			"-i/--importer \tWhich import method to use (default: BasicImporter)");
-														 "-e/--elf-file\t ELF File (default: UNSET)");
+	CommandLine::option_handle IMPORTER_ARGS =
+		cmd.addOption("I", "importer-args", Arg::Required,
+			"-I/--importer-args \tWhich import method to use (default: "")");
+	CommandLine::option_handle ELF_FILE =
+		cmd.addOption("e", "elf-file", Arg::Required,
+			"-e/--elf-file \tELF File (default: UNSET)");
+	CommandLine::option_handle MEMORYMAP =
+		cmd.addOption("m", "memorymap", Arg::Required,
+			"-m/--memorymap \tMemory map to intersect with trace (may be used more than once; default: UNSET)");
+
+	// variant 1: care (synthetic Rs)
+	// variant 2: don't care (synthetic Ws)
+	CommandLine::option_handle FAULTSPACE_RIGHTMARGIN =
+		cmd.addOption("", "faultspace-rightmargin", Arg::Required,
+			"--faultspace-rightmargin \tMemory access type (R or W) to "
+			"complete fault space at the right margin "
+			"(default: W -- don't care)");
+	// (don't) cutoff at first R
+	// (don't) cutoff at last R
+	//CommandLine::option_handle FAULTSPACE_CUTOFF =
+	//	cmd.addOption("", "faultspace-cutoff-end", Arg::Required,
+	//		"--faultspace-cutoff-end \tCut off fault space end (no, lastr) "
+	//		"(default: no)");
 
 
 	if (!cmd.parse()) {
@@ -129,14 +155,36 @@ int main(int argc, char *argv[]) {
 	if (cmd[ELF_FILE].count() > 0) {
 		elf_file = new ElfReader(cmd[ELF_FILE].first()->arg);
 	}
+	importer->set_elf_file(elf_file);
 
+	if (cmd[MEMORYMAP].count() > 0) {
+		memorymap = new MemoryMap();
+		for (option::Option *o = cmd[MEMORYMAP]; o; o = o->next()) {
+			if (!memorymap->readFromFile(o->arg)) {
+				LOG << "failed to load memorymap " << o->arg << endl;
+			}
+		}
+	}
+	importer->set_memorymap(memorymap);
 
+	if (cmd[FAULTSPACE_RIGHTMARGIN].count() > 0) {
+		std::string rightmargin(cmd[FAULTSPACE_RIGHTMARGIN].first()->arg);
+		if (rightmargin == "W") {
+			importer->set_faultspace_rightmargin('W');
+		} else if (rightmargin == "R") {
+			importer->set_faultspace_rightmargin('R');
+		} else {
+			LOG << "unknown memory access type '" << rightmargin << "', using default" << endl;
+			importer->set_faultspace_rightmargin('W');
+		}
+	} else {
+		importer->set_faultspace_rightmargin('W');
+	}
 
 	if (!importer->init(variant, benchmark, db)) {
 		LOG << "importer->init() failed" << endl;
 		exit(-1);
 	}
-	importer->set_elf_file(elf_file);
 
 	////////////////////////////////////////////////////////////////
 	// Do the actual import