Merge branch 'master' of github.com:simbricks/simbricks

trace/log_parser.cc

@@ -33,7 +33,9 @@
 
 namespace bio = boost::iostreams;
 
-log_parser::log_parser() : inf(nullptr), gz_file(nullptr), gz_in(nullptr) {
+log_parser::log_parser() : inf(nullptr), gz_file(nullptr), gz_in(nullptr),
+    buf_len(0), buf_pos(0)
+{
   buf = new char[block_size];
 }
 
@@ -95,13 +97,12 @@ size_t log_parser::try_line() {
 }
 
 bool log_parser::next_event() {
-  cur_event = nullptr;
-
   if (buf_len == 0 && !next_block()) {
     std::cerr << "escape 0" << std::endl;
     return false;
   }
 
+  got_event = false;
   do {
     size_t newpos = try_line();
     if (!newpos) {
@@ -117,7 +118,19 @@ bool log_parser::next_event() {
       }
     }
     buf_pos = newpos;
-  } while (!cur_event);
+  } while (!got_event);
 
   return true;
 }
+
+void log_parser::read_coro(coro_t::push_type &sink_) {
+  sink = &sink_;
+  while (next_event());
+}
+
+void log_parser::yield(std::shared_ptr<event> ev)
+{
+  got_event = true;
+  ev->source = this;
+  (*sink)(ev);
+}
\ No newline at end of file

trace/nicbm.cc

@@ -47,35 +47,35 @@ void nicbm_parser::process_line(char *line, size_t line_len) {
   if (p.consume_str("read(off=0x")) {
     if (p.consume_hex(addr) && p.consume_str(", len=") && p.consume_dec(len) &&
         p.consume_str(", val=0x") && p.consume_hex(val)) {
-      cur_event = new e_nic_mmio_r(ts, addr, len, val);
+      yield(std::make_shared<e_nic_mmio_r>(ts, addr, len, val));
     }
   } else if (p.consume_str("write(off=0x")) {
     if (p.consume_hex(addr) && p.consume_str(", len=") && p.consume_dec(len) &&
         p.consume_str(", val=0x") && p.consume_hex(val)) {
-      cur_event = new e_nic_mmio_w(ts, addr, len, val);
+      yield(std::make_shared<e_nic_mmio_w>(ts, addr, len, val));
     }
   } else if (p.consume_str("issuing dma op 0x")) {
     if (p.consume_hex(id) && p.consume_str(" addr ") && p.consume_hex(addr) &&
         p.consume_str(" len ") && p.consume_hex(len)) {
-      cur_event = new e_nic_dma_i(ts, id, addr, len);
+      yield(std::make_shared<e_nic_dma_i>(ts, id, addr, len));
     }
   } else if (p.consume_str("completed dma read op 0x") ||
              p.consume_str("completed dma write op 0x")) {
     if (p.consume_hex(id) && p.consume_str(" addr ") && p.consume_hex(addr) &&
         p.consume_str(" len ") && p.consume_hex(len)) {
-      cur_event = new e_nic_dma_c(ts, id);
+      yield(std::make_shared<e_nic_dma_c>(ts, id));
     }
   } else if (p.consume_str("issue MSI-X interrupt vec ")) {
     if (p.consume_dec(id)) {
-      cur_event = new e_nic_msix(ts, id);
+      yield(std::make_shared<e_nic_msix>(ts, id));
     }
   } else if (p.consume_str("eth tx: len ")) {
     if (p.consume_dec(len)) {
-      cur_event = new e_nic_tx(ts, len);
+      yield(std::make_shared<e_nic_tx>(ts, len));
     }
   } else if (p.consume_str("eth rx: port 0 len ")) {
     if (p.consume_dec(len)) {
-      cur_event = new e_nic_rx(ts, len);
+      yield(std::make_shared<e_nic_rx>(ts, len));
     }
 #if 1
   }

trace/parser.h

@@ -114,4 +114,20 @@ class parser {
     pos = end + 1;
     return true;
   }
+
+  inline bool skip_until_after(const char *s) {
+    size_t s_len = strlen(s);
+    if (pos + s_len > buf_len)
+      return false;
+
+    size_t end = pos;
+    for (; end <= buf_len - s_len; end++) {
+      if (buf[end] == s[0] && !memcmp(buf + end, s, s_len)) {
+        pos = end + s_len;
+        return true;
+      }
+    }
+
+    return false;
+  }
 };

trace/process.cc

@@ -24,18 +24,143 @@
 
 #include "trace/process.h"
 
+#include <boost/bind.hpp>
+#include <boost/foreach.hpp>
 #include <iostream>
+#include <memory>
+#include <vector>
 
 #include "trace/events.h"
 #include "trace/parser.h"
 
