Compute and pring the time that it takes to execute system calls. This data

is going to be skewed slightly, as calling gettimeofday() by itself also
takes a little bit of time. But it should be good enough to allow us to see
where we have performance bottlenecks.

TEST=none
BUG=none
Review URL: http://codereview.chromium.org/997009

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@41905 0039d316-1c4b-4281-b951-d872f2087c98

20 files changed, 327 insertions, 84 deletions

diff --git a/sandbox/linux/seccomp/access.cc b/sandbox/linux/seccomp/access.cc
index f0248b7..50e94bb 100644
--- a/sandbox/linux/seccomp/access.cc
+++ b/sandbox/linux/seccomp/access.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_access(const char *pathname, int mode) {
-  Debug::syscall(__NR_access, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_access, "Executing handler");
   size_t len                      = strlen(pathname);
   struct Request {
     int       sysnum;
@@ -30,6 +31,7 @@ int Sandbox::sandbox_access(const char *pathname, int mode) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward access() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_access);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/clone.cc b/sandbox/linux/seccomp/clone.cc
index 28a3584..148bae5 100644
--- a/sandbox/linux/seccomp/clone.cc
+++ b/sandbox/linux/seccomp/clone.cc
@@ -9,7 +9,8 @@ namespace playground {
 
 int Sandbox::sandbox_clone(int flags, void* stack, int* pid, int* ctid,
                            void* tls, void *wrapper_sp) {
-  Debug::syscall(__NR_clone, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_clone, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -43,6 +44,7 @@ int Sandbox::sandbox_clone(int flags, void* stack, int* pid, int* ctid,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward clone() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_clone);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/debug.cc b/sandbox/linux/seccomp/debug.cc
index 2d904d2..e4d6410 100644
--- a/sandbox/linux/seccomp/debug.cc
+++ b/sandbox/linux/seccomp/debug.cc
@@ -124,7 +124,83 @@ Debug::Debug() {
   }
 }
 
-void Debug::message(const char* msg) {
+bool Debug::enter() {
+  // Increment the recursion level in TLS storage. This allows us to
+  // make system calls from within our debugging functions, without triggering
+  // additional debugging output.
+  //
+  // This function can be called from both the sandboxed process and from the
+  // trusted process. Only the sandboxed process needs to worry about
+  // recursively calling system calls. The trusted process doesn't intercept
+  // system calls and thus doesn't have this problem. It also doesn't have
+  // a TLS. We explicitly set the segment selector to zero, when in the
+  // trusted process, so that we can avoid tracking recursion levels.
+  int level;
+  #if defined(__x86_64__)
+  asm volatile("mov  %%gs, %0\n"
+               "test %0, %0\n"
+               "jz   1f\n"
+               "movl %%gs:0x1050-0xD8, %0\n"
+               "incl %%gs:0x1050-0xD8\n"
+             "1:\n"
+               : "=r"(level)
+               :
+               : "memory");
+  #elif defined(__i386__)
+  asm volatile("mov  %%fs, %0\n"
+               "test %0, %0\n"
+               "jz   1f\n"
+               "movl %%fs:0x1034-0x54, %0\n"
+               "incl %%fs:0x1034-0x54\n"
+             "1:\n"
+               : "=r"(level)
+               :
+               : "memory");
+  #else
+  #error "Unsupported target platform"
+  #endif
+  return !level;
+}
+
+bool Debug::leave() {
+  // Decrement the recursion level in TLS storage. This allows us to
+  // make system calls from within our debugging functions, without triggering
+  // additional debugging output.
+  //
+  // This function can be called from both the sandboxed process and from the
+  // trusted process. Only the sandboxed process needs to worry about
+  // recursively calling system calls. The trusted process doesn't intercept
+  // system calls and thus doesn't have this problem. It also doesn't have
+  // a TLS. We explicitly set the segment selector to zero, when in the
+  // trusted process, so that we can avoid tracking recursion levels.
+  int level;
+  #if defined(__x86_64__)
+  asm volatile("mov  %%gs, %0\n"
+               "test %0, %0\n"
+               "jz   1f\n"
+               "decl %%gs:0x1050-0xD8\n"
+               "movl %%gs:0x1050-0xD8, %0\n"
+             "1:\n"
+               : "=r"(level)
+               :
+               : "memory");
+  #elif defined(__i386__)
+  asm volatile("mov  %%fs, %0\n"
+               "test %0, %0\n"
+               "jz   1f\n"
+               "decl %%fs:0x1034-0x54\n"
+               "movl %%fs:0x1034-0x54, %0\n"
+             "1:\n"
+               : "=r"(level)
+               :
+               : "memory");
+  #else
+  #error Unsupported target platform
+  #endif
+  return !level;
+}
+
+void Debug::_message(const char* msg) {
   if (enabled_) {
     Sandbox::SysCalls sys;
     size_t len = strlen(msg);
@@ -142,57 +218,92 @@ void Debug::message(const char* msg) {
   }
 }
 
-void Debug::syscall(int sysnum, const char* msg, int call) {
+void Debug::message(const char* msg) {
+  if (enabled_) {
+    if (enter()) {
+      _message(msg);
+    }
+    leave();
+  }
+}
+
+void Debug::gettimeofday(long long* tm) {
+  if (tm) {
+    struct timeval tv;
+    #if defined(__i386__)
+    // Zero out the lastSyscallNum, so that we don't try to coalesce
+    // calls to gettimeofday(). For debugging purposes, we need the
+    // exact time.
+    asm volatile("movl $0, %fs:0x102C-0x54");
+    #elif !defined(__x86_64__)
+    #error Unsupported target platform
+    #endif
+    ::gettimeofday(&tv, NULL);
+    *tm = 1000ULL*1000ULL*static_cast<unsigned>(tv.tv_sec) +
+          static_cast<unsigned>(tv.tv_usec);
+  }
+}
+
+void Debug::syscall(long long* tm, int sysnum, const char* msg, int call) {
   // This function gets called from the system call wrapper. Avoid calling
   // any library functions that themselves need system calls.
   if (enabled_) {
-    const char *sysname = NULL;
-    if (sysnum >= 0 && sysnum < numSyscallNames_) {
-      sysname = syscallNames_[sysnum];
-    }
-    char unnamed[40] = "Unnamed syscall #";
-    if (!sysname) {
-      itoa(const_cast<char *>(strrchr(sysname = unnamed, '\000')), sysnum);
-    }
-    #if defined(__NR_socketcall) || defined(__NR_ipc)
-    char extra[40];
-    *extra = '\000';
-    #if defined(__NR_socketcall)
-    if (sysnum == __NR_socketcall) {
-      static const char* socketcall_name[] = {
-        0, "socket", "bind", "connect", "listen", "accept", "getsockname",
-        "getpeername", "socketpair", "send", "recv", "sendto","recvfrom",
-        "shutdown", "setsockopt", "getsockopt", "sendmsg", "recvmsg",
-        "accept4"
-      };
-      if (call >= 1 && call < (int)(sizeof(socketcall_name)/sizeof(char *))) {
-        strcat(strcpy(extra, " "), socketcall_name[call]);
-      } else {
-        itoa(strcpy(extra, " #") + 2, call);
+    if (enter() || !tm) {
+      gettimeofday(tm);
+
+      const char *sysname = NULL;
+      if (sysnum >= 0 && sysnum < numSyscallNames_) {
+        sysname = syscallNames_[sysnum];
       }
-    }
-    #endif
-    #if defined(__NR_ipc)
-    if (sysnum == __NR_ipc) {
-      static const char* ipc_name[] = {
-        0, "semop", "semget", "semctl", "semtimedop", 0, 0, 0, 0, 0, 0,
-        "msgsnd", "msgrcv", "msgget", "msgctl", 0, 0, 0, 0, 0, 0,
-        "shmat", "shmdt", "shmget", "shmctl" };
-      if (call >= 1 && call < (int)(sizeof(ipc_name)/sizeof(char *)) &&
-          ipc_name[call]) {
-        strcat(strcpy(extra, " "), ipc_name[call]);
-      } else {
-        itoa(strcpy(extra, " #") + 2, call);
+      static const char kUnnamedMessage[] = "Unnamed syscall #";
+      char unnamed[40];
+      if (!sysname) {
+        memcpy(unnamed, kUnnamedMessage, sizeof(kUnnamedMessage) - 1);
+        itoa(unnamed + sizeof(kUnnamedMessage) - 1, sysnum);
+        sysname = unnamed;
       }
+      #if defined(__NR_socketcall) || defined(__NR_ipc)
+      char extra[40];
+      *extra = '\000';
+      #if defined(__NR_socketcall)
+      if (sysnum == __NR_socketcall) {
+        static const char* socketcall_name[] = {
+          0, "socket", "bind", "connect", "listen", "accept", "getsockname",
+          "getpeername", "socketpair", "send", "recv", "sendto","recvfrom",
+          "shutdown", "setsockopt", "getsockopt", "sendmsg", "recvmsg",
+          "accept4"
+        };
+        if (call >= 1 &&
+            call < (int)(sizeof(socketcall_name)/sizeof(char *))) {
+          strcat(strcpy(extra, " "), socketcall_name[call]);
+        } else {
+          itoa(strcpy(extra, " #") + 2, call);
+        }
+      }
+      #endif
+      #if defined(__NR_ipc)
+      if (sysnum == __NR_ipc) {
+        static const char* ipc_name[] = {
+          0, "semop", "semget", "semctl", "semtimedop", 0, 0, 0, 0, 0, 0,
+          "msgsnd", "msgrcv", "msgget", "msgctl", 0, 0, 0, 0, 0, 0,
+          "shmat", "shmdt", "shmget", "shmctl" };
+        if (call >= 1 && call < (int)(sizeof(ipc_name)/sizeof(char *)) &&
+            ipc_name[call]) {
+          strcat(strcpy(extra, " "), ipc_name[call]);
+        } else {
+          itoa(strcpy(extra, " #") + 2, call);
+        }
+      }
+      #endif
+      #else
+      static const char extra[1] = { 0 };
+      #endif
+      char buf[strlen(sysname) + strlen(extra) + (msg ? strlen(msg) : 0) + 4];
+      strcat(strcat(strcat(strcat(strcpy(buf, sysname), extra), ": "),
+                    msg ? msg : ""), "\n");
+      _message(buf);
     }
-    #endif
-    #else
-    static const char *extra = "";
-    #endif
-    char buf[strlen(sysname) + strlen(extra) + (msg ? strlen(msg) : 0) + 4];
-    strcat(strcat(strcat(strcat(strcpy(buf, sysname), extra), ": "),
-                  msg ? msg : ""), "\n");
-    message(buf);
+    leave();
   }
 }
 
@@ -224,6 +335,29 @@ char* Debug::itoa(char* s, int n) {
   return ret;
 }
 
+void Debug::elapsed(long long tm, int sysnum, int call) {
+  if (enabled_) {
+    if (enter()) {
+      // Compute the time that has passed since the system call started.
+      long long delta;
+      gettimeofday(&delta);
+      delta -= tm;
+
+      // Format "Elapsed time: %d.%03dms" without using sprintf().
+      char buf[80];
+      itoa(strrchr(strcpy(buf, "Elapsed time: "), '\000'), delta/1000);
+      delta %= 1000;
+      strcat(buf, delta < 100 ? delta < 10 ? ".00" : ".0" : ".");
+      itoa(strrchr(buf, '\000'), delta);
+      strcat(buf, "ms");
+
+      // Print system call name and elapsed time.
+      syscall(NULL, sysnum, buf, call);
+    }
+    leave();
+  }
+}
+
 } // namespace
 
 #endif // NDEBUG
diff --git a/sandbox/linux/seccomp/debug.h b/sandbox/linux/seccomp/debug.h
index 4201fbe..eb5a194 100644
--- a/sandbox/linux/seccomp/debug.h
+++ b/sandbox/linux/seccomp/debug.h
@@ -31,13 +31,23 @@ class Debug {
 
   // If debugging is enabled, write the name of the syscall and an optional
   // message to stderr.
-  static void syscall(int sysnum, const char* msg, int call = -1)
+  static void syscall(long long* tm, int sysnum,
+                      const char* msg, int call = -1)
   #ifndef NDEBUG
   ;
   #else
   { }
   #endif
 
+  // Print how much wall-time has elapsed since the last call to syscall()
+  static void elapsed(long long tm, int sysnum, int call = -1)
+  #ifndef NDEBUG
+  ;
+  #else
+  {
+  }
+  #endif
+
   // Check whether debugging is enabled.
   static bool isEnabled() {
     #ifndef NDEBUG
@@ -50,12 +60,16 @@ class Debug {
  private:
   #ifndef NDEBUG
   Debug();
+  static bool  enter();
+  static bool  leave();
+  static void  _message(const char* msg);
+  static void  gettimeofday(long long* tm);
   static char* itoa(char* s, int n);
 
   static Debug debug_;
 
   static bool  enabled_;
-  static int  numSyscallNames_;
+  static int   numSyscallNames_;
   static const char **syscallNames_;
   static std::map<int, std::string> syscallNamesMap_;
   #endif
diff --git a/sandbox/linux/seccomp/exit.cc b/sandbox/linux/seccomp/exit.cc
index 5aee3f5..5da9f97 100644
--- a/sandbox/linux/seccomp/exit.cc
+++ b/sandbox/linux/seccomp/exit.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_exit(int status) {
-  Debug::syscall(__NR_exit, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_exit, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
diff --git a/sandbox/linux/seccomp/getpid.cc b/sandbox/linux/seccomp/getpid.cc
index ad634f1..5b4239b 100644
--- a/sandbox/linux/seccomp/getpid.cc
+++ b/sandbox/linux/seccomp/getpid.cc
@@ -8,7 +8,9 @@
 namespace playground {
 
 int Sandbox::sandbox_getpid() {
-  Debug::syscall(__NR_getpid, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_getpid, "Executing handler");
+  Debug::elapsed(tm, __NR_getpid);
   return pid_;
 }
 
diff --git a/sandbox/linux/seccomp/gettid.cc b/sandbox/linux/seccomp/gettid.cc
index 5503c8c..1423383 100644
--- a/sandbox/linux/seccomp/gettid.cc
+++ b/sandbox/linux/seccomp/gettid.cc
@@ -8,8 +8,11 @@
 namespace playground {
 
 int Sandbox::sandbox_gettid() {
-  Debug::syscall(__NR_gettid, "Executing handler");
-  return tid();
+  long long tm;
+  Debug::syscall(&tm, __NR_gettid, "Executing handler");
+  pid_t t = tid();
+  Debug::elapsed(tm, __NR_gettid);
+  return t;
 }
 
 } // namespace
diff --git a/sandbox/linux/seccomp/ioctl.cc b/sandbox/linux/seccomp/ioctl.cc
index 34bfa13..75330e1 100644
--- a/sandbox/linux/seccomp/ioctl.cc
+++ b/sandbox/linux/seccomp/ioctl.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_ioctl(int d, int req, void *arg) {
-  Debug::syscall(__NR_ioctl, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_ioctl, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -27,6 +28,7 @@ int Sandbox::sandbox_ioctl(int d, int req, void *arg) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward ioctl() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_ioctl);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/ipc.cc b/sandbox/linux/seccomp/ipc.cc
index b894d8f..3cfcbf0 100644
--- a/sandbox/linux/seccomp/ipc.cc
+++ b/sandbox/linux/seccomp/ipc.cc
@@ -19,7 +19,8 @@ namespace playground {
 
 #if defined(__NR_shmget)
 void* Sandbox::sandbox_shmat(int shmid, const void* shmaddr, int shmflg) {
-  Debug::syscall(__NR_shmat, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_shmat, "Executing handler");
 
   struct {
     int       sysnum;
@@ -39,11 +40,13 @@ void* Sandbox::sandbox_shmat(int shmid, const void* shmaddr, int shmflg) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward shmat() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_shmat);
   return reinterpret_cast<void *>(rc);
 }
 
 int Sandbox::sandbox_shmctl(int shmid, int cmd, void* buf) {
-  Debug::syscall(__NR_shmctl, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_shmctl, "Executing handler");
 
   struct {
     int       sysnum;
@@ -63,11 +66,13 @@ int Sandbox::sandbox_shmctl(int shmid, int cmd, void* buf) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward shmctl() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_shmctl);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_shmdt(const void* shmaddr) {
-  Debug::syscall(__NR_shmdt, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_shmdt, "Executing handler");
 
   struct {
     int       sysnum;
@@ -85,11 +90,13 @@ int Sandbox::sandbox_shmdt(const void* shmaddr) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward shmdt() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_shmdt);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_shmget(int key, size_t size, int shmflg) {
-  Debug::syscall(__NR_shmget, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_shmget, "Executing handler");
 
   struct {
     int       sysnum;
@@ -109,6 +116,7 @@ int Sandbox::sandbox_shmget(int key, size_t size, int shmflg) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward shmget() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_shmget);
   return static_cast<int>(rc);
 }
 
@@ -240,7 +248,8 @@ bool Sandbox::process_shmget(int parentMapsFd, int sandboxFd, int threadFdPub,
 
 int Sandbox::sandbox_ipc(unsigned call, int first, int second, int third,
                          void* ptr, long fifth) {
-  Debug::syscall(__NR_ipc, "Executing handler", call);
+  long long tm;
+  Debug::syscall(&tm, __NR_ipc, "Executing handler", call);
   struct {
     int       sysnum;
     long long cookie;
@@ -262,6 +271,7 @@ int Sandbox::sandbox_ipc(unsigned call, int first, int second, int third,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward ipc() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_ipc, call);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/madvise.cc b/sandbox/linux/seccomp/madvise.cc
index 412b999..0df3be8 100644
--- a/sandbox/linux/seccomp/madvise.cc
+++ b/sandbox/linux/seccomp/madvise.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_madvise(void* start, size_t length, int advice) {
-  Debug::syscall(__NR_madvise, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_madvise, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -27,6 +28,7 @@ int Sandbox::sandbox_madvise(void* start, size_t length, int advice) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward madvise() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_madvise);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/mmap.cc b/sandbox/linux/seccomp/mmap.cc
index cefef3a..700da91 100644
--- a/sandbox/linux/seccomp/mmap.cc
+++ b/sandbox/linux/seccomp/mmap.cc
@@ -1,3 +1,7 @@
+// 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.
+
 #include "debug.h"
 #include "sandbox_impl.h"
 
@@ -5,7 +9,8 @@ namespace playground {
 
 void* Sandbox::sandbox_mmap(void *start, size_t length, int prot, int flags,
                           int fd, off_t offset) {
-  Debug::syscall(__NR_mmap, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_mmap, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -27,6 +32,7 @@ void* Sandbox::sandbox_mmap(void *start, size_t length, int prot, int flags,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward mmap() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_mmap);
   return rc;
 }
 
diff --git a/sandbox/linux/seccomp/mprotect.cc b/sandbox/linux/seccomp/mprotect.cc
index abe450b..d079104 100644
--- a/sandbox/linux/seccomp/mprotect.cc
+++ b/sandbox/linux/seccomp/mprotect.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_mprotect(const void *addr, size_t len, int prot) {
-  Debug::syscall(__NR_mprotect, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_mprotect, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -27,6 +28,7 @@ int Sandbox::sandbox_mprotect(const void *addr, size_t len, int prot) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward mprotect() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_mprotect);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/munmap.cc b/sandbox/linux/seccomp/munmap.cc
index d22b795..0c1a41c 100644
--- a/sandbox/linux/seccomp/munmap.cc
+++ b/sandbox/linux/seccomp/munmap.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_munmap(void* start, size_t length) {
-  Debug::syscall(__NR_munmap, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_munmap, "Executing handler");
   struct {
     int       sysnum;
     long long cookie;
@@ -26,6 +27,7 @@ int Sandbox::sandbox_munmap(void* start, size_t length) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward munmap() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_munmap);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/open.cc b/sandbox/linux/seccomp/open.cc
index 6a8ad6d..83db243 100644
--- a/sandbox/linux/seccomp/open.cc
+++ b/sandbox/linux/seccomp/open.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_open(const char *pathname, int flags, mode_t mode) {
-  Debug::syscall(__NR_open, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_open, "Executing handler");
   size_t len                    = strlen(pathname);
   struct Request {
     int       sysnum;
@@ -31,6 +32,7 @@ int Sandbox::sandbox_open(const char *pathname, int flags, mode_t mode) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward open() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_open);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/securemem.h b/sandbox/linux/seccomp/securemem.h
index f9a5c97..ac7823e 100644
--- a/sandbox/linux/seccomp/securemem.h
+++ b/sandbox/linux/seccomp/securemem.h
@@ -101,10 +101,20 @@ class SecureMem {
         void*            tmpArg6;
         void*            tmpReturnValue;
 
+        // Scratch space used to return the result of a rdtsc instruction
+        int              rdtscpEax;
+        int              rdtscpEdx;
+        int              rdtscpEcx;
+
         // We often have long sequences of calls to gettimeofday(). This is
         // needlessly expensive. Coalesce them into a single call.
-        long             lastSyscallNum;
+        int              lastSyscallNum;
         int              gettimeofdayCounter;
+
+        // For debugging purposes, we want to be able to log messages. This can
+        // result in additional system calls. Make sure that we don't trigger
+        // logging of those recursive calls.
+        int              recursionLevel;
       } __attribute__((packed));
       char               scratchPage[4096];
     };
diff --git a/sandbox/linux/seccomp/socketcall.cc b/sandbox/linux/seccomp/socketcall.cc
index f35d2bd..43116bb 100644
--- a/sandbox/linux/seccomp/socketcall.cc
+++ b/sandbox/linux/seccomp/socketcall.cc
@@ -11,7 +11,8 @@ namespace playground {
 
 ssize_t Sandbox::sandbox_recvfrom(int sockfd, void* buf, size_t len, int flags,
                                   void* from, socklen_t* fromlen) {
-  Debug::syscall(__NR_recvfrom, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_recvfrom, "Executing handler");
 
   SysCalls sys;
   if (!from && !flags) {
@@ -20,8 +21,10 @@ ssize_t Sandbox::sandbox_recvfrom(int sockfd, void* buf, size_t len, int flags,
     Debug::message("Replaced recv() with call to read()");
     ssize_t rc = sys.read(sockfd, buf, len);
     if (rc < 0) {
+      Debug::elapsed(tm, __NR_recvfrom);
       return -sys.my_errno;
     } else {
+      Debug::elapsed(tm, __NR_recvfrom);
       return rc;
     }
   }
@@ -46,11 +49,13 @@ ssize_t Sandbox::sandbox_recvfrom(int sockfd, void* buf, size_t len, int flags,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward recvfrom() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_recvfrom);
   return static_cast<int>(rc);
 }
 
 ssize_t Sandbox::sandbox_recvmsg(int sockfd, struct msghdr* msg, int flags) {
-  Debug::syscall(__NR_recvmsg, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_recvmsg, "Executing handler");
 
   // We cannot simplify recvmsg() to recvfrom(), recv() or read(), as we do
   // not know whether the caller needs us to set msg->msg_flags.
@@ -72,12 +77,14 @@ ssize_t Sandbox::sandbox_recvmsg(int sockfd, struct msghdr* msg, int flags) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward recvmsg() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_recvmsg);
   return static_cast<int>(rc);
 }
 
 size_t Sandbox::sandbox_sendmsg(int sockfd, const struct msghdr* msg,
                                 int flags) {
-  Debug::syscall(__NR_sendmsg, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_sendmsg, "Executing handler");
 
   if (msg->msg_iovlen == 1 && msg->msg_controllen == 0) {
     // sendmsg() can sometimes be simplified as sendto()
@@ -111,12 +118,14 @@ size_t Sandbox::sandbox_sendmsg(int sockfd, const struct msghdr* msg,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward sendmsg() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_sendmsg);
   return static_cast<int>(rc);
 }
 
 ssize_t Sandbox::sandbox_sendto(int sockfd, const void* buf, size_t len,
                                 int flags, const void* to, socklen_t tolen) {
-  Debug::syscall(__NR_sendto, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_sendto, "Executing handler");
 
   SysCalls sys;
   if (!to && !flags) {
@@ -125,8 +134,10 @@ ssize_t Sandbox::sandbox_sendto(int sockfd, const void* buf, size_t len,
     Debug::message("Replaced sendto() with call to write()");
     ssize_t rc = sys.write(sockfd, buf, len);
     if (rc < 0) {
+      Debug::elapsed(tm, __NR_sendto);
       return -sys.my_errno;
     } else {
+      Debug::elapsed(tm, __NR_sendto);
       return rc;
     }
   }
@@ -151,12 +162,14 @@ ssize_t Sandbox::sandbox_sendto(int sockfd, const void* buf, size_t len,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward sendto() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_sendto);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_setsockopt(int sockfd, int level, int optname,
                                 const void* optval, socklen_t optlen) {
-  Debug::syscall(__NR_setsockopt, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_setsockopt, "Executing handler");
 
   struct {
     int        sysnum;
@@ -178,12 +191,14 @@ int Sandbox::sandbox_setsockopt(int sockfd, int level, int optname,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward setsockopt() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_setsockopt);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_getsockopt(int sockfd, int level, int optname,
                                 void* optval, socklen_t* optlen) {
-  Debug::syscall(__NR_getsockopt, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_getsockopt, "Executing handler");
 
   struct {
     int        sysnum;
@@ -205,6 +220,7 @@ int Sandbox::sandbox_getsockopt(int sockfd, int level, int optname,
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward getsockopt() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_getsockopt);
   return static_cast<int>(rc);
 }
 
@@ -553,11 +569,13 @@ const struct Sandbox::SocketCallArgInfo Sandbox::socketCallArgInfo[] = {
 };
 
 int Sandbox::sandbox_socketcall(int call, void* args) {
-  Debug::syscall(__NR_socketcall, "Executing handler", call);
+  long long tm;
+  Debug::syscall(&tm, __NR_socketcall, "Executing handler", call);
 
   // When demultiplexing socketcall(), only accept calls that have a valid
   // "call" opcode.
   if (call < SYS_SOCKET || call > SYS_ACCEPT4) {
+    Debug::elapsed(tm, __NR_socketcall, call);
     return -ENOSYS;
   }
 
@@ -647,8 +665,10 @@ int Sandbox::sandbox_socketcall(int call, void* args) {
                            request->socketcall_req.args.send.buf,
                            request->socketcall_req.args.send.len);
     if (rc < 0) {
+      Debug::elapsed(tm, __NR_socketcall, call);
       return -sys.my_errno;
     } else {
+      Debug::elapsed(tm, __NR_socketcall, call);
       return rc;
     }
   }
@@ -670,8 +690,10 @@ int Sandbox::sandbox_socketcall(int call, void* args) {
                           request->socketcall_req.args.recv.buf,
                           request->socketcall_req.args.recv.len);
     if (rc < 0) {
+      Debug::elapsed(tm, __NR_socketcall, call);
       return -sys.my_errno;
     } else {
+      Debug::elapsed(tm, __NR_socketcall, call);
       return rc;
     }
   }
@@ -708,6 +730,7 @@ int Sandbox::sandbox_socketcall(int call, void* args) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward socketcall() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_socketcall, call);
   return static_cast<int>(rc);
 }
 
diff --git a/sandbox/linux/seccomp/stat.cc b/sandbox/linux/seccomp/stat.cc
index c84c453..53e7e14 100644
--- a/sandbox/linux/seccomp/stat.cc
+++ b/sandbox/linux/seccomp/stat.cc
@@ -8,7 +8,8 @@
 namespace playground {
 
 int Sandbox::sandbox_stat(const char *path, void *buf) {
-  Debug::syscall(__NR_stat, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_stat, "Executing handler");
   size_t len                    = strlen(path);
   struct Request {
     int       sysnum;
@@ -31,11 +32,13 @@ int Sandbox::sandbox_stat(const char *path, void *buf) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward stat() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_stat);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_lstat(const char *path, void *buf) {
-  Debug::syscall(__NR_lstat, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_lstat, "Executing handler");
   size_t len                    = strlen(path);
   struct Request {
     int       sysnum;
@@ -58,12 +61,14 @@ int Sandbox::sandbox_lstat(const char *path, void *buf) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward lstat() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_lstat);
   return static_cast<int>(rc);
 }
 
 #if defined(__NR_stat64)
 int Sandbox::sandbox_stat64(const char *path, void *buf) {
-  Debug::syscall(__NR_stat64, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_stat64, "Executing handler");
   size_t len                    = strlen(path);
   struct Request {
     int       sysnum;
@@ -86,11 +91,13 @@ int Sandbox::sandbox_stat64(const char *path, void *buf) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward stat64() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_stat64);
   return static_cast<int>(rc);
 }
 
 int Sandbox::sandbox_lstat64(const char *path, void *buf) {
-  Debug::syscall(__NR_lstat64, "Executing handler");
+  long long tm;
+  Debug::syscall(&tm, __NR_lstat64, "Executing handler");
   size_t len                    = strlen(path);
   struct Request {
     int       sysnum;
@@ -113,6 +120,7 @@ int Sandbox::sandbox_lstat64(const char *path, void *buf) {
       read(sys, threadFdPub(), &rc, sizeof(rc)) != sizeof(rc)) {
     die("Failed to forward lstat64() request [sandbox]");
   }
+  Debug::elapsed(tm, __NR_lstat64);
   return static_cast<int>(rc);
 }
 #endif
diff --git a/sandbox/linux/seccomp/syscall.cc b/sandbox/linux/seccomp/syscall.cc
index d3dc7aa..7f431a3 100644
--- a/sandbox/linux/seccomp/syscall.cc
+++ b/sandbox/linux/seccomp/syscall.cc
@@ -271,19 +271,20 @@ void* Sandbox::defaultSystemCallHandler(int syscallNum, void* arg0, void* arg1,
   // these system calls are not restricted in Seccomp mode. But depending on
   // the exact instruction sequence in libc, we might not be able to reliably
   // filter out these system calls at the time when we instrument the code.
-  SysCalls sys;
-  long     rc;
+  SysCalls  sys;
+  long      rc;
+  long long tm;
   switch (syscallNum) {
     case __NR_read:
-      Debug::syscall(syscallNum, "Allowing unrestricted system call");
+      Debug::syscall(&tm, syscallNum, "Allowing unrestricted system call");
       rc             = sys.read((long)arg0, arg1, (size_t)arg2);
       break;
     case __NR_write:
-      Debug::syscall(syscallNum, "Allowing unrestricted system call");
+      Debug::syscall(&tm, syscallNum, "Allowing unrestricted system call");
       rc             = sys.write((long)arg0, arg1, (size_t)arg2);
       break;
     case __NR_rt_sigreturn:
-      Debug::syscall(syscallNum, "Allowing unrestricted system call");
+      Debug::syscall(&tm, syscallNum, "Allowing unrestricted system call");
       rc             = sys.rt_sigreturn((unsigned long)arg0);
       break;
     default:
@@ -295,7 +296,7 @@ void* Sandbox::defaultSystemCallHandler(int syscallNum, void* arg0, void* arg1,
 
       if ((unsigned)syscallNum <= maxSyscall &&
           syscallTable[syscallNum].handler == UNRESTRICTED_SYSCALL) {
-        Debug::syscall(syscallNum, "Allowing unrestricted system call");
+        Debug::syscall(&tm, syscallNum, "Allowing unrestricted system call");
      perform_unrestricted:
         struct {
           int          sysnum;
@@ -309,9 +310,10 @@ void* Sandbox::defaultSystemCallHandler(int syscallNum, void* arg0, void* arg1,
             read(sys, thread, &rc, sizeof(rc)) != sizeof(rc)) {
           die("Failed to forward unrestricted system call");
         }
+        Debug::elapsed(tm, syscallNum);
         return rc;
       } else if (Debug::isEnabled()) {
-        Debug::syscall(syscallNum,
+        Debug::syscall(&tm, syscallNum,
                        "In production mode, this call would be disallowed");
         goto perform_unrestricted;
       } else {
@@ -321,6 +323,7 @@ void* Sandbox::defaultSystemCallHandler(int syscallNum, void* arg0, void* arg1,
   if (rc < 0) {
     rc               = -sys.my_errno;
   }
+  Debug::elapsed(tm, syscallNum);
   return (void *)rc;
 }
 
diff --git a/sandbox/linux/seccomp/trusted_process.cc b/sandbox/linux/seccomp/trusted_process.cc
index 9bf90bb..1320839 100644
--- a/sandbox/linux/seccomp/trusted_process.cc
+++ b/sandbox/linux/seccomp/trusted_process.cc
@@ -20,6 +20,7 @@ SecureMem::Args* Sandbox::getSecureMem() {
   if (!secureMemPool_.empty()) {
     SecureMem::Args* rc = secureMemPool_.back();
     secureMemPool_.pop_back();
+    memset(rc->scratchPage, 0, sizeof(rc->scratchPage));
     return rc;
   }
   return NULL;
@@ -27,6 +28,16 @@ SecureMem::Args* Sandbox::getSecureMem() {
 
 void Sandbox::trustedProcess(int parentMapsFd, int processFdPub, int sandboxFd,
                              int cloneFd, SecureMem::Args* secureArena) {
+  // The trusted process doesn't have access to TLS. Zero out the segment
+  // registers so that we can later test that we are in the trusted process.
+  #if defined(__x86_64__)
+  asm volatile("mov %0, %%gs\n" : : "r"(0));
+  #elif defined(__i386__)
+  asm volatile("mov %0, %%fs\n" : : "r"(0));
+  #else
+  #error Unsupported target platform
+  #endif
+
   std::map<long long, struct Thread> threads;
   SysCalls  sys;
   long long cookie               = 0;
diff --git a/sandbox/linux/seccomp/trusted_thread.cc b/sandbox/linux/seccomp/trusted_thread.cc
index af2e913..c73091c 100644
--- a/sandbox/linux/seccomp/trusted_thread.cc
+++ b/sandbox/linux/seccomp/trusted_thread.cc
@@ -86,6 +86,9 @@ void Sandbox::createTrustedThread(int processFdPub, int cloneFdPub,
       //   0x3C: RDTSCP result (%eax)
       //   0x40: RDTSCP result (%edx)
       //   0x44: RDTSCP result (%ecx)
+      //   0x48: last system call (not used on x86-64)
+      //   0x4C: number of consecutive calls to a time fnc (not used on x86-64)
+      //   0x50: nesting level of system calls (for debugging purposes only)
 
       // We use the %fs register for accessing the secure read-only page, and
       // the untrusted scratch space immediately following it. The segment
@@ -699,6 +702,7 @@ void Sandbox::createTrustedThread(int processFdPub, int cloneFdPub,
       //   0x28: RDTSCP result (%ecx)
       //   0x2C: last system call (updated in syscall.cc)
       //   0x30: number of consecutive calls to a time fnc. (e.g. gettimeofday)
+      //   0x34: nesting level of system calls (for debugging purposes only)
 
     "0:xor  %%esp, %%esp\n"
       "mov  $2, %%eax\n"           // %mm2 = initial sequence number