squid-3 profiling

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

squid-3 profiling

Adrian Chadd
Doing my usual run of squid checking:

  471       0.9703  squid                    xxfree
  486       1.0012  squid                    HttpHeader::clean()
  795       1.6377  squid                    ACLChecklist::fastCheck()
  1250      2.5750  squid                    xmalloc
  1392      2.8676  squid                    xstrncpy
  3495      7.1998  squid                    MemBuf::append(char const*, int)
  4697      9.6760  squid                    SqString::init(char const*)
  7706     15.8746  squid                    SqString::limitInit(char const*, unsigned int)
  7889     16.2516  squid                    SqString::initBuf(unsigned int)
  16160    33.2901  squid                    SqString::clear()
48543    10.8989  squid                    xprof_start
  48543    100.000  squid                    xprof_start [self]

.. lots of CPU time being spent in SqSquid.

to reproduce, looping this:

ab -c 1024 -n 100000 http://192.168.1.8:3128/squid-internal-static/icons/anthony-box.gif



Adrian

Reply | Threaded
Open this post in threaded view
|

Re: squid-3 profiling

Adrian Chadd

.. hm, the global info:                                                                                                                
                                                                                                                                       
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                                                                                  
218234   32.4504  no-vmlinux               (no symbols)                                                                                
73002    10.8551  squid                    xprof_start                                                                                  
54581     8.1159  squid                    xprof_stop                                                                                  
45273     6.7319  libc-2.3.6.so            memset                                                                                      
19949     2.9663  libc-2.3.6.so            memcpy                                                                                      
14566     2.1659  squid                    SqString::init(char const*)                                                                  
9664      1.4370  squid                    MemPool::get()                                                                              
8275      1.2305  libc-2.3.6.so            vfprintf                                                                                    
5967      0.8873  squid                    headersEnd                                                                                  
                                                                                                                                       
.. still quite high..                                                                                                                  
                                                                                                                                       
                                                                                                                                       
                                                                                                                                       
                                                                                                                                       
Adrian                                                                                                                                  
                                                                                                                                       

Reply | Threaded
Open this post in threaded view
|

Re: squid-3 profiling

Adrian Chadd
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