Golang is surely my first to go language to write web application, it hides many details but still gives a lot of flexibility. Recently I did strace
to an http service app, actually did it without a reason but I found something interesting.
Here’s what strace -c
gave me :
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 91.24 0.397615 336 1185 29 futex 4.13 0.018009 3 7115 clock_gettime 2.92 0.012735 19 654 epoll_wait 1.31 0.005701 6 911 write 0.20 0.000878 3 335 epoll_ctl 0.12 0.000525 1 915 457 read 0.02 0.000106 2 59 select 0.01 0.000059 0 170 close 0.01 0.000053 0 791 setsockopt 0.01 0.000035 0 158 getpeername 0.01 0.000034 0 170 socket 0.01 0.000029 0 160 getsockname 0.01 0.000026 0 159 getsockopt 0.00 0.000000 0 7 sched_yield 0.00 0.000000 0 166 166 connect 0.00 0.000000 0 3 1 accept4 ------ ----------- ----------- --------- --------- ---------------- 100.00 0.435805 12958 653 total
There are a lot of interesting things in that profiling result, but the highlight of this article are the error number of read and the number of futex call
At the first sight I didn’t think about futex
call, which most of them are a wake call. I thought that this app serve hundreds req per second, it should has many go routine; At the other hand it also leverage channel, it should has many under the hood blocking mechanism. So a lot of futex
call should be normal, later I found out that this number was also from other things -will back to it later-. Continue reading