Re: [squid-users] How to increase TCP-HIT ratio

From: Michal Weinfurtner <weinfurt@dont-contact.us>
Date: Tue, 27 Jul 2004 22:40:23 +0200

maes wrote:

>>...
>>
>>My worst problem is about images. I realy don't have any
>>idea, why some
>>images are not loaded :-( Do You think taht cache size a memory uasge
>>can be a reason ?
>>
>>
>
>What logged for those images in your access.log ?
>Can you show us some entries ?
>
>
Hello, i'm back.

I make some tests and here is result. I can simulate problem. I ran this
commands on other machine to simulate huge trafic on proxy server

$ export http_proxy="http://10.0.0.226:3128"
$ for i in www.seznam.cz www.yahoo.com www.centrum.cz www.lupa.cz
www.bbc.cz www.cnn.com www.msn.com www.amazon.com www.root.cz www.linux.cz
$ do
$ wget -r -q $i &
$ done

On proxy server i changed settings of debuging to ALL,3

Than on different machine i tried to get www.centrum.cz pages and ...
bingo ! Second hit i got two pictures was not loaded. When i tried to
grep URL of those unloaded images (
http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg ) i got this ( time is
right ! )

Tue Jul 27 14:54:17 2004 10 10.0.0.220 TCP_HIT/200 1347 GET
http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg - NONE/- image/jpeg

Than i tried to find this URL in cache.log , found this :

2004/07/27 14:54:17| The request GET
http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg is ALLOWED, because it
matched 'localnet'
2004/07/27 14:54:17| cbdataAdd: 0x852f190
2004/07/27 14:54:17| cbdataLock: 0x822e9b0
2004/07/27 14:54:17| cbdataLock: 0x88580c0
2004/07/27 14:54:17| cbdataLock: 0x882d320
2004/07/27 14:54:17| cbdataValid: 0x822e9b0
2004/07/27 14:54:17| aclCheck: checking 'no_cache deny QUERY'
2004/07/27 14:54:17| aclMatchAclList: checking QUERY
2004/07/27 14:54:17| aclMatchAcl: checking 'acl QUERY urlpath_regex
cgi-bin \?'
2004/07/27 14:54:17| aclMatchRegex: checking '/2/vrtad/pl21_1090824345.jpg'
2004/07/27 14:54:17| aclMatchRegex: looking for 'cgi-bin'
2004/07/27 14:54:17| aclMatchRegex: looking for '\?'
2004/07/27 14:54:17| aclMatchAclList: returning 0
2004/07/27 14:54:17| cbdataUnlock: 0x822e9b0
2004/07/27 14:54:17| aclCheck: NO match found, returning 1
2004/07/27 14:54:17| aclCheckCallback: answer=1
2004/07/27 14:54:17| cbdataValid: 0x882d320
2004/07/27 14:54:17| storeGet: looking up 942A79FACE6DD2216C5C6728E42E4459
2004/07/27 14:54:17| clientProcessRequest2: default HIT
2004/07/27 14:54:17| storeLockObject: key
'942A79FACE6DD2216C5C6728E42E4459' count=1
2004/07/27 14:54:17| storeDiskdDirRefObj: referencing 0x879e930 0/32056
2004/07/27 14:54:17| new_MemObject: returning 0x8a28698
2004/07/27 14:54:17| cbdataAdd: 0x8859a90
2004/07/27 14:54:17| cbdataLock: 0x882d320
2004/07/27 14:54:17| storeClientCopy: 942A79FACE6DD2216C5C6728E42E4459,
seen 0, want 0, size 4096, cb 0x805c2b0, cbdata 0x882d320
2004/07/27 14:54:17| cbdataLock: 0x8859a90
2004/07/27 14:54:17| storeClientCopy2: 942A79FACE6DD2216C5C6728E42E4459
2004/07/27 14:54:17| storeClientCopy3: Need to open swap in file
2004/07/27 14:54:17| storeSwapInStart: called for 0 00007D38
942A79FACE6DD2216C5C6728E42E4459
2004/07/27 14:54:17| storeSwapInStart: Opening fileno 00007D38
2004/07/27 14:54:17| storeDiskdOpen: fileno 00007D38
2004/07/27 14:54:17| cbdataAdd: 0x845d720
2004/07/27 14:54:17| cbdataLock: 0x8859a90
2004/07/27 14:54:17| cbdataLock: 0x845d720
2004/07/27 14:54:17| cbdataLock: 0x845d720
2004/07/27 14:54:17| storeClientCopy3: reading from STORE
2004/07/27 14:54:17| storeDiskdRead: dirno 0, fileno 00007D38
2004/07/27 14:54:17| cbdataValid: 0x845d720
2004/07/27 14:54:17| cbdataLock: 0x8859a90
2004/07/27 14:54:17| cbdataLock: 0x845d720
2004/07/27 14:54:17| cbdataUnlock: 0x8859a90
2004/07/27 14:54:17| cbdataUnlock: 0x882d320
2004/07/27 14:54:17| cbdataUnlock: 0x88580c0
2004/07/27 14:54:17| cbdataFree: 0x852f190
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x852f190
2004/07/27 14:54:17| cbdataUnlock: 0x882d320
2004/07/27 14:54:17| cbdataUnlock: 0x88580c0
2004/07/27 14:54:17| cbdataFree: 0x852f0b0
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x852f0b0
2004/07/27 14:54:17| cbdataValid: 0x845d720
2004/07/27 14:54:17| cbdataUnlock: 0x845d720
2004/07/27 14:54:17| storeDiskdOpenDone: dirno 0, fileno 00007d38 status 4
2004/07/27 14:54:17| commSetTimeout: FD 13 timeout 900
2004/07/27 14:54:17| InvokeHandlers: CB307558C66FA4E5E5185938A618DF25
2004/07/27 14:54:17| InvokeHandlers: checking client #0
2004/07/27 14:54:17| cbdataLock: 0x882d670
2004/07/27 14:54:17| storeClientCopy2: CB307558C66FA4E5E5185938A618DF25
2004/07/27 14:54:17| storeClientCopy3: Copying from memory
2004/07/27 14:54:17| cbdataValid: 0x8859508
2004/07/27 14:54:17| cbdataLock: 0x8859508
2004/07/27 14:54:17| cbdataUnlock: 0x882d670
2004/07/27 14:54:17| httpPconnTransferDone: FD 13
2004/07/27 14:54:17| commSetTimeout: FD 13 timeout -1
2004/07/27 14:54:17| cbdataUnlock: 0x8860710
2004/07/27 14:54:17| fwdUnregister: http://i.ck.cz/f/107/36p.jpg
2004/07/27 14:54:17| cbdataUnlock: 0x8857018
2004/07/27 14:54:17| pconnNew: adding i.ck.cz.80
2004/07/27 14:54:17| commSetTimeout: FD 13 timeout 120
2004/07/27 14:54:17| pconnPush: pushed FD 13 for i.ck.cz.80
2004/07/27 14:54:17| fwdComplete: http://i.ck.cz/f/107/36p.jpg
        status 200
2004/07/27 14:54:17| fwdReforward: http://i.ck.cz/f/107/36p.jpg?
2004/07/27 14:54:17| fwdReforward: No, ENTRY_FWD_HDR_WAIT isn't set
2004/07/27 14:54:17| fwdComplete: not re-forwarding status 200
2004/07/27 14:54:17| storeComplete: 'CB307558C66FA4E5E5185938A618DF25'
2004/07/27 14:54:17| storeEntryValidLength: Checking
'CB307558C66FA4E5E5185938A618DF25'
2004/07/27 14:54:17| storeSwapMetaBuild: http://i.ck.cz/f/107/36p.jpg
2004/07/27 14:54:17| cbdataAdd: 0x845ef80
2004/07/27 14:54:17| storeCreate: Selected dir '0' for obj size '3263'
2004/07/27 14:54:17| storeDiskdCreate: fileno 000092BA
2004/07/27 14:54:17| cbdataAdd: 0x845a638
2004/07/27 14:54:17| cbdataLock: 0x845ef80
2004/07/27 14:54:17| cbdataLock: 0x845a638
2004/07/27 14:54:17| HeapKeyGen_StoreEntry_GDSF:
CB307558C66FA4E5E5185938A618DF25 size=1.000000 refcnt=1
lastref=1090932857 age=1.000004 tie=0.000000 -> 2.000004
2004/07/27 14:54:17| HeapKeyGen_StoreEntry_GDSF:
url=http://i.ck.cz/f/107/36p.jpg
2004/07/27 14:54:17| storeLockObject: key
'CB307558C66FA4E5E5185938A618DF25' count=4
2004/07/27 14:54:17| cbdataLock: 0x845a638
2004/07/27 14:54:17| storeDiskdWrite: dirno 0, fileno 000092BA
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataLock: 0x845a638
2004/07/27 14:54:17| storeSwapOut: swap_buf_len = 3173
2004/07/27 14:54:17| storeSwapOut: swapping out 3173 bytes from 0
2004/07/27 14:54:17| storeDiskdWrite: dirno 0, fileno 000092BA
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataLock: 0x845a638
2004/07/27 14:54:17| storeSwapOutFileClose: CB307558C66FA4E5E5185938A618DF25
2004/07/27 14:54:17| storeSwapOutFileClose: sio = 0x845a638
2004/07/27 14:54:17| storeDiskdClose: dirno 0, fileno 000092BA
2004/07/27 14:54:17| cbdataLock: 0x845a638
2004/07/27 14:54:17| InvokeHandlers: CB307558C66FA4E5E5185938A618DF25
2004/07/27 14:54:17| InvokeHandlers: checking client #0
2004/07/27 14:54:17| fwdStateFree: 0x8857018
2004/07/27 14:54:17| storePendingNClients: returning 1
2004/07/27 14:54:17| storeUnlockObject: key
'CB307558C66FA4E5E5185938A618DF25' count=3
2004/07/27 14:54:17| cbdataFree: 0x8857018
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x8857018
2004/07/27 14:54:17| storeUnlockObject: key
'CB307558C66FA4E5E5185938A618DF25' count=2
2004/07/27 14:54:17| cbdataFree: 0x8860710
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x8860710
2004/07/27 14:54:17| cbdataValid: 0x845d720
2004/07/27 14:54:17| cbdataUnlock: 0x845d720
2004/07/27 14:54:17| cbdataValid: 0x8859a90
2004/07/27 14:54:17| cbdataUnlock: 0x8859a90
2004/07/27 14:54:17| storeDiskdReadDone: dirno 0, fileno 00007d38 status
1436
2004/07/27 14:54:17| storeClientReadHeader: len 1436
2004/07/27 14:54:17| storeClientReadHeader: copying 1325 bytes of body
2004/07/27 14:54:17| cbdataValid: 0x882d320
2004/07/27 14:54:17| clientCacheHit:
http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg, 1325 bytes
2004/07/27 14:54:17| refreshCheck:
'http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg'
2004/07/27 14:54:17| FRESH: expires 1091713343 >= check_time 1090932857
2004/07/27 14:54:17| Staleness = -1
2004/07/27 14:54:17| refreshCheck: Matched '<none> 0 20% 259200'
2004/07/27 14:54:17| refreshCheck: age = 83517
2004/07/27 14:54:17| check_time: Tue, 27 Jul 2004 12:54:17 GMT
2004/07/27 14:54:17| entry->timestamp: Mon, 26 Jul 2004
13:42:20 GMT
2004/07/27 14:54:17| clientSendMoreData: Appending 1056 bytes after 269
bytes of headers
2004/07/27 14:54:17| cbdataLock: 0x882d320
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataUnlock: 0x845a638
2004/07/27 14:54:17| storeDiskdOpenDone: dirno 0, fileno 000092ba status 5
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataUnlock: 0x845a638
2004/07/27 14:54:17| storeDiskdWriteDone: dirno 0, fileno 000092ba status 90
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataUnlock: 0x845a638
2004/07/27 14:54:17| storeDiskdWriteDone: dirno 0, fileno 000092ba
status 3173
2004/07/27 14:54:17| cbdataValid: 0x845a638
2004/07/27 14:54:17| cbdataUnlock: 0x845a638
2004/07/27 14:54:17| storeDiskdCloseDone: dirno 0, fileno 000092ba status 0
2004/07/27 14:54:17| cbdataValid: 0x845ef80
2004/07/27 14:54:17| storeUfsIOCallback: errflag=0
2004/07/27 14:54:17| cbdataUnlock: 0x845ef80
2004/07/27 14:54:17| cbdataFree: 0x845ef80
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x845ef80
2004/07/27 14:54:17| storeSwapOutFileClosed: SwapOut complete:
'http://i.ck.cz/f/107/36p.jpg' to 0,000092BA
2004/07/27 14:54:17| storeDirSwapLog: SWAP_LOG_ADD
CB307558C66FA4E5E5185938A618DF25 0 000092BA
2004/07/27 14:54:17| diskHandleWrite: FD 8
2004/07/27 14:54:17| diskHandleWrite: FD 8 writing 48 bytes
2004/07/27 14:54:17| diskHandleWrite: FD 8 len = 48
2004/07/27 14:54:17| storeSwapOutFileClosed: store_swapout.c:309
2004/07/27 14:54:17| cbdataUnlock: 0x845a638
2004/07/27 14:54:17| storeUnlockObject: key
'CB307558C66FA4E5E5185938A618DF25' count=1
2004/07/27 14:54:17| cbdataFree: 0x845a638
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x845a638
2004/07/27 14:54:17| cbdataValid: 0x882d320
2004/07/27 14:54:17| clientKeepaliveNextRequest: FD 10
2004/07/27 14:54:17| httpRequestFree:
http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg
2004/07/27 14:54:17| storeUnregister: called for
'942A79FACE6DD2216C5C6728E42E4459'
2004/07/27 14:54:17| storeDiskdClose: dirno 0, fileno 00007D38
2004/07/27 14:54:17| cbdataLock: 0x845d720
2004/07/27 14:54:17| cbdataUnlock: 0x845d720
2004/07/27 14:54:17| cbdataUnlock: 0x882d320
2004/07/27 14:54:17| cbdataFree: 0x8859a90
2004/07/27 14:54:17| cbdataFree: 0x8859a90 has 1 locks, not freeing
2004/07/27 14:54:17| storePendingNClients: returning 0
2004/07/27 14:54:17| storeUnlockObject: key
'942A79FACE6DD2216C5C6728E42E4459' count=0
2004/07/27 14:54:17| storePendingNClients: returning 0
2004/07/27 14:54:17| storePurgeMem: Freeing memory-copy of
942A79FACE6DD2216C5C6728E42E4459
2004/07/27 14:54:17| ctx: enter level 0:
'http://img.centrum.cz/2/vrtad/pl21_1090824345.jpg'
2004/07/27 14:54:17| destroy_MemObject: destroying 0x8a28698
2004/07/27 14:54:17| ctx: exit level 0
2004/07/27 14:54:17| storeDiskdDirUnrefObj: referencing 0x879e930 0/32056
2004/07/27 14:54:17| HeapKeyGen_StoreEntry_GDSF:
942A79FACE6DD2216C5C6728E42E4459 size=1436.000000 refcnt=2
lastref=1090932857age=1.000004 tie=0.000000 -> 1.001396
2004/07/27 14:54:17| cbdataFree: 0x882d320
2004/07/27 14:54:17| cbdataFree: 0x882d320 has 1 locks, not freeing
2004/07/27 14:54:17| commSetTimeout: FD 10 timeout 120
2004/07/27 14:54:17| clientReadRequest: FD 10: no data to process ((11)
Resource temporarily unavailable)
2004/07/27 14:54:17| cbdataUnlock: 0x882d320
2004/07/27 14:54:17| cbdataReallyFree: Freeing 0x882d320
2004/07/27 14:54:17| cbdataValid: 0x8859508

Any idea ?

Michal
Received on Tue Jul 27 2004 - 14:40:08 MDT

This archive was generated by hypermail pre-2.1.9 : Sun Aug 01 2004 - 12:00:02 MDT