From 62dc1f04051694ae381488ef44fad336c6260ad6 Mon Sep 17 00:00:00 2001 From: "markus@chromium.org" Date: Thu, 18 Mar 2010 01:05:59 +0000 Subject: 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 --- sandbox/linux/seccomp/access.cc | 4 +- sandbox/linux/seccomp/clone.cc | 4 +- sandbox/linux/seccomp/debug.cc | 226 ++++++++++++++++++++++++------- sandbox/linux/seccomp/debug.h | 18 ++- sandbox/linux/seccomp/exit.cc | 3 +- sandbox/linux/seccomp/getpid.cc | 4 +- sandbox/linux/seccomp/gettid.cc | 7 +- sandbox/linux/seccomp/ioctl.cc | 4 +- sandbox/linux/seccomp/ipc.cc | 20 ++- sandbox/linux/seccomp/madvise.cc | 4 +- sandbox/linux/seccomp/mmap.cc | 8 +- sandbox/linux/seccomp/mprotect.cc | 4 +- sandbox/linux/seccomp/munmap.cc | 4 +- sandbox/linux/seccomp/open.cc | 4 +- sandbox/linux/seccomp/securemem.h | 12 +- sandbox/linux/seccomp/socketcall.cc | 37 ++++- sandbox/linux/seccomp/stat.cc | 16 ++- sandbox/linux/seccomp/syscall.cc | 17 ++- sandbox/linux/seccomp/trusted_process.cc | 11 ++ sandbox/linux/seccomp/trusted_thread.cc | 4 + 20 files changed, 327 insertions(+), 84 deletions(-) (limited to 'sandbox/linux') 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(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(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(tv.tv_sec) + + static_cast(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(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 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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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(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 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 -- cgit v1.1