Slowness module generating for testsuite/systemtap.stress/current.stp due to elfutils-0.131

Slowness module generating for testsuite/systemtap.stress/current.stp due to elfutils-0.131

[William Cohen]

I was looking through the nightly test results and I noticed that recently
systemtap.stress/current.stp times out on all the machine running nightly tests. 
It uses to be that systemtap.stress/current.stp was a relatively quick test to run.

I looked through the nightly testing build that checks things out at 4:30 am EST
and it appears that stap is reasonably fast 20080124 then 2008125 it is
literally 30 times slower. Ran the following command with various versions of
systemtap in the testsuite directory:

/usr/bin/time ../stap
/home/wcohen/stap_testing_200802070930/src/testsuite/systemtap.stress/current.stp
-g -m x -v -c 'sleep 1'

Below is the table of results from the time command.

date	   output of time

20080124
	6.23user 1.25system 0:11.84elapsed 63%CPU
	(0avgtext+0avgdata 0maxresident)k
	0inputs+0outputs (406major+196130minor)pagefaults 0swaps
20080125
	230.78user 1.37system 3:55.77elapsed 98%CPU
	(0avgtext+0avgdata 0maxresident)k
	0inputs+0outputs (29major+213027minor)pagefaults 0swaps

The problem appear to be a huge amount of time spent in some of the rountines in 
   elfutils-0.131. Also see huge amount of time with elfutils-0.132. The same 
systemtap code built elfutils-0.129 is much faster (30 times faster). Below is a 
profiling data from oprofile showing the routines that  the systemtap spends its 
time in elfutils-0.132:

$ opreport -t1 ./stap -l
CPU: P4 / Xeon with 2 hyper-threads, speed 2793.08 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) 
with a unit mask of 0x01 (mandatory) count 100000
samples  %        image name               symbol name
4355797  68.3146  libdw.so.1               relocate.5976
1679547  26.3414  libelf.so.1              gelf_getsymshndx
168836    2.6480  libc-2.5.so              strcmp
94576     1.4833  libdw.so.1               anonymous symbol from section .plt


-Will

Re: [Forw:] Re: Slowness module generating for testsuite/systemtap.stress/current.stp due to elfutils-0.131

[Roland McGrath]

Sorry, I'm far too backlogged to look into this directly any time soon.
I can give you a few suggestions off hand on how to investigate.

First thing is to verify that libdwfl alone has slowed down, ruling out
some bizarre interaction with systemtap's particular use.  Compare
loc2c-test -K or some other elfutils test program between the two builds.
The -K option (or -K`uname -r`) translates to the same libdwfl reporting
functions that systemtap uses.  

Next, I'd check for any big difference in system calls.  If strace -c
output differs a great deal, then take traces to see if the new one is
opening a much larger number of files or something like that.

If all that is the same, the reporting pass is not the culprit.
The next thing that comes to mind is the new relocation behavior.
This is the feature added in 0.131 to facilitate the markers work
in .ko modules.  If you call dwfl_module_getelf then it eagerly
applies relocs to all sections in case you are going to get their
contents via libelf calls.  Perhaps we are getting too many relocs
eagerly applied and that is unexpectedly costly.  Or perhaps there 
is some bug causing the reloc work to be repeated many times or 
something like that.  In the debugger, look at the number of calls
to __libdwfl_relocate and __libdwfl_relocate_section.


Thanks,
Roland