[squid-users] Sudden but sustained high bandwidth usage

Fri Mar 11 16:25:57 UTC 2016

I managed to track down with GDB one of these swapfails...

Breakpoint 1, clientReplyContext::cacheHit (this=0x33bff58, result=...) 
at client_side_reply.cc:471
471             http->logType = LOG_TCP_SWAPFAIL_MISS;
(gdb) l
466             debugs(88, 3, "clientCacheHit: request aborted");
467             return;
468         } else if (result.flags.error) {
469             /* swap in failure */
470             debugs(88, 3, "clientCacheHit: swapin failure for " << 
http->uri);
471             http->logType = LOG_TCP_SWAPFAIL_MISS;
472             removeClientStoreReference(&sc, http);
473             processMiss();
474             return;
475         }

(gdb) p *this
$2 = {<Lock> = {_vptr.Lock = 0x84e668, count_ = 1}, <StoreClient> = 
{_vptr.StoreClient = 0x84e638}, purgeStatus = Http::scNone,
   lookingforstore = 5, http = 0x1eadb398, headers_sz = 0, sc = 
0x3034028, tempBuffer = {flags = {error = 0}, length = 0, offset = 0,
     data = 0x0}, old_reqsize = 0, reqsize = 210, reqofs = 0, tempbuf = 
'\000' <repeats 4095 times>, flags = {storelogiccomplete = 0,
     complete = 0, headersSent = false}, ourNode = 0xaa32198, 
holdingBuffer = {flags = {error = 0}, length = 0, offset = 0, data = 0x0},
   reply = 0x0, old_entry = 0x0, old_sc = 0x0, deleting = false, static 
CBDATA_clientReplyContext = 24}
(gdb) p result
$3 = {flags = {error = 1}, length = 0, offset = 0,
   data = 0x9ef18d8 "HTTP/1.1 200 Internal marker object\r\nServer: 
squid\r\nMime-Version: 1.0\r\nDate: Fri, 11 Mar 2016 15:57:32 
GMT\r\nContent-Type: x-squid-internal/vary\r\nExpires: Sat, 12 Mar 2016 
19:44:12 GMT\r\nVary: Accept-En"...}

It already came to client_side_reply.cc with "ERROR" set to 1...

(gdb) bt
#0  clientReplyContext::cacheHit (this=0x33bff58, result=...) at 
client_side_reply.cc:471
#1  0x000000000064dcbd in store_client::callback (this=0x3034028, 
sz=<optimized out>, error=<optimized out>) at store_client.cc:130
#2  0x000000000064e6c1 in store_client::startSwapin 
(this=this at entry=0x3034028) at store_client.cc:382
#3  0x00000000006501d3 in store_client::doCopy 
(this=this at entry=0x3034028, anEntry=anEntry at entry=0xab07eb0) at 
store_client.cc:359
#4  0x000000000065033c in storeClientCopy2 (e=0xab07eb0, 
sc=sc at entry=0x3034028) at store_client.cc:315
#5  0x0000000000650db9 in storeClientCopy2 (sc=0x3034028, e=<optimized 
out>) at store_client.cc:281
#6  store_client::copy (this=0x3034028, anEntry=0xab07eb0, copyRequest=...,
     callback_fn=0x55b250 <clientReplyContext::CacheHit(void*, 
StoreIOBuffer)>, data=0x33bff58) at store_client.cc:232
#7  0x0000000000558111 in clientReplyContext::doGetMoreData 
(this=this at entry=0x33bff58) at client_side_reply.cc:1799
#8  0x0000000000558422 in clientReplyContext::identifyFoundObject 
(this=0x33bff58, newEntry=<optimized out>) at client_side_reply.cc:1649
#9  0x000000000055a8b8 in clientReplyContext::cacheHit (this=0x33bff58, 
result=...) at client_side_reply.cc:525
#10 0x000000000064dcbd in store_client::callback (this=0x51d5b08, 
sz=<optimized out>, error=<optimized out>) at store_client.cc:130
#11 0x000000000064e1ba in store_client::readBody 
(this=this at entry=0x51d5b08, buf=<optimized out>, len=len at entry=210) at 
store_client.cc:497
#12 0x000000000064f76b in store_client::readHeader (this=0x51d5b08, 
buf=<optimized out>, len=<optimized out>) at store_client.cc:611
#13 0x0000000000732790 in Rock::IoState::callReaderBack (this=<optimized 
out>,
     buf=0x9ef18d8 "HTTP/1.1 200 Internal marker object\r\nServer: 
