Re: [squid-users] squidaio_queue_request: WARNING - Queue congestion

On Tue, 16 Feb 2010 14:30:06 -0800, Tory M Blue <tmblue_at_gmail.com> wrote:
> I'm starting to lose my mind here. New hardware test bed including a
> striped set of SSD's
>
> Same hardware, controller etc as my other squid servers, just added
> SSD's for testing. I've used default threads and I've built with 24
> threads. And what's blowing my mind is I get the error immediately
> upon startup of my cache server (what?) and when I start banging on it
> with over 75 connections p/sec..
>
> The issue with the "well if you only see a few ignore", is that I
> actually get 500 errors when this happens. So something is going on
> and I'm not sure what.
>
> No Load
> No I/O wait.
>
> Fedora 12
> Squid2.7Stable7
> Dual Core
> 6gigs of ram
> Striped SSD's
>
> And did I mention no wait and zero load when this happens?
>
> "configure options: '--host=i686-pc-linux-gnu'
> '--build=i686-pc-linux-gnu' '--target=i386-redhat-linux'
> '--program-prefix=' '--prefix=/usr' '--exec-prefix=/usr'
> '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc'
> '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib'
> '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib'
> '--mandir=/usr/share/man' '--infodir=/usr/share/info'
> '--exec_prefix=/usr' '--libexecdir=/usr/lib/squid'
> '--localstatedir=/var' '--datadir=/usr/share/squid'
> '--sysconfdir=/etc/squid' '--disable-dependency-tracking'
> '--enable-arp-acl' '--enable-follow-x-forwarded-for'
> '--enable-auth=basic,digest,negotiate'
> '--enable-basic-auth-helpers=NCSA,PAM,getpwnam,SASL'
> '--enable-digest-auth-helpers=password'
> '--enable-negotiate-auth-helpers=squid_kerb_auth'
> '--enable-external-acl-helpers=ip_user,session,unix_group'
> '--enable-cache-digests' '--enable-cachemgr-hostname=localhost'
> '--enable-delay-pools' '--enable-epoll' '--enable-ident-lookups'
> '--with-large-files' '--enable-linux-netfilter' '--enable-referer-log'
> '--enable-removal-policies=heap,lru' '--enable-snmp' '--enable-ssl'
> '--enable-storeio=aufs,diskd,ufs' '--enable-useragent-log'
> '--enable-wccpv2' '--with-aio' '--with-maxfd=16384' '--with-dl'
> '--with-openssl' '--with-pthreads' '--with-aufs-threads=24'
> 'build_alias=i686-pc-linux-gnu' 'host_alias=i686-pc-linux-gnu'
> 'target_alias=i386-redhat-linux' 'CFLAGS=-fPIE -Os -g -pipe
> -fsigned-char -O2 -g -march=i386 -mtune=i686' 'LDFLAGS=-pie'"
>
>
> 2010/02/16 14:15:49| Starting Squid Cache version 2.7.STABLE7 for
> i686-pc-linux-gnu...
> 2010/02/16 14:15:49| Process ID 19222
> 2010/02/16 14:15:49| With 4096 file descriptors available
> 2010/02/16 14:15:49| Using epoll for the IO loop
> 2010/02/16 14:15:49| Performing DNS Tests...
> 2010/02/16 14:15:49| Successful DNS name lookup tests...
> 2010/02/16 14:15:49| DNS Socket created at 0.0.0.0, port 52964, FD 6
>
> 2010/02/16 14:15:49| User-Agent logging is disabled.
> 2010/02/16 14:15:49| Referer logging is disabled.
> 2010/02/16 14:15:49| Unlinkd pipe opened on FD 10
> 2010/02/16 14:15:49| Swap maxSize 32768000 + 102400 KB, estimated
> 2528492 objects
> 2010/02/16 14:15:49| Target number of buckets: 126424
> 2010/02/16 14:15:49| Using 131072 Store buckets
> 2010/02/16 14:15:49| Max Mem size: 102400 KB
> 2010/02/16 14:15:49| Max Swap size: 32768000 KB
> 2010/02/16 14:15:49| Local cache digest enabled; rebuild/rewrite every
> 3600/3600 sec
> 2010/02/16 14:15:49| Store logging disabled
> 2010/02/16 14:15:49| Rebuilding storage in /cache (CLEAN)
> 2010/02/16 14:15:49| Using Least Load store dir selection
> 2010/02/16 14:15:49| Set Current Directory to /var/spool/squid
> 2010/02/16 14:15:49| Loaded Icons.
> 2010/02/16 14:15:50| Accepting accelerated HTTP connections at
> 0.0.0.0, port 80, FD 13.
> 2010/02/16 14:15:50| Accepting ICP messages at 0.0.0.0, port 3130, FD
14.
> 2010/02/16 14:15:50| Accepting SNMP messages on port 3401, FD 15.
> 2010/02/16 14:15:50| WCCP Disabled.
> 2010/02/16 14:15:50| Ready to serve requests.
> 2010/02/16 14:15:50| Configuring host,domain.com Parent
> host.domain.com/80/0
> 2010/02/16 14:15:50| Store rebuilding is 0.4% complete
> 2010/02/16 14:16:05| Store rebuilding is 66.1% complete
> 2010/02/16 14:16:12| Done reading /cache swaplog (948540 entries)
> 2010/02/16 14:16:12| Finished rebuilding storage from disk.
> 2010/02/16 14:16:12| 948540 Entries scanned
> 2010/02/16 14:16:12| 0 Invalid entries.
> 2010/02/16 14:16:12| 0 With invalid flags.
> 2010/02/16 14:16:12| 948540 Objects loaded.
> 2010/02/16 14:16:12| 0 Objects expired.
> 2010/02/16 14:16:12| 0 Objects cancelled.
> 2010/02/16 14:16:12| 0 Duplicate URLs purged.
> 2010/02/16 14:16:12| 0 Swapfile clashes avoided.
> 2010/02/16 14:16:12| Took 23.0 seconds (41316.8 objects/sec).

