[squid-users] Squid loops on epoll/read/gettimeofday

From: Marcus Kool <marcus.kool_at_urlfilterdb.com>
Date: Mon, 29 Mar 2010 13:58:58 -0300

I use squid
Squid Cache: Version 3.0.STABLE20
configure options: '--prefix=/local/squid' '--with-default-user=squid'
'--with-filedescriptors=2400' '--enable-icap-client' '--enable-storeio=aufs,ufs,null'
'--with-pthreads' '--enable-async-io=8' '--enable-removal-policies=lru'
'--enable-default-err-language=English' '--enable-err-languages=Dutch English Portuguese'
'--enable-ssl' '--enable-cachemgr-hostname=localhost' '--enable-cache-digests'
'--enable-follow-x-forwarded-for' '--enable-forw-via-db' '--enable-xmalloc-statistics'
'--disable-hostname-checks' '--enable-epoll' '--enable-useragent-log' '--enable-referer-log'
'--enable-underscores' 'CC=gcc' 'CFLAGS=-O2 -m32' 'CXXFLAGS=-O2 -m32'

strace shows this:
      0.000029 gettimeofday({1269878848, 223018}, NULL) = 0
      0.000033 epoll_wait(6, {{EPOLLIN, {u32=23, u64=8800387989527}}}, 2400, 10) = 1
      0.000032 gettimeofday({1269878848, 223083}, NULL) = 0
      0.000031 read(27, 0xffd3de98, 256) = -1 EAGAIN (Resource temporarily unavailable)
      0.000030 gettimeofday({1269878848, 223143}, NULL) = 0
      0.000033 epoll_wait(6, {{EPOLLIN, {u32=23, u64=8800387989527}}}, 2400, 10) = 1
      0.000031 gettimeofday({1269878848, 223208}, NULL) = 0
      0.000032 read(27, 0xffd3de98, 256) = -1 EAGAIN (Resource temporarily unavailable)
      0.000029 gettimeofday({1269878848, 223269}, NULL) = 0
      0.000033 epoll_wait(6, {{EPOLLIN, {u32=23, u64=8800387989527}}}, 2400, 10) = 1
      0.000032 gettimeofday({1269878848, 223334}, NULL) = 0
      ...
So Squid loops on epoll/read/gettimeofday on FD 27.
Squid works! I can continue using it but it uses 100% CPU.

