Nginx stops sending file after ~1.5mb ?

[Igor Sysoev]

On Tue, Jan 20, 2009 at 11:45:13AM +0200, Yo'av Moshe wrote:

> Sorry, but it is still the same... server is now running the modified nginx,
> but this file still can't be fetched:
> http://www.noal.org.il/static/temp/barvazi2.pdf .
> I just can't think what the problem might be.
> 
> If it helps, my VPS is running CentOS 5.2 with kernel 2.6.18.
> 
> Any more tests I can run?

The patch tries to sendfile() until EAGAIN, even it already said
that it sent smaller chunk than it was requested.

Could you create a new strace and grep single pid to ensure that
nginx calls sendfile() until EAGAIN ?

If the patch does not help, I suspect a bug in kernel/VPS/etc, as kernel
does not return event via epoll_wait().

> Thanks again.
> Yo'av.
> 
> 
> 2009/1/20 Igor Sysoev <is at rambler-co.ru>
> 
> > On Tue, Jan 20, 2009 at 02:59:34AM +0200, Yo'av Moshe wrote:
> >
> > > Thanks.
> > > I'm not an strace guru but I don't think it shows anything unusual...
> > >
> > > http://paste-it.net/public/mffe731/
> > >
> > > You can see download starts right at the beginning, and at 02:25:25 you
> > can
> > > see the last sendfile64 event. After that, no data was sent and I
> > couldn't
> > > find anything related to that in this strace log.
> > >
> > > The only thing this strace log is telling me is that nginx knows that
> > there
> > > is still more data to send, since it recognized the right size of the
> > file
> > > in the beginning (line 13: sendfile64(22, 23, [0], *1950230)*), and it
> > knows
> > > it has more to send by the last sendfile event (line 1173: sendfile64(22,
> > > 23, [1618265], *331965*)).
> > >
> > > What stops the sending?
> >
> > Looking at these lines:
> >
> > 2140  02:25:24 epoll_wait(11,  <unfinished ...>
> > 2140  02:25:24 <... epoll_wait resumed> {{EPOLLOUT, {u32=140043201,
> > u64=13817743186826159041}}}, 512, 22224) = 1
> > 2140  02:25:24 gettimeofday({1232411124, 913871}, NULL) = 0
> > 2140  02:25:24 sendfile64(22, 23, [1559225], 391005) = 28800
> >
> > 2140  02:25:24 epoll_wait(11, {{EPOLLOUT, {u32=140043201,
> > u64=13817743186826159041}}}, 512, 22077) = 1
> > 2140  02:25:25 gettimeofday({1232411125, 66164}, NULL) = 0
> > 2140  02:25:25 sendfile64(22, 23, [1588025], 362205) = 30240
> >
> > 2140  02:25:25 epoll_wait(11, {{EPOLLOUT, {u32=140043201,
> > u64=13817743186826159041}}}, 512, 21924) = 1
> > 2140  02:25:25 gettimeofday({1232411125, 211986}, NULL) = 0
> > 2140  02:25:25 sendfile64(22, 23, [1618265], 331965) = 28800
> >
> > I see that client socket (22) is associated with u64=13817743186826159041
> > in epoll. Also I see that the socket was added and modified in epoll
> > in the start of the transfer:
> >
> > 2140  02:25:12 epoll_ctl(11, EPOLL_CTL_ADD, 22, {EPOLLIN|EPOLLET,
> > {u32=140043201
> > , u64=579069412499841985}}) = 0
> >
> > 2140  02:25:12 epoll_ctl(11, EPOLL_CTL_MOD, 22, {EPOLLIN|EPOLLOUT|EPOLLET,
> > {u32=140043201, u64=13817743186826159041}}) = 0
> >
> > However, I do not see socket deletion from epoll or closing.
> > I see only that after 02:25:25 epoll_wait(), i.e. kernel, never
> > returned any events about 22 socket.
> >
> > You may try the attached patch.
> >
> >
> > --
> > Igor Sysoev
> > http://sysoev.ru/en/
> >
> 
> 
> 
> -- 
> Yo'av Moshe

-- 
Igor Sysoev
http://sysoev.ru/en/