[Bug testsuite/11514] nd_syscall.exp takes more than 10 times longer than syscall.exp testcase

["jistone at redhat dot com" <sourceware-bugzilla at sourceware dot org>]

------- Additional Comments From jkenisto at linux dot vnet dot ibm dot com  2010-04-19 18:36 -------
Subject: Re:  nd_syscall.exp takes more than 10 times
 longer than syscall.exp testcase

On Mon, 2010-04-19 at 17:56 +0000, mjw at redhat dot com wrote:
> ------- Additional Comments From mjw at redhat dot com  2010-04-19 17:56 -------
> Time seems to be spend in Pass 5?
> 
> $ gcc /home/mark/src/systemtap/testsuite/systemtap.syscall/clock.c   -lm   -o
> /tmp/clock
> 
> $ ./run-stap -k -v testsuite/systemtap.syscall/sys.stp -c /tmp/clock
> Pass 1: parsed user script and 70 library script(s) using
> 21108virt/13220res/2052shr kb, in 230usr/10sys/232real ms.
> Pass 2: analyzed script: 641 probe(s), 123 function(s), 22 embed(s), 4 global(s)
> using 189788virt/48040res/3100shr kb, in 1230usr/360sys/1601real ms.
> Pass 3: translated to C into "/tmp/stapDAIhAi/stap_10047.c" using
> 189508virt/51668res/6840shr kb, in 1460usr/200sys/1682real ms.
> Pass 4: compiled C into "stap_10047.ko" in 24680usr/900sys/25350real ms.
> Pass 5: starting run.
> [...]
> Pass 5: run completed in 30usr/80sys/1135real ms.
> Keeping temporary directory "/tmp/stapDAIhAi"
> 
> Versus:
> 
> $ ./run-stap -k -v testsuite/systemtap.syscall/nd_sys.stp -c /tmp/clock
> Pass 1: parsed user script and 70 library script(s) using
> 21112virt/13220res/2052shr kb, in 220usr/10sys/231real ms.
> Pass 2: analyzed script: 1401 probe(s), 97 function(s), 22 embed(s), 4 global(s)
> using 161124virt/19324res/2940shr kb, in 370usr/340sys/711real ms.
> Pass 3: translated to C into "/tmp/stapm1mCJz/stap_9513.c" using
> 161256virt/19624res/3148shr kb, in 320usr/50sys/366real ms.
> Pass 4: compiled C into "stap_9513.ko" in 27210usr/890sys/28005real ms.
> Pass 5: starting run.
> [...]
> Pass 5: run completed in 30usr/22210sys/23274real ms.
> Keeping temporary directory "/tmp/stapm1mCJz"
> 

The nd_syscalls*.stp tapsets use the *_arg functions (in
tapset/*/registers.stp) to obtain the arg values.  I have no reason to
think that they're particularly slow, but I don't think I ever
benchmarked them.

Jim



------- Additional Comments From jistone at redhat dot com  2010-04-19 20:33 -------
I believe this is because kprobes is doing a *linear* search through kallsyms
when registering by symbol name, and we have 1400 probes to register.

Here are the top-5 perf results for staprun on this script: 
  probe nd_syscall.** {} probe begin { exit() }

# Samples: 137286
#
# Overhead  Command  Shared Object  Symbol
# ........  .......  .............  ......
#
    90.20%   stapio  [kernel]       [k] kallsyms_expand_symbol
     4.12%   stapio  [kernel]       [k] strcmp
     3.15%   stapio  [kernel]       [k] kallsyms_lookup_name
     0.56%   stapio  [kernel]       [k] read_hpet
     0.40%   stapio  [kernel]       [k] mod_find_symname


For comparison, here's with normal syscalls:
  probe syscall.** {} probe begin { exit() }

# Samples: 1051
#
# Overhead  Command  Shared Object  Symbol
# ........  .......  .............  ......
#
     2.38%   stapio  [kernel]       [k] __link_path_walk
     2.38%   stapio  [kernel]       [k] _spin_lock
     2.28%   stapio  [kernel]       [k] clear_page_c
     2.00%   stapio  /lib64/libc-2.11.1.so  [.] _IO_vfscanf_internal
     1.81%   stapio  [kernel]       [k] copy_user_generic_string


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11514

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.