[squid-users] Squid: Small packets and low performance between squid and icap

Thu Nov 5 02:43:10 UTC 2015

Hi folks,

I have a setup with ICAP running a custom server alongside Squid.
While testing file upload scenarios, I ran into a slow upload issue
and have narrowed it down to slowness between squid and icap,
especially in the request handling path.

The slowness is down to extremely small packets sent by squid towards
the ICAP server. These packets are a few 10s of bytes in size. This
despite receiving large-sized packets from the client over the HTTPS
connection. The ICAP server responds with the ACK quickly enough, so
this isn't a case of small packets being generated because the server
isn't quick enough to read.

The debugs haven't shown any hints. It appears that there are times
when Squid allocates only small buffers to read from the HTTPS
connection. I see buffers of even a single byte being allocated during
message processing. I am new to the Squid code, so I might be reading
it all wrong.

I have pasted below a sample TCP dump (incomplete) showing the
behavior, resulting from a curl request. The request was generated on
the same node where squid and ICAP are resident.

Any hints/tips on what may be going wrong here? Appreciate any help in
this matter. Thank you.

Regards.
Prashanth

TCP dump:
Note that on my setup, squid is running on port 443.
Note also that the packets to-from both ports 443 and 1344 are
available in this sequence.

20:53:31.479166 IP localhost.56475 > localhost.https: Flags [S], seq
2166915705, win 32792, options [mss 16396,sackOK,TS val 3300947254 ecr
0,nop,wscale 12], length 0
20:53:31.479178 IP localhost.https > localhost.56475: Flags [S.], seq
728006122, ack 2166915706, win 32768, options [mss 16396,sackOK,TS val
3300947254 ecr 3300947254,nop,wscale 12], length 0
20:53:31.479186 IP localhost.56475 > localhost.https: Flags [.], ack
1, win 9, options [nop,nop,TS val 3300947254 ecr 3300947254], length 0
20:53:31.479308 IP localhost.56475 > localhost.https: Flags [P.], seq
1:221, ack 1, win 9, options [nop,nop,TS val 3300947254 ecr
3300947254], length 220
20:53:31.479317 IP localhost.https > localhost.56475: Flags [.], ack
221, win 9, options [nop,nop,TS val 3300947254 ecr 3300947254], length
0
20:53:31.483620 IP localhost.https > localhost.56475: Flags [P.], seq
1:40, ack 221, win 9, options [nop,nop,TS val 3300947255 ecr
3300947254], length 39
20:53:31.483636 IP localhost.56475 > localhost.https: Flags [.], ack
40, win 9, options [nop,nop,TS val 3300947255 ecr 3300947255], length
0
20:53:31.497413 IP localhost.56475 > localhost.https: Flags [P.], seq
221:534, ack 40, win 9, options [nop,nop,TS val 3300947259 ecr
3300947255], length 313
20:53:31.530394 IP localhost.https > localhost.56475: Flags [P.], seq
40:3153, ack 534, win 9, options [nop,nop,TS val 3300947267 ecr
3300947259], length 3113
20:53:31.531331 IP localhost.56475 > localhost.https: Flags [P.], seq
534:1108, ack 3153, win 10, options [nop,nop,TS val 3300947267 ecr
3300947267], length 574
20:53:31.549229 IP localhost.https > localhost.56475: Flags [P.], seq
3153:3204, ack 1108, win 9, options [nop,nop,TS val 3300947272 ecr
3300947267], length 51
20:53:31.549589 IP localhost.56475 > localhost.https: Flags [P.], seq
1108:1453, ack 3204, win 10, options [nop,nop,TS val 3300947272 ecr
3300947272], length 345

