gramineproject / graphene

Graphene / Graphene-SGX - a library OS for Linux multi-process applications, with Intel SGX support
https://grapheneproject.io
GNU Lesser General Public License v3.0
765 stars 262 forks source link

web server use golang, QPS(queries per second) is very low #2695

Closed yanzhichao closed 2 years ago

yanzhichao commented 2 years ago

Description of the problem

Steps to reproduce

It's an web app which developed by beego. beego is an opensource MVC web framework which use golang (https://github.com/beego/beego/)

The app have a restfulAPI :http://10.10.11.8:30002/marketplace/dp/v1/welfare/all It's work fine without grahene-sgx , But it's QPS is very low when run in graphene-sgx , as follow pic show: need about 2 min to finish the requst. image

There must be some problems,could you give me some suggestion ?

graphene version:75962a812d686e839

the logs which one requst is as follow:

[P12:T2:premain] trace: ---- return from shim_futex(...) = -110
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x7fffecd0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_futex(...) = -110
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x80a04150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T20:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x7fffecd0, 0x0, 0) ...
[P12:T20:premain] trace: ---- shim_epoll_pwait(5, 0x521fd740, 128, 0, 0x0, 0x10) ...
[P12:T20:premain] trace: ---- return from shim_epoll_pwait(...) = 0x3
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdc70) = 0x0
[P12:T20:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T20:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdd20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T20:premain] trace: ---- shim_futex(0x8088a150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T20:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T15:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8ba0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T15:premain] trace: ---- shim_futex(0x80169d50, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T15:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] trace: ---- shim_read(11, 0x803c5000, 0x1000) ...
[P12:T13:premain] trace: ---- shim_futex(0x8078c150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T15:premain] trace: ---- return from shim_read(...) = 0x1e9
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8d30) = 0x0
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T13:premain] trace: ---- shim_read(10, 0x805b6000, 0x1000) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- shim_futex(0x80168950, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- return from shim_read(...) = 0x1e9
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffed30) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T3:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_accept4(8, 0x80175b18, 0x80175b0c, 526336) ...
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8d30) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T3:premain] trace: ---- shim_futex(0x80a8a150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
debug: sock_getopt (fd = 26, sockopt addr = 0x7fccaefaaf70) is not implemented and always returns 0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T3:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T19:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fddd0) = 0x0
[P12:T16:premain] trace: ---- return from shim_accept4(...) = 0x9
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffeba0) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(0, 0xcbf8dd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffed30) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffed30) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T19:premain] trace: ---- shim_futex(0x80806150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdbb0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(0, 0xcbf8dd0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffebb0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T19:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T20:premain] trace: ---- shim_getpid() = 0x1
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8b10) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806ba0) = 0x0
[P12:T20:premain] trace: ---- shim_tgkill(1, 13, [SIGURG]) = 0x0
[P12:T18:premain] trace: ---- shim_nanosleep([0,3000], 0x0) ...
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdbb0) = 0x0
[P12:T19:premain] trace: ---- shim_getpid() = 0x1
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdbb0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T13:premain] trace: ---- shim_tgkill(1, 15, [SIGURG]) = 0x0
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fddd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T13:premain] debug: Created sigframe for sig: 23 at 0x804cd390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T15:premain] trace: ---- shim_getpid() = 0x1
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T20:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T13:premain] trace: ---- shim_rt_sigreturn()
[P12:T18:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T15:premain] debug: Created sigframe for sig: 23 at 0x80893390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_tgkill(1, 19, [SIGURG]) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdbb0) = 0x0
[P12:T19:premain] trace: ---- shim_tgkill(1, 3, [SIGURG]) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffebb0) = 0x0
[P12:T3:premain] debug: Created sigframe for sig: 23 at 0x8018f390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffed30) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T15:premain] trace: ---- shim_rt_sigreturn()
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffebb0) = 0x0
[P12:T18:premain] trace: ---- shim_futex(0x80582550, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T3:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] debug: add fd 9 (handle 0xf290a1c8) to epoll handle 0xf2909e78
[P12:T19:premain] debug: Created sigframe for sig: 23 at 0x80a93390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fddd0) = 0x0
[P12:T13:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T19:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] trace: ---- shim_epoll_ctl(5, 1, 9, 0x80175bfc) = 0x0
[P12:T15:premain] trace: ---- shim_tgkill(1, 20, [SIGURG]) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffebb0) = 0x0
[P12:T21:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T20:premain] debug: Created sigframe for sig: 23 at 0x80a0d390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T18:premain] trace: ---- shim_read(11, 0x803ac2b1, 0x1) ...
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T20:premain] trace: ---- shim_rt_sigreturn()
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_getsockname(9, 0x80175c38, 0x80175c34) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T18:premain] trace: ---- return from shim_read(...) = 0x0
[P12:T21:premain] trace: ---- shim_futex(0x119f2b0, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T15:premain] trace: ---- shim_getpid() = 0x1
[P12:T3:premain] trace: ---- shim_tgkill(1, 19, [SIGURG]) = 0x0
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806dd0) = 0x0
[P12:T21:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T19:premain] debug: Created sigframe for sig: 23 at 0x80a93390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T1:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T19:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] trace: ---- shim_setsockopt(9, 6, 1, 0x80175d0c, 4) = 0x0
[P12:T15:premain] trace: ---- shim_tgkill(1, 20, [SIGURG]) = 0x0
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T20:premain] debug: Created sigframe for sig: 23 at 0x80a0d390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffedd0) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9a40) = 0x0
[P12:T20:premain] trace: ---- shim_rt_sigreturn()
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffedd0) = 0x0
[P12:T18:premain] trace: ---- shim_getpid() = 0x1
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T3:premain] trace: ---- shim_tgkill(1, 15, [SIGURG]) = 0x0
[P12:T16:premain] trace: ---- shim_setsockopt(9, 1, 9, 0x80175d0c, 4) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T1:premain] trace: ---- shim_nanosleep([0,3000], 0x0) ...
[P12:T21:premain] trace: ---- shim_clock_gettime(0, 0x4bffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T15:premain] trace: ---- shim_getpid() = 0x1
[P12:T18:premain] trace: ---- shim_tgkill(1, 13, [SIGURG]) = 0x0
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T16:premain] trace: ---- shim_setsockopt(9, 6, 5, 0x80175cfc, 4) = -92
[P12:T15:premain] debug: Created sigframe for sig: 23 at 0x80893390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T15:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T1:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T13:premain] debug: Created sigframe for sig: 23 at 0x804cd390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T13:premain] trace: ---- shim_rt_sigreturn()
[P12:T3:premain] trace: ---- shim_tgkill(1, 20, [SIGURG]) = 0x0
[P12:T20:premain] debug: Created sigframe for sig: 23 at 0x80a0d390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T15:premain] trace: ---- shim_tgkill(1, 19, [SIGURG]) = 0x0
[P12:T1:premain] trace: ---- shim_futex(0x804ce150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T20:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] trace: ---- shim_accept4(8, 0x80175b18, 0x80175b0c, 526336) ...
[P12:T19:premain] debug: Created sigframe for sig: 23 at 0x80a93390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T19:premain] trace: ---- shim_rt_sigreturn()
[P12:T13:premain] trace: ---- shim_tgkill(1, 21, [SIGURG]) = 0x0
debug: sock_getopt (fd = 29, sockopt addr = 0x7fccaefaaf70) is not implemented and always returns 0
[P12:T1:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T14:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T21:premain] debug: Created sigframe for sig: 23 at 0x80597390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T21:premain] trace: ---- shim_rt_sigreturn()
[P12:T19:premain] trace: ---- shim_getpid() = 0x1
[P12:T16:premain] trace: ---- return from shim_accept4(...) = 0xc
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T14:premain] trace: ---- shim_futex(0x8098a150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T19:premain] trace: ---- shim_tgkill(1, 15, [SIGURG]) = 0x0
[P12:T16:premain] debug: add fd 12 (handle 0xf290a6c8) to epoll handle 0xf2909e78
[P12:T14:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T21:premain] trace: ---- shim_getpid() = 0x1
[P12:T15:premain] debug: Created sigframe for sig: 23 at 0x80893390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_epoll_ctl(5, 1, 12, 0x80175bfc) = 0x0
[P12:T17:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- shim_getsockname(12, 0x80175c38, 0x80175c34) = 0x0
[P12:T1:premain] trace: ---- shim_mmap(0x0, 0x40000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0x0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(0, 0x621fddd0) = 0x0
[P12:T18:premain] trace: ---- shim_getpid() = 0x1
[P12:T19:premain] trace: ---- shim_getpid() = 0x1
[P12:T21:premain] trace: ---- shim_tgkill(1, 3, [SIGURG]) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fddd0) = 0x0
[P12:T17:premain] trace: ---- shim_nanosleep([0,3000], 0x0) ...
[P12:T3:premain] debug: Created sigframe for sig: 23 at 0x8018f390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T3:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T1:premain] trace: ---- return from shim_mmap(...) = 0x84c78000
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T18:premain] trace: ---- shim_tgkill(1, 19, [SIGURG]) = 0x0
[P12:T17:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T19:premain] trace: ---- shim_tgkill(1, 16, [SIGURG]) = 0x0
[P12:T13:premain] trace: ---- shim_tgkill(1, 15, [SIGURG]) = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T19:premain] debug: Created sigframe for sig: 23 at 0x80a93390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T16:premain] debug: Created sigframe for sig: 23 at 0x80795390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T17:premain] trace: ---- shim_futex(0x80702150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T19:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T17:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T15:premain] debug: Created sigframe for sig: 23 at 0x80893390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T3:premain] trace: ---- shim_tgkill(1, 13, [SIGURG]) = 0x0
[P12:T15:premain] trace: ---- shim_rt_sigreturn()
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fddd0) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T13:premain] debug: Created sigframe for sig: 23 at 0x804cd390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T17:premain] trace: ---- shim_read(10, 0x805b0041, 0x1) ...
[P12:T16:premain] trace: ---- shim_tgkill(1, 21, [SIGURG]) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(0, 0xab2e9c70) = 0x0
[P12:T13:premain] trace: ---- shim_rt_sigreturn()
[P12:T14:premain] trace: ---- shim_clock_gettime(0, 0x621fddd0) = 0x0
[P12:T21:premain] debug: Created sigframe for sig: 23 at 0x80597390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T17:premain] trace: ---- return from shim_read(...) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x8068c150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fddd0) = 0x0
[P12:T21:premain] trace: ---- shim_rt_sigreturn()
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fddd0) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T18:premain] trace: ---- shim_getpid() = 0x1
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T11:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T14:premain] trace: ---- shim_write(10, 0x805b7000, 0x896) ...
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T17:premain] trace: ---- shim_getpid() = 0x1
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T20:premain] trace: ---- shim_getpid() = 0x1
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8cc0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 18, [SIGURG]) = 0x0
[P12:T11:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_tgkill(1, 3, [SIGURG]) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T14:premain] trace: ---- return from shim_write(...) = 0x896
[P12:T18:premain] trace: ---- shim_tgkill(1, 19, [SIGURG]) = 0x0
[P12:T11:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T12:premain] debug: Created sigframe for sig: 23 at 0x8070b390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T3:premain] trace: ---- shim_tgkill(1, 1, [SIGURG]) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(0, 0x621fddd0) = 0x0
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T17:premain] trace: ---- shim_tgkill(1, 12, [SIGURG]) = 0x0
[P12:T20:premain] trace: ---- shim_tgkill(1, 16, [SIGURG]) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fddd0) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8cc0) = 0x0
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T1:premain] debug: Created sigframe for sig: 23 at 0x80009390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T19:premain] trace: ---- shim_getpid() = 0x1
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fddd0) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(0, 0x621fddd0) = 0x0
[P12:T12:premain] trace: ---- shim_rt_sigreturn()
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T19:premain] debug: Created sigframe for sig: 23 at 0x80a93390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fddd0) = 0x0
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fddd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T1:premain] trace: ---- shim_rt_sigreturn()
[P12:T21:premain] trace: ---- shim_write(11, 0x803d8000, 0x896) ...
[P12:T3:premain] debug: Created sigframe for sig: 23 at 0x8018f390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T19:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x80582150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T13:premain] trace: ---- shim_tgkill(1, 17, [SIGURG]) = 0x0
[P12:T18:premain] debug: Created sigframe for sig: 23 at 0x8080f390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T11:premain] trace: ---- shim_setsockopt(12, 6, 1, 0x80175d0c, 4) = 0x0
[P12:T3:premain] trace: ---- shim_rt_sigreturn()
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8dd0) = 0x0
[P12:T14:premain] trace: ---- shim_read(10, 0x805b6000, 0x1000) ...
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T16:premain] debug: Created sigframe for sig: 23 at 0x80795390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T21:premain] trace: ---- return from shim_write(...) = 0x896
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T18:premain] trace: ---- shim_rt_sigreturn()
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T13:premain] trace: ---- shim_getpid() = 0x1
[P12:T14:premain] trace: ---- return from shim_read(...) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T19:premain] trace: ---- shim_tgkill(1, 15, [SIGURG]) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T21:premain] trace: ---- shim_clock_gettime(0, 0x4bffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T16:premain] trace: ---- shim_rt_sigreturn()
[P12:T9:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T15:premain] debug: Created sigframe for sig: 23 at 0x80893390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T3:premain] trace: ---- shim_getpid() = 0x1
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffedd0) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9c70) = 0x0
[P12:T18:premain] trace: ---- shim_getpid() = 0x1
[P12:T11:premain] trace: ---- shim_setsockopt(12, 1, 9, 0x80175d0c, 4) = 0x0
[P12:T12:premain] debug: Created sigframe for sig: 23 at 0x8070b390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T21:premain] trace: ---- shim_clock_gettime(0, 0x4bffedd0) = 0x0
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fddd0) = 0x0
[P12:T15:premain] trace: ---- shim_rt_sigreturn()
[P12:T13:premain] trace: ---- shim_tgkill(1, 12, [SIGURG]) = 0x0
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T7:premain] trace: ---- shim_clock_gettime(0, 0x725fbdd0) = 0x0
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8cc0) = 0x0
[P12:T19:premain] trace: ---- shim_clock_gettime(1, 0x53ffeba0) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9a40) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T14:premain] debug: delete fd 10 (handle 0xf290a308) from epoll handle 0xf2909e78
[P12:T9:premain] trace: ---- shim_futex(0x80168d50, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T20:premain] trace: ---- shim_clock_gettime(1, 0x521fdba0) = 0x0
[P12:T12:premain] trace: ---- shim_rt_sigreturn()
[P12:T7:premain] trace: ---- shim_clock_gettime(1, 0x725fbdd0) = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 13, [SIGURG]) = 0x0
[P12:T17:premain] debug: Created sigframe for sig: 23 at 0x80993390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T15:premain] trace: ---- shim_clock_gettime(1, 0xcbf8ba0) = 0x0
[P12:T11:premain] trace: ---- shim_setsockopt(12, 6, 5, 0x80175cfc, 4) = -92
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T14:premain] trace: ---- shim_epoll_ctl(5, 2, 10, 0x803b39cc) = 0x0
[P12:T3:premain] trace: ---- shim_tgkill(1, 1, [SIGURG]) = 0x0
[P12:T18:premain] trace: ---- shim_tgkill(1, 21, [SIGURG]) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T13:premain] debug: Created sigframe for sig: 23 at 0x804cd390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T17:premain] trace: ---- shim_rt_sigreturn()
[P12:T9:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T11:premain] trace: ---- shim_clock_gettime(0, 0x387fadd0) = 0x0
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fddd0) = 0x0
[P12:T19:premain] trace: ---- shim_futex(0x80a8a150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T20:premain] trace: ---- shim_futex(0x80a04150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806dd0) = 0x0
[P12:T11:premain] trace: ---- shim_clock_gettime(1, 0x387fadd0) = 0x0
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fddd0) = 0x0
[P12:T9:premain] trace: ---- shim_clock_gettime(1, 0x6a1fddd0) = 0x0
[P12:T21:premain] trace: ---- shim_read(11, 0x803c5000, 0x1000) ...
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9ba0) = 0x0
[P12:T13:premain] trace: ---- shim_rt_sigreturn()
[P12:T7:premain] trace: ---- shim_read(9, 0x803d9000, 0x1000) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffeba0) = 0x0
[P12:T1:premain] debug: Created sigframe for sig: 23 at 0x80009390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fdba0) = 0x0
[P12:T15:premain] trace: ---- shim_futex(0x8088a150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T9:premain] trace: ---- shim_clock_gettime(1, 0x6a1fddd0) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T4:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T1:premain] trace: ---- shim_rt_sigreturn()
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fdba0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806ba0) = 0x0
[P12:T21:premain] trace: ---- return from shim_read(...) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9dd0) = 0x0
[P12:T21:premain] debug: Created sigframe for sig: 23 at 0x80597390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T14:premain] trace: ---- shim_close(10) = 0x0
[P12:T3:premain] trace: ---- shim_nanosleep([0,3000], 0x0) ...
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9a40) = 0x0
[P12:T11:premain] trace: ---- shim_accept4(8, 0x80175b18, 0x80175b0c, 526336) ...
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806ba0) = 0x0
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fdba0) = 0x0
[P12:T7:premain] trace: ---- return from shim_read(...) = 0x1e9
[P12:T21:premain] trace: ---- shim_rt_sigreturn()
[P12:T4:premain] trace: ---- shim_clock_gettime(1, 0x743fcba0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9ba0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffeba0) = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T9:premain] trace: ---- shim_clock_gettime(0, 0x6a1fddd0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T11:premain] trace: ---- return from shim_accept4(...) = -11
[P12:T9:premain] trace: ---- shim_clock_gettime(1, 0x6a1fddd0) = 0x0
[P12:T21:premain] debug: delete fd 11 (handle 0xf290a588) from epoll handle 0xf2909e78
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T14:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T1:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T18:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T17:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T3:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T13:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T21:premain] trace: ---- shim_epoll_ctl(5, 2, 11, 0x803af9cc) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T4:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 14, [SIGURG]) = 0x0
[P12:T7:premain] trace: ---- shim_clock_gettime(0, 0x725fbdd0) = 0x0
[P12:T1:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T18:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T17:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_clock_gettime(1, 0x725fbdd0) = 0x0
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T1:premain] trace: ---- return from shim_futex(...) = -11
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T11:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T4:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T17:premain] trace: ---- return from shim_futex(...) = -11
[P12:T18:premain] trace: ---- return from shim_futex(...) = -11
[P12:T9:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T14:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T3:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T13:premain] trace: ---- return from shim_futex(...) = -11
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T21:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = -11
[P12:T14:premain] trace: ---- return from shim_futex(...) = -512
[P12:T11:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T9:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T14:premain] debug: Created sigframe for sig: 23 at 0x804d7390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T1:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T3:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T21:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T17:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T18:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T13:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T14:premain] trace: ---- shim_rt_sigreturn()
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 7, [SIGURG]) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T14:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T1:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T7:premain] debug: Created sigframe for sig: 23 at 0x8021d390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T17:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T18:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T7:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_tgkill(1, 9, [SIGURG]) = 0x0
[P12:T9:premain] debug: Created sigframe for sig: 23 at 0x8058b390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T9:premain] trace: ---- shim_rt_sigreturn()
[P12:T9:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T9:premain] trace: ---- return from shim_futex(...) = -11
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T4:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T9:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffecb0) = 0x0
[P12:T4:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T9:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T11:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x5bffecc8, 0x0, 0) ...
[P12:T4:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T3:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T9:premain] trace: ---- shim_read(12, 0x80a9c000, 0x1000) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T11:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T4:premain] trace: ---- shim_clock_gettime(1, 0x743fcba0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T3:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T9:premain] trace: ---- return from shim_read(...) = -11
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T11:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T21:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T3:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T11:premain] trace: ---- shim_clock_gettime(1, 0x387fabe0) = 0x0
[P12:T9:premain] trace: ---- shim_clock_gettime(1, 0x6a1fdbe0) = 0x0
[P12:T14:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T4:premain] trace: ---- shim_futex(0x80168d50, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fdba0) = 0x0
[P12:T21:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- return from shim_futex(...) = -110
[P12:T9:premain] trace: ---- shim_futex(0x80582150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T3:premain] trace: ---- shim_clock_gettime(0, 0x7e1fddd0) = 0x0
[P12:T11:premain] trace: ---- shim_futex(0x8068c150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T14:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffecb0) = 0x0
[P12:T21:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fddd0) = 0x0
[P12:T1:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T3:premain] trace: ---- shim_clock_gettime(1, 0x7e1fdbd0) = 0x0
[P12:T14:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T17:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T1:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T14:premain] trace: ---- shim_clock_gettime(1, 0x621fda00) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T3:premain] trace: ---- shim_futex(0x80168950, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T17:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T1:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T21:premain] trace: ---- shim_close(11) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 3, [SIGURG]) = 0x0
[P12:T14:premain] trace: ---- shim_futex(0x804ce150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T21:premain] trace: ---- shim_clock_gettime(0, 0x4bffedd0) = 0x0
[P12:T17:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T3:premain] trace: ---- return from shim_futex(...) = -512
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T1:premain] trace: ---- shim_clock_gettime(1, 0xab2e9a40) = 0x0
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffedd0) = 0x0
[P12:T18:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T3:premain] debug: Created sigframe for sig: 23 at 0x8018f390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T17:premain] trace: ---- shim_clock_gettime(1, 0x5a1fdba0) = 0x0
[P12:T3:premain] trace: ---- shim_rt_sigreturn()
[P12:T21:premain] trace: ---- shim_clock_gettime(1, 0x4bffebd0) = 0x0
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T1:premain] trace: ---- shim_futex(0x119f2b0, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T3:premain] trace: ---- shim_futex(0x80168950, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T17:premain] trace: ---- shim_futex(0x8098a150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806ba0) = 0x0
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T16:premain] trace: ---- shim_tgkill(1, 21, [SIGURG]) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T21:premain] trace: ---- shim_futex(0x80582550, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffecb0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffeba0) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T21:premain] trace: ---- return from shim_futex(...) = -512
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T18:premain] trace: ---- shim_futex(0x80806150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T21:premain] debug: Created sigframe for sig: 23 at 0x80597390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x5bffecc8, 0x0, 0) ...
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9ba0) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T21:premain] trace: ---- shim_rt_sigreturn()
[P12:T13:premain] trace: ---- shim_clock_gettime(0, 0x63ffedd0) = 0x0
[P12:T21:premain] trace: ---- shim_futex(0x80582550, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T12:premain] trace: ---- shim_nanosleep([0,3000], 0x0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T7:premain] trace: ---- shim_clock_gettime(1, 0x725fb9b0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T13:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T7:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- shim_tgkill(1, 13, [SIGURG]) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- return from shim_futex(...) = -512
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T13:premain] debug: Created sigframe for sig: 23 at 0x804cd390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T13:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_tgkill(1, 12, [SIGURG]) = 0x0
[P12:T12:premain] debug: Created sigframe for sig: 23 at 0x8070b390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T12:premain] trace: ---- shim_rt_sigreturn()
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = -11
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffecb0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x5bffecc8, 0x0, 0) ...
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- shim_read(9, 0x8029e041, 0x1) ...
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x80806150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_read(...) = -11
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T13:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T18:premain] trace: ---- shim_clock_gettime(1, 0xe2806ba0) = 0x0
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffe9b0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = -11
[P12:T18:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T16:premain] trace: ---- shim_getpid() = 0x1
[P12:T18:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T7:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T13:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_tgkill(1, 7, [SIGURG]) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = -11
[P12:T16:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T7:premain] debug: Created sigframe for sig: 23 at 0x8021d390 (handler: 0x473320, restorer: 0xae0ebc70)
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T7:premain] trace: ---- shim_rt_sigreturn()
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffece0) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x7fffecd0, 0x0, 0) ...
[P12:T18:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_futex(0x119ebc8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x5bffecf0, 0x0, 0) ...
[P12:T18:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T18:premain] trace: ---- shim_futex(0x80806150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- shim_futex(0x80169d50, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ebc8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- return from shim_futex(...) = -110
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x80702150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_epoll_pwait(5, 0x5bffe748, 128, 0, 0x0, 0xffffffffffffffff) ...
[P12:T16:premain] trace: ---- return from shim_epoll_pwait(...) = 0x2
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffec80) = 0x0
[P12:T16:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T2:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_futex(0x80702150, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- shim_sched_yield() = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAIT, 2, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_futex(0x119ebf8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x5bffecd8, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- return from shim_futex(...) = -11
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T12:premain] trace: ---- shim_futex(0x119ead8, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9ae0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f99b0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T12:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T12:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- shim_write(9, 0x80a16000, 0x896) ...
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9cc0) = 0x0
[P12:T12:premain] trace: ---- shim_clock_gettime(1, 0x269f9ba0) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x80169d50, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- return from shim_write(...) = 0x896
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T12:premain] trace: ---- shim_futex(0x80702150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T13:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T13:premain] trace: ---- shim_clock_gettime(1, 0x63ffe9b0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T13:premain] trace: ---- shim_futex(0x80169d50, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T16:premain] trace: ---- shim_clock_gettime(0, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffedd0) = 0x0
[P12:T16:premain] trace: ---- shim_read(9, 0x803d9000, 0x1000) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- return from shim_read(...) = -11
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T16:premain] trace: ---- shim_clock_gettime(1, 0x5bffeba0) = 0x0
[P12:T7:premain] trace: ---- shim_clock_gettime(1, 0x725fbbe0) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T16:premain] trace: ---- shim_futex(0x8078c150, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T7:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x7fffecd0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_futex(...) = -110
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAKE, 1, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- return from shim_futex(...) = 0x1
[P12:T7:premain] trace: ---- return from shim_futex(...) = 0x0
[P12:T2:premain] trace: ---- shim_nanosleep([0,20000], 0x0) ...
[P12:T7:premain] trace: ---- shim_clock_gettime(1, 0x725fbba0) = 0x0
[P12:T2:premain] trace: ---- return from shim_nanosleep(...) = 0x0
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffed20) = 0x0
[P12:T7:premain] trace: ---- shim_futex(0x80200550, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x0, 0x0, 0) ...
[P12:T2:premain] trace: ---- shim_clock_gettime(1, 0x7fffecc0) = 0x0
[P12:T2:premain] trace: ---- shim_futex(0x119ebd8, FUTEX_PRIVATE|FUTEX_WAIT, 0, 0x7fffecd0, 0x0, 0) ...
dimakuv commented 2 years ago

Golang on Linux uses raw system calls (raw syscall instructions, see https://www.felixcloutier.com/x86/syscall.html).

Intel SGX hardware disallows raw syscall instructions. This means that every syscall instruction invoked inside the SGX enclave results in a SIGILL ("Illegal Instruction", see also https://www.felixcloutier.com/x86/ud) exception. Exceptions in Intel SGX hardware are very expensive.

Gramine implements "trap-and-emulate" approach to catch SIGILL exceptions due to syscall instructions in the SGX enclave -- Gramine catches SIGILL, understands that the illegal instruction is a syscall, emulates this instruction via Gramine internal syscall logic, and then returns from the SIGILL exception back to normal execution. So from functionality perspective, the Golang application doesn't notice anything and happily continues its execution. But from performance perspective, there was a whole SIGILL exception -> AEX -> EENTER -> trap-and-emulate in Gramine -> EEXIT -> ERESUME flow, which is very expensive.

Why does this SIGILL exception happen only with Golang applications, you may ask. That's because all other applications/frameworks/runtimes (that I'm aware of) use dynamic linking against the C Standard library (Glibc). And all system call invokations happen through Glibc, so all raw syscall instructions are concentrated in Glibc code. Gramine provides a patched Glibc where all these raw syscall instructions are replaced with classic function calls into Gramine (see for example https://github.com/gramineproject/gramine/blob/v1.0/subprojects/packagefiles/glibc-2.34/glibc-2.34.patch). So when running applications with Gramine, there will be no raw syscall instructions because the patched Glibc will directly call Gramine syscall emulations. Thus, no SIGILL exceptions happen, and SGX performance is good.

You may wonder why Golang is so special (I think this is the only language/runtime that chooses to implement raw system calls instead of going through Glibc/Musl). It is actually a very interesting topic. Here are the relevant links:

The irony here is that to date (October 2021), Golang runtimes do not use raw syscall instructions and instead invoke system calls through the C Standard library on: Windows, MacOS, Illumos, Solaris, OpenBSD. But not on Linux. So if we would run Gramine-SGX on Windows or Mac, we would not have the awful performance penalty that we have currently on Linux.

As far as I know, there is currently no (simple) way to force Golang applications to invoke system calls through Glibc on Linux (please note that CGO_ENABLED Golang config does link against Glibc, but it does not remove raw syscall instructions from the Golang application). Some complex ways are:

  1. Statically analyze and replace syscall instructions in Golang binaries.
  2. Dynamically analyze and replace syscall instructions in Golang binaries. (UPDATE: In-place patching of syscall instructions is impossible in general case, though one may try ad-hoc solutions.)
  3. Find an (unofficial) toolchain that produces Golang binaries that invoke system calls through Glibc.
  4. Wait for X years until Golang team allows invoking system calls through Glibc on Linux.

The Gramine team could explore solution (2) and incorporate some small dynamic binary rewriter into Gramine-SGX. But no promises here. On your side, you can google for solutions (1) and (3), or wait for solution (4).

yanzhichao commented 2 years ago

Thank you @dimakuv
Every reply is very timely

Ok, I will have a try to use solutions (1) and (3) otherwish We can only consider implementing our application in another language

Thanks for your analysis again.

dimakuv commented 2 years ago

@yanzhichao Please inform us of any interesting findings!

mkow commented 2 years ago

Seems stale, closing.