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