https://bugs.wireshark.org/bugzilla/show_bug.cgi?id=6794
Summary: slow voip/sip flow chart for large captures
Product: Wireshark
Version: SVN
Platform: All
OS/Version: All
Status: NEW
Severity: Enhancement
Priority: Medium
Component: Wireshark
AssignedTo: bugzilla-admin@xxxxxxxxxxxxx
ReportedBy: const.crist@xxxxxxxxxxxxxx
Build Information:
wireshark 1.7.1 (SVN Rev 40740 from /trunk)
Copyright 1998-2012 Gerald Combs <gerald@xxxxxxxxxxxxx> and contributors.
This is free software; see the source for copying conditions. There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
Compiled (64-bit) with GTK+ 2.24.4, with Cairo 1.10.2, with Pango 1.28.4, with
GLib 2.28.6, with libpcap, with libz 1.2.3.4, with POSIX capabilities (Linux),
with SMI 0.4.8, with c-ares 1.7.5, with Lua 5.1, without Python, with GnuTLS
2.12.10, with Gcrypt 1.5.0, with MIT Kerberos, with GeoIP, with PortAudio
V19-devel (built Jul 20 2011 00:01:38), without AirPcap.
Running on Linux 3.1.0-1-amd64, with locale en_US.UTF-8, with libpcap version
1.1.1, with libz 1.2.3.4, GnuTLS 2.12.10, Gcrypt 1.5.0.
Built using gcc 4.6.1.
--
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 rendering 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.
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; I do NOT know whether it works correctly with dumps
having also non-sip voip calls.
pls. let me know your oppinion.
--
Configure bugmail: https://bugs.wireshark.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are watching all bug changes.
