Re: squid-3 profiling

On Thu, May 24, 2007, Adrian Chadd wrote:
>
> .. hm, the global info:

.. and just now, after fixing some local connectivity issues at home which
prevented the hammering actually .. hammering. I've also removed the kernel
profiling time just so the user space percentages are very visible.

CPU: P4 / Xeon, speed 2656.13 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 50000
samples % image name symbol name
143182 21.0369 libc-2.3.6.so memset
37499 5.5095 libc-2.3.6.so memcpy
27073 3.9777 squid SqString::init(char const*)
17745 2.6072 libc-2.3.6.so vfprintf
13905 2.0430 squid MemPool::get()
10410 1.5295 squid headersEnd
9166 1.3467 squid MemPool::push(void*)
8668 1.2735 libc-2.3.6.so _IO_vfscanf
8124 1.1936 libc-2.3.6.so _IO_default_xsputn
7896 1.1601 squid statHistBin(_StatHist const*, double)
7224 1.0614 libc-2.3.6.so strtok
6262 0.9200 libc-2.3.6.so _int_malloc

The memset time:

samples % image name symbol name
-------------------------------------------------------------------------------
  55 0.0156 libc-2.3.6.so strftime
  269 0.0762 squid storeKeyPublicByRequestMethod
  717 0.2030 squid _comm_close(int, char const*, int)
  2285 0.6470 squid internalRemoteUri
  2620 0.7419 libc-2.3.6.so vsscanf
  4677 1.3243 squid HttpRequest::HttpRequest(_method_t, protocol_t, char const*)
  5094 1.4424 squid ClientHttpRequest::ClientHttpRequest(RefCount<ConnStateData>)
  26074 7.3830 squid ClientSocketContextNew(ClientHttpRequest*)
  311371 88.1666 squid MemPool::deallocate(void*)
352527 21.1205 libc-2.3.6.so memset
  352527 100.000 libc-2.3.6.so memset [self]

And deallocate leads to this:

  3952 1.1014 squid cbdataInternalUnlock(void const*)
  5031 1.4021 squid HttpRequest::~HttpRequest()
  11187 3.1178 squid HttpHeader::clean()
  21442 5.9758 squid MemBuf::clean()
  23860 6.6497 squid memFree2K(void*)
  69047 19.2433 squid SqString::clear()
  81290 22.6554 squid ConnStateData::In::~In()
  136442 38.0261 squid cbdataInternalFree(void*)
13743 0.8234 squid MemImplementingAllocator::free(void*)
  341774 95.2447 squid MemPool::deallocate(void*)
  13743 3.8299 squid MemImplementingAllocator::free(void*) [self]
  3321 0.9255 squid MemPool::push(void*)

.. definitely should look into trying to sort out memory allocation overhead
and what can/can't be bzero'ed post squid-3 release. Being able to get back 20%
of the CPU runtime from memset would be very very shiny.

Adrian
Received on Thu May 24 2007 - 08:53:42 MDT