<div dir="auto"><div><br><div class="gmail_extra"><br><div class="gmail_quote">11 Янв 2017 г. 21:40 пользователь "Maxim Dounin" <<a href="mailto:mdounin@mdounin.ru">mdounin@mdounin.ru</a>> написал:<br type="attribution"><blockquote class="quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hello!<br>
<div class="elided-text"><br>
On Wed, Jan 11, 2017 at 08:54:31PM +0300, Руслан Закиров wrote:<br>
<br>
> On Wed, Jan 11, 2017 at 6:44 PM, Maxim Dounin <<a href="mailto:mdounin@mdounin.ru">mdounin@mdounin.ru</a>> wrote:<br>
><br>
> > Hello!<br>
> ><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>><br>
> > 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 })<br>
> > = 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,{<br>
> > 5.253000000<br>
> > > }) = 20 (0x14)<br>
> > ><br>
> > ><br>
> > > 1 second delay between two syscalls. Then nginx goes nuts processing all<br>
> > 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>
> > Using ktrace / kdump might be a better option, it shows both<br>
> > syscall enter and syscall return with exact timestamps.<br>
> ><br>
><br>
> Tried. Found at least one issue with sendfile blocking:<br>
><br>
> 66193 nginx 1484152162.182601 CALL<br>
> openat(AT_FDCWD,0x80639aac4,<wbr>0x4<O_NONBLOCK>,<unused>0)<br>
> 66193 nginx 1484152162.182607 NAMI ...<br>
> 66193 nginx 1484152162.182643 RET openat 40/0x28<br>
> ... gz lookup and stats ...<br>
> 66193 nginx 1484152162.182683 CALL<br>
> setsockopt(0x211,0x6,0x4,<wbr>0x7fffffffd96c,0x4)<br>
> 66193 nginx 1484152162.182687 RET setsockopt 0<br>
> 66193 nginx 1484152162.182689 CALL<br>
> sendfile(0x28,0x211,0,0x806f,<wbr>0x7fffffffe1d8,0x7fffffffe240,<wbr><invalid=0>)<br>
> 66193 nginx 1484152163.541770 RET sendfile 0<br>
><br>
> Sendfile blocks for 1.3 seconds. However, it's:<br>
><br>
> $ sysctl hw.model hw.machine hw.ncpu<br>
> hw.model: Intel(R) Xeon(R) CPU E5620 @ 2.40GHz<br>
> hw.machine: amd64<br>
> hw.ncpu: 16<br>
><br>
> So sfbufs don't apply here, but documentation doesn't tell what resource<br>
> applies... or I couldn't find correct doc.<br>
<br>
</div>On amd64 sendfile() uses mbufs / mbuf clusters. Try looking into<br>
"vmstat -z" to see if there are enough mbuf clusters in various<br>
zones. Note well tha sendfile() normally blocks on disk, and it<br>
might simply mean that your disk subsystem is (occasionally)<br>
overloaded. Try gstat to see some details.<br></blockquote></div></div></div><div dir="auto"><br></div><div dir="auto"><div class="gmail_extra"><div class="gmail_quote"><blockquote class="quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"></blockquote></div></div></div><div dir="auto">It is goes red periodically and i should look further there.</div><div dir="auto"><br></div><div dir="auto">At this moment i wonder if turning off sendfile will help. Will nginx use aio to serve static files from disk without blocking?</div><div dir="auto"><br></div><div dir="auto">Also, sendfile syscall has two flags on bsd to avoid blocking. Can these be used to avoid blocks?</div><div dir="auto"><div class="gmail_extra"><div class="gmail_quote"><blockquote class="quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
' <br>
Either way, blocking for 1.3s in a syscall perfectly explains why<br>
300ms timeouts are sometimes triggered unexpectedly. If a timer<br>
is set after such a blocking call and just before kevent() (that<br>
is, connection is highly unlikely to be established in before<br>
kevent() returns), on the next event loop iteraction nginx will<br>
think that 1.3+ seconds has passed since the timer was set, and<br>
will trigger a timeout (after processing all the events reported by<br>
kevent()).<br>
<div class="elided-text"><br>
--<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></blockquote></div>' А там </div></div></div>