To add to the confusion on the buffers used by squid:
I have observed something that looks similar to this issue:squid is writing to the network with 4k buffers, even if it has got everything in its local buffers, so it could do a write of the whole buffer...
Here an example that delivers: 17961 body-bytes to the peer from the filled buffers:
1288787592.475200 epoll_ctl(6, EPOLL_CTL_ADD, 58, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=58, u64=18133351923770}}) = 0
1288787592.475324 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475358 gettimeofday({1288787592, 475366}, NULL) = 0
1288787592.475387 write(58, "HTTP/1.0 200 OK\r\nContent-Type: text/html;charset=UTF-8\r\nCache-Control: no-cache\r\nContent-Length: 17961\r\nDate: Wed, 03 Nov 2010 12:33:11 GMT\r\nVary: User-Agent,Accept-Encoding\r\nPragma: no-cache\r\nConnection: keep-alive\r\n\r\n<?xml version=\"1.0\" "..., 4222) = 4222
1288787592.475537 gettimeofday({1288787592, 475546}, NULL) = 0
1288787592.475584 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475615 gettimeofday({1288787592, 475624}, NULL) = 0
1288787592.475645 write(58, "/center></d"..., 4096) = 4096
1288787592.475784 gettimeofday({1288787592, 475794}, NULL) = 0
1288787592.475828 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475858 gettimeofday({1288787592, 475867}, NULL) = 0
1288787592.475887 write(58, "ody><tr><td"..., 4096) = 4096
1288787592.476044 gettimeofday({1288787592, 476069}, NULL) = 0
1288787592.476098 epoll_ctl(6, EPOLL_CTL_DEL, 72, {0, {u32=72, u64=20385083017920584}}) = 0
1288787592.476140 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.476585 gettimeofday({1288787592, 476594}, NULL) = 0
1288787592.476615 write(58, "refront?"..., 4096) = 4096
1288787592.476758 gettimeofday({1288787592, 476767}, NULL) = 0
So you see that there is no IO what so ever that comes from ICAP or the backend system.
What is also surprising is that communication with ICAP is reading at 65536 bytes....
In Summary:
* read from Network (proxying call - FD=48) 4094 bytes
* write to ICAP (FD=72) writes header and body separately (no upper limit found - I assume limit is 65535 bytes - as below)
* reads from ICAP (FD=72) with buffer of 65535
* writes to network (final response - FD=58) first 4222 bytes (header and body together) and then subsequently 4096 bytes (for the body).
The question is: why so many different buffer sizes are used for the different use-cases.
Also: why does squid write only 4096 bytes at a time to the network, when it could write everything in one go to the OS (non-blocking)?
Martin
P.s: here the full strace of the relevant portions of Proxied request, communication with ICAP and delivery of the bytes...
1288787592.454856 epoll_wait(6, {{EPOLLIN, {u32=48, u64=20666222987182128}}}, 32768, 10) = 1
1288787592.454959 gettimeofday({1288787592, 454968}, NULL) = 0
1288787592.454989 read(48, "HTTP/1.1 200 OK\r\nServer: Apache-Coyote/1.1\r\nSet-Cookie: msisdnfilter=NTI4OTk", 4094) = 1460
1288787592.455103 gettimeofday({1288787592, 455111}, NULL) = 0
1288787592.455169 epoll_wait(6, {{EPOLLIN, {u32=48, u64=20666222987182128}}}, 32768, 10) = 1
1288787592.455432 gettimeofday({1288787592, 455441}, NULL) = 0
1288787592.455463 epoll_ctl(6, EPOLL_CTL_DEL, 48, {0, {u32=48, u64=20666222987182128}}) = 0
1288787592.455492 gettimeofday({1288787592, 455501}, NULL) = 0
1288787592.455531 epoll_ctl(6, EPOLL_CTL_ADD, 48, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=48, u64=17583596109872}}) = 0
1288787592.455568 epoll_wait(6, {{EPOLLIN, {u32=48, u64=17583596109872}}}, 32768, 10) = 1
1288787592.455659 gettimeofday({1288787592, 455668}, NULL) = 0
1288787592.455689 read(48, "rk/login_icon_5800.gif"..., 4094) = 4094
1288787592.455837 gettimeofday({1288787592, 455846}, NULL) = 0
1288787592.455878 epoll_wait(6, {{EPOLLIN, {u32=48, u64=17583596109872}}}, 32768, 10) = 1
1288787592.455909 gettimeofday({1288787592, 455917}, NULL) = 0
1288787592.455938 read(48, "=\"0\"><tbody><tr><td>"..., 4094) = 4094
1288787592.456083 gettimeofday({1288787592, 456092}, NULL) = 0
1288787592.456119 epoll_ctl(6, EPOLL_CTL_DEL, 72, {0, {u32=72, u64=20385083017920584}}) = 0
1288787592.456158 epoll_wait(6, {{EPOLLIN, {u32=48, u64=17583596109872}}}, 32768, 10) = 1
1288787592.456188 gettimeofday({1288787592, 456196}, NULL) = 0
1288787592.456217 read(48, "LO \302\241B\303\201JA "..., 4094) = 3733
1288787592.456359 gettimeofday({1288787592, 456367}, NULL) = 0
1288787592.456390 epoll_ctl(6, EPOLL_CTL_ADD, 72, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=72, u64=281470681743432}}) = 0
1288787592.456510 epoll_ctl(6, EPOLL_CTL_MOD, 72, {EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=72, u64=7829725380680}}) = 0
1288787592.456555 epoll_wait(6, {{EPOLLOUT, {u32=72, u64=7829725380680}}}, 32768, 10) = 1
1288787592.456585 gettimeofday({1288787592, 456594}, NULL) = 0
1288787592.456629 write(72, "RESPMOD icap://127.0.0.1:1344/respmod ICAP/1.0\r\nHost: 127.0.0.1:1344\r\nDate: ", 1823) = 1823
1288787592.456894 gettimeofday({1288787592, 456903}, NULL) = 0
1288787592.456934 epoll_wait(6, {{EPOLLOUT, {u32=72, u64=7829725380680}}}, 32768, 10) = 1
1288787592.456963 gettimeofday({1288787592, 456972}, NULL) = 0
1288787592.456992 write(72, "100\r\n<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<!DOCTYPE html\n PUBLIC \"-/", 268) = 268
1288787592.457141 gettimeofday({1288787592, 457150}, NULL) = 0
1288787592.457176 epoll_wait(6, {{EPOLLIN|EPOLLOUT, {u32=72, u64=7829725380680}}}, 32768, 10) = 1
1288787592.457205 gettimeofday({1288787592, 457213}, NULL) = 0
1288787592.457234 read(72, "ICAP/1.0 100 Continue after ICAP Preview\r\nDate: Wed, 03 Nov 2010 12:33:12 GMT\", 65535) = 157
1288787592.457278 epoll_ctl(6, EPOLL_CTL_MOD, 72, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=72, u64=21330448269443144}}) = 0
1288787592.457308 gettimeofday({1288787592, 457316}, NULL) = 0
1288787592.457360 epoll_ctl(6, EPOLL_CTL_MOD, 72, {EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=72, u64=54674933678152}}) = 0
1288787592.457396 epoll_wait(6, {{EPOLLOUT, {u32=72, u64=54674933678152}}}, 32768, 10) = 1
1288787592.457425 gettimeofday({1288787592, 457433}, NULL) = 0
1288787592.457453 write(72, "31ad\r\n/css\" href=\".."..., 12730) = 12730
1288787592.466330 gettimeofday({1288787592, 466365}, NULL) = 0
1288787592.466471 epoll_wait(6, {{EPOLLIN|EPOLLOUT, {u32=72, u64=54674933678152}}}, 32768, 10) = 1
1288787592.466561 gettimeofday({1288787592, 466581}, NULL) = 0
1288787592.466561 gettimeofday({1288787592, 466581}, NULL) = 0
1288787592.466637 read(72, "ICAP/1.0 200 OK\r\nDate: Wed, 03 Nov 2010 12:33:12 GMT\r\nConnection: keep-alive"..., 65535) = 17034
1288787592.466838 epoll_ctl(6, EPOLL_CTL_MOD, 72, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=72, u64=21330448269443144}}) = 0
1288787592.466946 gettimeofday({1288787592, 466966}, NULL) = 0
1288787592.467122 epoll_wait(6, {{EPOLLIN, {u32=72, u64=21330448269443144}}}, 32768, 10) = 1
1288787592.467199 gettimeofday({1288787592, 467218}, NULL) = 0
1288787592.467272 read(72, "px\" alt=\"\" src=\"http: ", 65535) = 1584
1288787592.467442 gettimeofday({1288787592, 467462}, NULL) = 0
1288787592.467550 epoll_wait(6, {{EPOLLIN, {u32=15, u64=810040968148418575}}}, 32768, 10) = 1
1288787592.473758 gettimeofday({1288787592, 473792}, NULL) = 0
1288787592.474709 epoll_ctl(6, EPOLL_CTL_ADD, 141, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=141, u64=17587891077261}}) = 0
1288787592.474843 gettimeofday({1288787592, 474852}, NULL) = 0
1288787592.474949 epoll_wait(6, {{EPOLLIN, {u32=141, u64=17587891077261}}}, 32768, 10) = 1
1288787592.474982 gettimeofday({1288787592, 474991}, NULL) = 0
1288787592.475074 gettimeofday({1288787592, 475083}, NULL) = 0
1288787592.475200 epoll_ctl(6, EPOLL_CTL_ADD, 58, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=58, u64=18133351923770}}) = 0
1288787592.475324 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475358 gettimeofday({1288787592, 475366}, NULL) = 0
1288787592.475387 write(58, "HTTP/1.0 200 OK\r\nContent-Type: text/html;charset=UTF-8\r\nCache-Control: no-ca"..., 4222) = 4222
1288787592.475537 gettimeofday({1288787592, 475546}, NULL) = 0
1288787592.475584 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475615 gettimeofday({1288787592, 475624}, NULL) = 0
1288787592.475645 write(58, "/center></div><table cellspacing= "..., 4096) = 4096
1288787592.475784 gettimeofday({1288787592, 475794}, NULL) = 0
1288787592.475828 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.475858 gettimeofday({1288787592, 475867}, NULL) = 0
1288787592.475887 write(58, "ody><tr><td><div class=\"Label\"> \"..., 4096) = 4096
1288787592.476044 gettimeofday({1288787592, 476069}, NULL) = 0
1288787592.476098 epoll_ctl(6, EPOLL_CTL_DEL, 72, {0, {u32=72, u64=20385083017920584}}) = 0
1288787592.476140 epoll_wait(6, {{EPOLLOUT, {u32=58, u64=18133351923770}}}, 32768, 10) = 1
1288787592.476585 gettimeofday({1288787592, 476594}, NULL) = 0
1288787592.476615 write(58, "refront?item=1997025&BK=index "..., 4096) = 4096
1288787592.476758 gettimeofday({1288787592, 476767}, NULL) = 0
> -----Original Message-----
> From: Amos Jeffries [mailto:squid3@xxxxxxxxxxxxx]
> Sent: Dienstag, 02. November 2010 02:15
> To: squid-users@xxxxxxxxxxxxxxx
> Subject: Re: Squid network read()'s only 2k long?
>
> On Mon, 1 Nov 2010 23:20:52 +0000, Declan White <declanw@xxxxxxxxxxxx>
> wrote:
> > On Mon, Nov 01, 2010 at 10:55:12PM +0000, Declan White wrote:
> >> On Mon, Nov 01, 2010 at 09:36:53PM +0000, Amos Jeffries wrote:
> >> > On Mon, 1 Nov 2010 15:00:21 +0000, declanw@xxxxxxxxxxxx wrote:
> >> > > I went for a rummage in the code for the buffer size decisions, but
> >> > > got
> >> > > very very lost in the OO abstractions very quickly. Can anyone
> point
> >> > > me at
> >> > > anything I can tweak to fix this?
> >> >
> >> > It's a global macro defined by auto-probing your operating systems
> TCP
> >> > receiving buffer when building. Default is 16KB and max is 64KB.
> There
> >> > may
> >> > also be auto-probing done at run time.
> >> >
> >> > It is tunable at run-time with
> >> > http://www.squid-cache.org/Doc/config/tcp_recv_bufsize/
> >>
> >> Oh thank God! Thanks :) (and annoyed with myself that I missed that)
> >
> > Nuts.. actually, that didn't do anything :(
> >
> > 17314: write(16, " G E T / c f g m a n .".., 639) = 639
> > 17314: ioctl(6, DP_POLL, 0x100459B90) = 1
> > 17314: write(6, "\0\0\010\b\0\0\0\0\0\010".., 16) = 16
> > 17314: ioctl(6, DP_POLL, 0x100459B90) = 1
> > 17314: read(11, " H T T P / 1 . 1 2 0 0".., 2046) = 2046
> > 17314: write(6, "\0\0\0\n\004\0\0", 8) = 8
> > 17314: ioctl(6, DP_POLL, 0x100459B90) = 2
> > 17314: write(10, " H T T P / 1 . 0 2 0 0".., 2180) = 2180
> > 17314: read(11, " f o n t - s i z e : 3".., 2046) = 834
> > 17314: ioctl(6, DP_POLL, 0x100459B90) = 2
> > 17314: write(10, " f o n t - s i z e : 3".., 834) = 834
> > 17314: read(11, " n o n e ;\n }\n\n # m".., 2046) = 1066
> > 17314: ioctl(6, DP_POLL, 0x100459B90) = 1
> > 17314: write(10, " n o n e ;\n }\n\n # m".., 1066) = 1066
> > 17314: write(8, " [ 0 1 / N o v / 2 0 1 0".., 403) = 403
> >
> > It's still reading from the remote server in 2046 byte lumps, which
> meant
> > three trips round the event loop where it might only have needed one.
> >
> > I'm guessing that setting is for the kernel level TCP receive buffer,
> and
> > not the application read-from-that-buffer size.
> >
> > I even doubled HTTP_REQBUF_SZ in defines.h for fun, and that did nothing
> > either. I can't find where the read() size might be decided in the code.
>
> Hmm. I think I've tracked this down. It appears to be MemBuf::init()
> defaulting to 2KB of buffer. The default is defined in src/Membuf.cc.
> Though I'm unsure why an exponential grow() is not triggered to make that
> third read 4K.
>
> If you can confirm that I'll work on making that config setting affect the
> buffer initial values for the future.
>
> Amos
This message and the information contained herein is proprietary and confidential and subject to the Amdocs policy statement,
you may review at http://www.amdocs.com/email_disclaimer.asp
