[asterisk-dev] [Code Review] Improve event API cache performance
Russell Bryant
russell at digium.com
Wed Mar 25 15:30:45 CDT 2009
> On 2009-03-24 22:14:43, Eliel Sardañons wrote:
> >
Thanks for the review!
> On 2009-03-24 22:14:43, Eliel Sardañons wrote:
> > /branches/1.6.1/main/event.c, lines 145-153
> > <http://reviewboard.digium.com/r/205/diff/2/?file=3678#file3678line145>
> >
> > I always try to avoid writing prototypes for the static functions, I try to order the code to avoid such things (They look like an ugly workaround for compilers). But if there is no way to avoid this situation I don't recommend writing the documentation there.
> >
> > What if the static function doesn't have a prototype?
> > We will have part of the documentation of the code in prototypes at the begining and part of the documentation in the implementation.
Okay, I'll move the documentation to the implementation. I didn't have a strong preference for where to put it in the first place.
> On 2009-03-24 22:14:43, Eliel Sardañons wrote:
> > /branches/1.6.1/main/event.c, line 1272
> > <http://reviewboard.digium.com/r/205/diff/2/?file=3678#file3678line1272>
> >
> > I think static functions should be called without ast_* prefix. So when we read ast_* we know is part of an API. If we start calling internal functions in this way we won't have the name of the function as a parameter of what type it is..
> >
> > As an example, when xmldoc was written, We have used ast_xmldoc_* for every function that was part of the API and xmldoc_* for the internal (static) functions. Using this naming convention we avoid confusing the developer when reading the code.
The fact that the function is declared with static linkage makes it clear that the function isn't a public API call. :-)
In this case, I think the names as they stand are more expressive, in that the data type that they operate on is an "ast_event".
> On 2009-03-24 22:14:43, Eliel Sardañons wrote:
> > /branches/1.6.1/res/ais/evt.c, lines 349-354
> > <http://reviewboard.digium.com/r/205/diff/2/?file=3679#file3679line349>
> >
> > I think if you move this code before allocating publish_event you will avoid calling ast_free()
Done!
> On 2009-03-24 22:14:43, Eliel Sardañons wrote:
> > /branches/1.6.1/res/ais/evt.c, lines 415-420
> > <http://reviewboard.digium.com/r/205/diff/2/?file=3679#file3679line415>
> >
> > The same here, just to avoid the ast_free().
Done!
- Russell
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
http://reviewboard.digium.com/r/205/#review625
-----------------------------------------------------------
On 2009-03-24 16:18:49, Russell Bryant wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> http://reviewboard.digium.com/r/205/
> -----------------------------------------------------------
>
> (Updated 2009-03-24 16:18:49)
>
>
> Review request for Asterisk Developers.
>
>
> Summary
> -------
>
> I have learned a lot since I originally wrote event.c a couple of years ago. Lately, I have been reflecting on some of the performance implications of some of the design decisions that I made. Then, this past Friday, I did some load testing for unrelated reasons and found that the conversion of device state handling to use the event API in 1.6.1 introduced a significant performance hit for the test that I was doing.
>
> Specifically, the test I was doing at the time was sending many thousands of IAX2 registrations at an Asterisk box. Asterisk 1.6.0 could handle it just fine. 1.6.1 choked. The reason was the performance of the event API cache with handling that many entries in the cache. In 1.6.0, when the devicestate code needed to find out the state of an IAX2 device, it would call into chan_iax2, which could determine the state by looking up the peer in a hash table. The performance gained by using the hash table was lost in 1.6.1, mostly due to the way the cache was implemented.
>
> Here is a summary of the changes that have been made, in order of both invasiveness and performance impact, from smallest to largest.
>
> 1) Asterisk 1.6.1 introduces some additional logic to be able to handle distributed device state. This functionality comes at a cost. One relatively minor change in this patch is that the extra processing required for distributed device state is now completely bypassed if it's not needed.
>
> 2) One of the things that I noticed when profiling this code was that a _lot_ of time was spent doing string comparisons. I changed the way strings are represented in an event to include a hash value at the front. So, before doing a string comparison, we do an integer comparison on the hash.
>
> 3) Finally, the code that handles the event cache has been re-written. I tried to do this in a such a way that it had minimal impact on the API. I did have to change one API call, though - ast_event_queue_and_cache(). However, the way it works now is nicer, IMO. Each type of event that can be cached (MWI, device state) has its own hash table and rules for hashing and comparing objects. This by far made the biggest impact on performance.
>
>
> To be clear, I am proposing that these changes be merged into 1.6.1, 1.6.2, and trunk. I consider the performance issues here a regression.
>
>
> This addresses bug 14738.
> http://bugs.digium.com/view.php?id=14738
>
>
> Diffs
> -----
>
> /branches/1.6.1/apps/app_voicemail.c 184036
> /branches/1.6.1/channels/chan_dahdi.c 184036
> /branches/1.6.1/channels/chan_iax2.c 184036
> /branches/1.6.1/channels/chan_mgcp.c 184036
> /branches/1.6.1/channels/chan_sip.c 184036
> /branches/1.6.1/channels/chan_skinny.c 184036
> /branches/1.6.1/channels/chan_unistim.c 184036
> /branches/1.6.1/include/asterisk/_private.h 184036
> /branches/1.6.1/include/asterisk/devicestate.h 184036
> /branches/1.6.1/include/asterisk/event.h 184036
> /branches/1.6.1/include/asterisk/strings.h 184036
> /branches/1.6.1/main/asterisk.c 184036
> /branches/1.6.1/main/devicestate.c 184036
> /branches/1.6.1/main/event.c 184036
> /branches/1.6.1/res/ais/evt.c 184036
>
> Diff: http://reviewboard.digium.com/r/205/diff
>
>
> Testing
> -------
>
> The first set of tests I did were functionality tests.
>
> For device state, I set up some hints and verified that when I changed the state of the associated device, the hint would change state. I ran this test with and without the distributed devstate processing code turned on.
>
> For MWI, I set up a mailbox, left a message, and verified that a NOTIFY was sent by chan_sip to my phone assigned to that mailbox.
>
>
> The second set of tests was performance. The box I was using for this has an Intel Core 2 Duo CPU @ 2.33 GHz. It has 2 GB of RAM. When I mention the CPU usage percentage for the Asterisk process, it is out of 200%, since this is a dual core box.
>
> The test I ran is that I ran a tool which sent 12000 IAX2 registrations to Asterisk, evenly spaced out over 1 minute (one every 5 ms). IAX2 dynamic realtime was enabled, with caching turned on.
>
> The oprofile results include all functions that were taking up 0.5% of Asterisk's CPU time or higher.
>
> ----------------------------------------
>
> Version: Asterisk SVN-branch-1.6.0-r183915
>
> Average CPU usage of asterisk: 3% to 5%
>
> oprofile results:
>
> samples % image name app name symbol name
> 26088 44.3357 asterisk asterisk ast_sched_add_variable
> 8226 13.9798 chan_iax2.so chan_iax2.so network_thread
> 4731 8.0402 asterisk asterisk _ast_sched_del
> 4262 7.2431 chan_iax2.so chan_iax2.so __find_callno
> 3785 6.4325 chan_iax2.so chan_iax2.so socket_process
> 1842 3.1304 chan_iax2.so chan_iax2.so pvt_destructor
> 1652 2.8075 [vdso] (tgid:24198 range:0xb7f64000-0xb7f65000) asterisk (no symbols)
> 617 1.0486 asterisk asterisk cd_cb
> 523 0.8888 asterisk asterisk bt_broot
> 339 0.5761 chan_iax2.so chan_iax2.so build_peer
> 337 0.5727 res_config_odbc.so res_config_odbc.so realtime_odbc
> 329 0.5591 chan_iax2.so chan_iax2.so register_verify
>
> ----------------------------------------
>
> Version: Asterisk SVN-branch-1.6.1-r183916
>
> The CPU usage by Asterisk increased steadily throughout this test and peaked at about 140%.
>
> oprofile results:
>
> samples % image name app name symbol name
> 317713 49.4110 asterisk asterisk match_ie_val
> 75913 11.8061 asterisk asterisk ast_event_queue_and_cache
> 58659 9.1227 asterisk asterisk schedule
> 51157 7.9560 asterisk asterisk ast_event_get_cached
> 44859 6.9765 asterisk asterisk ast_event_dump_cache
> 31661 4.9240 chan_iax2.so chan_iax2.so network_thread
> 15696 2.4411 asterisk asterisk .plt
> 8601 1.3376 chan_iax2.so chan_iax2.so socket_process
> 7524 1.1701 chan_iax2.so chan_iax2.so __find_callno
> 6401 0.9955 chan_iax2.so chan_iax2.so pvt_destructor
> 4282 0.6659 chan_iax2.so chan_iax2.so __attempt_transmit
>
> ----------------------------------------
>
> Version: Asterisk SVN-russell-event_performance-r183985-/branches/1.6.1
>
> Average CPU usage of asterisk: 3% to 5%
>
> oprofile results:
>
> samples % image name app name symbol name
> 42952 44.9665 asterisk asterisk schedule
> 18687 19.5634 chan_iax2.so chan_iax2.so network_thread
> 6553 6.8603 chan_iax2.so chan_iax2.so __find_callno
> 6444 6.7462 chan_iax2.so chan_iax2.so socket_process
> 3882 4.0641 chan_iax2.so chan_iax2.so pvt_destructor
> 2261 2.3670 [vdso] (tgid:22953 range:0xb7f99000-0xb7f9a000) asterisk (no symbols)
> 1658 1.7358 chan_iax2.so chan_iax2.so __attempt_transmit
> 977 1.0228 asterisk asterisk __ao2_callback
> 682 0.7140 asterisk asterisk __ao2_ref
> 549 0.5747 asterisk asterisk bt_broot
>
> ----------------------------------------
>
> Analysis of results:
>
> As you can see, the current code in Asterisk 1.6.1 has some performance issues, and the clear culprit is the event code. After this set of changes, the event code drops off of th profiling map, and we're back to what we would expect to be the biggest consumers of CPU time during this test.
>
> Additional Commentary:
>
> The scheduler is the next big offender in CPU consumption here. Luckily, this code has been heavily modified in trunk and 1.6.2 (http://reviewboard.digium.com/r/160/), so once these changes make their way around, it will be interesting to do this test again in 1.6.2. After the scheduler, the IAX2 network_thread is the next biggest consumer of CPU. When looking closer at that code, the offending piece of code is actually the handling of the IAX2 frame cache. There are some very easy changes we could make to significantly reduce the CPU consumption there, but I'll save that for another day. :-)
>
>
> Thanks,
>
> Russell
>
>
More information about the asterisk-dev
mailing list