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

1 files changed, 30 insertions, 7 deletions

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);
 }