Comment mesurer le temps que prennent les appels système liés aux fichiers en perf ?

Question

J'ai une application qui tourne anormalement lentement. J'ai des raisons de penser que cela peut être dû au fait que certains fichiers spécifiques sont plus lents à lire et à statuer.

Je sais que je peux utiliser Strace pour obtenir des informations sur la synchronisation, mais je préférerais utiliser perf parce que l'overhead est beaucoup plus faible.

Brendan Gregg propose quelques exemples utiles d'utilisation de perf :

http://www.brendangregg.com/perf.html

Mais son premier exemple d'appel système ne montre que les délais globaux pour tous les appels et j'ai besoin de délais par fichier. Son deuxième exemple d'appel système n'inclut pas les délais, et ne montre que les numéros de fd, pas les chemins réels.

Comment puis-je rassembler les pièces ? Je cherche à obtenir quelque chose de similaire à ce que je pourrais obtenir avec "strace -Tttt -e trace=file".

Un bonus supplémentaire serait que je puisse mesurer les cycles en même temps.

Answer 1

Sortie de strace -Tttt -e trace=file est trace (outil de traçage), et perf est généralement utilisé comme outil de profilage (agrégation du temps passé dans une fonction par nom - en perf record par défaut sur le temps ou sur les événements matériels + perf report , perf top ) ou comme outil de statistiques (dans les modes perf stat mode - avec comptage de certains événements sur toute la durée du programme).

Vous devriez essayer un outil de traçage ( trace-cmd , sysdig , lttng , ...) ou vous pouvez essayer d'utiliser perf dans les modes de traçage ( perf record avec des tracepoints et perf script pour produire un journal non agrégé dans le temps)

Il existe des tracepoints pour les appels système ( syscalls 614 ) : http://www.brendangregg.com/perf.html#Tracepoints http://www.brendangregg.com/perf.html#StaticKernelTracing

perf record -e 'syscalls:sys_*' ./program
perf script

Exemple de sortie au format : nom du processus, pid, [cpu_core], time_since_boot_seconds.microseconds :, tracepoint_name, tracepoint_arguments

          ls 19178 [001]  16529.466566:                   syscalls:sys_enter_open: filename: 0x7f6ae4c38f82, flags: 0x00080000, mode: 0x
          ls 19178 [001]  16529.466570:                    syscalls:sys_exit_open: 0x4
          ls 19178 [001]  16529.466570:               syscalls:sys_enter_newfstat: fd: 0x00000004, statbuf: 0x7ffe22df92f0
          ls 19178 [001]  16529.466572:                syscalls:sys_exit_newfstat: 0x0
          ls 19178 [001]  16529.466573:                   syscalls:sys_enter_mmap: addr: 0x00000000, len: 0x00042e6f, prot: 0x00000001,
          ls 19178 [001]  16529.466767:                    syscalls:sys_exit_mmap: 0x7f6ae4df8000
          ls 19178 [001]  16529.466768:                  syscalls:sys_enter_close: fd: 0x00000004
          ls 19178 [001]  16529.466769:                   syscalls:sys_exit_close: 0x0

Vous pouvez également essayer perf record -g -e 'syscalls:sys_*' pour enregistrer le backtrace de la fonction (pour obtenir des informations sur la fonction de l'application qui a fait l'appel système, et qui a appelé cette fonction ; fonctionne mieux avec les informations de débogage).

perf en tant qu'outil de traçage ne peut pas décoder les arguments de syscall (tracepoint) ; et les outils de traçage comme trace-cmd ou lttng peuvent mieux les décoder (au moins décoder le nom de fichier dans syscall ouvert).