wireshark-dev February 2012 archive
Main Archive Page > Month Archives  > wireshark-dev archives
wireshark-dev: Re: [Wireshark-dev] slow sip voip flow for large

Re: [Wireshark-dev] slow sip voip flow for large captures

From: Anders Broman <a.broman_at_nospam>
Date: Sat Feb 04 2012 - 11:43:24 GMT
To: Developer support list for Wireshark <wireshark-dev@wireshark.org>

Please add your patch as it is so we can have a look at it.
Regards
Anders

Cristian Constantin skrev 2012-02-03 15:19:
> On Fri, Feb 3, 2012 at 3:02 PM, Anders Broman
> <anders.broman@ericsson.com> wrote:
>> Hi,
>> Forget about my comment about the sip hash table.
>>
>> Please add the patch(es) to bugzilla, if possible break it up to something we can commit straight away and stuff that needs to be worked on to work
>> For all taps as that can't be committed until it's done for all tap. Two bug reports?
> cristian: but this means really 2 different patches which I have to
> test separately, right?
> otoh:
>
> * the append operation on lists with over 10k elements is really cpu
> intensive (imo it
> does NOT actually make sense to iterate over 10k pointers just to get
> to the end of
> some linked list)
>
> * if one does NOT apply that patch (step 3),
> one cannot actually see the actual improvement.
>
> I will open one bug report and post the results/patches there.
>
>> Regards
>> Anders
>> -----Original Message-----
>> From: wireshark-dev-bounces@wireshark.org [mailto:wireshark-dev-bounces@wireshark.org] On Behalf Of Cristian Constantin
>> Sent: den 3 februari 2012 14:54
>> To: Developer support list for Wireshark
>> Subject: Re: [Wireshark-dev] slow sip voip flow for large captures
>>
>> On Fri, Feb 3, 2012 at 1:44 PM, Anders Broman<anders.broman@ericsson.com> wrote:
>>> Hi,
>>> Please put the patches in bugzilla, if possible split them in two
>>> parts one that's ok for all types(Step 2,3,4?) of calls and one which Implements the stuff for SIP but not for the other call types.
>> cristian: step 1 is dealing only with sip packets.
>>
>> step 2's improvement could be used all voip taps.
>>
>> step 3 is tricky since the lists have to be reversed (trivial operation for double linked lists; glib offers an api for this). however currently the prepend and reversing is performed only for sip calls. extra-work to be done here for other voip taps to use more efficient linked lists operations (prepend and eventl. reverse). also, this step modifies the callback for the button "Flow" of the "VoIP" window - on_graph_bt_clicked() - to reverse (once) the lists:
>>
>> * voip_calls_get_info()->callsinfo_list
>> * voip_calls_get_info()->graph_analysis->list
>>
>> so, in order to work correctly with the other taps, they have to use the "prepend" operation/convention as well.
>>
>> step 4 could be used for all taps
>>
>> let me see what I can do about the patches.
>>
>>> I think the SIP dissector keeps a table over the calls as well could that table be shared?
>> cristian: I do not know which table is that.
>>
>>> Regards
>>> Anders
>>>
>>> -----Original Message-----
>>> From: wireshark-dev-bounces@wireshark.org
>>> [mailto:wireshark-dev-bounces@wireshark.org] On Behalf Of Cristian
>>> Constantin
>>> Sent: den 3 februari 2012 13:01
>>> To: Developer support list for Wireshark
>>> Subject: [Wireshark-dev] slow sip voip flow for large captures
>>>
>>> hi!
>>>
>>> wireshark can draw call flows for sip voip calls (accessible through the menu Telephony/VoIP Calls).
>>>
>>> however, when the capture is large, containing tens of thousands of sip voip calls, wireshark becomes very slow at producing the list of calls and the call flows.
>>>
>>> here are my experiences with a capture file of 500 MB containing approx. 40K calls on a debian machine having:
>>>
>>> 4xAMD Phenom(tm) II X4 940 Processor
>>> 4GB RAM
>>>
>>> with the svn stock it takes about 10 hours to do it; the report of the profiling done with oprofile looks like this:
>>>
>>> CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted
>>> CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
>>> mask of 0x00 (No unit mask) count 750000 samples % image name
>>> app name symbol name 8146520 55.2011 lt-wireshark
>>> lt-wireshark
>>> append_to_frame_graph.isra.7
>>> 3698478 25.0610 libglib-2.0.so.0.2800.6 lt-wireshark
>>> g_list_last
>>> 1566933 10.6176 lt-wireshark lt-wireshark
>>> SIPcalls_packet
>>> 1162377 7.8763 libc-2.13.so lt-wireshark
>>> __strcmp_sse2
>>> 8734 0.0592 libwireshark.so.0.0.1 lt-wireshark
>>> serv_name_lookup 8130 0.0551 libwireshark.so.0.0.1
>>> lt-wireshark dissect_sip_common
>>> 6504 0.0441 libwireshark.so.0.0.1 lt-wireshark
>>> format_text
>>> 5749 0.0390 libwireshark.so.0.0.1 lt-wireshark
>>> tap_push_tapped_queue
>>> 4753 0.0322 libglib-2.0.so.0.2800.6 lt-wireshark
>>> g_unichar_isprint
>>> 4627 0.0314 libglib-2.0.so.0.2800.6 lt-wireshark
>>> g_hash_table_lookup
>>> 3699 0.0251 libwireshark.so.0.0.1 lt-wireshark
>>> guint8_pbrk
>>>
>>> step 1
>>> ------
>>>
>>> by changing SIPcalls_packet() to use a hash table for the lookup of the calls (on sip call-id) the runtime decreases to an (estimated) 3-4 hours.
>>> SIPcalls_packet()'s cpu usage has decreased from 10.61% to 0.0115%
>>> (1000 times faster)
>>>
>>> CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted
>>> CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
>>> mask of 0x00 (No unit mask) count 750000 samples % image name
>>> symbol name
>>> 411305 69.4523 lt-wireshark
>>> append_to_frame_graph.isra.7
>>> 171549 28.9675 libglib-2.0.so.0.2800.6 g_list_last
>>> 475 0.0802 libwireshark.so.0.0.1 serv_name_lookup
>>> 439 0.0741 libwireshark.so.0.0.1 dissect_sip_common
>>> 375 0.0633 libwireshark.so.0.0.1 format_text 360
>>> 0.0608 libwireshark.so.0.0.1 tap_push_tapped_queue
>>> 303 0.0512 libglib-2.0.so.0.2800.6 g_hash_table_lookup
>>> 283 0.0478 libglib-2.0.so.0.2800.6 g_unichar_isprint
>>> 202 0.0341 libwireshark.so.0.0.1 guint8_pbrk
>>> 172 0.0290 libwireshark.so.0.0.1 proto_tree_add_item
>>> 149 0.0252 libwireshark.so.0.0.1 compute_offset_length
>>> 143 0.0241 libc-2.13.so __memcpy_sse2
>>> 141 0.0238 libwireshark.so.0.0.1 call_dissector_work
>>> 141 0.0238 libwireshark.so.0.0.1 emem_free_all
>>> 115 0.0194 libc-2.13.so __strncmp_sse2
>>> 112 0.0189 libc-2.13.so vfprintf
>>> 105 0.0177 libwireshark.so.0.0.1 proto_item_add_subtree
>>> 104 0.0176 libglib-2.0.so.0.2800.6
>>> g_slice_free_chain_with_offset
>>> 99 0.0167 libwireshark.so.0.0.1 dissect_sdp
>>> 91 0.0154 libc-2.13.so free
>>> 91 0.0154 libwireshark.so.0.0.1 dissect_ip 90 0.0152
>>> libwireshark.so.0.0.1 proto_field_is_referenced 90 0.0152
>>> libwireshark.so.0.0.1 tvb_length_remaining 90 0.0152
>>> lt-wireshark process_specified_packets.constprop.10
>>> 89 0.0150 libglib-2.0.so.0.2800.6 g_slice_free1
>>> 89 0.0150 libwiretap.so.0.0.1 file_seek
>>> 88 0.0149 libwireshark.so.0.0.1 dissect
>>> 86 0.0145 libwireshark.so.0.0.1 dissect_frame
>>> 82 0.0138 libwireshark.so.0.0.1 proto_is_protocol_enabled
>>> 79 0.0133 libc-2.13.so __strcmp_sse2
>>> 79 0.0133 libc-2.13.so _int_malloc
>>> 78 0.0132 libglib-2.0.so.0.2800.6 g_slice_alloc
>>> 75 0.0127 libpthread-2.13.so pthread_getspecific
>>> 73 0.0123 libwireshark.so.0.0.1 tvb_find_guint8
>>> 72 0.0122 libc-2.13.so malloc
>>> 71 0.0120 libwireshark.so.0.0.1 fast_ensure_contiguous
>>> 68 0.0115 lt-wireshark SIPcalls_packet
>>>
>>> step 2
>>> ------
>>>
>>> the next improvment was to change append_to_frame_graph() to use a hash table for graph analysis (still slow, over 1 hour):
>>>
>>> CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted
>>> CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
>>> mask of 0x00 (No unit mask) count 750000 samples % image name
>>> symbol name
>>> 565268 94.6185 libglib-2.0.so.0.2800.6 g_list_last
>>> 1863 0.3118 libwireshark.so.0.0.1 serv_name_lookup 1620
>>> 0.2712 libwireshark.so.0.0.1 dissect_sip_common 1340 0.2243
>>> libwireshark.so.0.0.1 format_text
>>> 987 0.1652 libglib-2.0.so.0.2800.6 g_unichar_isprint
>>> 982 0.1644 libglib-2.0.so.0.2800.6 g_hash_table_lookup
>>> 819 0.1371 libwireshark.so.0.0.1 tap_push_tapped_queue
>>> 731 0.1224 libwireshark.so.0.0.1 guint8_pbrk
>>> 628 0.1051 libwireshark.so.0.0.1 proto_tree_add_item
>>> 587 0.0983 libglib-2.0.so.0.2800.6
>>> g_hash_table_insert_internal
>>> 574 0.0961 libwireshark.so.0.0.1 compute_offset_length
>>> 405 0.0678 libwireshark.so.0.0.1 proto_is_protocol_enabled
>>> 401 0.0671 libwireshark.so.0.0.1 emem_free_all
>>> 395 0.0661 libwireshark.so.0.0.1 dissect_ip
>>> 391 0.0654 libc-2.13.so __strncmp_sse2
>>> 367 0.0614 libwireshark.so.0.0.1 dissect ...
>>> 20 0.0017 lt-wireshark
>>> append_to_frame_graph.isra.8
>>>
>>> however, append_to_frame_graph() got from 69.45% to 0.0017% (40852
>>> times better)
>>>
>>> step 3
>>> ------
>>>
>>> I have changed the graph analysis list and the callsinfo list to use prepend instead of append:
>>>
>>> CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted
>>> CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
>>> mask of 0x00 (No unit mask) count 750000 samples % image name
>>> symbol name
>>> 130285 18.6875 libc-2.13.so msort_with_tmp
>>> 66464 9.5333 libglib-2.0.so.0.2800.6 node_get_pos 53790
>>> 7.7154 libglib-2.0.so.0.2800.6 g_hash_table_insert_internal
>>> 51146 7.3361 libc-2.13.so __memcpy_sse2
>>> 44419 6.3712 libglib-2.0.so.0.2800.6 node_get_next
>>> 42461 6.0904 libgtk-x11-2.0.so.0.2400.4 gtk_rbtree_reorder_fixup
>>> 41265 5.9189 libglib-2.0.so.0.2800.6 is_end
>>> 40819 5.8549 libglib-2.0.so.0.2800.6 g_hash_table_resize
>>> 38905 5.5803 libgtk-x11-2.0.so.0.2400.4 _gtk_rbtree_next
>>> 36069 5.1736 libgtk-x11-2.0.so.0.2400.4 _gtk_rbtree_reorder
>>> 35828 5.1390 libglib-2.0.so.0.2800.6 g_hash_table_lookup
>>> 29469 4.2269 libgtk-x11-2.0.so.0.2400.4 save_positions
>>> 26858 3.8524 libgtk-x11-2.0.so.0.2400.4 generate_order
>>> 7892 1.1320 libc-2.13.so __memset_sse2
>>> 7752 1.1119 libgtk-x11-2.0.so.0.2400.4
>>> gtk_rbtree_reorder_sort_func 6860 0.9840
>>> libgtk-x11-2.0.so.0.2400.4 gtk_rbtree_reorder_invert_func
>>> 6835 0.9804 libglib-2.0.so.0.2800.6
>>> g_hash_table_remove_all_nodes
>>> 4085 0.5859 libglib-2.0.so.0.2800.6 g_array_append_vals
>>> 3864 0.5542 libglib-2.0.so.0.2800.6 g_sequence_iter_is_end
>>> 3591 0.5151 libc-2.13.so __memset_x86_64
>>> 2057 0.2950 libglib-2.0.so.0.2800.6 g_array_maybe_expand
>>>
>>> step 4
>>> ------
>>>
>>> reordering is performed _continously_ while adding elements to the voip calls list.
>>> (by _gtk_rbtree_reorder which is calling qsort from libc which is
>>> calling msort_with_tmp)
>>>
>>> after disabling continous reordering, by using in voip_calls_dlg_update():
>>>
>>> /* disable the re-ordering */
>>> gtk_tree_sortable_set_sort_column_id(sortable,
>>> GTK_TREE_SORTABLE_UNSORTED_SORT_COLUMN_ID, GTK_SORT_ASCENDING);
>>>
>>> listx = g_list_first(listx);
>>> while (listx) {
>>> add_to_list_store((voip_calls_info_t*)(listx->data));
>>> listx = g_list_next(listx);
>>> }
>>>
>>> /* enable the re-ordering */
>>> gtk_tree_sortable_set_sort_column_id(sortable,
>>> CALL_COL_START_TIME, GTK_SORT_ASCENDING);
>>>
>>> CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted
>>> CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
>>> mask of 0x00 (No unit mask) count 750000 samples % image name
>>> symbol name
>>> 13495 8.8003 libwireshark.so.0.0.1 format_text
>>> 10698 6.9763 libglib-2.0.so.0.2800.6 g_unichar_isprint
>>> 7421 4.8394 libwireshark.so.0.0.1 guint8_pbrk
>>> 4973 3.2430 libwireshark.so.0.0.1 compute_offset_length
>>> 4776 3.1145 libglib-2.0.so.0.2800.6 g_hash_table_lookup
>>> 4029 2.6274 libwireshark.so.0.0.1 dissect_sip_common
>>> 3851 2.5113 libglib-2.0.so.0.2800.6 g_atomic_pointer_get
>>> 3186 2.0776 libc-2.13.so __memcpy_sse2
>>> 3064 1.9981 libglib-2.0.so.0.2800.6
>>> g_hash_table_insert_internal
>>> 3008 1.9616 libwireshark.so.0.0.1 emem_free_all
>>> 2964 1.9329 libwireshark.so.0.0.1 fast_ensure_contiguous
>>> 2803 1.8279 libwireshark.so.0.0.1 serv_name_lookup
>>> 2793 1.8214 libwireshark.so.0.0.1
>>> check_offset_length_no_exception
>>> 2114 1.3786 libc-2.13.so _int_malloc
>>> 2063 1.3453 libglib-2.0.so.0.2800.6 g_slice_free1
>>> 2046 1.3342 libwireshark.so.0.0.1 tap_push_tapped_queue
>>> 1841 1.2005 libwireshark.so.0.0.1 tvb_get_guint8
>>> 1713 1.1171 libc-2.13.so memchr
>>> 1668 1.0877 libwireshark.so.0.0.1 tvb_length_remaining
>>> 1625 1.0597 libglib-2.0.so.0.2800.6 g_atomic_int_get 1550
>>> 1.0108 libwireshark.so.0.0.1 proto_tree_add_item
>>> 1524 0.9938 libc-2.13.so vfprintf
>>> 1475 0.9619 libwireshark.so.0.0.1 emem_alloc_chunk
>>> 1439 0.9384 libc-2.13.so __strncmp_sse2
>>> 1395 0.9097 libglib-2.0.so.0.2800.6 g_slice_alloc
>>> 1312 0.8556 libwireshark.so.0.0.1 tvb_find_guint8
>>> 1279 0.8341 libwireshark.so.0.0.1
>>> ensure_contiguous_no_exception
>>> 1052 0.6860 libc-2.13.so malloc
>>> 1028 0.6704 libwireshark.so.0.0.1 dissect_sdp
>>> 1022 0.6665 libwireshark.so.0.0.1 tvb_pbrk_guint8
>>>
>>> the runtime decreased now to approx. 1 minute (pretty reasonable when
>>> compared to 10 hours)
>>>
>>> I can publish the patches on bugzilla; however, the changes/tests have been explicitly targeted at sip voip calls.
>>> some of the data structures are global and used by _all_ voip protocol taps; it won't work correctly with dumps having also non-sip voip calls.
>>>
>>> pls. let me know your opinion.
>>>
>>> thanks.
>>> cristian
>>> ______________________________________________________________________
>>> _____ Sent via: Wireshark-dev mailing list
>>> <wireshark-dev@wireshark.org>
>>> Archives: http://www.wireshark.org/lists/wireshark-dev
>>> Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
>>>
>>> mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe
>>> ______________________________________________________________________
>>> _____ Sent via: Wireshark-dev mailing list
>>> <wireshark-dev@wireshark.org>
>>> Archives: http://www.wireshark.org/lists/wireshark-dev
>>> Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
>>>
>>> mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe
>> ___________________________________________________________________________
>> Sent via: Wireshark-dev mailing list<wireshark-dev@wireshark.org>
>> Archives: http://www.wireshark.org/lists/wireshark-dev
>> Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
>> mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe
>> ___________________________________________________________________________
>> Sent via: Wireshark-dev mailing list<wireshark-dev@wireshark.org>
>> Archives: http://www.wireshark.org/lists/wireshark-dev
>> Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
>> mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe
> ___________________________________________________________________________
> Sent via: Wireshark-dev mailing list<wireshark-dev@wireshark.org>
> Archives: http://www.wireshark.org/lists/wireshark-dev
> Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
> mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe
>

___________________________________________________________________________
Sent via: Wireshark-dev mailing list <wireshark-dev@wireshark.org>
Archives: http://www.wireshark.org/lists/wireshark-dev
Unsubscribe: https://wireshark.org/mailman/options/wireshark-dev
             mailto:wireshark-dev-request@wireshark.org?subject=unsubscribe