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

sandbox/linux/seccomp/socketcall.cc

 // 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"
 
 namespace playground {
 
 #if defined(__NR_socket)
 
 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) {
     // recv() with a NULL sender and no flags is the same as read(), which
     // is unrestricted in seccomp mode.
     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;
     }
   }
 
   struct {
     int       sysnum;
     long long cookie;
     RecvFrom  recvfrom_req;
   } __attribute__((packed)) request;
   request.sysnum               = __NR_recvfrom;
   request.cookie               = cookie();
   request.recvfrom_req.sockfd  = sockfd;
   request.recvfrom_req.buf     = buf;
   request.recvfrom_req.len     = len;
   request.recvfrom_req.flags   = flags;
   request.recvfrom_req.from    = from;
   request.recvfrom_req.fromlen = fromlen;
 
   long rc;
   if (write(sys, processFdPub(), &request, sizeof(request)) !=
       sizeof(request) ||
       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.
   struct {
     int       sysnum;
     long long cookie;
     RecvMsg   recvmsg_req;
   } __attribute__((packed)) request;
   request.sysnum             = __NR_recvmsg;
   request.cookie             = cookie();
   request.recvmsg_req.sockfd = sockfd;
   request.recvmsg_req.msg    = msg;
   request.recvmsg_req.flags  = flags;
 
   long rc;
   SysCalls sys;
   if (write(sys, processFdPub(), &request, sizeof(request)) !=
       sizeof(request) ||
       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()
     return sandbox_sendto(sockfd, msg->msg_iov, msg->msg_iovlen,
                           flags, msg->msg_name, msg->msg_namelen);
   }
 
   struct Request {
     int           sysnum;
     long long     cookie;
@@ skipping 13 matching lines @@
     msg->msg_namelen,
       msg->msg_control, msg->msg_controllen);
 
   long rc;
   SysCalls sys;
   if (write(sys, processFdPub(), &data, sizeof(data)) !=
       (ssize_t)sizeof(data) ||
       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) {
     // sendto() with a NULL recipient and no flags is the same as write(),
     // which is unrestricted in seccomp mode.
     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;
     }
   }
 
   struct {
     int       sysnum;
     long long cookie;
     SendTo    sendto_req;
   } __attribute__((packed)) request;
   request.sysnum            = __NR_sendto;
   request.cookie            = cookie();
   request.sendto_req.sockfd = sockfd;
   request.sendto_req.buf    = buf;
   request.sendto_req.len    = len;
   request.sendto_req.flags  = flags;
   request.sendto_req.to     = to;
   request.sendto_req.tolen  = tolen;
 
   long rc;
   if (write(sys, processFdPub(), &request, sizeof(request)) !=
       sizeof(request) ||
       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;
     long long  cookie;
     SetSockOpt setsockopt_req;
   } __attribute__((packed)) request;
   request.sysnum                 = __NR_setsockopt;
   request.cookie                 = cookie();
   request.setsockopt_req.sockfd  = sockfd;
   request.setsockopt_req.level   = level;
   request.setsockopt_req.optname = optname;
   request.setsockopt_req.optval  = optval;
   request.setsockopt_req.optlen  = optlen;
 
   long rc;
   SysCalls sys;
   if (write(sys, processFdPub(), &request, sizeof(request)) !=
       sizeof(request) ||
       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;
     long long  cookie;
     GetSockOpt getsockopt_req;
   } __attribute__((packed)) request;
   request.sysnum                 = __NR_getsockopt;
   request.cookie                 = cookie();
   request.getsockopt_req.sockfd  = sockfd;
   request.getsockopt_req.level   = level;
   request.getsockopt_req.optname = optname;
   request.getsockopt_req.optval  = optval;
   request.getsockopt_req.optlen  = optlen;
 
   long rc;
   SysCalls sys;
   if (write(sys, processFdPub(), &request, sizeof(request)) !=
       sizeof(request) ||
       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);
 }
 
 bool Sandbox::process_recvfrom(int parentMapsFd, int sandboxFd,
                                int threadFdPub, int threadFd,
                                SecureMem::Args* mem) {
   // Read request
   RecvFrom recvfrom_req;
   SysCalls sys;
   if (read(sys, sandboxFd, &recvfrom_req, sizeof(recvfrom_req)) !=
@@ skipping 328 matching lines @@
   { SIZE(getsockopt)                                                   },
   { SIZE(sendmsg)                                                      },
   { SIZE(recvmsg)                                                      },
   { SIZE(accept4)                                                      }
   #undef STRUCT
   #undef SIZE
   #undef OFF
 };
 
 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;
   }
 
   // Some type of calls include a pointer to an address or name, which cannot
   // be accessed by the trusted process, as it lives in a separate address
   // space. For these calls, append the extra data to the serialized request.
   // This requires some copying of data, as we have to make sure there is
   // only a single atomic call to write().
   socklen_t   numExtraData  = 0;
   const void* extraDataAddr = NULL;
@@ skipping 69 matching lines @@
     numExtraData = 0;
   }
   if (call == SYS_SEND && !request->socketcall_req.args.send.flags) {
     // send() with no flags is the same as write(), which is unrestricted
     // in seccomp mode.
     Debug::message("Replaced socketcall() with call to write()");
     ssize_t rc = sys.write(request->socketcall_req.args.send.sockfd,
                            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;
     }
   }
 
   // Simplify recv(), and recvfrom(), if there are simpler equivalent calls.
   // This allows us to occasionally replace them with calls to read(), which
   // don't have to be forwarded to the trusted process.
   // We cannot simplify recvmsg() to recvfrom(), recv() or read(), as we do
   // not know whether the caller needs us to set msg->msg_flags.
   if (call == SYS_RECVFROM && !request->socketcall_req.args.recvfrom.from) {
     // recvfrom() with a NULL address buffer is the same as recv()
     call = SYS_RECV;
   }
   if (call == SYS_RECV && !request->socketcall_req.args.recv.flags) {
     // recv() with no flags is the same as read(), which is unrestricted
     // in seccomp mode.
     Debug::message("Replaced socketcall() with call to read()");
     ssize_t rc = sys.read(request->socketcall_req.args.recv.sockfd,
                           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;
     }
   }
 
   // Fill in the rest of the request header.
   request->sysnum                 = __NR_socketcall;
   request->cookie                 = cookie();
   request->socketcall_req.call    = call;
   request->socketcall_req.arg_ptr = args;
   int padding = sizeof(request->socketcall_req.args) -
@@ skipping 16 matching lines @@
     memcpy(request + 1, extraDataAddr, numExtraData);
   }
 
   // Send request to trusted process and collect response from trusted thread.
   long rc;
   ssize_t len                     = sizeof(struct Request) + numExtraData;
   if (write(sys, processFdPub(), data, len) != len ||
       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);
 }
 
 bool Sandbox::process_socketcall(int parentMapsFd, int sandboxFd,
                                  int threadFdPub, int threadFd,
                                  SecureMem::Args* mem) {
   // Read request
   SocketCall socketcall_req;
   SysCalls sys;
   if (read(sys, sandboxFd, &socketcall_req, sizeof(socketcall_req)) !=
@@ skipping 288 matching lines @@
     default:
     deny:
       SecureMem::abandonSystemCall(threadFd, rc);
       return false;
   }
 }
 
 #endif
 
 } // namespace