1 files changed, 191 insertions, 0 deletions
diff --git a/sandbox/linux/seccomp/timestats.cc b/sandbox/linux/seccomp/timestats.cc
new file mode 100644
index 0000000..5d9b66a
--- /dev/null
+++ b/sandbox/linux/seccomp/timestats.cc
@@ -0,0 +1,191 @@
+// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// Helper program to analyze the time that Chrome's renderers spend in system
+// calls. Start Chrome like this:
+//
+// SECCOMP_SANDBOX_DEBUGGING=1 chrome --enable-seccomp-sandbox 2>&1 | timestats
+//
+// The program prints CPU time (0-100%) spent within system calls. This gives
+// a general idea of where it is worthwhile to spend effort optimizing Chrome.
+//
+// Caveats:
+//  - there currently is no way to estimate what the overhead is for running
+//    inside of the sandbox vs. running without a sandbox.
+//  - we currently use a very simple heuristic to decide whether a system call
+//    is blocking or not. Blocking system calls should not be included in the
+//    computations. But it is quite possible for the numbers to be somewhat
+//    wrong, because the heuristic failed.
+//  - in order to collect this data, we have to turn on sandbox debugging.
+//    There is a measurable performance penalty to doing so. Production numbers
+//    are strictly better than the numbers reported by this tool.
+#include <set>
+#include <vector>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/time.h>
+#include <time.h>
+
+static const int kAvgWindowSizeMs  =    500;
+static const int kPeakWindowSizeMs = 2*1000;
+
+// Class containing information on a single system call. Most notably, it
+// contains the time when the system call happened, and the time that it
+// took to complete.
+class Datum {
+  friend class Data;
+ public:
+  Datum(const char* name, double ms)
+    : name_(name),
+      ms_(ms) {
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+    timestamp_ = tv.tv_sec*1000.0 + tv.tv_usec/1000.0;
+  }
+  virtual ~Datum() { }
+
+  double operator-(const Datum& b) {
+    return timestamp_ - b.timestamp_;
+  }
+
+ protected:
+  const char* name_;
+  double      ms_;
+  double      timestamp_;
+};
+
+// Class containing data on the most recent system calls. It maintains
+// sliding averages for total CPU time used, and it also maintains a peak
+// CPU usage. The peak usage is usually updated slower than the average
+// usage, as that makes it easier to inspect visually.
+class Data {
+ public:
+  Data() { }
+  virtual ~Data() { }
+
+  void addData(const char* name, double ms) {
+    average_.push_back(Datum(name, ms));
+    peak_.push_back(Datum(name, ms));
+
+    // Prune entries outside of the window
+    std::vector<Datum>::iterator iter;
+    for (iter = average_.begin();
+         *average_.rbegin() - *iter > kAvgWindowSizeMs;
+         ++iter) {
+    }
+    average_.erase(average_.begin(), iter);
+
+    for (iter = peak_.begin();
+         *peak_.rbegin() - *iter > kPeakWindowSizeMs;
+         ++iter){
+    }
+    peak_.erase(peak_.begin(), iter);
+
+    // Add the total usage of all system calls inside of the window
+    double total = 0;
+    for (iter = average_.begin(); iter != average_.end(); ++iter) {
+      total += iter->ms_;
+    }
+
+    // Compute the peak CPU usage during the last window
+    double peak = 0;
+    double max = 0;
+    std::vector<Datum>::iterator tail = peak_.begin();
+    for (iter = tail; iter != peak_.end(); ++iter) {
+      while (*iter - *tail > kAvgWindowSizeMs) {
+        peak -= tail->ms_;
+        ++tail;
+      }
+      peak += iter->ms_;
+      if (peak > max) {
+        max = peak;
+      }
+    }
+
+    // Print the average CPU usage in the last window
+    char buf[80];
+    total *= 100.0/kAvgWindowSizeMs;
+    max   *= 100.0/kAvgWindowSizeMs;
+    sprintf(buf, "%6.2f%% (peak=%6.2f%%) ", total, max);
+
+    // Animate the actual usage, displaying both average and peak values
+    int len   = strlen(buf);
+    int space = sizeof(buf) - len - 1;
+    int mark  = (total * space + 50)/100;
+    int bar   = (max   * space + 50)/100;
+    for (int i = 0; i < mark; ++i) {
+      buf[len++] = '*';
+    }
+    if (mark == bar) {
+      if (bar) {
+        len--;
+      }
+    } else {
+      for (int i = 0; i < bar - mark - 1; ++i) {
+        buf[len++] = ' ';
+      }
+    }
+    buf[len++] = '|';
+    while (len < static_cast<int>(sizeof(buf))) {
+      buf[len++] = ' ';
+    }
+    strcpy(buf + len, "\r");
+    fwrite(buf, len + 1, 1, stdout);
+    fflush(stdout);
+  }
+
+ private:
+  std::vector<Datum> average_;
+  std::vector<Datum> peak_;
+};
+static Data data;
+
+
+int main(int argc, char *argv[]) {
+  char buf[80];
+  bool expensive = false;
+  while (fgets(buf, sizeof(buf), stdin)) {
+    // Allow longer delays for expensive system calls
+    if (strstr(buf, "This is an expensive system call")) {
+      expensive = true;
+      continue;
+    }
+
+    // Parse the string and extract the elapsed time
+    const char elapsed[] = "Elapsed time: ";
+    char* ms_string = strstr(buf, elapsed);
+    char* endptr;
+    double ms;
+    char* colon = strchr(buf, ':');
+
+    // If this string doesn't match, then it must be some other type of
+    // message. Just ignore it.
+    // It is quite likely that we will regularly encounter debug messages
+    // that either should be parsed by a completely different tool, or
+    // messages that were intended for humans to read.
+    if (!ms_string ||
+        ((ms = strtod(ms_string + sizeof(elapsed) - 1, &endptr)),
+         endptr == ms_string) ||
+        !colon) {
+      continue;
+    }
+
+    // Filter out system calls that were probably just blocking
+    // TODO(markus): automatically compute the cut-off for blocking calls
+    if (!expensive && ms > 0.05) {
+      continue;
+    }
+    expensive = false;
+
+    // Extract the name of the system call
+    *colon = '\000';
+
+    // Add the data point and update the display
+    data.addData(buf, ms);
+  }
+  puts("");
+  return 0;
+}