lsof shows that FD 27 is a pipe:
[root_at_srv004 fd]# lsof -c squid
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
squid 13663 root cwd DIR 9,2 4096 65089 /root
squid 13663 root rtd DIR 9,2 4096 2 /
squid 13663 root txt REG 9,3 1880413 4718713 /local/squid/sbin/squid
squid 13663 root mem REG 9,2 125736 1431984 /lib/ld-2.5.so
squid 13663 root mem REG 9,2 1611564 1432001 /lib/libc-2.5.so
squid 13663 root mem REG 9,2 76400 716063 /lib/libresolv-2.5.so
squid 13663 root mem REG 9,2 75028 867107 /usr/lib/libz.so.1.2.3
squid 13663 root mem REG 9,2 129716 1432048 /lib/libpthread-2.5.so
squid 13663 root mem REG 9,2 101404 716061 /lib/libnsl-2.5.so
squid 13663 root mem REG 9,2 45288 716062 /lib/libcrypt-2.5.so
squid 13663 root mem REG 9,2 936908 867168 /usr/lib/libstdc++.so.6.0.8
squid 13663 root mem REG 9,2 217016 3289491 /var/db/nscd/group
squid 13663 root mem REG 9,2 217016 3289470 /var/db/nscd/passwd
squid 13663 root mem REG 9,2 243928 3905305 /lib/libsepol.so.1
squid 13663 root mem REG 9,2 91892 1431943 /lib/libselinux.so.1
squid 13663 root mem REG 9,2 6404 1432021 /lib/libkeyutils-1.2.so
squid 13663 root mem REG 9,2 32024 859697
/usr/lib/libkrb5support.so.0.1
squid 13663 root mem REG 9,2 16428 1433428 /lib/libdl-2.5.so
squid 13663 root mem REG 9,2 155608 859112 /usr/lib/libk5crypto.so.3.1
squid 13663 root mem REG 9,2 6300 1433405 /lib/libcom_err.so.2.1
squid 13663 root mem REG 9,2 609068 854936 /usr/lib/libkrb5.so.3.3
squid 13663 root mem REG 9,2 184812 855987
/usr/lib/libgssapi_krb5.so.2.2
squid 13663 root mem REG 9,2 46476 4035468
/lib/libgcc_s-4.1.2-20080825.so.1
squid 13663 root mem REG 9,2 208352 1433430 /lib/libm-2.5.so
squid 13663 root mem REG 9,2 1295424 1431972 /lib/libcrypto.so.0.9.8e
squid 13663 root mem REG 9,2 291236 1433501 /lib/libssl.so.0.9.8e
squid 13663 root 0u CHR 1,3 1736 /dev/null
squid 13663 root 1u CHR 1,3 1736 /dev/null
squid 13663 root 2u CHR 1,3 1736 /dev/null
squid 13663 root 3u REG 9,3 3390696 4718891 /local/squid/logs/cache.log
squid 13663 root 4u CHR 1,3 1736 /dev/null
squid 13663 root 5u unix 0xffff810002e816c0 1723398 socket
squid 13665 squid cwd DIR 9,2 4096 65089 /root
squid 13665 squid rtd DIR 9,2 4096 2 /
squid 13665 squid txt REG 9,3 1880413 4718713 /local/squid/sbin/squid
squid 13665 squid mem REG 9,2 125736 1431984 /lib/ld-2.5.so
squid 13665 squid mem REG 9,2 1611564 1432001 /lib/libc-2.5.so
squid 13665 squid mem REG 9,2 76400 716063 /lib/libresolv-2.5.so
squid 13665 squid mem REG 9,2 75028 867107 /usr/lib/libz.so.1.2.3
squid 13665 squid mem REG 9,2 129716 1432048 /lib/libpthread-2.5.so
squid 13665 squid mem REG 9,2 101404 716061 /lib/libnsl-2.5.so
squid 13665 squid mem REG 9,2 45288 716062 /lib/libcrypt-2.5.so
squid 13665 squid mem REG 9,2 936908 867168 /usr/lib/libstdc++.so.6.0.8
squid 13665 squid mem REG 9,2 46680 1438370 /lib/libnss_files-2.5.so
squid 13665 squid mem REG 9,2 217016 3289506 /var/db/nscd/hosts
squid 13665 squid mem REG 9,2 217016 3289491 /var/db/nscd/group
squid 13665 squid mem REG 9,2 217016 3289470 /var/db/nscd/passwd
squid 13665 squid mem REG 9,2 243928 3905305 /lib/libsepol.so.1
squid 13665 squid mem REG 9,2 91892 1431943 /lib/libselinux.so.1
squid 13665 squid mem REG 9,2 6404 1432021 /lib/libkeyutils-1.2.so
squid 13665 squid mem REG 9,2 32024 859697
/usr/lib/libkrb5support.so.0.1
squid 13665 squid mem REG 9,2 16428 1433428 /lib/libdl-2.5.so
squid 13665 squid mem REG 9,2 155608 859112 /usr/lib/libk5crypto.so.3.1
squid 13665 squid mem REG 9,2 6300 1433405 /lib/libcom_err.so.2.1
squid 13665 squid mem REG 9,2 609068 854936 /usr/lib/libkrb5.so.3.3
squid 13665 squid mem REG 9,2 184812 855987
/usr/lib/libgssapi_krb5.so.2.2
squid 13665 squid mem REG 9,2 46476 4035468
/lib/libgcc_s-4.1.2-20080825.so.1
squid 13665 squid mem REG 9,2 208352 1433430 /lib/libm-2.5.so
squid 13665 squid mem REG 9,2 1295424 1431972 /lib/libcrypto.so.0.9.8e
squid 13665 squid mem REG 9,2 291236 1433501 /lib/libssl.so.0.9.8e
squid 13665 squid 0u CHR 1,3 1736 /dev/null
squid 13665 squid 1u CHR 1,3 1736 /dev/null
squid 13665 squid 2u CHR 1,3 1736 /dev/null
squid 13665 squid 3u REG 9,3 3390696 4718891 /local/squid/logs/cache.log
squid 13665 squid 4u CHR 1,3 1736 /dev/null
squid 13665 squid 5u REG 9,3 3390696 4718891 /local/squid/logs/cache.log
squid 13665 squid 6r 0000 0,11 0 1723405 eventpoll
squid 13665 squid 7u IPv4 1723426 UDP *:46523
squid 13665 squid 8u unix 0xffff81007420e3c0 1723427 socket
squid 13665 squid 9u unix 0xffff81007420eec0 1723429 socket
squid 13665 squid 10u unix 0xffff8100200b8bc0 1723431 socket
squid 13665 squid 11u unix 0xffff810002e80e80 1723433 socket
squid 13665 squid 12u unix 0xffff810002e81140 1723435 socket
squid 13665 squid 13u unix 0xffff81004d9053c0 1723437 socket
squid 13665 squid 14u unix 0xffff81006f096080 1723439 socket
squid 13665 squid 15u unix 0xffff810002e80640 1723441 socket
squid 13665 squid 16u unix 0xffff810004ede400 1723443 socket
squid 13665 squid 17u unix 0xffff81004d904080 1723473 socket
squid 13665 squid 18u unix 0xffff81005708a3c0 1723481 socket
squid 13665 squid 19u unix 0xffff81000d6ba080 1723495 socket
squid 13665 squid 20w REG 9,3 1478687 4718702 /local/squid/logs/access.log
squid 13665 squid 21r FIFO 0,6 1723502 pipe
squid 13665 squid 22w REG 9,3 30400812 4718715
/local/squid/cache/swap.state
squid 13665 squid 23r FIFO 0,6 1723506 pipe
squid 13665 squid 24w FIFO 0,6 1723503 pipe
squid 13665 squid 25u IPv4 1723505 TCP *:squid (LISTEN)
squid 13665 squid 26w FIFO 0,6 1723506 pipe
squid 13665 squid 27r FIFO 0,6 1723507 pipe FD 27 *****
squid 13665 squid 28w FIFO 0,6 1723507 pipe
squid 13665 squid 29u IPv4 1771231 TCP srv004:squid->xxx
(ESTABLISHED)
squid 13665 squid 30u IPv4 1771237 TCP srv004:54837->xxx
(ESTABLISHED)
squid 13665 squid 31u IPv4 1771322 TCP srv004:squid->xxx
(ESTABLISHED)
squid 13665 squid 32u IPv4 1771276 TCP srv004:58505->xxx
(ESTABLISHED)
squid 13665 squid 33u IPv4 1771324 TCP srv004:58838->xxx
(ESTABLISHED)
squid 13665 squid 36u IPv4 1771381 TCP srv004:squid->xxx
(ESTABLISHED)
squid 13665 squid 37u IPv4 1771383 TCP srv004:50201->xxx
(ESTABLISHED)

Note that FD 27 and FD 28 have the same NODE.
This pipe is used for what ???

The EAGAIN return code to read is strange. It suggest that the
read() could return data soon, but Squid is looping now for over 4 hours.

Hopefully one of the developers knows what the pipe is used for and
can do a guess what is causing the EAGAIN return code.

-Marcus
Received on Mon Mar 29 2010 - 16:59:04 MDT

This archive was generated by hypermail 2.2.0 : Tue Mar 30 2010 - 12:00:08 MDT