tracing: factor out generic log parser

trace/Makefile

 CXXFLAGS := -O3 -Wall -Wextra -g -Wno-unused-parameter -fpermissive
 LDLIBS := -lboost_iostreams
 
-process: process.o sym_map.o
+process: process.o sym_map.o log_parser.o gem5.o
 process: CC=$(CXX)
 
 clean:

trace/events.h

 #pragma once
 
-class Event {
+class event {
   public:
     uint64_t ts;
 
-    Event(uint64_t ts_)
+    event(uint64_t ts_)
         : ts(ts_)
     {
     }
@@ -12,12 +12,12 @@ class Event {
     virtual void dump(std::ostream &out) = 0;
 };
 
-class EHostCall : public Event {
+class EHostCall : public event {
   public:
     const std::string &fun;
 
     EHostCall(uint64_t ts_, const std::string &fun_)
-        : Event(ts_), fun(fun_)
+        : event(ts_), fun(fun_)
     {
     }
 
@@ -27,12 +27,12 @@ class EHostCall : public Event {
     }
 };
 
-class EHostMsiX : public Event {
+class EHostMsiX : public event {
   public:
     uint16_t vec;
 
     EHostMsiX(uint64_t ts_, uint16_t vec_)
-        : Event(ts_), vec(vec_)
+        : event(ts_), vec(vec_)
     {
     }
 
@@ -42,14 +42,14 @@ class EHostMsiX : public Event {
     }
 };
 
-class EHostDmaR : public Event {
+class EHostDmaR : public event {
   public:
     uint64_t id;
     uint64_t addr;
     uint64_t size;
 
     EHostDmaR(uint64_t ts_, uint64_t id_, uint64_t addr_, uint64_t size_)
-        : Event(ts_), id(id_), addr(addr_), size(size_)
+        : event(ts_), id(id_), addr(addr_), size(size_)
     {
     }
 
@@ -60,14 +60,14 @@ class EHostDmaR : public Event {
     }
 };
 
-class EHostDmaW : public Event {
+class EHostDmaW : public event {
   public:
     uint64_t id;
     uint64_t addr;
     uint64_t size;
 
     EHostDmaW(uint64_t ts_, uint64_t id_, uint64_t addr_, uint64_t size_)
-        : Event(ts_), id(id_), addr(addr_), size(size_)
+        : event(ts_), id(id_), addr(addr_), size(size_)
     {
     }
 
@@ -78,12 +78,12 @@ class EHostDmaW : public Event {
     }
 };
 
-class EHostDmaC : public Event {
+class EHostDmaC : public event {
   public:
     uint64_t id;
 
     EHostDmaC(uint64_t ts_, uint64_t id_)
-        : Event(ts_), id(id_)    {
+        : event(ts_), id(id_)    {
     }
 
     virtual void dump(std::ostream &out)
@@ -92,14 +92,14 @@ class EHostDmaC : public Event {
     }
 };
 
-class EHostMmioR : public Event {
+class EHostMmioR : public event {
   public:
     uint64_t id;
     uint64_t addr;
     uint64_t size;
 
     EHostMmioR(uint64_t ts_, uint64_t id_, uint64_t addr_, uint64_t size_)
-        : Event(ts_), id(id_), addr(addr_), size(size_)
+        : event(ts_), id(id_), addr(addr_), size(size_)
     {
     }
 
@@ -110,14 +110,14 @@ class EHostMmioR : public Event {
     }
 };
 
-class EHostMmioW : public Event {
+class EHostMmioW : public event {
   public:
     uint64_t id;
     uint64_t addr;
     uint64_t size;
 
     EHostMmioW(uint64_t ts_, uint64_t id_, uint64_t addr_, uint64_t size_)
-        : Event(ts_), id(id_), addr(addr_), size(size_)
+        : event(ts_), id(id_), addr(addr_), size(size_)
     {
     }
 
@@ -128,12 +128,12 @@ class EHostMmioW : public Event {
     }
 };
 
-class EHostMmioC : public Event {
+class EHostMmioC : public event {
   public:
     uint64_t id;
 
     EHostMmioC(uint64_t ts_, uint64_t id_)
-        : Event(ts_), id(id_)    {
+        : event(ts_), id(id_)    {
     }
 
     virtual void dump(std::ostream &out)

trace/gem5.cpp

+#include <iostream>
+
+#include "events.h"
+#include "parser.h"
+#include "process.h"
+
+namespace bio = boost::iostreams;
+
+gem5_parser::gem5_parser(sym_map &syms_)
+    : syms(syms_)
+{
+}
+
+gem5_parser::~gem5_parser()
+{
+}
+
+void gem5_parser::process_msg(uint64_t ts, char *comp_name,
+        size_t comp_name_len, char *msg, size_t msg_len)
+{
+    parser p(msg, msg_len, 0);
+
+    /*if (ts < ts_first)
+        return;*/
+
+    if (comp_name_len == 18 && !memcmp(comp_name, "system.switch_cpus", 18)) {
+        //cpu_lines++;
+        if (!p.consume_str("T0 : 0x"))
+            return;
+
+        uint64_t addr;
+        if (!p.consume_hex(addr) || p.consume_char('.'))
+            return;
+
+        if (const std::string *s = syms.lookup(addr)) {
+            cur_event = new EHostCall(ts, *s);
+        }
+    } else if (comp_name_len == 18 && !memcmp(comp_name, "system.pc.ethernet", 18)) {
+        //eth_lines++;
+
+        /*std::cout.write(msg, msg_len);
+        std::cout << std::endl;*/
+
+        if (!p.consume_str("cosim: "))
+            return;
+
+        uint64_t id = 0;
+        uint64_t addr = 0;
+        uint64_t size = 0;
+        if (p.consume_str("received ")) {
+            if (p.consume_str("MSI-X intr vec ") && p.consume_dec(id)) {
+                cur_event = new EHostMsiX(ts, id);
+            } else if (p.consume_str("DMA read id ") && p.consume_dec(id) &&
+                    p.consume_str(" addr ") && p.consume_hex(addr) &&
+                    p.consume_str(" size ") && p.consume_dec(size))
+            {
+                // cosim: received DMA read id 94113551511792 addr 23697ad60 size 20
+                cur_event = new EHostDmaR(ts, id, addr, size);
+            } else if (p.consume_str("DMA write id ") && p.consume_dec(id) &&
+                    p.consume_str(" addr ") && p.consume_hex(addr) &&
+                    p.consume_str(" size ") && p.consume_dec(size))
+            {
+                // cosim: received DMA write id 94113551528032 addr 236972000 size 4
+                cur_event = new EHostDmaW(ts, id, addr, size);
+            } else if (p.consume_str("read completion id ") &&
+                    p.consume_dec(id))
+            {
+                // cosim: received read completion id 94583743418112
+                cur_event = new EHostMmioC(ts, id);
+            } else if (p.consume_str("write completion id ") &&
+                    p.consume_dec(id))
+            {
+                // cosim: received write completion id 94583743418736
+                cur_event = new EHostMmioC(ts, id);
+            }
+        } else if (p.consume_str("sending ")) {
+            if (p.consume_str("read addr ") && p.consume_hex(addr) &&
+                    p.consume_str(" size ") && p.consume_dec(size) &&
+                    p.consume_str(" id ") && p.consume_dec(id))
+            {
+                // cosim: sending read addr c012a500 size 4 id 94583743418112
+                cur_event = new EHostMmioR(ts, id, addr, size);
+            } else if (p.consume_str("write addr ") && p.consume_hex(addr) &&
+                    p.consume_str(" size ") && p.consume_dec(size) &&
+                    p.consume_str(" id ") && p.consume_dec(id))
+            {
+                // cosim: sending write addr c0108000 size 4 id 94584005188256
+                cur_event = new EHostMmioW(ts, id, addr, size);
+            }
+        } else if (p.consume_str("completed DMA id ") && p.consume_dec(id)) {
+            cur_event = new EHostDmaC(ts, id);
+        }
+    }
+
+    /*if (!cur_event) {
+        std::cout.write(msg, msg_len);
+        std::cout << std::endl;
+    }*/
+}
+
+
+void gem5_parser::process_line(char *line, size_t line_len)
+{
+    size_t pos = 0;
+
+    size_t line_start = pos;
+    size_t comp_name_start = 0;
+    size_t comp_name_len = 0;
+    bool valid = true;
+
+    // eat spaces
+    for (; pos < line_len && line[pos] == ' '; pos++);
+
+    // parse ts
+    uint64_t ts = 0;
+    size_t ts_len = 0;
+    for (; pos < line_len && line[pos] >= '0' && line[pos] <= '9'; pos++) {
+        ts = ts * 10 + line[pos] - '0';
+        ts_len++;
+    }
+    if (ts_len == 0) {
+        valid = false;
+        goto out;
+    }
+
+    // skip colon
+    if (line[pos] != ':') {
+        valid = false;
+        goto out;
+    }
+    pos++;
+
+    // skip space
+    if (line[pos] != ' ') {
+        valid = false;
+        goto out;
+    }
+    pos++;
+
+    comp_name_start = pos;
+    for (; pos < line_len && line[pos] != ' ' && line[pos] != '\n'; pos++,
+            comp_name_len++);
+    // skip space
+    if (line[pos] != ' ') {
+        valid = false;
+        goto out;
+    }
+    if (line[pos - 1] != ':') {
+        valid = false;
+        goto out;
+    }
+    comp_name_len--;
+    pos++;
+
+out:
+    size_t msg_start = pos;
+    size_t msg_len = line_len - msg_start;
+    line[line_len - 1] = 0;
+    if (valid) {
+        process_msg(ts, line + comp_name_start, comp_name_len, line + msg_start,
+                msg_len);
+    } else {
+        std::cout << line + line_start << std::endl;
+        std::cout << pos << std::endl;
+    }
+
+    return;
+}

trace/log_parser.cpp

+#include <fstream>
+#include <iostream>
+#include <boost/iostreams/filtering_streambuf.hpp>
+#include <boost/iostreams/filter/gzip.hpp>
+
+#include "events.h"
+#include "parser.h"
+#include "process.h"
+
+namespace bio = boost::iostreams;
+
+log_parser::log_parser()
+    : inf(nullptr), gz_file(nullptr), gz_in(nullptr)
+{
+    buf = new char[block_size];
+}
+
+log_parser::~log_parser()
+{
+    if (inf)
+        delete inf;
+    if (gz_file) {
+        delete gz_in;
+        delete gz_file;
+    }
+    delete[] buf;
+}
+
+bool log_parser::next_block()
+{
+    if (buf_pos == buf_len) {
+        buf_pos = 0;
+    } else {
+        memmove(buf, buf + buf_pos, buf_len - buf_pos);
+        buf_pos = buf_len - buf_pos;
+    }
+
+    inf->read(buf + buf_pos, block_size - buf_pos);
+    size_t newlen = inf->gcount();
+
+    buf_len = buf_pos + newlen;
+    buf_pos = 0;
+
+    return newlen != 0;
+}
+
+void log_parser::open(const char *path)
+{
+    inf = new std::ifstream(path, std::ios_base::in);
+}
+
+void log_parser::open_gz(const char *path)
+{
+    gz_file = new std::ifstream(path, std::ios_base::in |
+            std::ios_base::binary);
+    gz_in = new bio::filtering_streambuf<bio::input>();
+
+    gz_in->push(bio::gzip_decompressor());
+    gz_in->push(*gz_file);
+
+    inf = new std::istream(gz_in);
+}
+
+size_t log_parser::try_line()
+{
+    size_t pos = buf_pos;
+    size_t line_len = 0;
+
+    for (; pos < buf_len && buf[pos] != '\n'; pos++, line_len++);
+    if (pos >= buf_len) {
+        // line is incomplete
+        return 0;
+    }
+
+    process_line(buf + buf_pos, line_len);
+
+    return pos + 1;
+}
+
+
+bool log_parser::next_event()
+{
+    cur_event = nullptr;
+
+    if (buf_len == 0 && !next_block()) {
+        std::cerr << "escape 0" << std::endl;
+        return false;
+    }
+
+    do {
+        size_t newpos = try_line();
+        if (!newpos) {
+            if (!next_block()) {
+                std::cerr << "escape 1" << std::endl;
+                return false;
+            }
+
+            newpos = try_line();
+            if (!newpos) {
+                std::cerr << "escape 2" << std::endl;
+                return false;
+            }
+        }
+        buf_pos = newpos;
+    } while (!cur_event);
+
+    return true;
+}

trace/process.cpp

-#include <fstream>
 #include <iostream>
-#include <map>
-#include <set>
-#include <string>
-#include <boost/iostreams/filtering_streambuf.hpp>
-#include <boost/iostreams/copy.hpp>
-#include <boost/iostreams/filter/gzip.hpp>
 
 #include "events.h"
 #include "parser.h"
 #include "process.h"
 
-namespace bio = boost::iostreams;
-
-sym_map sym_map;
-
-size_t cpu_lines = 0;
-size_t eth_lines = 0;
-uint64_t ts_first = 2686011870000ULL;//2655884308815ULL;
-
-
-void process_msg(uint64_t ts, char *comp_name, size_t comp_name_len, char *msg,
-        size_t msg_len)
+int main(int argc, char *argv[])
 {
-    Event *e = nullptr;
-    parser p(msg, msg_len, 0);
-
-
-    /*if (ts < ts_first)
-        return;*/
-
-    if (comp_name_len == 18 && !memcmp(comp_name, "system.switch_cpus", 18)) {
-        cpu_lines++;
-        if (!p.consume_str("T0 : 0x"))
-            return;
-
-        uint64_t addr;
-        if (!p.consume_hex(addr) || p.consume_char('.'))
-            return;
-
-        if (const std::string *s = sym_map.lookup(addr)) {
-            e = new EHostCall(ts, *s);
-        }
-    } else if (comp_name_len == 18 && !memcmp(comp_name, "system.pc.ethernet", 18)) {
-        eth_lines++;
-
-        /*std::cout.write(msg, msg_len);
-        std::cout << std::endl;*/
-
-        if (!p.consume_str("cosim: "))
-            return;
+    sym_map syms;
+    syms.add_filter("entry_SYSCALL_64");
+    syms.add_filter("__do_sys_gettimeofday");
+    syms.add_filter("__sys_sendto");
+    syms.add_filter("i40e_lan_xmit_frame");
+    syms.add_filter("syscall_return_via_sysret");
+    syms.add_filter("__sys_recvfrom");
+    syms.add_filter("deactivate_task");
+    syms.add_filter("interrupt_entry");
+    syms.add_filter("i40e_msix_clean_rings");
+    syms.add_filter("napi_schedule_prep");
+    syms.add_filter("__do_softirq");
+    syms.add_filter("trace_napi_poll");
+    syms.add_filter("net_rx_action");
+    syms.add_filter("i40e_napi_poll");
+    syms.add_filter("activate_task");
+    syms.add_filter("copyout");
+
+    syms.load_file("linux.dump", 0);
+    syms.load_file("i40e.dump", 0xffffffffa0000000ULL);
+    std::cerr << "map loaded" << std::endl;
 
-        uint64_t id = 0;
-        uint64_t addr = 0;
-        uint64_t size = 0;
-        if (p.consume_str("received ")) {
-            if (p.consume_str("MSI-X intr vec ") && p.consume_dec(id)) {
-                e = new EHostMsiX(ts, id);
-            } else if (p.consume_str("DMA read id ") && p.consume_dec(id) &&
-                    p.consume_str(" addr ") && p.consume_hex(addr) &&
-                    p.consume_str(" size ") && p.consume_dec(size))
-            {
-                // cosim: received DMA read id 94113551511792 addr 23697ad60 size 20
-                e = new EHostDmaR(ts, id, addr, size);
-            } else if (p.consume_str("DMA write id ") && p.consume_dec(id) &&
-                    p.consume_str(" addr ") && p.consume_hex(addr) &&
-                    p.consume_str(" size ") && p.consume_dec(size))
-            {
-                // cosim: received DMA write id 94113551528032 addr 236972000 size 4
-                e = new EHostDmaW(ts, id, addr, size);
-            } else if (p.consume_str("read completion id ") &&
-                    p.consume_dec(id))
+    gem5_parser client(syms);
+    gem5_parser server(syms);
+    client.open(argv[1]);
+    server.open(argv[2]);
+
+    client.next_event();
+    server.next_event();
+    while (client.cur_event || server.cur_event) {
+        event *ev;
+        const char *pref;
+        if (((client.cur_event && server.cur_event) &&
+                    client.cur_event->ts <= server.cur_event->ts) ||
+                (!server.cur_event && client.cur_event))
         {
-                // cosim: received read completion id 94583743418112
-                e = new EHostMmioC(ts, id);
-            } else if (p.consume_str("write completion id ") &&
-                    p.consume_dec(id))
-            {
-                // cosim: received write completion id 94583743418736
-                e = new EHostMmioC(ts, id);
-            }
-        } else if (p.consume_str("sending ")) {
-            if (p.consume_str("read addr ") && p.consume_hex(addr) &&
-                    p.consume_str(" size ") && p.consume_dec(size) &&
-                    p.consume_str(" id ") && p.consume_dec(id))
-            {
-                // cosim: sending read addr c012a500 size 4 id 94583743418112
-                e = new EHostMmioR(ts, id, addr, size);
-            } else if (p.consume_str("write addr ") && p.consume_hex(addr) &&
-                    p.consume_str(" size ") && p.consume_dec(size) &&
-                    p.consume_str(" id ") && p.consume_dec(id))
-            {
-                // cosim: sending write addr c0108000 size 4 id 94584005188256
-                e = new EHostMmioW(ts, id, addr, size);
-            }
-        } else if (p.consume_str("completed DMA id ") && p.consume_dec(id)) {
-            e = new EHostDmaC(ts, id);
-        }
-    }
-
-    if (e) {
-        e->dump(std::cout);
-    } /*else {
-        std::cout.write(msg, msg_len);
-        std::cout << std::endl;
-    }*/
-}
-
-size_t process_line(char *buf, size_t pos, size_t buf_len)
-{
-    size_t line_start = pos;
-    size_t comp_name_start = 0;
-    size_t comp_name_len = 0;
-    bool valid = true;
-
-    // eat spaces
-    for (; pos < buf_len && buf[pos] == ' '; pos++);
-
-    // parse ts
-    uint64_t ts = 0;
-    size_t ts_len = 0;
-    for (; pos < buf_len && buf[pos] >= '0' && buf[pos] <= '9'; pos++) {
-        ts = ts * 10 + buf[pos] - '0';
-        ts_len++;
-    }
-    if (ts_len == 0) {
-        valid = false;
-        goto out;
-    }
-
-    // skip colon
-    if (buf[pos] != ':') {
-        valid = false;
-        goto out;
-    }
-    pos++;
-
-    // skip space
-    if (buf[pos] != ' ') {
-        valid = false;
-        goto out;
-    }
-    pos++;
-
-    comp_name_start = pos;
-    for (; pos < buf_len && buf[pos] != ' ' && buf[pos] != '\n'; pos++, comp_name_len++);
-    // skip space
-    if (buf[pos] != ' ') {
-        valid = false;
-        goto out;
-    }
-    if (buf[pos - 1] != ':') {
-        valid = false;
-        goto out;
-    }
-    comp_name_len--;
-    pos++;
-
-out:
-    // eat line
-    size_t msg_start = pos;
-    size_t msg_len = 0;
-    for (; pos < buf_len && buf[pos] != '\n'; pos++, msg_len++);
-    if (pos >= buf_len) {
-        // line is incomplete
-        return 0;
-    }
-
-    buf[pos] = 0;
-    if (valid) {
-        process_msg(ts, buf + comp_name_start, comp_name_len, buf + msg_start,
-                msg_len);
+            ev = client.cur_event;
+            client.next_event();
+            pref = "C";
         } else {
-        std::cout << buf + line_start << std::endl;
-        std::cout << pos << std::endl;
+            ev = server.cur_event;
+            server.next_event();
+            pref = "S";
         }
-
-    return pos + 1;
-}
-
-void gem5_parse(const std::string &path)
-{
-    bool use_gz = false;
-    std::istream *inf = nullptr;
-
-    if (use_gz) {
-        std::ifstream *file = new std::ifstream(path, std::ios_base::in |
-                std::ios_base::binary);
-        bio::filtering_streambuf<bio::input> *in = new
-            bio::filtering_streambuf<bio::input>();
-
-        in->push(bio::gzip_decompressor());
-        in->push(*file);
-
-        inf = new std::istream(in);
-    } else {
-        inf = new std::ifstream(path, std::ios_base::in);
-    }
-
-    const size_t buf_size = 16 * 1024 * 1024;
-    char *buf = new char[buf_size];
-
-    size_t len, off = 0, pos = 0;
-
-    do {
-        inf->read(buf + pos, buf_size - pos);
-        len = pos + inf->gcount();
-        off += len;
-
-        pos = 0;
-        size_t newpos;
-        while (pos != len && (newpos = process_line(buf, pos, len)) != 0) {
-            pos = newpos;
+        std::cout << pref << " ";
+        ev->dump(std::cout);
     }
 
-        if (pos == len) {
-            pos = 0;
-        } else {
-            memmove(buf, buf + pos, len - pos);
-            pos = len - pos;
-        }
-    } while (len > 0);
-    delete[] buf;
-}
-
-int main(int argc, char *argv[])
-{
-    sym_map.add_filter("entry_SYSCALL_64");
-    sym_map.add_filter("__do_sys_gettimeofday");
-    sym_map.add_filter("__sys_sendto");
-    sym_map.add_filter("i40e_lan_xmit_frame");
-    sym_map.add_filter("syscall_return_via_sysret");
-    sym_map.add_filter("__sys_recvfrom");
-    sym_map.add_filter("deactivate_task");
-    sym_map.add_filter("interrupt_entry");
-    sym_map.add_filter("i40e_msix_clean_rings");
-    sym_map.add_filter("napi_schedule_prep");
-    sym_map.add_filter("__do_softirq");
-    sym_map.add_filter("trace_napi_poll");
-    sym_map.add_filter("net_rx_action");
-    sym_map.add_filter("i40e_napi_poll");
-    sym_map.add_filter("activate_task");
-    sym_map.add_filter("copyout");
-
-    sym_map.load_file("linux.dump", 0);
-    sym_map.load_file("i40e.dump", 0xffffffffa0000000ULL);
-    std::cerr << "map loaded" << std::endl;
-    gem5_parse(argv[1]);
-
 }

trace/process.h

@@ -3,6 +3,9 @@
 #include <map>
 #include <set>
 #include <string>
+#include <boost/iostreams/filtering_streambuf.hpp>
+
+#include "events.h"
 
 class sym_map {
   protected:
@@ -26,3 +29,43 @@ class sym_map {
         return &it->second;
     }
 };
+
+class log_parser {
+  protected:
+    std::istream *inf;
+
+    std::ifstream *gz_file;
+    boost::iostreams::filtering_streambuf<boost::iostreams::input> *gz_in;
+
+    static const size_t block_size = 16 * 1024 * 1024;
+    char *buf;
+    size_t buf_len;
+    size_t buf_pos;
+
+    bool next_block();
+    size_t try_line();
+    virtual void process_line(char *line, size_t len) = 0;
+
+  public:
+    event *cur_event;
+
+    log_parser();
+    virtual ~log_parser();
+    void open(const char *path);
+    void open_gz(const char *path);
+
+    bool next_event();
+};
+
+class gem5_parser : public log_parser {
+  protected:
+    sym_map &syms;
+
+    virtual void process_line(char *line, size_t len);
+    void process_msg(uint64_t ts, char *comp_name, size_t comp_name_len,
+            char *msg, size_t msg_len);
+
+  public:
+    gem5_parser(sym_map &syms_);
+    virtual ~gem5_parser();
+};