Ethereal-dev: Re: [Ethereal-dev] Performance. Ethereal is slow whenusing largecaptures.

Note: This archive is from the project's previous web site, ethereal.com. This list is no longer active.

Date Index Thread Index Other Months All Mailing Lists
Date Prev Date Next Thread Prev Thread Next
From: Ian Schorr <spamcontrol2@xxxxxxxxxxx>
Date: Sat, 15 Nov 2003 01:05:49 -0500
By far the place I can see it called from the most is epan/proto.c:find_protocol_by_id(), but I only see that function called 4065724 times (and none of the 5 functions where I see g_list_find_custom called from appears to be able to call it more than once), so I must be missing something. 

What is g_list_find_custom?

Ian Schorr wrote:
No, that's part of the problem. gprof is having a heck of a time identifying the calling function for quite a few of these operations. It lists g_list_find_custom, for example, as being a "spontaneous" call - one where the "identify of the caller of a function cannot be determined".
I can't even find where g_list_find_custom is defined, though I see that it's called in several places in epan/proto.c and prefs.c 

Ronnie Sahlberg wrote:


Hm I was actually surprised by this.
Good thing is that if it is possible to optimize this function  it could
give a >20% performance boost
which is nothing to sneeze at.

Together with g_list_find_custom() accounting to ~30% of the time spent.
Can you see in the data from where this function is called so many times? 


----- Original Message ----- From: "Newbie"
Sent: Saturday, November 15, 2003 4:36 PM
Subject: Re: [Ethereal-dev] Performance. Ethereal is slow whenusing
largecaptures.



Ronnie,

I haven't done a "formal" test, per se, but I ran a couple of quick
tests out of curiosity and thought I'd share the results.

I used a file I had sitting around - a 124,568 packet trace containing
primarily CIFS traffic.

I ran two tests with profiling enabled:  One where I simply opened the
file, then exited the program, and another where I opened the file, then 
refiltered using "smb" as a display filter, then exited the program.

Both tests gave me nearly identical results as far as the most "costly"
procedures, so I'll concentrate just on the second test.

The function consuming the most time was epan/proto.c:compare_proto_id,
at 22.9%, 8.14s, and 777,148,074 calls (nearly more calls, I believe,
than to all other functions combined).

add_packet_to_packet_list actually came in at #5, with 7.6%, 2.64s -
including time spend in its child functions (epan_dissect_run, mostly
(5.1%/1.8s), which in turn spent the majority of its time in
dissect_packet (5.1%, 1.71s)).

compare_proto_id appeared to be a called by g_list_find_custom.  It
accounted for an additional 5.9%/2.11s, for a total of 28.8% spent in
this particular function (when added to the time spent in its child
function, compare_proto_id)

proto_tree_add_pi appeared to be more "expensive" (10.0%, 2.82s) than
add_packet_to_packet_list, and proto_tree_add_uint (6.7%, 2.01s).

The test system is an Apple G5 running OS X 10.3, with GTK+ 1.2.10,
Ethereal 0.9.16 with no special GCC flags and


"configure --without-plugins".

Let me know if you want me to do a more "formal" test, and upload the
trace to some shared area (perhaps Gerald wouldn't mind setting up an
area temporarily on ftp.ethereal.com, or do we already have something
like that?).

Ian


Ronnie Sahlberg wrote:


Good point.
I never noticed that the number of sessions affected the refilter speed. The type of traffic (some reassembled PDUs take much longer than others 


to

dissect) I know would affect it but never knew the number of sessions
did.
The problem now is that fore VERY large captures, ethereal is always slow 
under all circumstances.
So let us start with just a simple random generic capture and measure for 


it

to try to keep the number of variables low.
(If it is as you say the number of sessions affect it as well,  do you



mean

the number of TCP sessions or what kind of sessions?
At some point, when the worst performance problem has been addressed



this

would be a very interesting area to look at.
(I could create different synthetic capture files to measure with,



same

number of packets, same payload just different number of sessions)
Make a note that you have observed the number of sessions to possibly



have

an effect on the dissection speed so we dont forget to look at
it furhter down the track
)
I currently belive that during refiltering of a capture, most time would 


be

spent inside file.c/add_packet_to_packet_list().
It would be VERY VERY useful to verify that this assumption is correct. I would really like someone to look at gprof data and analyze where most time is consumed to either verify my claim add_packet_to_packet_list() 
or to invalidate it.

The thing inside this function I think consumes the most cpu I belive



would
be where we call epan_dissect_run() and perform a full dissection of the 
packet.
As I see it, apart from the initial time we encounter the packet during 


file
read (or live capture) there are not that many instances where we really 
must
dissect the packet at all.
OK. If we select a packet in the list so it gets displayed in the dissect 
pane that might be an exception but that is not something that we do



100.000

times
per capture anyway so the performance of that is irrelevant.
We might also need to do a full rescan/redissect of all packets IF we



have
changed the preferences in such a way that the packets will be dissected 
differently  or when we have changed stuff using  DecodeAs.

However, for me and many other users, the MAIN reason ethereal rescans



the

packet list is because we have applied or changed a filter. Some users



will
filter and refilter a capture file over and over and over, ten, twenty, 
thirty if not more times for each capture they work with.
Or see when a ConversationList dislog or a ServiceResponseTime dialog is 
opened.


Well enough of that. To my idea:

Hypothesis:  A significant part of the slowness of ethereal when



refiltering

a capture file comes from the expensive calls to epan_dissect_run()



called

from add_packet_to_packet_list() in file.c
Potential fix: Reduce the number of calls made to epan_dissect_run() at 


the

expense of additional memory requirements (enabled by a preference)
Assuming that most of the time we perform a full rescan/redissect of the 
capture file is when we really just want to reapply a display filter.



(and

are not doing anything that affects how a packet is dissected).
What do we need in order to refilter the packet list if we do not allow 
calling epan_dissect_run()?
1, We need to remember all COL values for all packets so that we can just reapply them when adding the packet to the packetlist without calling the 
dissector and recreating them that way.   This will consume additional
memory.
2, For every packet we need to keep a list of all the hf_fields that were 
encountered in the packet.
  This list contains the index of the hf variable as well as the value



it

has.
  Nothing else needs to be stored there (in order to reduce the impact



on

memory)
  This list may NOT be pruned as the edt structs are. This is because



we

want to be able to still use this list even after the filters have



changed

and thus
the pruning would be different.   No pruning.
The "ApplyFilterToEdtStructure" fucntions would need to be changed (or
duplicated) so they could operate on the list in 2 instead of the edt
structure.
This function might also need to be looked at so that it would be



efficient

even for very large lists (no pruning)
1 would allow us to rebuild the packet list without needing to call the 
dissector (?)
2 would allow us to refilter the entire trace without calling any
dissectors.

ideas, comments?


Right now it would be nice if someone could create a capture as I



proposed

earlier and use GPROF to check where most of the CPU is spent when
refiltering the capture. To verify if my assumptions are correct or
invalidate them.


(
As a nice benefit in the future, IF we were to have that list of fields 


for
each packet, easily available, we could do things like merging this list 
between packets.
Say #6 is the Call and #27 is the Response.
Since these packets are paired we could merge the lists from these two
packets into a single one.
Then when searcing for something that occured in the Response packet, we 
would automatically also pick up the matching Call packet sinte their



lists

were merged.
I.e filtering for smb.error==foo   would both find the Response that



barfed

saying foo  but also teh matched Call to this Response.
That would also be useful.
)