Re: cost of kprobe and jprobe operations

[William Cohen <wcohen at redhat dot com>]

William Cohen wrote:
> I did some experiments this morning to get an idea of the cost of kprobe 
> and jprobe operations. The attached gzipped tarball has the simple 
> module that was used to get some measurements. It does a couple millions 
> jprobes and kprobes. The module was made with:
>
> make -C /lib/modules/`uname -r`/build M=`pwd` modules


I cleaned up my modules to do the timing expirements this afternoon and 
added a script to automate the data collection with oprofile.  The 
measurements should exclude the overhead caused by unloading the module. 
The test is triggered by reading out /dev/kprobe. I also wrote it so the 
average number of cycles from the experiment is returned by /dev/kprobe.

I have tried this out on a FC4 test machine and things seem to work. The 
script get_oprof_data assumes that there is a valid kernel vmlinux for 
the experiments (why you would want to do the experiment without one is 
beyond me). Below are the results from running the experiments.


# ./get_oprof_data /usr/lib/debug/lib/modules/`uname -r`/vmlinux

Doing experiment for kprobe-timing

Using 2.6+ OProfile kernel interface.
Reading module info.
Using log file /var/lib/oprofile/oprofiled.log
Daemon started.
Profiler running.
Stopping profiling.
Killing daemon.
CPU: PIII, speed 861.246 MHz (estimated)
Counted CPU_CLK_UNHALTED events (clocks processor is not halted) with a 
unit mask of 0x00 (No unit mask) count 100000
samples  %        symbol name
1556     12.2366  __module_text_address
1179      9.2718  default_idle
1112      8.7449  int3
1073      8.4382  debug
845       6.6452  do_debug
760       5.9767  _spin_unlock
660       5.1903  kprobe_handler
636       5.0016  lock_kprobes
622       4.8915  _spin_lock
463       3.6411  restore_all
351       2.7603  _spin_lock_irqsave
335       2.6345  kernel_map_pages
194       1.5256  _spin_unlock_irqrestore
190       1.4942  get_kprobe
184       1.4470  kprobe_exceptions_notify
156       1.2268  do_wp_page

Doing experiment for jprobe-timing

Using 2.6+ OProfile kernel interface.
Reading module info.
Using log file /var/lib/oprofile/oprofiled.log
Daemon started.
Profiler running.
Stopping profiling.
Killing daemon.
CPU: PIII, speed 861.246 MHz (estimated)
Counted CPU_CLK_UNHALTED events (clocks processor is not halted) with a 
unit mask of 0x00 (No unit mask) count 100000
samples  %        symbol name
1606     12.1427  __module_text_address
1171      8.8538  do_debug
1164      8.8008  default_idle
797       6.0260  int3
688       5.2019  kprobe_exceptions_notify
589       4.4533  _spin_unlock
578       4.3702  restore_all
575       4.3475  _spin_lock
472       3.5687  debug
451       3.4100  notifier_call_chain
402       3.0395  _spin_lock_irqsave
374       2.8278  kprobe_handler
361       2.7295  resume_execution
345       2.6085  kernel_map_pages
319       2.4119  debug_stack_correct
240       1.8146  longjmp_break_handler
201       1.5197  lock_kprobes
183       1.3836  memcpy
179       1.3534  _spin_unlock_irqrestore
147       1.1114  do_wp_page

Attachment: timing_kprobe.tar.gz
Description: Unix tar archive