[[https://github.com/namhyung/uftrace|Code source]], [[https://github.com/namhyung/uftrace/tree/master/doc|Doc]] [[https://www.youtube.com/watch?v=s0B8hV2O8ps|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===== 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. [[https://github.com/namhyung/uftrace/blob/master/doc/uftrace-live.md|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 [[https://github.com/namhyung/uftrace/tree/review/auto-args-v2|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''. {{:prog:uftrace:tracing.png|Tracing}} Pour mémo : [[https://github.com/catapult-project/catapult/blob/master/tracing/bin/trace2html|trace2html]] et [[https://github.com/brendangregg/FlameGraph|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 [[https://github.com/namhyung/uftrace/blob/master/doc/uftrace-script.md|doc]]