-struct log_parser_cmp {
-  bool operator()(const log_parser *l, const log_parser *r) const {
-    return l->cur_event->ts < r->cur_event->ts;
+template <typename T>
+struct event_pair_cmp {
+  bool operator()(const std::pair<T, std::shared_ptr<event>> l,
+                  const std::pair<T, std::shared_ptr<event>> r) const {
+    return l.second->ts < r.second->ts;
   }
 };
 
+/** merge multiple event streams into one ordered by timestamp */
+void MergeEvents(coro_t::push_type &sink,
+                 std::set<coro_t::pull_type *> &all_parsers) {
+  typedef std::pair<coro_t::pull_type *, std::shared_ptr<event>> itpair_t;
+
+  // create set of pairs of source and next event, ordered by timestamp of next
+  // event.
+  std::set<itpair_t, event_pair_cmp<coro_t::pull_type *>> active;
+
+  // initially populate the set
+  for (auto p : all_parsers) {
+    if (*p) {
+      auto ev = p->get();
+      (*p)();
+      active.insert(std::make_pair(p, ev));
+    }
+  }
+
+  // iterate until there are no more active sources
+  while (!active.empty()) {
+    // grab event with lowest timestamp
+    auto i = active.begin();
+    itpair_t p = *i;
+    active.erase(i);
+
+    // emit event
+    sink(p.second);
+
+    // check if there is another event in the source, if so, re-enqueue
+    if (*p.first) {
+      auto ev = p.first->get();
+      (*p.first)();
+      active.insert(std::make_pair(p.first, ev));
+    }
+  }
+}
+
+void Printer(coro_t::pull_type &source) {
+  uint64_t ts_off = 0;
+  for (auto ev: source) {
+    std::shared_ptr<EHostCall> hc;
+    std::shared_ptr<EHostInstr> hi;
+    if ((hi = std::dynamic_pointer_cast<EHostInstr>(ev))) {
+      continue;
+    } else if ((hc = std::dynamic_pointer_cast<EHostCall>(ev)) &&
+        strcmp(ev->source->label, "C") &&
+        hc->fun == "__sys_sendto") {
+      std::cout << "---------- REQ START:" << ev->ts << std::endl;
+      ts_off = ev->ts;
+    }
+
+    std::cout << ev->source->label << " ";
+
+    ev->ts -= ts_off;
+    ev->ts /= 1000;
+    ev->dump(std::cout);
+  }
+}
+
+void Consumer(coro_t::pull_type &source) {
+  for (auto ev: source) {
+  }
+}
+
+struct InstStatsData {
+  const char *label;
+  uint64_t nInsts;
+  uint64_t tMin;
+  uint64_t tMax;
+  uint64_t tMean;
+  std::vector <uint64_t> tAll;
+};
+
+void InstStats(coro_t::push_type &sink, coro_t::pull_type &source,
+    struct InstStatsData &data) {
+  uint64_t last_ts = 0;
+  uint64_t first_ts = 0;
+  data.nInsts = 0;
+  for (auto ev: source) {
+    std::shared_ptr<EHostInstr> hi;
+    if ((hi = std::dynamic_pointer_cast<EHostInstr>(ev))) {
+      if (!last_ts) {
+        // first instruction
+        first_ts = hi->ts;
+        data.tMin = UINT64_MAX;
+        data.tMax = 0;
+      } else {
+        uint64_t lat = hi->ts - last_ts;
+
+        data.nInsts++;
+        data.tAll.push_back(lat);
+        if (lat < data.tMin)
+          data.tMin = lat;
+        if (lat > data.tMax)
+          data.tMax = lat;
+
+        /*if (lat > 4000)
+          std::cout << "ILAT: " << lat  << " " << std::hex << hi->pc <<
+              std::dec << "  " << hi->ts << std::endl;*/
+        }
+      last_ts = hi->ts;
+      //last_pc = hi->pc;
+    }
+    sink(ev);
+  }
+
+  if (data.nInsts != 0)
+    data.tMean = (last_ts - first_ts) / data.nInsts;
+  else
+    data.tMean = 0;
+}
+
+
 int main(int argc, char *argv[]) {
+  if (argc != 5) {
+    std::cerr << "Usage: process CLIENT_HLOG CLIENT_NLOG SERVER_HLOG "
+                  "SERVER_CLOG" << std::endl;
+    return 1;
+  }
+
   sym_map syms;
   syms.add_filter("entry_SYSCALL_64");
   syms.add_filter("__do_sys_gettimeofday");
@@ -59,51 +184,58 @@ int main(int argc, char *argv[]) {
   std::cerr << "map loaded" << std::endl;
 
   std::set<log_parser *> all_parsers;
+
   gem5_parser ch(syms);
+  ch.open(argv[1]);
+  ch.label = "C";
+  all_parsers.insert(&ch);
+
   gem5_parser sh(syms);
+  sh.open(argv[3]);
+  sh.label = "S";
+  all_parsers.insert(&sh);
+
   nicbm_parser cn;
-  nicbm_parser sn;
-  ch.open(argv[1]);
   cn.open(argv[2]);
-  sh.open(argv[3]);
-  sn.open(argv[4]);
-  ch.label = cn.label = "C";
-  sh.label = sn.label = "S";
-  all_parsers.insert(&ch);
+  cn.label = "C";
   all_parsers.insert(&cn);
-  all_parsers.insert(&sh);
+
+  nicbm_parser sn;
+  sn.open(argv[4]);
+  sn.label = "S";
   all_parsers.insert(&sn);
 
-  std::set<log_parser *, log_parser_cmp> active_parsers;
+  std::cerr << "Opened all" << std::endl;
 
+  std::set<coro_t::pull_type *> sources;
+  std::set<InstStatsData *> isds;
   for (auto p : all_parsers) {
-    if (p->next_event() && p->cur_event)
-      active_parsers.insert(p);
+    coro_t::pull_type *src = new coro_t::pull_type(
+      boost::bind(&log_parser::read_coro, boost::ref(*p), _1));
+      InstStatsData *isd = new InstStatsData;
+      isd->label = p->label;
+    coro_t::pull_type *istat = new coro_t::pull_type(
+      boost::bind(InstStats, _1, boost::ref(*src), boost::ref(*isd)));
+    sources.insert(istat);
+    isds.insert(isd);
   }
 
-  uint64_t ts_off = 0;
-  while (!active_parsers.empty()) {
-    auto i = active_parsers.begin();
-    log_parser *p = *i;
-    active_parsers.erase(i);
-
-    EHostCall *hc;
-    event *ev = p->cur_event;
-    if (p == &ch && (hc = dynamic_cast<EHostCall *>(ev)) &&
-        hc->fun == "__sys_sendto") {
-      std::cout << "---------- REQ START:" << ev->ts << std::endl;
-      ts_off = ev->ts;
-    }
-
-    std::cout << p->label << " ";
+  coro_t::pull_type merged(boost::bind(MergeEvents, _1, boost::ref(sources)));
+  Consumer(merged);
 
-    ev->ts -= ts_off;
-    ev->ts /= 1000;
-    ev->dump(std::cout);
+  std::cout << "Stats:" << std::endl;
+  for (auto isd : isds) {
+    if (!isd->nInsts)
+      continue;
 
-    delete ev;
+    std::sort(isd->tAll.begin(), isd->tAll.end());
 
-    if (p->next_event() && p->cur_event)
-      active_parsers.insert(p);
+    std::cout << " - " << isd->label << std::endl;
+    std::cout << "    Instrs: " << isd->nInsts << std::endl;
+    std::cout << "    Mean instr time: " << isd->tMean << std::endl;
+    for (int i = 0; i <= 100; i += 1)
+      std::cout << "    P[" << i << "] instr time: " <<
+          isd->tAll[isd->tAll.size() * i / 100 - (i == 100 ? 1 : 0)] <<
+          std::endl;
   }
 }

trace/process.h

@@ -24,13 +24,17 @@
 
 #pragma once
 
+#include <boost/coroutine2/all.hpp>
 #include <boost/iostreams/filtering_streambuf.hpp>
 #include <map>
+#include <memory>
 #include <set>
 #include <string>
 
 #include "trace/events.h"
 
+typedef boost::coroutines2::asymmetric_coroutine<std::shared_ptr<event>> coro_t;
+
 class sym_map {
  protected:
   bool filter_en;
@@ -67,25 +71,31 @@ class log_parser {
   size_t buf_len;
   size_t buf_pos;
 
+  coro_t::push_type *sink;
+  bool got_event;
+
   bool next_block();
   size_t try_line();
   virtual void process_line(char *line, size_t len) = 0;
 
+  bool next_event();
+  void yield(std::shared_ptr<event> ev);
+
  public:
   const char *label;
-  event *cur_event;
 
   log_parser();
   virtual ~log_parser();
   void open(const char *path);
   void open_gz(const char *path);
 
-  bool next_event();
+  void read_coro(coro_t::push_type &sink_);
 };
 
 class gem5_parser : public log_parser {
  protected:
   sym_map &syms;
+  std::shared_ptr<EHostInstr> prevInstr;
 
   virtual void process_line(char *line, size_t len);
   void process_msg(uint64_t ts, char *comp_name, size_t comp_name_len,

trace/rules.mk

@@ -26,7 +26,8 @@ bin_trace_process := $(d)process
 
 OBJS := $(addprefix $(d), process.o sym_map.o log_parser.o gem5.o nicbm.o)
 
-$(bin_trace_process): $(OBJS) -lboost_iostreams
+$(bin_trace_process): $(OBJS) -lboost_iostreams -lboost_coroutine \
+	-lboost_context
 
 CLEAN := $(bin_trace_process) $(OBJS)
 ALL := $(bin_trace_process)