tracevis_adds_legends_to_graph_and_refactors / src / binlog.cpp

/*
 * TraceVis log file processor.
 *
 * Default action is to print a text summary. The |-h| option instead writes the history to
 * stdout in a binary format.
 *
 * Binary history format:
 *
 *       length            contents
 *
 *       12                text:   |TraceVis-History|
 *        4                text:   format-version-id (e.g. |0001|).
 *
 *        8                uint64: rdtsc time elapsed for entire log
 *        4                uint32: count of following records = M (= S_COUNT)
 *       8M              M uint64: rdtsc time totals by state, from 0 to S_COUNT-1
 *       9N              N 9-byte packed records (X = 17+9N)
 *                         Each record represents a transition out of an activity.
 *             1                 byte:   VM state before transition
 *             1                 byte:   reason code (used only for events)
 *             8                 uint64: rdtsc timestamp
 */

#include <stdio.h>
#include <sys/stat.h>
#include <vector>
#include <algorithm>

#include "tracevis.h"
#include "tracevis_gen.h"

const char* FORMAT_ID = "TraceVis-History";
const int FORMAT_ID_LEN = strlen(FORMAT_ID);
const int VERSION_ID = 1;

const size_t BODY_POS = 20;

const double CPU_SPEED = 2.2e9;
typedef unsigned long long uint64;
typedef unsigned uint32;

const char* filename = "/tmp/jsacts";
const size_t pagesize = 4096;
const unsigned page_records = pagesize/sizeof(uint64);

// options
bool print_summary = true;
bool print_history = false;
const char* history_filename = 0;

FILE* history_file = 0;

static void rep(char ch, int n)
{
  for (int i = 0; i < n; ++i)
    putchar(ch);
  putchar('\n');
}

class Record
{
public:
  uint64      t;
  int         s;
  int         r;

  Record(uint64 t, int s, int r) : t(t), s(s), r(r) {}

  Record(uint64 raw) : t(raw & ~(0x1ffllu << 55)), s((raw >> 60) & 0xf), r((raw >> 55) & 0x1f) {}

  void list() const {
    printf("%llu %2d %2d\n", t, s, r);
  }
};

// Extended reason, also includes states
class EReason {
  int         n;
public:
  EReason(const Record& rec) {
    if (rec.r)
      n = rec.r;
    else
      n = R_COUNT + rec.s;
  }

  EReason(int n) : n(n) {}

  operator const char* () const {
    if (n == R_COUNT)
      return "start";
    if (n < R_COUNT)
      return reason_names[n];
    return state_names[n - R_COUNT];
  }

  operator int () const {
    return n;
  }
};

const int ER_COUNT = R_COUNT + S_COUNT;

class ReasonCounter {
public:
  EReason r;
  uint64  t;
  int     n;

  ReasonCounter(EReason r) : r(r), t(0), n(0) {}

  ReasonCounter& operator+=(uint64 dt) {
    t += dt;
    n += 1;
    return *this;
  }
};

bool operator<(const ReasonCounter& c1, const ReasonCounter& c2)
{
  return c1.t > c2.t;
}

class History {
public:
  uint64                  state_summary[S_COUNT];
  std::vector<Record>     stack;

  Record                  to_interp;
  std::vector<ReasonCounter>   reason_summary;
  uint64                  t0;
  uint64                  t1;

  History() : to_interp(0, 0, 0) {
    for (int i = 0; i < S_COUNT; ++i) {
      state_summary[i] = 0;
    }
    for (int i = 0; i < ER_COUNT; ++i) {
      reason_summary.push_back(ReasonCounter(i));
    }
  }

  void write(int state, int reason, uint64 time) {
    if (print_history) {
      putc(state, history_file);
      putc(reason, history_file);
      uint64 t = time - t0;
      fwrite(&t, sizeof(t), 1, history_file);
    }
  }

  void transition(const Record& rec0, const Record& rec1) {
    t1 = rec1.t;
    uint64 dt = rec1.t - rec0.t;
    state_summary[rec0.s] += dt;

    write(rec0.s, 0, rec1.t);

    // Transition to interpreter
    if (rec0.s != S_INTERP && rec1.s == S_INTERP) {
      to_interp.t = rec1.t;
      to_interp.s = rec0.s;
      to_interp.r = rec1.r;
    }

    // Transition from interpreter
    if (rec0.s == S_INTERP && rec1.s != S_INTERP) {
      //reason_summary[EReason(to_interp)] += rec1.t - to_interp.t;
      reason_summary[EReason(to_interp)] += rec1.t - to_interp.t;
    }
  }

  void enter(const Record& rec) {
    // State values >= S_COUNT represent events instead of states.
    if (rec.s >= S_COUNT) {
      write(rec.s, rec.r, rec.t);
    } else {
	if (stack.size() == 0) {
	  t0 = rec.t;
	  stack.push_back(Record(rec.t, 0, 0));
	}
	transition(stack.back(), rec);
	stack.push_back(rec);
    }
  }

