Hateburo: kazeburo hatenablog

SRE / 運用系小姑 / Goを書くPerl Monger

Starlet の次期バージョンは少し速くなる

3/8に開発バージョンの0.17_1が出ましたが、このバージョンはひとつ前の0.16に比べて少し高速になっています。

local $SIG{...} = sub {}

が使われていた部分を最適化してリクエストの前後でsystem callを減らしました。straceでみると

before
23:02:27.213488 accept(4, {sa_family=AF_INET, sin_port=htons(32851), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
23:02:28.500636 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff0140fd80) = -1 EINVAL (Invalid argument)
23:02:28.500710 lseek(5, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek)
23:02:28.500785 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff0140fd80) = -1 EINVAL (Invalid argument)
23:02:28.500859 lseek(5, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek)
23:02:28.500917 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
23:02:28.501047 fcntl(5, F_GETFL)       = 0x2 (flags O_RDWR)
23:02:28.501125 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
23:02:28.501196 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
23:02:28.501312 getpeername(5, {sa_family=AF_INET, sin_port=htons(32851), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
23:02:28.501479 rt_sigprocmask(SIG_BLOCK, [TERM], [], 8) = 0
23:02:28.501568 rt_sigaction(SIGTERM, {0x47e5b0, [], SA_RESTORER, 0x7f41b61f6ba0}, {SIG_DFL, [], SA_RESTORER, 0x7f41b61f6ba0}, 8) = 0
23:02:28.501663 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
23:02:28.501770 read(5, "GET / HTTP/1.1\r\nUser-Agent: curl/7.19.7 (x86_64-pc-linux-gnu) libcurl/7.19.7 OpenSSL/0.9.8k zlib/1.2.3.3 libidn/1.15\r\nHost: 127."..., 131072) = 155
23:02:28.501942 gettimeofday({1362837748, 501975}, NULL) = 0
23:02:28.502080 write(5, "HTTP/1.0 200 OK\r\nDate: Sat, 09 Mar 2013 14:02:28 GMT\r\nServer: Plack::Handler::Starlet\r\n\r\nOK", 91) = 91
23:02:28.502174 rt_sigprocmask(SIG_BLOCK, [TERM], [], 8) = 0
23:02:28.502254 rt_sigaction(SIGTERM, {SIG_DFL, [], SA_RESTORER, 0x7f41b61f6ba0}, {0x47e5b0, [], SA_RESTORER, 0x7f41b61f6ba0}, 8) = 0
23:02:28.502348 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
23:02:28.502438 close(5)                = 0
23:02:28.502542 rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
23:02:28.502598 rt_sigaction(SIGPIPE, {SIG_DFL, [], SA_RESTORER, 0x7f41b61f6ba0}, {SIG_IGN, [], SA_RESTORER, 0x7f41b61f6ba0}, 8) = 0
23:02:28.502672 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
23:02:28.502757 rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
23:02:28.502834 rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER, 0x7f41b61f6ba0}, {SIG_DFL, [], SA_RESTORER, 0x7f41b61f6ba0}, 8) = 0
23:02:28.502894 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
23:02:28.503058 accept(4
after
23:03:34.097181 accept(4, {sa_family=AF_INET, sin_port=htons(34512), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
23:03:36.122974 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff2d13b630) = -1 EINVAL (Invalid argument)
23:03:36.123104 lseek(5, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek)
23:03:36.123188 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff2d13b630) = -1 EINVAL (Invalid argument)
23:03:36.123276 lseek(5, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek)
23:03:36.123341 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
23:03:36.123490 fcntl(5, F_GETFL)       = 0x2 (flags O_RDWR)
23:03:36.123562 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
23:03:36.123650 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
23:03:36.123763 getpeername(5, {sa_family=AF_INET, sin_port=htons(34512), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
23:03:36.123951 read(5, "GET / HTTP/1.1\r\nUser-Agent: curl/7.19.7 (x86_64-pc-linux-gnu) libcurl/7.19.7 OpenSSL/0.9.8k zlib/1.2.3.3 libidn/1.15\r\nHost: 127."..., 131072) = 155
23:03:36.124123 gettimeofday({1362837816, 124153}, NULL) = 0
23:03:36.124255 write(5, "HTTP/1.0 200 OK\r\nDate: Sat, 09 Mar 2013 14:03:36 GMT\r\nServer: Plack::Handler::Starlet\r\n\r\nOK", 91) = 91
23:03:36.124595 close(5)                = 0
23:03:36.125413 accept(4

rt_sig* 系のsystem callがなくなりました

ベンチマーク

実際のアプリケーションの参考にはなりませんが、次のようにplackupでサーバを起動してabによるテストを行いました

plackup -E production -s Starlet -p 5321 --max-workers 2  \
             --max-reqs-per-child 100000 -e 'sub{[200,[],["OK"]]}'

abコマンド

ab -c 1 -n 100000  http://127.0.0.1:5321/

結果

Starlet 0.16
Concurrency Level:      1
Time taken for tests:   41.003 seconds
Complete requests:      100000
Failed requests:        0
Write errors:           0
Total transferred:      9100000 bytes
HTML transferred:       200000 bytes
Requests per second:    2438.87 [#/sec] (mean)
Time per request:       0.410 [ms] (mean)
Time per request:       0.410 [ms] (mean, across all concurrent requests)
Transfer rate:          216.74 [Kbytes/sec] received
Starlet 0.17_1
Concurrency Level:      1
Time taken for tests:   37.932 seconds
Complete requests:      100000
Failed requests:        0
Write errors:           0
Total transferred:      9100000 bytes
HTML transferred:       200000 bytes
Requests per second:    2636.31 [#/sec] (mean)
Time per request:       0.379 [ms] (mean)
Time per request:       0.379 [ms] (mean, across all concurrent requests)
Transfer rate:          234.28 [Kbytes/sec] received

time per requestが20〜30μsぐらい短くなって、全体のrpsが1割ぐらい増えたので、このベンチマークでは効果ありそうです。ぜひお試しくださいませ

ベンチマーク環境はさくらのVPS VCPU 2個