昨日からmasuidriveさんと調査してた
eventmachineのバグ
ですが、straceで追いかけてみた結果、
以下の部分が原因である事が分かりました。
em.cpp EventMachine_t::_RunEpollOnce() の最後付近
1 timeval tv = {0,0};
2 EmSelect (0, NULL, NULL, NULL, &tv);
3
4 return true;
見るからにWorkaroundっぽいですね。
straceの結果では、正常に実行されてる場合には
ADDからEPOLLINまでのシステムコール呼び出しが以下のような感じなのに対して、
1 write(1, "************** epoll-add: 0.0377"..., 39************** epoll-add: 0.03
2 7784 - 8
3 ) = 39epoll_ctl(6, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=138272384, u64=1323936545317780646
4 4}}) = 0
5 epoll_wait(6, {{EPOLLIN, {u32=138272384, u64=13239365453177806464}}}, 65536, 50)
6 = 1
7 gettimeofday({1230425221, 603705}, NULL) = 0
8 write(1, "************** epoll-read: 0.020"..., 40************** epoll-read: 0.0
9 20716 - 8
異常時には以下のように謎のselectが発生していました。
1 write(1, "************** epoll-add: 0.0295"..., 39************** epoll-add: 0.029586 - 8
2 ) = 39
3 epoll_ctl(6, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=138272384, u64=1323936545317780646
4 4}}) = 0
5 epoll_wait(6, {}, 65536, 50) = 0
6 select(0, NULL, NULL, NULL, {0, 0}) = 0 (Timeout)
7 time(NULL) = 1230425221
8 gettimeofday({1230425221, 787115}, NULL) = 0
9 epoll_wait(6, {}, 65536, 50) = 0
10 select(0, NULL, NULL, NULL, {0, 0}) = 0 (Timeout)time(NULL) = 1230425221
11 gettimeofday({1230425221, 839105}, NULL) = 0
12 epoll_wait(6, {{EPOLLIN, {u32=138272384, u64=13239365453177806464}}}, 65536, 50) = 1
13 gettimeofday({1230425221, 843713}, NULL) = 0
14 write(1, "************** epoll-read: 0.110"..., 40************** epoll-read: 0.1
15 10337 - 8
どうやらこの謎のEmSelect呼び出しはビジーループ対策のために
挿入されているらしいのですが、以下のような形に直すと問題が
発生しなくなるようです。
1
2
3 #ifdef BUILD_FOR_RUBY
4 if (!rb_thread_alone()) {
5 rb_thread_schedule();
6 }
7 #endif
eventmachineのticketにpatchが上がっている
ので、近いうちに修正されるかもしれません。
ということで、ひとまずお疲れさまでしたー>masuidriveさん