Some more Lusca Profiling..

More Lusca profiling of a simple test workload:

samples % image name symbol name

234266 6.7052 libc-2.3.6.so _int_malloc

138031 3.9507 libc-2.3.6.so vfprintf

111831 3.2008 libc-2.3.6.so calloc

104393 2.9879 libc-2.3.6.so malloc_consolidate

98984 2.8331 libc-2.3.6.so memcpy

91783 2.6270 libc-2.3.6.so _int_free

72578 2.0773 libc-2.3.6.so memset

69068 1.9769 libc-2.3.6.so free

50473 1.4446 squid clientTryParseRequest

50064 1.4329 squid memPoolAlloc

45211 1.2940 libc-2.3.6.so re_search_internal

40469 1.1583 squid httpRequestFree

39227 1.1228 squid statHistBin

38916 1.1139 squid comm_select

36974 1.0583 libc-2.3.6.so _IO_default_xsputn

36260 1.0378 squid memPoolFree

.. CPU is still taken up in the standard areas: memory allocation, stdio, and memcpy.

memcpy() I can't tackle right now. malloc() and friends I can tackle, but it may cause strange bugs and I'm not willing to commit anything which upsets stability too much right now. But vfprintf() is fun.

51285 22.7881 libc-2.3.6.so vsprintf

168714 74.9667 libc-2.3.6.so vsnprintf

156434 100.000 libc-2.3.6.so vfprintf

.. so most of the CPU is vsnprintf().

2549 1.0775 squid httpHeaderPutStrf

78253 33.0790 squid memBufVPrintf

153322 64.8121 libc-2.3.6.so snprintf

13601 100.000 libc-2.3.6.so vsnprintf

.. memBufVPrintf():

33231 36.8652 httpHeaderPutStrf

55577 61.6549 packerPrintf

7225 100.000 memBufVPrintf

.. snprintf():

5021 2.8271 squid clientAccessCheckDone

31897 17.9597 squid clientSendHeaders

53339 30.0327 squid xitoa

85548 48.1681 squid urlCanonical

7870 100.000 libc-2.3.6.so snprintf

.. so it's likely that eliminating the random calls through the printf() code to do "stuff" like assembling the URL and request/reply strings will shave off about 4% of this workload. But the biggest issue right now is the stupidly large amount of CPU being used in the memory allocation routines.

But the annoying one is memcpy():

10557 7.3665 squid httpAccept

20779 14.4992 squid stringDup

37010 25.8250 squid httpHeaderEntryPackInto

47882 33.4113 squid connStateFree

143177 100.000 libc-2.3.6.so memcpy

.. there's no memcpy() call in connStateFree. Which means I need to go hunting to figure out what's going on. Grr.

Async IO changes to Lusca

I've just cut out all of the mempool'ed buffers from Lusca and converted said buffers to just use xmalloc()/xfree(). Since memory pools in Lusca now don't "cache" memory - ie, they're just for statistics keeping - the only extra thing said memory pooled buffers were doing was providing NUL'ed memory for disk buffers.

So now, for the "high hit rate, large object" workload which the mirror nodes are currently doing, the top CPU user is memcpy() - via aioCheckCallbacks(). At least it wasn't -also- memset() as well.

That memcpy() is taking ~ 17% of the total userland CPU used by Lusca in this particular workload.

I have this nagging feeling that said memcpy() is the one done in storeAufsReadDone(), where the AUFS code copies the result from the async read into the supplied buffer. It does this because its entirely possible the caller has disappeared between the time the storage manager read was scheduled and the time the filesystem read() was scheduled.

Because the Squid codebase doesn't explicitly cancel or wait for completion of async events - and instead relies on this "locking" and "invalidation" semantics provided by the callback data scheme - trying to pass buffers (and structs in general) into threads is pretty much plainly impossible to do correctly.

In any case, the performance should now be noticably better.

(obnote: I tried explaining this to the rest of the core Squid developers last year and somehow I don't quite think I convinced them that the current approach, with or without the AsyncCallback scheme in Squid-3, is going to work without significant re-engineering of the source tree. Alas..)