Amos Jeffries wrote:
> On 12.11.2012 03:25, Frantisek Hanzlik wrote:
>> With this squid configuration:
>> acl localnet src 172.16.0.0/12
>> acl localnet src 192.168.0.0/16
>> acl SSL_ports port 443
>> acl SSL_ports port 85
>> acl SSL_ports port 81
>> acl SSL_ports port 5443
>> acl Safe_ports port 80
>> acl Safe_ports port 21
>> acl Safe_ports port 443
>> acl Safe_ports port 70
>> acl Safe_ports port 210
>> acl Safe_ports port 1025-65535
>> acl Safe_ports port 280
>> acl Safe_ports port 488
>> acl Safe_ports port 591
>> acl Safe_ports port 777
>> acl Safe_ports port 5443
>> acl Safe_ports port 85
>> acl Safe_ports port 81
>> acl CONNECT method CONNECT
>> http_access allow manager localhost
>> http_access deny manager
>> http_access deny !Safe_ports
>> http_access deny CONNECT !SSL_ports
>> http_access allow localnet
>> http_access allow localhost
>> http_access deny all
>> http_port 3128
>> hierarchy_stoplist cgi-bin ?
>> cache_dir ufs /var/spool/squid 1000 16 256 max-size=999000
>> cache_mem 512 MB
>> maximum_object_size 4096 KB
>> memory_pools off
>> cache_swap_low 90
>> cache_swap_high 95
>> dns_nameservers 172.16.1.1
>> client_db off
>> half_closed_clients off
>> max_filedesc 4096
>> coredump_dir /var/spool/squid
>> refresh_pattern ^ftp: 1440 20% 10080
>> refresh_pattern ^gopher: 1440 0% 1440
>> refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
>> refresh_pattern . 0 20% 4320
>> acl users src 172.31.0.0/16
>> delay_pools 1
>> delay_class 1 2
>> delay_parameters 1 5000000/10000000 5000000/10000000
>> delay_access 1 allow users
>>
>> squid very often load CPU at near 100%, with cca 200 users and 4000
>> connections (~2000 to users, 2000 to internet). Removing delay pool
>> configuration has no big effect.
>
> Users and connections is meaningless in HTTP. Requests per second flowing
> over those connections is what counts.
>
> The proxy might have all 4000 links idle (low CPU; zero bandwidth; zero
> disk I/O), be downloading video (or .iso) images simultaneously (low CPU;
> maxed out bandwidth; high disk I/O), or parsing and processing
> header-only requests (100% CPU; moderate or low bandwidth; no disk I/O).
>
> NP: 3.2 uses HTTP/1.1. A lot of the protocol performance features in
> HTTP/1.1 are done by removing object bodies and reducing the transactions
> to header-only requests and responses.
>
>
>> HW configuration: Dual core E8500@3.16GHz CPU, 4GB RAM, 2x SATA 7k2
>> Raid Edition disks in SW RAID1 for squid cache (disk performance
>> seems isn't problem, IOWAIT is small), gigabit ethernet cards to
>> internet (~800 Mbps line) and to LAN.
>> It is squid-3.2.3.20121106.r11695-1.fc14.i686 on Fedora 14 i686
>> (I test it with some older squid 3.1 version and same configuration
>> too, but results were same, or rather worse)
>>
>> It this CPU load normal, or can be there done some performance
>> tunnning for it?
>
> In order of likelyhood:
>
> Experiment #1 is remove that SW RAID and test again.
> Sure iowait is not bad (um, to *master* disk it is same as accessing
> without RAID at all), however iowait is only half the story with SW RAID.
> Being SW every I/O op sucks away some ... CPU. Disk I/O CPU loading in
> particular can be doubled depending on the implementations buffering
> efficiency.
> If you need RAID at all use HW RAID instead of SW. The only benefit you
> get from RAID under Squid is some advance notice of disks failing before
> the proxy crashes (or starts TCP_SWAPFAIL_MISS'ing - but UFS cache type
> still crashes so maybe you do need RAID).
> By using SW RAID in particular you are taking CPU cycles away from
> Squid, which would otherwise be using them to process a higher req/sec
> peak capacity. If your peak traffic is low req/sec this is not a problem,
> but for several thousand users I expect your peak capacity needs are high.
> Choice is yours, but I seriously advise moving away from SW RAID.
>
>
> Experiment #2 is to set "memory_pools on".
> Up to 90% of malloc/free calls are for very short strings and small
> objects. Squid can save on a lot of system allocator cycles and shrink
> the overall system RAM requirements a little bit by allocating these in
> batches/blocks/pools. This will help speed up req/sec capacity in the
> traffic which consists of mostly HTTP headers.
>
>
> Experiment #3 is to raise max_filedesc
> I suspect this setting is the only thing limiting your proxy to 2000 user
> connections and 2000 internet connections. Notice that makes 4000, and
> with 100 connections held in reserve for unexpected disk access it would
> seem that you are not using disks at all for many of these connections
> (TCP_MISS and TCP_MEM_HIT being most of your load?).
> When there are not enough FD to service all incoming requests Squid
> starts limiting them and spends extra CPU cycles doing management of the
> waiting client connection queue.
>
>
> Experiment #4 is to set "cache_swap_low 97" and "cache_swap_high 98".
> Periodic garbage collection happens when the cache fills up. With a 1GB
> disk cache the default settings make about 50-100MB of objects being
> processed in the cache and erased from disk. Most objects will be only a
> few KB - see your avg object size stats.
> NOTE: this may only marginally appear in iowait, but shows up better in
> the related erase/unlink operation stats.
>
> Amos
Thank You for recommendations. I think #3 perhaps isn't problem there,
as squids cache.log says there is 16384 filedescriptors (i do not
understand why it is this number, in startup script i'm setting
'ulimit -HSn 65536'
just before starting squid - then why no. of fd is only 16384? Some other
system limitations?):
2012/11/17 08:40:29 kid1| Starting Squid Cache version
3.2.3-20121106-r11695 for i686-pc-linux-gnu...
2012/11/17 08:40:29 kid1| Process ID 2497
2012/11/17 08:40:29 kid1| Process Roles: worker
2012/11/17 08:40:29 kid1| With 16384 file descriptors available
2012/11/17 08:40:29 kid1| Initializing IP Cache...
2012/11/17 08:40:29 kid1| DNS Socket created at 0.0.0.0, FD 9
2012/11/17 08:40:29 kid1| Adding nameserver 172.16.1.1 from squid.conf
2012/11/17 08:40:29 kid1| Logfile: opening log
daemon:/var/log/squid/access.log
2012/11/17 08:40:29 kid1| Logfile Daemon: opening log
/var/log/squid/access.log
2012/11/17 08:40:29 kid1| Unlinkd pipe opened on FD 15
2012/11/17 08:40:29 kid1| Local cache digest enabled; rebuild/rewrite
every 3600/3600 sec
2012/11/17 08:40:29 kid1| Store logging disabled
2012/11/17 08:40:29 kid1| Swap maxSize 1024000 + 524288 KB, estimated
119099 objects
2012/11/17 08:40:29 kid1| Target number of buckets: 5954
2012/11/17 08:40:29 kid1| Using 8192 Store buckets
2012/11/17 08:40:29 kid1| Max Mem size: 524288 KB
2012/11/17 08:40:29 kid1| Max Swap size: 1024000 KB
2012/11/17 08:40:29 kid1| Rebuilding storage in /var/spool/squid (dirty log)
2012/11/17 08:40:29 kid1| Using Least Load store dir selection
2012/11/17 08:40:29 kid1| Set Current Directory to /var/spool/squid
2012/11/17 08:40:30 kid1| Loaded Icons.
2012/11/17 08:40:30 kid1| HTCP Disabled.
2012/11/17 08:40:30 kid1| Squid plugin modules loaded: 0
2012/11/17 08:40:30 kid1| Adaptation support is off.
2012/11/17 08:40:30 kid1| Accepting HTTP Socket connections at
local=0.0.0.0:3128 remote=[::] FD 18 flags=9
2012/11/17 08:40:30 kid1| Store rebuilding is 0.11% complete
2012/11/17 08:40:45 kid1| Store rebuilding is 40.44% complete
2012/11/17 08:41:00 kid1| Store rebuilding is 83.15% complete
2012/11/17 08:41:05 kid1| Done reading /var/spool/squid swaplog (3699238
entries)
2012/11/17 08:41:05 kid1| Finished rebuilding storage from disk.
2012/11/17 08:41:05 kid1| 1877119 Entries scanned
2012/11/17 08:41:05 kid1| 6 Invalid entries.
2012/11/17 08:41:05 kid1| 0 With invalid flags.
2012/11/17 08:41:05 kid1| 54901 Objects loaded.
2012/11/17 08:41:05 kid1| 0 Objects expired.
2012/11/17 08:41:05 kid1| 1821036 Objects cancelled.
2012/11/17 08:41:05 kid1| 53 Duplicate URLs purged.
2012/11/17 08:41:05 kid1| 1129 Swapfile clashes avoided.
2012/11/17 08:41:05 kid1| Took 35.95 seconds (1527.34 objects/sec).
2012/11/17 08:41:05 kid1| Beginning Validation Procedure
2012/11/17 08:41:06 kid1| Completed Validation Procedure
2012/11/17 08:41:06 kid1| Validated 54895 Entries
2012/11/17 08:41:06 kid1| store_swap_size = 922068.00 KB
2012/11/17 08:41:06 kid1| storeLateRelease: released 6 objects
Thus I started with recommendation #2: setting 'memory_pools on'.
This seemed to me firstly as it highly helped: CPU load was dropped
to approx. 40-50% at the time of highest load (this is only between
18 to 21 hours our time /UTC+1/, in all other time is squid load
much smaller and CPU load was reasonable). But then I noticed
that '(squid-1)' process (PID 14667 below, child of 11769) changes
its PID, as if died and parent started new copy:
1 11769 11769 11769 ? -1 Ss 0 0:00 squid -f /etc/squid/squid.conf
11769 14667 11769 11769 ? -1 R 23 0:11 (squid-1) -f /etc/squid/squid.conf
14667 14670 11769 11769 ? -1 S 23 0:00 (logfile-daemon)
/var/log/squid/access.log
And then I found in /var/log/messages these lines
(/var/log/squid/cache.log contained nothing suspicious(*) ):
Nov 19 16:53:40 172 squid[2834]: Squid Parent: (squid-1) process 32702
exited due to signal 6 with status 0
Nov 19 16:53:43 172 squid[2834]: Squid Parent: (squid-1) process 1407 started
Nov 19 17:11:22 172 squid[2834]: Squid Parent: (squid-1) process 1407
exited due to signal 6 with status 0
Nov 19 17:11:25 172 squid[2834]: Squid Parent: (squid-1) process 2366 started
Nov 19 17:19:41 172 squid[2834]: Squid Parent: (squid-1) process 2366
exited due to signal 6 with status 0
Nov 19 17:19:44 172 squid[2834]: Squid Parent: (squid-1) process 2776 started
Nov 19 17:19:47 172 squid[2834]: Squid Parent: (squid-1) process 2776
exited due to signal 6 with status 0
Nov 19 17:19:50 172 squid[2834]: Squid Parent: (squid-1) process 2784 started
Nov 19 17:30:53 172 squid[2834]: Squid Parent: (squid-1) process 2784
exited due to signal 6 with status 0
Nov 19 17:30:56 172 squid[2834]: Squid Parent: (squid-1) process 3384 started
Nov 19 17:57:56 172 squid[2834]: Squid Parent: (squid-1) process 3384
exited due to signal 6 with status 0
Nov 19 17:57:59 172 squid[2834]: Squid Parent: (squid-1) process 4807 started
Nov 19 17:58:00 172 squid[2834]: Squid Parent: (squid-1) process 4807
exited due to signal 6 with status 0
Nov 19 17:58:03 172 squid[2834]: Squid Parent: (squid-1) process 4813 started
Nov 19 18:54:18 172 squid[2834]: Squid Parent: (squid-1) process 4813
exited due to signal 6 with status 0
Nov 19 18:54:21 172 squid[2834]: Squid Parent: (squid-1) process 7704 started
Nov 19 18:58:15 172 squid[2834]: Squid Parent: (squid-1) process 7704
exited due to signal 6 with status 0
Nov 19 18:58:18 172 squid[2834]: Squid Parent: (squid-1) process 7904 started
Nov 19 18:58:18 172 squid[2834]: Squid Parent: (squid-1) process 7904
exited due to signal 6 with status 0
Nov 19 18:58:21 172 squid[2834]: Squid Parent: (squid-1) process 7915 started
Nov 19 19:05:00 172 squid[2834]: Squid Parent: (squid-1) process 7915
exited due to signal 6 with status 0
Nov 19 19:05:03 172 squid[2834]: Squid Parent: (squid-1) process 8298 started
Nov 19 19:13:58 172 squid[2834]: Squid Parent: (squid-1) process 8298
exited due to signal 6 with status 0
Nov 19 19:14:01 172 squid[2834]: Squid Parent: (squid-1) process 8765 started
Nov 19 19:14:04 172 squid[2834]: Squid Parent: (squid-1) process 8765
exited due to signal 6 with status 0
Nov 19 19:14:07 172 squid[2834]: Squid Parent: (squid-1) process 8776 started
Nov 19 19:14:08 172 squid[2834]: Squid Parent: (squid-1) process 8776
exited due to signal 6 with status 0
Nov 19 19:14:11 172 squid[2834]: Squid Parent: (squid-1) process 8785 started
Nov 19 19:14:12 172 squid[2834]: Squid Parent: (squid-1) process 8785
exited due to signal 6 with status 0
Nov 19 19:14:15 172 squid[2834]: Squid Parent: (squid-1) process 8793 started
Nov 19 19:14:16 172 squid[2834]: Squid Parent: (squid-1) process 8793
exited due to signal 6 with status 0
Nov 19 19:14:19 172 squid[2834]: Squid Parent: (squid-1) process 8804 started
Nov 19 19:14:19 172 squid[2834]: Squid Parent: (squid-1) process 8804
exited due to signal 6 with status 0
Nov 19 19:14:19 172 squid[2834]: Squid Parent: (squid-1) process 8804
will not be restarted due to repeated, frequent failures
Nov 19 19:14:19 172 squid[2834]: Exiting due to repeated, frequent failures
At this time exited parent squid process as well and it is necessary
manually restart squid. Note this complete exit occurs after seven days
of working. And before these 7 days squid crashed with this message in
"/var/log/message":
Nov 12 20:14:38 172 kernel: [9002060.957453] squid[2494]: segfault at e51
ip 082d4917 sp bfc7dbc0 error 6 in squid[8048000+460000]
Nov 12 20:14:38 172 squid[32322]: Squid Parent: (squid-1) process 2494
exited due to signal 11 with status 0
Signal 6 is SIGABRT, how it can appear here?
(*) /var/log/squid/cache.log contains several messages like this, I not
know if they are important:
2012/11/19 20:43:47 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
2012/11/19 20:43:48 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
2012/11/19 20:43:49 kid1| WARNING: 100 swapin MD5 mismatches
2012/11/19 20:43:53 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
...
2012/11/19 20:49:09 kid1| Failed to select source for 'http://ppvsvuvduc/'
2012/11/19 20:49:09 kid1| always_direct = 0
2012/11/19 20:49:09 kid1| never_direct = 0
2012/11/19 20:49:09 kid1| timedout = 0
2012/11/19 20:49:09 kid1| Failed to select source for 'http://wweeplgxyf/'
2012/11/19 20:49:09 kid1| always_direct = 0
2012/11/19 20:49:09 kid1| never_direct = 0
2012/11/19 20:49:09 kid1| timedout = 0
2012/11/19 20:49:09 kid1| Failed to select source for 'http://sscvjtloms/'
2012/11/19 20:49:09 kid1| always_direct = 0
2012/11/19 20:49:09 kid1| never_direct = 0
2012/11/19 20:49:09 kid1| timedout = 0
...
2012/11/19 20:55:52 kid1| Failed to select source for
'http://u1353354961016s928369347.r6.td.ipv6test.semnicneposilejte.cz/1x1.png?u1353354961016s928369347.r6.td'
2012/11/19 20:55:52 kid1| always_direct = 0
2012/11/19 20:55:52 kid1| never_direct = 0
2012/11/19 20:55:52 kid1| timedout = 0
2012/11/19 20:55:52 kid1| Failed to select source for
'http://pages.etology.com/crossdomain.xml'
2012/11/19 20:55:52 kid1| always_direct = 0
2012/11/19 20:55:52 kid1| never_direct = 0
2012/11/19 20:55:52 kid1| timedout = 0
2012/11/19 20:55:53 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
...
2012/11/19 20:57:30 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
2012/11/19 20:57:34 kid1| Failed to select source for '[null_entry]'
2012/11/19 20:57:34 kid1| always_direct = 0
2012/11/19 20:57:34 kid1| never_direct = 0
2012/11/19 20:57:34 kid1| timedout = 0
2012/11/19 20:57:35 kid1| Failed to select source for '[null_entry]'
2012/11/19 20:57:35 kid1| always_direct = 0
2012/11/19 20:57:35 kid1| never_direct = 0
2012/11/19 20:57:35 kid1| timedout = 0
2012/11/19 20:57:35 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
2012/11/19 20:57:35 kid1| Failed to select source for '[null_entry]'
2012/11/19 20:57:35 kid1| always_direct = 0
2012/11/19 20:57:35 kid1| never_direct = 0
2012/11/19 20:57:35 kid1| timedout = 0
2012/11/19 20:57:44 kid1| ipcacheParse: No Address records in response to
'ipv6.msftncsi.com'
What now?
Should I try newer version then that just tested 3.2.3.20121106.r11695 ?
Or I have some wrong settings?
I'm not using IPv6 address on any interface and ipv6.ko kernel module
isn't loaded (it is Fedora 14 i686, which still has ipv6 as module;
later Fedora versions have ipv6 compiled in kernel). It is OK?
(squid has not any command-line switches for disabling IPv6, right?)
Thanks, Franta Hanzlik
