Also,
Just killed all connections to squid process. CPU still pegged at 15%
and decreasing
Here is what the process is doing:
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 1
accept(8, 0xFFFFFD7FFFDFFB90, 0xFFFFFD7FFFDFFB7C, SOV_DEFAULT) = 12
getsockname(12, 0xFFFFFD7FFFDFFB80, 0xFFFFFD7FFFDFFB7C, SOV_DEFAULT) = 0
fcntl(12, F_GETFL) = 130
fcntl(12, F_SETFD, 0x00000083) = 0
fcntl(12, F_GETFL) = 130
fcntl(12, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFB90, 0xFFFFFD7FFFDFFB7C, SOV_DEFAULT) Err#11 EAGAIN
write(3, "\f\0\0\0\0\b\0\0\f\0\0\0".., 16) = 16
ioctl(3, DP_POLL, 0x005036B0) = 1
read(12, " G E T / f i l e / 1 1".., 4095) = 51
write(3, "\f\0\0\0\0\b\0\0\f\0\0\0".., 32) = 32
ioctl(3, DP_POLL, 0x005036B0) = 1
write(12, " H T T P / 1 . 0 2 0 0".., 1736) = 1736
close(12) = 0
write(3, "\f\0\0\0\0\b\0\0", 8) = 8
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 0
ioctl(3, DP_POLL, 0x005036B0) = 1
I have 2 squid instances.
Both are taking the same amount of connections, and both are
connecting to the same exact pool of origins via a lb.
2344 root 13G 13G cpu1 0 0 4:03:10 25% squid/1
2096 root 13G 13G sleep 31 0 4:47:22 9.2% squid/1
After about 14 hours of runtime, the instances hit 25% utilization,
and then never seem to restabilize.
This is all I see in my cache.log for the instance that is maxed out:
2007/10/05 10:47:25| clientReadRequest: FD 107 (82.38.189.46:5430)
Invalid Request
2007/10/05 11:05:13| WARNING: unparseable HTTP header field
{Accept-CharsetGET /pict/320155568274_1.jpg HTTP/1.1}
2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
2007/10/05 11:06:55| clientReadRequest: FD 1808 (84.71.71.234:35312)
Invalid Request
2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
2007/10/05 11:06:55| clientReadRequest: FD 1007 (12.25.108.29:63647)
Invalid Request
2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
2007/10/05 11:22:01| clientReadRequest: FD 1612 (81.104.41.63:48329)
Invalid Request
2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
2007/10/05 11:22:01| clientReadRequest: FD 1685 (74.236.38.154:50482)
Invalid Request
2007/10/05 11:22:06| parseHttpRequest: Unsupported method 'Connection:'
2007/10/05 11:22:06| clientReadRequest: FD 6278 (83.112.151.249:53849)
Invalid Request
The box is a 2 cpu dual core, so each squid instance maxes out at 25% cpu.
The are strictly in memory cache (no disk), and they each have 9G of
RAM per instance.
Can someone give me an idea of what is happening?
Thanks.
**
Greetings,
Also, here is some truss output to show what the process is doing.
accept(9, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) Err#11 EAGAIN
write(5635, " G E T / f i l e / 2 7".., 842) = 842
write(5636, " G E T / f i l e / 2 5".., 654) = 654
write(5637, " G E T / f i l e / 2 3".., 475) = 475
write(5638, " H T T P / 1 . 0 2 0 0".., 3100) = 3100
read(5638, 0x35F4C4A00, 4095) Err#11 EAGAIN
read(5641, " G E T / f i l e / 2 6".., 4095) = 468
write(5644, " H T T P / 1 . 0 2 0 0".., 2117) = 2117
read(5644, 0x30A678AB0, 4095) Err#11 EAGAIN
write(5645, " H T T P / 1 . 0 2 0 0".., 3487) = 3487
read(5645, 0x3568248E0, 4095) Err#11 EAGAIN
write(5646, " H T T P / 1 . 0 2 0 0".., 4130) = 4130
read(5647, " G E T / f i l e / 2 6".., 4095) = 383
write(5649, " G E T / f i l e / 2 8".., 500) = 500
read(5651, " G E T / f i l e / 1 3".., 4095) = 364
write(5652, " H T T P / 1 . 0 2 0 0".., 3331) = 3331
read(5652, 0x35BF4ACF0, 4095) Err#11 EAGAIN
read(5653, 0x35A5B2B70, 4095) Err#131 ECONNRESET
close(5653) = 0
read(5655, 0x35D087890, 4095) Err#131 ECONNRESET
close(5655) = 0
write(5656, " H T T P / 1 . 0 2 0 0".., 2459) = 2459
read(5656, 0x358970130, 4095) Err#11 EAGAIN
read(5657, 0x30E6DB710, 4095) = 0
close(5657) = 0
write(5663, " G E T / f i l e / 1 1".., 541) = 541
write(5666, " H T T P / 1 . 0 2 0 0".., 2539) = 2539
read(5666, 0x2490B2C20, 4095) Err#11 EAGAIN
write(5669, " H T T P / 1 . 0 2 0 0".., 2783) = 2783
read(5669, 0x35A397400, 4095) Err#11 EAGAIN
read(5670, " G E T / f i l e / 2 6".., 4095) = 477
read(5671, 0x1F6170000, 4095) Err#131 ECONNRESET
close(5671) = 0
write(5672, " H T T P / 1 . 0 2 0 0".., 2031) = 2031
read(5672, 0x358112740, 4095) Err#11 EAGAIN
write(5683, " G E T / f i l e / 1 1".., 463) = 463
read(5684, " G E T / f i l e / 1 9".., 4095) = 442
write(5685, " H T T P / 1 . 0 2 0 0".., 4127) = 4127
write(5686, " H T T P / 1 . 0 2 0 0".., 2882) = 2882
read(5686, 0x35CE62750, 4095) Err#11 EAGAIN
read(5687, " G E T / f i l e / 2 0".., 4095) = 994
read(5691, " G E T / f i l e / 1 4".., 4095) = 375
write(5692, " H T T P / 1 . 0 2 0 0".., 2392) = 2392
read(5692, 0x35A3077F0, 4095) Err#11 EAGAIN
read(5693, " G E T / f i l e / 1 6".., 4095) = 643
write(5702, " H T T P / 1 . 0 2 0 0".., 2435) = 2435
read(5702, 0x35C769C90, 4095) Err#11 EAGAIN
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3156
getsockname(3156, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3156, F_GETFL) = 130
fcntl(3156, F_SETFD, 0x00000083) = 0
fcntl(3156, F_GETFL) = 130
fcntl(3156, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3158
getsockname(3158, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3158, F_GETFL) = 130
fcntl(3158, F_SETFD, 0x00000083) = 0
fcntl(3158, F_GETFL) = 130
fcntl(3158, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3161
getsockname(3161, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3161, F_GETFL) = 130
fcntl(3161, F_SETFD, 0x00000083) = 0
fcntl(3161, F_GETFL) = 130
fcntl(3161, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3169
getsockname(3169, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3169, F_GETFL) = 130
fcntl(3169, F_SETFD, 0x00000083) = 0
fcntl(3169, F_GETFL) = 130
fcntl(3169, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3170
getsockname(3170, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3170, F_GETFL) = 130
fcntl(3170, F_SETFD, 0x00000083) = 0
fcntl(3170, F_GETFL) = 130
fcntl(3170, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3175
getsockname(3175, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3175, F_GETFL) = 130
fcntl(3175, F_SETFD, 0x00000083) = 0
fcntl(3175, F_GETFL) = 130
fcntl(3175, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3176
getsockname(3176, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3176, F_GETFL) = 130
fcntl(3176, F_SETFD, 0x00000083) = 0
fcntl(3176, F_GETFL) = 130
fcntl(3176, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3177
getsockname(3177, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3177, F_GETFL) = 130
fcntl(3177, F_SETFD, 0x00000083) = 0
fcntl(3177, F_GETFL) = 130
fcntl(3177, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3179
getsockname(3179, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3179, F_GETFL) = 130
fcntl(3179, F_SETFD, 0x00000083) = 0
fcntl(3179, F_GETFL) = 130
fcntl(3179, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(8, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 3180
getsockname(3180, 0xFFFFFD7FFFDFFAE0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) = 0
fcntl(3180, F_GETFL) = 130
fcntl(3180, F_SETFD, 0x00000083) = 0
fcntl(3180, F_GETFL) = 130
fcntl(3180, F_SETFL, FWRITE|FNONBLOCK) = 0
accept(9, 0xFFFFFD7FFFDFFAF0, 0xFFFFFD7FFFDFFADC, SOV_DEFAULT) Err#11 EAGAIN
read(5703, " G E T / f i l e / 1 8".., 4095) = 607
write(5704, " H T T P / 1 . 0 2 0 0".., 2416) = 2416
read(5704, 0x2F9114E50, 4095) Err#11 EAGAIN
read(5706, " G E T / f i l e / 1 6".., 4095) = 382
write(5707, " H T T P / 1 . 0 2 0 0".., 2493) = 2493
read(5707, 0x29D770F60, 4095) Err#11 EAGAIN
write(5709, " H T T P / 1 . 0 2 0 0".., 2681) = 2681
read(5709, 0x35857DA50, 4095) Err#11 EAGAIN
write(5717, " G E T / f i l e / 2 9".., 538) = 538
write(5718, " G E T / f i l e / 2 6".., 395) = 395
write(5720, " H T T P / 1 . 0 2 0 0".., 2765) = 2765
read(5720, 0x35882EC00, 4095) Err#11 EAGAIN
write(5721, " H T T P / 1 . 0 2 0 0".., 2993) = 2993
read(5721, 0x3577FA750, 4095) Err#11 EAGAIN
write(5722, " H T T P / 1 . 0 2 0 0".., 2167) = 2167
read(5722, 0x246BF64B0, 4095) Err#11 EAGAIN
read(5723, 0x358E66F80, 4095) Err#131 ECONNRESET
close(5723) = 0
write(5724, " H T T P / 1 . 0 2 0 0".., 1989) = 1989
read(5724, 0x35E2A5B40, 4095) Err#11 EAGAIN
write(5725, " H T T P / 1 . 0 2 0 0".., 2038) = 2038
close(5725) = 0
read(5727, " G E T / f i l e / 3 3".., 4095) = 382
write(5733, " H T T P / 1 . 0 2 0 0".., 2905) = 2905
read(5733, 0x357CCA630, 4095) Err#11 EAGAIN
write(5734, " H T T P / 1 . 0 2 0 0".., 3072) = 3072
read(5734, 0x35C535630, 4095) Err#11 EAGAIN
write(5735, " H T T P / 1 . 0 2 0 0".., 3366) = 3366
****
On 10/5/07, Frank Ruiz <frank.ruiz@gmail.com> wrote:
> I have 2 squid instances.
>
> Both are taking the same amount of connections, and both are
> connecting to the same exact pool of origins via a lb.
>
> 2344 root 13G 13G cpu1 0 0 4:03:10 25% squid/1
> 2096 root 13G 13G sleep 31 0 4:47:22 9.2% squid/1
>
>
> After about 14 hours of runtime, the instances hit 25% utilization,
> and then never seem to restabilize.
>
>
> This is all I see in my cache.log for the instance that is maxed out:
>
> 2007/10/05 10:47:25| clientReadRequest: FD 107 (82.38.189.46:5430)
> Invalid Request
> 2007/10/05 11:05:13| WARNING: unparseable HTTP header field
> {Accept-CharsetGET /pict/320155568274_1.jpg HTTP/1.1}
> 2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:06:55| clientReadRequest: FD 1808 (84.71.71.234:35312)
> Invalid Request
> 2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:06:55| clientReadRequest: FD 1007 (12.25.108.29:63647)
> Invalid Request
> 2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:01| clientReadRequest: FD 1612 (81.104.41.63:48329)
> Invalid Request
> 2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:01| clientReadRequest: FD 1685 (74.236.38.154:50482)
> Invalid Request
> 2007/10/05 11:22:06| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:06| clientReadRequest: FD 6278 (83.112.151.249:53849)
> Invalid Request
>
>
> The box is a 2 cpu dual core, so each squid instance maxes out at 25% cpu.
> The are strictly in memory cache (no disk), and they each have 9G of
> RAM per instance.
>
> Can someone give me an idea of what is happening?
>
> Thanks.
>
Here are my compile time options:
./configure --enable-storeio=diskd,null --enable-snmp --enable-devpoll
On 10/5/07, Frank Ruiz <frank.ruiz@gmail.com> wrote:
- Show quoted text -
> I have 2 squid instances.
>
> Both are taking the same amount of connections, and both are
> connecting to the same exact pool of origins via a lb.
>
> 2344 root 13G 13G cpu1 0 0 4:03:10 25% squid/1
> 2096 root 13G 13G sleep 31 0 4:47:22 9.2% squid/1
>
>
> After about 14 hours of runtime, the instances hit 25% utilization,
> and then never seem to restabilize.
>
>
> This is all I see in my cache.log for the instance that is maxed out:
>
> 2007/10/05 10:47:25| clientReadRequest: FD 107 (82.38.189.46:5430)
> Invalid Request
> 2007/10/05 11:05:13| WARNING: unparseable HTTP header field
> {Accept-CharsetGET /pict/320155568274_1.jpg HTTP/1.1}
> 2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:06:55| clientReadRequest: FD 1808 (84.71.71.234:35312)
> Invalid Request
> 2007/10/05 11:06:55| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:06:55| clientReadRequest: FD 1007 (12.25.108.29:63647)
> Invalid Request
> 2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:01| clientReadRequest: FD 1612 (81.104.41.63:48329)
> Invalid Request
> 2007/10/05 11:22:01| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:01| clientReadRequest: FD 1685 (74.236.38.154:50482)
> Invalid Request
> 2007/10/05 11:22:06| parseHttpRequest: Unsupported method 'Connection:'
> 2007/10/05 11:22:06| clientReadRequest: FD 6278 (83.112.151.249:53849)
> Invalid Request
>
>
> The box is a 2 cpu dual core, so each squid instance maxes out at 25% cpu.
> The are strictly in memory cache (no disk), and they each have 9G of
> RAM per instance.
>
> Can someone give me an idea of what is happening?
>
> Thanks.
>
Also,
I have 32G additional RAM avail, and I swap looks healthy:
0 0 0 41870868 33463280 0 0 0 0 0 0 0 0 0 0 0 7381 13369 1557 36 6 58
0 0 0 41870868 33463280 0 0 0 0 0 0 0 2 0 0 0 7503 15598 1498 36 8 57
0 0 0 41870868 33463280 0 0 0 0 0 0 0 0 0 0 0 8071 15602 1662 35 7 58
0 0 0 41870868 33463280 0 0 0 0 0 0 0 3 0 0 0 8121 16271 1487 36 12 53
0 0 0 41870868 33463280 0 0 0 0 0 0 0 0 0 0 0 8154 15720 1545 36 7 57
0 0 0 41870868 33463280 0 0 0 0 0 0 0 0 0 0 0 8322 15764 1491 35 8 56
0 0 0 41870856 33463268 0 0 0 0 0 0 0 0 0 0 0 8386 19134 1863 34 8 58
Received on Fri Oct 05 2007 - 13:18:06 MDT
This archive was generated by hypermail pre-2.1.9 : Thu Nov 01 2007 - 13:00:01 MDT