<div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Jan 11, 2017 at 6:44 PM, Maxim Dounin <span dir="ltr"><<a href="mailto:mdounin@mdounin.ru" target="_blank">mdounin@mdounin.ru</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hello!<br>
<div><div class="gmail-h5"><br>
On Wed, Jan 11, 2017 at 06:07:01PM +0300, Руслан Закиров wrote:<br>
<br>
> On Mon, Jan 9, 2017 at 10:59 PM, Maxim Dounin <<a href="mailto:mdounin@mdounin.ru">mdounin@mdounin.ru</a>> wrote:<br>
><br>
> > Typical kern.sched.quantum is about 100ms, so several<br>
> > CPU-intensive tasks can delay processing of the events enough to<br>
> > trigger a timeout if a context switch happens at a bad time.<br>
> ><br>
><br>
> Here what I see in truss' output:<br>
><br>
> 38.820523207 0.000006568 kevent(28,{ },0,{<br>
> 198,EVFILT_WRITE,EV_CLEAR,0x0,<wbr>0x8218,0x821405071 },512,{ 6.215000000 }) = 1<br>
> (0x1)<br>
> 39.783094188 0.000022875 kevent(28,{ },0,{<br>
> 52,EVFILT_READ,0x0,0x0,0x30b,<wbr>0x81f800068<br>
> 204,EVFILT_WRITE,EV_CLEAR,0x0,<wbr>0x8218,0x821401588<br>
> 51,EVFILT_READ,0x0,0x0,0xec,<wbr>0x81f800000<br>
> 68,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x8bf,0x81f816580<br>
> 7,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x27f,0x81f813869<br>
> 57,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x767,0x81f817bd8<br>
> 203,EVFILT_READ,EV_CLEAR|EV_<wbr>EOF,0x0,0x248,0x81f8030c1<br>
> 181,EVFILT_READ,EV_CLEAR|EV_<wbr>EOF,0x0,0x9b77,0x81f80ea68<br>
> 178,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x39d,0x81f8010a9<br>
> 198,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x3d3,0x81f805071<br>
> 204,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x9da,0x81f801588<br>
> 190,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x4ff,0x81f80fc48<br>
> 154,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x88e,0x81f8130b1<br>
> 151,EVFILT_READ,EV_CLEAR|EV_<wbr>EOF,0x0,0xc1db,0x81f814290<br>
> 157,EVFILT_READ,EV_CLEAR|EV_<wbr>EOF,0x0,0xe841,0x81f80c029<br>
> 195,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x952,0x81f8090a1<br>
> 194,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x929,0x81f809ac8<br>
> 201,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x4ef,0x81f80c980<br>
> 174,EVFILT_READ,EV_CLEAR,0x0,<wbr>0x51e,0x81f816518<br>
> 77,EVFILT_READ,EV_CLEAR|EV_<wbr>EOF,0x0,0x1168,0x81f811c61 },512,{ 5.253000000<br>
> }) = 20 (0x14)<br>
><br>
><br>
> 1 second delay between two syscalls. Then nginx goes nuts processing all it<br>
> missed during this second. I can not tell from this output how much time<br>
> was spent in these syscalls. Can anyone?<br>
<br>
</div></div>Using ktrace / kdump might be a better option, it shows both<br>
syscall enter and syscall return with exact timestamps.<br></blockquote><div><br></div><div>Tried. Found at least one issue with sendfile blocking:</div><div><div><br></div><div> 66193 nginx    1484152162.182601 CALL  openat(AT_FDCWD,0x80639aac4,0x4<O_NONBLOCK>,<unused>0)</div><div> 66193 nginx    1484152162.182607 NAMI  ...</div><div> 66193 nginx    1484152162.182643 RET   openat 40/0x28</div><div>... gz lookup and stats ...</div><div> 66193 nginx    1484152162.182683 CALL  setsockopt(0x211,0x6,0x4,0x7fffffffd96c,0x4)<br></div><div> 66193 nginx    1484152162.182687 RET   setsockopt 0</div><div> 66193 nginx    1484152162.182689 CALL  sendfile(0x28,0x211,0,0x806f,0x7fffffffe1d8,0x7fffffffe240,<invalid=0>)</div><div> 66193 nginx    1484152163.541770 RET   sendfile 0</div><div><br></div></div><div>Sendfile blocks for 1.3 seconds. However, it's:</div><div><br></div><div>$ sysctl hw.model hw.machine hw.ncpu</div><div>hw.model: Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz</div><div>hw.machine: amd64</div><div>hw.ncpu: 16</div><div><br></div><div>So sfbufs don't apply here, but documentation doesn't tell what resource applies... or I couldn't find correct doc.</div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><span class="gmail-">
> What I don't like is timeout greater than 5 seconds. Doesn't it mean that<br>
> system is allowed to block for timeout time to collect events?<br>
<br>
</span>Timeout as passed to kevent() is the nearest timer set in nginx.<br>
That is, nginx has nothing to do till the time specified, and<br>
allows kernel to block that long if there are no events.  Kernel<br>
is expected to return events as soon as it has any, or return 0 if<br>
the specified time limit expires.<br></blockquote><div><br></div><div>This I figured from reading nginx source code.</div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div class="gmail-HOEnZb"><div class="gmail-h5">
--<br>
Maxim Dounin<br>
<a href="http://nginx.org/" rel="noreferrer" target="_blank">http://nginx.org/</a><br>
______________________________<wbr>_________________<br>
nginx mailing list<br>
<a href="mailto:nginx@nginx.org">nginx@nginx.org</a><br>
<a href="http://mailman.nginx.org/mailman/listinfo/nginx" rel="noreferrer" target="_blank">http://mailman.nginx.org/<wbr>mailman/listinfo/nginx</a></div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br><div class="gmail_signature"><div dir="ltr"><div>Руслан Закиров</div><div>Руководитель отдела разработки веб-сервисов</div><div><span>+7(916) 597-92-69</span>, <span>ruz @ <a href="http://www.sports.ru/" target="_blank"><img src="http://farm7.static.flickr.com/6235/6210250811_19a888dbba_o.jpg" width="43" height="14" style="vertical-align: bottom; margin-right: 0px;"></a></span></div></div></div>
</div></div>