Derzeit beschäftige ich mich mit
Oprofile.
Oprofile is a system-wide profiler for Linux systems, capable of profiling all running code at low overhead. OProfile is released under the GNU GPL.
It consists of a kernel driver and a daemon for collecting sample data, and several post-profiling tools for turning data into information.
OProfile leverages the hardware performance counters of the CPU to enable profiling of a wide variety of interesting statistics, which can also be used for basic time-spent profiling. All code is profiled: hardware and software interrupt handlers, kernel modules, the kernel, shared libraries, and applications.
Um CPU-Engpässe (oder andere Engpässe) aufzuspüren kann oprofile das Tool der Wahl sein. Wenn das Prinzip einmal verstanden ist kommt man damit recht schnell zu den ersten Ergebnissen.
Gegeben sei das folgende kleine C-Programm, welches nichts sinnvolles tut ausser ein wenig CPU zu verbrauchen:
earth:~# cat test.c
#include <stdio.h>
#define FOO 10000
void one();
void two(unsigned int i);
void three();
void one() {
unsigned int i;
for (i = FOO; i != 0; --i)
two(i);
}
void two(unsigned int i) {
double foo = i * 23.3 / 4.3;
}
void three() {
unsigned int i;
for (i = FOO; i != 0; --i)
one();
}
int main (void) {
one();
three();
return (0);
}
earth:~# gcc test.c -o test
earth:~# file test
test: ELF 32-bit LSB executable, Intel 80386, version 1
(SYSV), dynamically linked (uses shared libs), for
GNU/Linux 2.6.8, not stripped
earth:~#
Jetzt möchten wir es gerne profilen:
earth:~# opcontrol --start
Profiler running.
earth:~# ps aux | grep oprofiled
root 5332 0.1 0.3 5276 3616 ?
S 08:08 0:00 /usr/bin/oprofiled
--session-dir=/var/lib/oprofile --separate-lib=0
--separate-kernel=0 --separate-thread=0
--separate-cpu=0
--events=GLOBAL_POWER_EVENTS:29:0:100000:1:1:1,
--vmlinux=/boot/vmlinux --kernel-range=c0101000,c02bfc00
earth:~# time ./test
real 0m12.686s
user 0m5.040s
sys 0m0.124s
earth:~# opcontrol --stop
Stopping profiling.
Mit opreport lässt sich das Verhalten nachträglich reporten:
earth:~# opreport -l test
CPU: P4 / Xeon, speed 2392.38 MHz (estimated)
samples % symbol name
184204 61.3774 one
115913 38.6226 two
Es besteht die Möglichkeit den dazugehörigen Assemblercode samt Performancedaten zu reporten:
earth:~# opannotate --source --assembly test
/*
* Command line: opannotate --source --assembly test
*
* Interpretation of command line:
* Output annotated assembly listing with samples
*
* CPU: P4 / Xeon, speed 2392.38 MHz (estimated)
* Counted GLOBAL_POWER_EVENTS events
* (time during which processor is not stopped) with a
* unit mask of 0x01 (mandatory) count 100000
*/
:
:/root/test: file format elf32-i386
:
:Disassembly of section .init:
:Disassembly of section .plt:
:Disassembly of section .text:
:
08048374 : /* one total: 184204 61.3774 */
: 8048374: push %ebp
: 8048375: mov %esp,%ebp
183062 60.9969 : 8048377: sub $0x18,%esp
: 804837a: movl $0x2710,-0x4(%ebp)
: 8048381: jmp 8048392
112 0.0373 : 8048383: mov -0x4(%ebp),%eax
1 3.3e-04 : 8048386: mov %eax,(%esp)
325 0.1083 : 8048389: call 804839a
339 0.1130 : 804838e: subl $0x1,-0x4(%ebp)
115 0.0383 : 8048392: cmpl $0x0,-0x4(%ebp)
249 0.0830 : 8048396: jne 8048383
: 8048398: leave
1 3.3e-04 : 8048399: ret
:Disassembly of section .fini:
:
:/root/test: file format elf32-i386
:
:Disassembly of section .init:
:Disassembly of section .plt:
:Disassembly of section .text:
:
0804839a : /* two total: 115913 38.6226 */
289 0.0963 : 804839a: push %ebp
201 0.0670 : 804839b: mov %esp,%ebp
: 804839d: sub $0x10,%esp
3991 1.3298 : 80483a0: mov 0x8(%ebp),%eax
1 3.3e-04 : 80483a3: mov $0x0,%edx
: 80483a8: push %edx
121 0.0403 : 80483a9: push %eax
194 0.0646 : 80483aa: fildll (%esp)
57419 19.1322 : 80483ad: lea 0x8(%esp),%esp
1550 0.5165 : 80483b1: fldl 0x80484d0
2 6.7e-04 : 80483b7: fmulp %st,%st(1)
2802 0.9336 : 80483b9: fldl 0x80484d8
: 80483bf: fdivrp %st,%st(1)
48482 16.1544 : 80483c1: fstpl -0x8(%ebp)
728 0.2426 : 80483c4: leave
133 0.0443 : 80483c5: ret
:Disassembly of section .fini:
Wenn das Binary mit Debugging-Symbolen kompiliert wurde, dann kann man mittels opannotate den original C-Code ins Profiling einbeziehen:
earth:~# gcc test.c -o test -g3 -ggdb3
earth:~# opreport --start
earth:~# ./test
earth:~# opreport --stop
earth:~# mkdir annotate
earth:~# opannotate --source --output-dir=./annotate test
earth:~# cat annotate/root/test.c
:#include
:
:#define FOO 10000
:
:void one();
:void two(unsigned int i);
:void three();
:
183063 43.9076 :void one() { /* one total: 185577 44.5106 */
: unsigned int i;
1777 0.4262 : for (i = FOO; i != 0; --i)
735 0.1763 : two(i);
2 4.8e-04 :}
:
8277 1.9852 :void two(unsigned int i) { /* two total: 231351 55.4894 */
221034 53.0149 : double foo = i * 23.3 / 4.3;
2040 0.4893 :}
:
:void three() {
: unsigned int i;
: for (i = FOO; i != 0; --i)
: one();
:}
:
:int main (void) {
: one();
: three();
: return (0);
:}
/*
* Total samples for file : "/root/test.c"
*
* 416928 100.000
*/
Bei den hiesigen Ergebnissen fällt auf, dass die Funktion three() angeblich keinmal durchlaufen ist. Das stimmt aber nicht. Oprofile merkt nicht jeden Funktionsaufruf. Es sammelt lediglich Ergebnisse mehrerer Samples/Snapshots des Ist-Zustandes. Es besteht dabei die Möglichkeit, dass diverse Zustände gar nicht erfasst werden. Dies genügt allerdings den Anforderungen eines Perfomance-Benchmarkes. Aufrufe, die eh kaum vorkommen, sind auch nicht Performancerelevant.
Das Profiling ist dabei nicht auf ein bestimmtes Binary beschränkt, sondern kann systemweit operieren (indem man kein explizites Binary angibt):
earth:~# opreport | head -n 50
CPU: P4 / Xeon, speed 2392.38 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during
which processor is not stopped) with a unit mask of 0x01
(mandatory) count 100000
GLOBAL_POWER_E...|
samples| %|
------------------
416928 21.8677 test
348208 18.2634 libflashplayer.so
245742 12.8891 opera
GLOBAL_POWER_E...|
samples| %|
------------------
242472 98.6693 opera
669 0.2722 anon (tgid:5014 range:0xb4330000-0xb4368000)
613 0.2494 [vdso] (tgid:5014 range:0xb770c000-0xb770d000)
432 0.1758 anon (tgid:5014 range:0xb6ff0000-0xb7000000)
265 0.1078 anon (tgid:5014 range:0xb44fc000-0xb452c000)
247 0.1005 anon (tgid:5014 range:0xb413e000-0xb4146000)
213 0.0867 anon (tgid:5014 range:0xb4504000-0xb452c000)
130 0.0529 anon (tgid:5014 range:0xb4504000-0xb451c000)
95 0.0387 anon (tgid:5014 range:0xb4358000-0xb4368000)
80 0.0326 anon (tgid:5014 range:0xb44ec000-0xb452c000)
73 0.0297 anon (tgid:5014 range:0xb4490000-0xb44a0000)
55 0.0224 anon (tgid:5014 range:0xb3828000-0xb3858000)
52 0.0212 anon (tgid:3734 range:0xb45c0000-0xb45d0000)
45 0.0183 [vdso] (tgid:3746 range:0xb771b000-0xb771c000)
43 0.0175 [vdso] (tgid:3734 range:0xb7752000-0xb7753000)
41 0.0167 anon (tgid:3734 range:0xad0e3000-0xad0eb000)
37 0.0151 anon (tgid:3746 range:0xb3d3a000-0xb3dd2000)
35 0.0142 anon (tgid:5014 range:0xb4348000-0xb4368000)
28 0.0114 anon (tgid:5014 range:0xb4338000-0xb4368000)
20 0.0081 anon (tgid:3734 range:0xb44f3000-0xb44fb000)
19 0.0077 anon (tgid:3746 range:0xb4022000-0xb4042000)
13 0.0053 anon (tgid:5014 range:0xb4350000-0xb4368000)
10 0.0041 anon (tgid:3746 range:0xb0662000-0xb066a000)
9 0.0037 anon (tgid:3746 range:0xb26d7000-0xb26f7000)
9 0.0037 anon (tgid:3746 range:0xb412d000-0xb418d000)
8 0.0033 anon (tgid:3746 range:0xb2365000-0xb237d000)
8 0.0033 anon (tgid:3746 range:0xb45b1000-0xb45b9000)
5 0.0020 anon (tgid:3734 range:0xb4629000-0xb4661000)
5 0.0020 anon (tgid:5014 range:0xb6fc3000-0xb6feb000)
3 0.0012 anon (tgid:3746 range:0xb2350000-0xb2360000)
2 8.1e-04 anon (tgid:3746 range:0xb2604000-0xb2654000)
2 8.1e-04 anon (tgid:3746 range:0xb419c000-0xb41b4000)
2 8.1e-04 anon (tgid:5014 range:0xb4580000-0xb45b0000)
1 4.1e-04 anon (tgid:3734 range:0xb45d0000-0xb4ae1000)
1 4.1e-04 anon (tgid:3746 range:0xb12f3000-0xb134b000)
242239 12.7053 vmlinux
134676 7.0637 libc-2.7.so
125083 6.5605 perl
87316 4.5797 bash
Oprofile ist nicht auf Userland-Programme und Bibliotheken beschränkt. Es besteht die Möglichkeit mit einem speziell präparieten Kernel (
vmlinux anstelle oder zusätzlich zu vmlinuz) auch sämtliche Kernelcalls zu profilen:
earth:~# opreport -l /boot/vmlinux | head -n 50
CPU: P4 / Xeon, speed 2392.38 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during
which processor is not stopped) with a unit mask of 0x01
(mandatory) count 100000
samples % symbol name
24150 9.9695 radix_tree_gang_lookup_tag
17137 7.0744 sysenter_past_esp
13835 5.7113 lg_set_features
9769 4.0328 radix_tree_lookup_slot
7815 3.2262 do_filp_open
7376 3.0449 lg_notify
7189 2.9677 radix_tree_lookup
6241 2.5764 xfrm_init_state
4539 1.8738 init_transmeta
4065 1.6781 get_pageblock_flags_group
3544 1.4630 do_sys_truncate
3543 1.4626 sys_sigsuspend
3480 1.4366 dma_async_memcpy_pg_to_pg
3305 1.3644 bdi_debug_stats_show
3014 1.2442 hrtimer_force_reprogram
2980 1.2302 pm_qos_add_requirement
2943 1.2149 nommu_map_single
2909 1.2009 apply_to_page_range
2624 1.0832 vfs_follow_link
2511 1.0366 shmem_getpage
2152 0.8884 pm_qos_power_open
1987 0.8203 identify_cpu
1446 0.5969 sys_mkdirat
1347 0.5561 kmem_cache_create
1303 0.5379 posix_cpu_timer_set
1018 0.4202 cpuidle_add_sysfs
979 0.4041 kvm_register_clock
970 0.4004 native_calculate_cpu_khz
906 0.3740 __show_registers
887 0.3662 xfrm_state_unregister_afinfo
867 0.3579 do_coredump
856 0.3534 kobject_uevent_env
855 0.3530 update_curr_rt
827 0.3414 do_ip_setsockopt
822 0.3393 radix_tree_tag_clear
710 0.2931 dma_async_device_register
708 0.2923 show_regs
697 0.2877 dquot_initialize
689 0.2844 wake_up_new_task
670 0.2766 idr_remove
639 0.2638 sock_common_recvmsg
631 0.2605 note_interrupt
620 0.2559 release_dev
617 0.2547 tcp_v4_do_rcv
612 0.2526 sys_timer_create
603 0.2489 __dequeue_rt_entity
596 0.2460 pipe_read
Oprofile bietet die Möglichkeit Anhaltspunkte in Hinsicht einer Performanceoptimierung des Systems zu bringen.