20:53:31.556517 IP localhost.46489 > localhost.1344: Flags [S], seq
2773005283, win 32792, options [mss 16396,sackOK,TS val 3300947274 ecr
0,nop,wscale 12], length 0
20:53:31.556527 IP localhost.1344 > localhost.46489: Flags [S.], seq
2778855454, ack 2773005284, win 32768, options [mss 16396,sackOK,TS
val 3300947274 ecr 3300947274,nop,wscale 12], length 0
20:53:31.556534 IP localhost.46489 > localhost.1344: Flags [.], ack 1,
win 9, options [nop,nop,TS val 3300947274 ecr 3300947274], length 0
20:53:31.559075 IP localhost.46489 > localhost.1344: Flags [P.], seq
1:602, ack 1, win 9, options [nop,nop,TS val 3300947274 ecr
3300947274], length 601
20:53:31.559092 IP localhost.1344 > localhost.46489: Flags [.], ack
602, win 9, options [nop,nop,TS val 3300947274 ecr 3300947274], length
0

20:53:31.588467 IP localhost.https > localhost.56475: Flags [.], ack
1453, win 10, options [nop,nop,TS val 3300947282 ecr 3300947272],
length 0
20:53:32.550821 IP localhost.56475 > localhost.https: Flags [.], seq
1453:17837, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947282], length 16384
20:53:32.550849 IP localhost.https > localhost.56475: Flags [.], ack
17837, win 12, options [nop,nop,TS val 3300947522 ecr 3300947522],
length 0
20:53:32.550856 IP localhost.56475 > localhost.https: Flags [P.], seq
17837:17866, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947282], length 29
20:53:32.550859 IP localhost.https > localhost.56475: Flags [.], ack
17866, win 12, options [nop,nop,TS val 3300947522 ecr 3300947522],
length 0
20:53:32.550916 IP localhost.56475 > localhost.https: Flags [.], seq
17866:34250, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947522], length 16384
20:53:32.550938 IP localhost.https > localhost.56475: Flags [.], ack
34250, win 10, options [nop,nop,TS val 3300947522 ecr 3300947522],
length 0
20:53:32.550942 IP localhost.56475 > localhost.https: Flags [P.], seq
34250:34279, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947522], length 29
20:53:32.550946 IP localhost.https > localhost.56475: Flags [.], ack
34279, win 10, options [nop,nop,TS val 3300947522 ecr 3300947522],
length 0
20:53:32.550993 IP localhost.56475 > localhost.https: Flags [.], seq
34279:50663, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947522], length 16384
20:53:32.551009 IP localhost.https > localhost.56475: Flags [.], ack
50663, win 6, options [nop,nop,TS val 3300947522 ecr 3300947522],
length 0
20:53:32.551014 IP localhost.56475 > localhost.https: Flags [P.], seq
50663:50692, ack 3204, win 10, options [nop,nop,TS val 3300947522 ecr
3300947522], length 29

20:53:32.552297 IP localhost.46489 > localhost.1344: Flags [P.], seq
602:647, ack 1, win 9, options [nop,nop,TS val 3300947522 ecr
3300947274], length 45
20:53:32.552303 IP localhost.1344 > localhost.46489: Flags [.], ack
647, win 9, options [nop,nop,TS val 3300947522 ecr 3300947522], length
0
20:53:32.553609 IP localhost.46489 > localhost.1344: Flags [P.], seq
647:1644, ack 1, win 9, options [nop,nop,TS val 3300947523 ecr
3300947522], length 997
20:53:32.553615 IP localhost.1344 > localhost.46489: Flags [.], ack
1644, win 9, options [nop,nop,TS val 3300947523 ecr 3300947523],
length 0
20:53:32.553983 IP localhost.1344 > localhost.46489: Flags [P.], seq
1:26, ack 1644, win 9, options [nop,nop,TS val 3300947523 ecr
3300947523], length 25
20:53:32.553988 IP localhost.46489 > localhost.1344: Flags [.], ack
26, win 9, options [nop,nop,TS val 3300947523 ecr 3300947523], length
0

20:53:32.554939 IP localhost.https > localhost.56475: Flags [.], ack
50692, win 12, options [nop,nop,TS val 3300947523 ecr 3300947522],
length 0
20:53:32.554951 IP localhost.56475 > localhost.https: Flags [P.], seq
50692:62824, ack 3204, win 10, options [nop,nop,TS val 3300947523 ecr
3300947523], length 12132