Hmm, this may be part of a hint. the other clean loads I've seen posted
recently, even on old hardware were in or very close to the millions of
objects per second. All its really doing so far is loading a text file into
memory from disk...

> 2010/02/16 14:16:12| Beginning Validation Procedure
> 2010/02/16 14:16:13| 262144 Entries Validated so far.
> 2010/02/16 14:16:13| 524288 Entries Validated so far.
> 2010/02/16 14:16:13| 786432 Entries Validated so far.
> 2010/02/16 14:16:13| Completed Validation Procedure
> 2010/02/16 14:16:13| Validated 948540 Entries
> 2010/02/16 14:16:13| store_swap_size = 3794160k
> 2010/02/16 14:16:14| storeLateRelease: released 0 objects
> 2010/02/16 14:18:00| squidaio_queue_request: WARNING - Queue congestion
> 2010/02/16 14:18:04| squidaio_queue_request: WARNING - Queue congestion
> 2010/02/16 14:18:08| squidaio_queue_request: WARNING - Queue
> congestion <-- load test starts here.
> 2010/02/16 14:18:15| squidaio_queue_request: WARNING - Queue congestion
> 2010/02/16 14:18:26| squidaio_queue_request: WARNING - Queue congestion
>
> What can I look for, if I don't believe it's IO wait or load (the box
> is sleeping), what else can it be. I thought creating a new build with
> 24 threads would help but it has not (I can rebuild with 10 threads vs
> the default 18 (is that right?) I guess.

Each of the warnings doubles the previous queue size, so

I think its time we took this to the next level of debug.
Please run a startup with the option -X and lets see what squid is really
trying to do there.

Amos
Received on Wed Feb 17 2010 - 00:03:30 MST