squid\r\nMime-Version: 1.0\r\nDate: Fri, 11 Mar 2016 15:57:32 
GMT\r\nContent-Type: x-squid-internal/vary\r\nExpires: Sat, 12 Mar 2016 
19:44:12 GMT\r\nVary: Accept-En"..., rlen=428) at rock/RockIoState.cc:143
#14 0x0000000000726ec1 in Rock::SwapDir::readCompleted (this=<optimized 
out>, buf=<optimized out>, rlen=428, errflag=0, r=...)
     at rock/RockSwapDir.cc:822
#15 0x00000000006f22c0 in IpcIoFile::readCompleted (this=<optimized 
out>, readRequest=0x5417008, response=<optimized out>)
     at DiskIO/IpcIo/IpcIoFile.cc:255
#16 0x00000000006f6bcc in IpcIoFile::handleResponse (this=<optimized 
out>, ipcIo=...) at DiskIO/IpcIo/IpcIoFile.cc:462
#17 0x00000000006f6fde in IpcIoFile::HandleResponses 
(when=when at entry=0x851324 "after notification") at 
DiskIO/IpcIo/IpcIoFile.cc:449

...help!

-- 
Heiler Bemerguy - (91) 98151-4894
Assessor Técnico - CINBESA (91) 3184-1751

Em 11/03/2016 10:55, Heiler Bemerguy escreveu:
>
> Hi Eliezer,
>
> We usually don't restart it ever. Only recently I've been restarting 
> it because of these issues. The shutdown_lifetime is set to 5 seconds 
> only.
>
> We are still getting SWAPFAIL_MISS without any apparent reason, and if 
> it is for a RANGE request, it would multiply it to many parallel 
> connections.... I'd like to track it down but I'm afraid I don't have 
> the knowledge to do it...
>
> root at proxy:/var/log/squid# tail -f access.log |grep SWAPF
> 1457703376.593    383 10.88.100.100 TCP_SWAPFAIL_MISS/206 533 GET 
> http://vdownloader.com/wp-content/uploads/multiwebsite-570x321.png - 
> HIER_DIRECT/104.25.245.28 image/png
> 1457703376.942    726 10.88.100.100 TCP_SWAPFAIL_MISS/206 530 GET 
> http://vdownloader.com/wp-content/uploads/social-media-share-570x321.jpg 
> - HIER_DIRECT/104.25.244.28 image/jpeg
> 1457703376.964    746 10.88.100.100 TCP_SWAPFAIL_MISS/206 529 GET 
> http://vdownloader.com/wp-content/uploads/Cnet-logo.png - 
> HIER_DIRECT/104.25.244.28 image/png
> 1457703540.685 106669 10.101.1.50 TCP_SWAPFAIL_MISS/200 3342325 GET 
> http://www.rarlab.com/rar/wrar531br.exe - HIER_DIRECT/5.135.104.98 
> application/octet-stream
> 1457703631.055   4088 10.101.1.130 TCP_SWAPFAIL_MISS/206 33062 GET 
> http://www.cetapnet.com.br/arquivos_cetap/arquivos/pma_001_2015_anexo_03.pdf 
> - HIER_DIRECT/200.219.214.204 application/pdf
> 1457703637.471   6407 10.101.1.130 TCP_SWAPFAIL_MISS/206 352287 GET 
> http://www.cetapnet.com.br/arquivos_cetap/arquivos/pma_001_2015_anexo_03.pdf 
> - HIER_DIRECT/200.219.214.204 application/pdf
> 1457703755.673    262 10.72.0.24 TCP_SWAPFAIL_MISS/206 21736 GET 
> http://ciac.ufpa.br/phocadownload/EDITAL_018-2016-RET-HOM_REC_2-CH-SISU-2016.pdf 
> - HIER_DIRECT/200.239.64.160 application/pdf
> 1457703755.712     35 10.72.0.24 TCP_SWAPFAIL_MISS/206 65938 GET 
> http://ciac.ufpa.br/phocadownload/EDITAL_018-2016-RET-HOM_REC_2-CH-SISU-2016.pdf 
> - HIER_DIRECT/200.239.64.160 application/pdf
>
> Best Regards,
>