20:53:32.556392 IP localhost.46489 > localhost.1344: Flags [.], seq
1644:18028, ack 26, win 9, options [nop,nop,TS val 3300947523 ecr
3300947523], length 16384
20:53:32.556415 IP localhost.46489 > localhost.1344: Flags [P.], seq
18028:21146, ack 26, win 9, options [nop,nop,TS val 3300947524 ecr
3300947523], length 3118
20:53:32.556422 IP localhost.1344 > localhost.46489: Flags [.], ack
21146, win 12, options [nop,nop,TS val 3300947524 ecr 3300947523],
length 0
20:53:32.557860 IP localhost.46489 > localhost.1344: Flags [P.], seq
21146:33403, ack 26, win 9, options [nop,nop,TS val 3300947524 ecr
3300947524], length 12257
20:53:32.559221 IP localhost.46489 > localhost.1344: Flags [P.], seq
33403:33409, ack 26, win 9, options [nop,nop,TS val 3300947524 ecr
3300947524], length 6
20:53:32.559243 IP localhost.1344 > localhost.46489: Flags [.], ack
33409, win 12, options [nop,nop,TS val 3300947524 ecr 3300947524],
length 0
20:53:32.560692 IP localhost.46489 > localhost.1344: Flags [.], seq
33409:49793, ack 26, win 9, options [nop,nop,TS val 3300947525 ecr
3300947524], length 16384
20:53:32.560713 IP localhost.46489 > localhost.1344: Flags [P.], seq
49793:49799, ack 26, win 9, options [nop,nop,TS val 3300947525 ecr
3300947524], length 6
20:53:32.560717 IP localhost.1344 > localhost.46489: Flags [.], ack
49799, win 12, options [nop,nop,TS val 3300947525 ecr 3300947525],
length 0
20:53:32.562076 IP localhost.46489 > localhost.1344: Flags [P.], seq
49799:49806, ack 26, win 9, options [nop,nop,TS val 3300947525 ecr
3300947525], length 7
20:53:32.562333 IP localhost.https > localhost.56475: Flags [.], ack
62824, win 12, options [nop,nop,TS val 3300947525 ecr 3300947523],
length 0
20:53:32.563442 IP localhost.46489 > localhost.1344: Flags [P.], seq
49806:49849, ack 26, win 9, options [nop,nop,TS val 3300947525 ecr
3300947525], length 43
20:53:32.563463 IP localhost.1344 > localhost.46489: Flags [.], ack
49849, win 12, options [nop,nop,TS val 3300947525 ecr 3300947525],
length 0
20:53:32.564775 IP localhost.46489 > localhost.1344: Flags [P.], seq
49849:49856, ack 26, win 9, options [nop,nop,TS val 3300947526 ecr
3300947525], length 7
20:53:32.566070 IP localhost.46489 > localhost.1344: Flags [P.], seq
49856:49899, ack 26, win 9, options [nop,nop,TS val 3300947526 ecr
3300947525], length 43
20:53:32.566091 IP localhost.1344 > localhost.46489: Flags [.], ack
49899, win 12, options [nop,nop,TS val 3300947526 ecr 3300947526],
length 0
20:53:32.567372 IP localhost.46489 > localhost.1344: Flags [P.], seq
49899:49906, ack 26, win 9, options [nop,nop,TS val 3300947526 ecr
3300947526], length 7
20:53:32.568686 IP localhost.46489 > localhost.1344: Flags [P.], seq
49906:49949, ack 26, win 9, options [nop,nop,TS val 3300947527 ecr
3300947526], length 43
20:53:32.568707 IP localhost.1344 > localhost.46489: Flags [.], ack
49949, win 12, options [nop,nop,TS val 3300947527 ecr 3300947526],
length 0
20:53:32.569992 IP localhost.46489 > localhost.1344: Flags [P.], seq
49949:49956, ack 26, win 9, options [nop,nop,TS val 3300947527 ecr
3300947527], length 7
20:53:32.571285 IP localhost.46489 > localhost.1344: Flags [P.], seq
49956:49999, ack 26, win 9, options [nop,nop,TS val 3300947527 ecr
3300947527], length 43
20:53:32.571305 IP localhost.1344 > localhost.46489: Flags [.], ack
49999, win 12, options [nop,nop,TS val 3300947527 ecr 3300947527],
length 0