  void exit(const Record& rec) {
    Record entry = stack.back();
    stack.pop_back();
    Record& prior = stack.back();
    Record exit = rec;
    exit.s = prior.s;
    transition(entry, exit);
    prior.t = rec.t;
    prior.r = rec.r;
  }

  void list_state_summary() const {
    printf("Activity summary:\n");
    printf("%-18s %12s\n", "Activity", "time (ms)");
    rep('=', 31);
    uint64 subtotal = 0;
    for (int i = 1; i < S_COUNT; ++i) {
      subtotal += state_summary[i];
      printf("%-18s %12.6f\n", state_names[i], state_summary[i] / CPU_SPEED * 1000);
    }
    rep('-', 31);
    printf("%-18s %12.6f\n", "Subtotal", subtotal / CPU_SPEED * 1000);
    printf("%-18s %12.6f\n", "Non-JS", state_summary[0] / CPU_SPEED * 1000);
    rep('=', 31);
    printf("%-18s %12.6f\n", "Total", (state_summary[0]+subtotal) / CPU_SPEED * 1000);
  }

  void list_reason_summary() {
    printf("Reasons for transitions to intepreter:\n");
    printf("%-18s %12s %8s %12s\n", 
	   "reason", "time (ms)", "count", "avg time (ms)");
    rep('=', 53);

    // FIXME: don't mutate original
    std::sort(reason_summary.begin(), reason_summary.end());
    uint64 subtotal = 0;
    for (std::vector<ReasonCounter>::iterator p = reason_summary.begin();
	 p < reason_summary.end(); ++p) {
      ReasonCounter& c = *p;
      if (c.t == 0)
	break;
      subtotal += c.t;
      printf("%-18s %12.3f %8d %12.3f\n", 
	     static_cast<const char*>(c.r), 
	     c.t / CPU_SPEED * 1000,
	     c.n,
	     c.t / CPU_SPEED * 1000 / c.n
	     );
    }
    rep('=', 53);
    printf("%-18s %12.3f\n", "Total", (subtotal) / CPU_SPEED * 1000);
  }
};

void process_record(History& h, uint64 raw)
{
  Record rec(raw);
  if (rec.s)
    h.enter(rec);
  else
    h.exit(rec);
}

bool streq(const char* s1, const char* s2)
{
  return !strcmp(s1, s2);
}

void open_history_file()
{
  struct stat st;
  int rc = stat(history_filename, &st);
  if (rc == 0) {
    FILE* f = fopen(history_filename, "rb");
    char buf[FORMAT_ID_LEN];
    fread(buf, 1, FORMAT_ID_LEN, f);
    if (memcmp(buf, FORMAT_ID, FORMAT_ID_LEN) != 0) {
      printf("file exists and is not a history file: %s\n", history_filename);
      exit(1);
    }
    fclose(f);
  }
  history_file = fopen(history_filename, "wb");
  if (!history_file) {
    printf("cannot open output file: %s\n", history_filename);
    exit(1);
  }
  fprintf(history_file, "TraceVis-History%04d", VERSION_ID);
  assert(ftell(history_file) == BODY_POS);
}

int main(int argc, char **argv)
{
  int i = 1;
  for (; i < argc; ++i) {
    const char* arg = argv[i];
    if (streq(arg, "-h")) {
      print_history = true;
      history_filename = argv[++i];
    } else {
      break;
    }
  }

  if (i < argc)
    filename = argv[i];

  FILE* f = fopen(filename, "rb");
  if (!f) {
    printf("cannot open input file: %s\n", filename);
    exit(1);
  }

  uint64 recs[page_records];
  History h;

  if (print_history) {
    open_history_file();
    fseek(history_file, 8 + 4 + 8 * S_COUNT, SEEK_CUR);
  }

  while (true) {
    size_t nread = fread(recs, sizeof(uint64), page_records, f);
    if (nread == 0)
      break;
    for (size_t i = 0; i < nread; ++i) {
      process_record(h, recs[i]);
    }
  }

  if (print_history) {
    uint64 dt = h.t1 - h.t0;
    fseek(history_file, BODY_POS, SEEK_SET);
    fwrite(&dt, sizeof(dt), 1, history_file);
    
    uint32 n = S_COUNT;
    fwrite(&n, sizeof(n), 1, history_file);
    fwrite(h.state_summary, sizeof(h.state_summary[0]), S_COUNT, history_file);

    fclose(history_file);    
  }

  if (print_summary) {
    h.list_state_summary();
    printf("\n");
    h.list_reason_summary();
  }
  return 0;
}
Tip: Filter by directory path e.g. /media app.js to search for public/media/app.js.
Tip: Use camelCasing e.g. ProjME to search for ProjectModifiedEvent.java.
Tip: Filter by extension type e.g. /repo .js to search for all .js files in the /repo directory.
Tip: Separate your search with spaces e.g. /ssh pom.xml to search for src/ssh/pom.xml.
Tip: Use ↑ and ↓ arrow keys to navigate and return to view the file.
Tip: You can also navigate files with Ctrl+j (next) and Ctrl+k (previous) and view the file with Ctrl+o.
Tip: You can also navigate files with Alt+j (next) and Alt+k (previous) and view the file with Alt+o.