[Home]

Summary:ASTERISK-06613: [patch] new command: show profile (and update to show threads)
Reporter:Luigi Rizzo (rizzo)Labels:
Date Opened:2006-03-24 09:33:31.000-0600Date Closed:2006-04-13 07:50:33
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) show-profile.diff
( 1) show-profile2.diff
Description:The attached patch implements two new commands extremely useful for
profiling/development.
- "show threads", already discussed in ASTERISK-5895, and here there is just an
 update of the code that compiles on OSX (thanks to oej);
 This one is basically ready for production.

- "show profile" introduces support to dynamically register profile
 counters that can be used to count events, timer ticks, TSC ticks
 or other info of interest.
 This one only needs a few minor tweaks but otherwise is also
 very little intrusive and almost ready for production
 (modulo possible name changes for the functions, selecting
 the proper header file for "rdtsc()" or replacement functions
 on different OS), and maybe a little bit of protection to avoid
 races between allocation of counters and use.)

 As an example of use, if you compile
 asterisk with -DMTX_PROFILE, the code will register TSC counters
 around ast_mtx_lock() calls on each file, giving you a chance to see
 what goes on. E.g. an example of output on my system is below,
 with the columns being the counter ID, the "scale factor", the
 number of events, the total number of (scaled) TSC ticks, the
 average number of (scaled) TSC ticks, and the event name.

The usage is as simple as calling
   static int counter_id = ast_add_profile("my name", scale_factor);
to create a new counter, and then wrapping interesting sections of
code with
         ast_mark(counter_id, 1); /* start measuring ticks */
         <the code to measure>
         ast_mark(counter_id, 0); /* stop and accumulate ticks */
to measure TSC ticks, or just
         ast_profile(counter_id, delta)
to add delta to a counter.
Then, "show profile" will show all counters, "show profile N M"
will show counters between N and M, and "show profile xyz" will
show all counter whose name contains "xyz".

NOTE - this code at the moment only works on i386 which have the rdtsc(),
and needs to #include the appropriate header file on Linux.
Other than that, it is very little intrusive and in my opinion
is extremely useful to debug performance issues, especially because
one can keep it enabled even on a production machine and so we can
easily verify our suspects that this or that piece of code does
something bad (e.g. see chan_iax2.c below calling mtx_lock 200 times
per second even without any IAX device connected, or the basic ast_lock()
operations costing between 1000 and 2000 ticks (this is a 2GHz machine)
on this particular system, which means that using inline functions
to implement them is completely negligible in terms of performance.


****** ADDITIONAL INFORMATION ******

*CLI> show profile chan
profile values (185, allocated 190)
-------------------
   16: [       0]          0            0            0 mtx_lock_chanvars.c
   37: [       0]        223       210816          945 mtx_lock_channel.c
   60: [       0]          2         5216         2608 mtx_lock_chan_agent.c
   61: [       0]          0            0            0 mtx_lock_chan_features.c
   64: [       0]     113991    201392768         1766 mtx_lock_chan_iax2.c
   65: [       0]          0            0            0 mtx_lock_chan_local.c
   66: [       0]       4515      7337320         1625 mtx_lock_chan_mgcp.c
   67: [       0]          0            0            0 mtx_lock_chan_oss.c
   68: [       0]      14059     18214552         1295 mtx_lock_chan_sip.c
   69: [       0]       1129      3984444         3529 mtx_lock_chan_skinny.c
   70: [       0]       2257      3636672         1611 mtx_lock_chan_zap.c
   76: [       0]          0            0            0 mtx_lock_app_chanisavail.c
   77: [       0]          0            0            0 mtx_lock_app_chanspy.c
   85: [       0]          0            0            0 mtx_lock_app_dumpchan.c
  167: [       0]          0            0            0 mtx_lock_func_channel.c
Comments:By: Russell Bryant (russell) 2006-03-28 19:39:34.000-0600

I tried to build this on linux.  First, I had to add <inttypes.h> to include/asterisk.h to get uint64_t.

I grep'd through /usr/include to try to find what I needed to include for rdtsc() and found only the following definition:

#define rdtsc(low,high) \
    __asm__ __volatile__("rdtsc" : "=a" (low), "=d" (high))

This is the same one someone referred to on the asterisk-dev mailing list, in asm/msr.h.  The definition is actually found in asm-i486/msr.h.  However, the exact same definition exists in asm-x86_64/msr.h as well.  I really don't know what any of this means, but it's obviously not directly compatible with what you are using, since this macro takes two arguments.
By: Luigi Rizzo (rizzo) 2006-03-29 14:52:14.000-0600

updated the new patch that works with linux (i586 and above).
the 'show threads' command is not compatible with DEBUG_THREADS.
By: Luigi Rizzo (rizzo) 2006-04-12 15:43:15

committed to SVN 19544-19545