Code source, Doc CppCon 2017: Honggyu Kim “Understanding the runtime behaviors of C++ programs using uftrace tool”
Prérequis
Le programme doit être compilé avec -pg.
La base
- main.c
void bar () { } int foo(int i) { bar(); return i; } int main() { foo(4); }
Sans -pg
uftrace a.out
ERROR: Can't find 'mcount' symbol in the 'a.out'.
It seems not to be compiled with -pg or -finstrument-functions flag
which generates traceable code. Please check your binary file.
Mais il est possible de forcer pour analyser les librairies systèmes (dans ce cas précis, il n'y en a pas).
uftrace --force a.out
WARN: no trace data found
Avec -pg
Exécution :
uftrace a.out
# DURATION TID FUNCTION
[24318] | main() {
[24318] | foo() {
0.165 us [24318] | bar();
1.635 us [24318] | } /* foo */
2.268 us [24318] | } /* main */
Exécution avec enregistrement :
uftrace record a.out uftrace replay …
Paramètres
- Afficher les arguments et la valeur de retour. uftrace-live :
Valeur de retour de foo : -R foo@retval. Il n'est pas possible de désigner tout le monde.
Arguments de foo : -A foo@arg1/u64. arg pour nombre entier, 1 pour l'argument 1, u pour unsigned int, 64 pour la taille. Il est aussi possible d'utiliser fparg pour les flottants.
Il y a l'option --auto-args mais qui est dans une branche et pas encore dans le code source master.
- Limiter l'affichage au fonction les plus longues :
-t 5us : limiter à minimum 5 microsecondes
- Inclure les appels entre librairie et pas seulement ceux du programme vers ses dépendances directes :
–nest-libcall
- Affichage graphique de l'état de la pile en fonction du temps :
uftrace record a.out uftrace dump --chrome >> log.js
et ouvrir le fichier log.js avec Google Chrome depuis l'adresse interne chrome://tracing.
Pour mémo : trace2html et Flame Graph
Différences entre 2 exécutions
uftrace record -d 1 a.out uftrace record -d 2 a.out uftrace report --data 1 --diff 2
Mais j'ai quelques doutes sur le résultat. Normalement, les deux premières colonnes de temps devraient être à peu près identique alors que là, on dirait que c'est la première colonne qui contient le diff.
#
# uftrace diff
# [0] base: 1 (from uftrace record -d 1 -k a.out )
# [1] diff: 2 (from uftrace record -d 2 -k a.out )
#
Total time (diff) Self time (diff) Calls (diff) Function
=================================== =================================== ================================ ================================================
- 572.484 us +572.484 us - 572.484 us +572.484 us 0 157 +157 __do_page_fault
- 217.218 us +217.218 us - 217.218 us +217.218 us 0 1 +1 do_syscall_64
- 167.109 us +167.109 us - 162.286 us +162.286 us 0 34 +34 sys_mmap
4.394 us 170.853 us +166.459 us 4.394 us 170.853 us +166.459 us 3 237 +234 smp_irq_work_interrupt
- 155.828 us +155.828 us - 148.641 us +148.641 us 0 21 +21 sys_read
- 152.856 us +152.856 us - 149.136 us +149.136 us 0 30 +30 sys_open
- 117.696 us +117.696 us - 109.732 us +109.732 us 0 23 +23 sys_mprotect
55.976 us 145.693 us +89.717 us 55.976 us 145.693 us +89.717 us 1 12 +11 exit_to_usermode_loop
- 53.185 us +53.185 us - 50.139 us +50.139 us 0 6 +6 sys_munmap
81.100 us 133.748 us +52.648 us 1.174 us 1.285 us +0.111 us 1 1 0 main
79.926 us 132.463 us +52.537 us 5.419 us 3.635 us -1.784 us 1 1 0 puts
- 20.987 us +20.987 us - 20.429 us +20.429 us 0 1 +1 sys_readlink
2.705 us 23.271 us +20.566 us 2.122 us 20.099 us +17.977 us 1 19 +18 sys_newfstat
- 16.990 us +16.990 us - 16.383 us +16.383 us 0 5 +5 sys_writev
- 15.621 us +15.621 us - 14.503 us +14.503 us 0 21 +21 sys_close
12.015 us 23.654 us +11.639 us 12.015 us 23.084 us +11.069 us 1 3 +2 sys_write
- 9.853 us +9.853 us - 5.503 us +5.503 us 0 6 +6 sys_rt_sigaction
- 6.998 us +6.998 us - 6.430 us +6.430 us 0 1 +1 sys_statfs
- 5.634 us +5.634 us - 5.634 us +5.634 us 0 3 +3 sys_newstat
- 5.449 us +5.449 us - 3.925 us +3.925 us 0 3 +3 sys_brk
- 5.327 us +5.327 us - 4.085 us +4.085 us 0 3 +3 sys_futex
- 4.470 us +4.470 us - 4.470 us +4.470 us 0 1 +1 finish_task_switch
- 3.929 us +3.929 us - 3.929 us +3.929 us 0 2 +2 sys_ftruncate
- 3.099 us +3.099 us - 3.099 us +3.099 us 0 1 +1 sys_access
- 2.976 us +2.976 us - 2.349 us +2.349 us 0 3 +3 sys_fcntl
- 1.780 us +1.780 us - 1.780 us +1.780 us 0 1 +1 smp_reschedule_interrupt
- 1.288 us +1.288 us - 1.288 us +1.288 us 0 3 +3 sys_getpid
- 0.854 us +0.854 us - 0.854 us +0.854 us 0 1 +1 sys_prlimit64
- 0.535 us +0.535 us - 0.535 us +0.535 us 0 1 +1 sys_rt_sigprocmask
- 0.499 us +0.499 us - 0.499 us +0.499 us 0 1 +1 sys_set_tid_address
- 0.443 us +0.443 us - 0.443 us +0.443 us 0 1 +1 sys_arch_prctl
- 0.383 us +0.383 us - 0.383 us +0.383 us 0 1 +1 sys_gettid
- 0.292 us +0.292 us - 0.292 us +0.292 us 0 1 +1 fsnotify
- 0.290 us +0.290 us - 0.290 us +0.290 us 0 1 +1 __fsnotify_parent
- 0.269 us +0.269 us - 0.269 us +0.269 us 0 1 +1 sys_set_robust_list
- 0.246 us +0.246 us - 0.246 us +0.246 us 0 1 +1 _raw_spin_lock_irq
0.526 us 0.548 us +0.022 us 0.526 us 0.548 us +0.022 us 1 1 0 __cxa_atexit
0.735 us 0.726 us -0.009 us 0.735 us 0.726 us -0.009 us 1 1 0 __monstartup
- - 0 us - - 0 us 0 1 +1 sys_exit_group
Python
Pour mémo, il est aussi possible d'appliquer des filtres plus évolués en utilisant Python. Voir la doc