MC, 09:21 czwartek, 12.04.2018 r.
Linux strace - TOP 12 przykładów
Pragnę w tym artykule zestawić 12, w mojej ocenie najbardziej przydatnych wywołań programu monitorującego strace. Nie będę tutaj jednak wchodził w szczegóły tego, czym ten program jest, jak działa i jak analizować logi stworzone przy jego pomocy. Zostawię sobie tę problematykę na jeden z kolejnych wpisów. Tutaj chciałbym pozostawić jedynie listę praktycznych snippetów. Zachęcam do lektury.
Słowem wstępu
Choć na początku artykułu zaznaczyłem, że nie będzie to wpis poświęcony teorii stojącej za programem strace, to jednak kilka słów objaśniających, z czym ma się do czynienia, wypada powiedzieć. Zatem, ujmując sprawę najkrócej, strace pozwala na podgląd i analizę wywołań poleceń systemowych wydawanych przez wskazany proces, przy czym możemy strace’em proces taki uruchomić, bądź podłączyć się do już działającego. Jest to zatem jedno z podstawowych narzędzi administratora systemu, a także świetna pomoc w odrobaczaniu programów i szukaniu problemów wydajnościowych.
W całym artykule poza jednym przypadkiem analizuję polecenie pwd, które wyświetla obecną lokację w terminalu. Proszę zwrócić uwagę i może nawet zadziwić się przez moment, jak wiele poleceń systemowych jest wykonywanych przez, zdawałoby się, tak prostą komendę.
$ pwd /home/mateusz/Pulpit
1. Uruchomienie procesu i podstawowy podgląd poleceń systemowych
Zacznę od wywołania najprostszego, a mianowicie od uruchomienia procesu przy pomocy strace i podglądu wszystkich poleceń systemowych aż do jego zakończenia.
strace [polecenie]
$ strace pwd
execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
brk(0) = 0x1b5f000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fdfe464d000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fdfe464c000
mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fdfe4087000
mprotect(0x7fdfe4245000, 2097152, PROT_NONE) = 0
mmap(0x7fdfe4445000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7fdfe4445000
mmap(0x7fdfe444b000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fdfe444b000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fdfe464a000
arch_prctl(ARCH_SET_FS, 0x7fdfe464a740) = 0
mprotect(0x7fdfe4445000, 16384, PROT_READ) = 0
mprotect(0x606000, 4096, PROT_READ) = 0
mprotect(0x7fdfe4672000, 4096, PROT_READ) = 0
munmap(0x7fdfe464d000, 149391) = 0
brk(0) = 0x1b5f000
brk(0x1b80000) = 0x1b80000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fdfe3870000
close(3) = 0
getcwd("/home/mateusz/Pulpit", 4096) = 21
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fdfe4671000
write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21
close(1) = 0
munmap(0x7fdfe4671000, 4096) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++Zgodnie z zapowiedzią, log jest całkiem obszerny, dlatego w kolejnych przykładach będę nieco zawężać zakres informacji, starając się wyłuskać to, co rzeczywiście może mnie w danej sytuacji interesować.
2. Wyświetlenie logów tylko jednego polecenia systemowego
Spróbuję teraz ograniczyć log z poprzedniego przykładu wyłącznie do jednego polecenia systemowego, np. open().
strace -e trace=[nazwa polecenia systemowego] [polecenie]
$ strace -e trace=open pwd
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
/home/mateusz/Pulpit
+++ exited with 0 +++Zdecydowanie mniejszy szum informacyjny, jeśli więc wiadomo, czego się szuka, warto pominąć niepotrzebne wywołania.
3. Wyświetlenie logów wyłącznie wskazanych poleceń systemowych
Przykład podobny do poprzedniego, z tą różnicą, że poproszę o logi z więcej niż jednego polecenia systemowego..
strace -e trace=[polecenia systemowe oddzielone przecinkiem] [polecenie]
$ strace -e trace=open,close pwd
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
close(3) = 0
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
close(3) = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
close(3) = 0
/home/mateusz/Pulpit
close(1) = 0
close(2) = 0
+++ exited with 0 +++4. Zapis logów do pliku
Kiedy potrzebna jest szczegółowa analiza całego logu, na przykład gdy poszukujemy bliżej nieokreślonego problemu, warto zapisać wyniki działania programu strace do pliku.
strace -o [plik wyjściowy] [polecenie]
$ strace -o straceOut.txt pwd /home/mateusz/Pulpit
$ cat straceOut.txt
execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
brk(0) = 0x204f000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5274075000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5274074000
mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5273aaf000
mprotect(0x7f5273c6d000, 2097152, PROT_NONE) = 0
mmap(0x7f5273e6d000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f5273e6d000
mmap(0x7f5273e73000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5273e73000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5274072000
arch_prctl(ARCH_SET_FS, 0x7f5274072740) = 0
mprotect(0x7f5273e6d000, 16384, PROT_READ) = 0
mprotect(0x606000, 4096, PROT_READ) = 0
mprotect(0x7f527409a000, 4096, PROT_READ) = 0
munmap(0x7f5274075000, 149391) = 0
brk(0) = 0x204f000
brk(0x2070000) = 0x2070000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5273298000
close(3) = 0
getcwd("/home/mateusz/Pulpit", 4096) = 21
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5274099000
write(1, "/home/mateusz/Pulpitn", 21) = 21
close(1) = 0
munmap(0x7f5274099000, 4096) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++5. Podłączanie się do istniejącego procesu
Do tej pory w każdym przykładzie inicjowałem proces razem z wywołaniem strace. Tym razem podłączę się do już istniejącego, przy pomocy numeru PID (więcej o pobieraniu numeru PID). Procesem tym jest polecenie top, któremu przypisane jest PID 18739. Proszę zwrócić uwagę, że tym razem należy wywołać strace na prawach admina.
sudo strace -p [numer PID procesu]
$ sudo strace -p 18739
pselect6(1, [0], NULL, NULL, {0, 868139653}, {[], 8}) = 0 (Timeout)
openat(AT_FDCWD, "/proc", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
getdents(3, /* 356 entries */, 32768) = 9072
stat("/proc/1", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
open("/proc/1/stat", O_RDONLY) = 8
read(8, "1 (init) S 0 1 1 0 -1 4219136 62"..., 1024) = 178
close(8) = 0
open("/proc/1/statm", O_RDONLY) = 8
read(8, "8506 1145 675 62 0 480 0n", 1024) = 25
close(8) = 0
[...]6. Śledzenie procesów potomnych
Czasem zachodzi potrzeba śledzenia poczynań nie tylko wskazanego procesu, ale również wszystkich innych procesów, które on wywołuje (procesy potomne).
sudo strace -f [polecenie]
$ strace -f pwd
execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
brk(0) = 0x114a000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f574de99000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f574de98000
mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f574d8d3000
mprotect(0x7f574da91000, 2097152, PROT_NONE) = 0
mmap(0x7f574dc91000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f574dc91000
mmap(0x7f574dc97000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f574dc97000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f574de96000
arch_prctl(ARCH_SET_FS, 0x7f574de96740) = 0
mprotect(0x7f574dc91000, 16384, PROT_READ) = 0
mprotect(0x606000, 4096, PROT_READ) = 0
mprotect(0x7f574debe000, 4096, PROT_READ) = 0
munmap(0x7f574de99000, 149391) = 0
brk(0) = 0x114a000
brk(0x116b000) = 0x116b000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f574d0bc000
close(3) = 0
getcwd("/home/mateusz/Pulpit", 4096) = 21
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f574debd000
write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21
close(1) = 0
munmap(0x7f574debd000, 4096) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++7. Sprawdzanie jakie inne programy otwiera proces
Pozostaję w kontekście poprzedniego przykładu, czyli śledzę procesy główny i potomne, zawężając jednak pytanie, do tego, jakie inne programy są uruchamiane przez nie uruchamiane. Bardzo przydatne wywołanie!
strace -fe trace=execve [polecenie]
$ strace -fe trace=execve pwd
execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
/home/mateusz/Pulpit
+++ exited with 0 +++8. Dołączenie timestamp do logów wywołań
Czasem bardzo cenną informacją podczas analizy logów strace jest moment w czasie, kiedy dane polecenie systemowe zostało wywołane. Dołączenie znacznika czasu (timestamp) sprowadza się do dodania flagi do wywołania strace.
strace -t [polecenie]
$ strace -t pwd
07:10:49 execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
07:10:49 brk(0) = 0x1749000
07:10:49 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
07:10:49 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
07:10:49 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
07:10:49 fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
07:10:49 mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7fc9d0a000
07:10:49 close(3) = 0
07:10:49 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
07:10:49 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
07:10:49 read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
07:10:49 fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
07:10:49 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7fc9d09000
07:10:49 mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7fc9744000
07:10:49 mprotect(0x7f7fc9902000, 2097152, PROT_NONE) = 0
07:10:49 mmap(0x7f7fc9b02000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f7fc9b02000
07:10:49 mmap(0x7f7fc9b08000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7fc9b08000
07:10:49 close(3) = 0
07:10:49 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7fc9d07000
07:10:49 arch_prctl(ARCH_SET_FS, 0x7f7fc9d07740) = 0
07:10:49 mprotect(0x7f7fc9b02000, 16384, PROT_READ) = 0
07:10:49 mprotect(0x606000, 4096, PROT_READ) = 0
07:10:49 mprotect(0x7f7fc9d2f000, 4096, PROT_READ) = 0
07:10:49 munmap(0x7f7fc9d0a000, 149391) = 0
07:10:49 brk(0) = 0x1749000
07:10:49 brk(0x176a000) = 0x176a000
07:10:49 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
07:10:49 fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
07:10:49 mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7fc8f2d000
07:10:49 close(3) = 0
07:10:49 getcwd("/home/mateusz/Pulpit", 4096) = 21
07:10:49 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
07:10:49 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7fc9d2e000
07:10:49 write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21
07:10:49 close(1) = 0
07:10:49 munmap(0x7f7fc9d2e000, 4096) = 0
07:10:49 close(2) = 0
07:10:49 exit_group(0) = ?
07:10:49 +++ exited with 0 +++9. Dołączenie Linux-epoch timestamp do logów wywołań
Choć ja osobiście, nigdy z tego nie korzystałem, warto odnotować możliwość przedstawienia znaczników czasu w formacie czasu unixowego.
strace -ttt [polecenie]
$ strace -ttt pwd
1523509849.031836 execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
1523509849.032025 brk(0) = 0x1776000
1523509849.032057 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
1523509849.032089 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
1523509849.032116 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
1523509849.032144 fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
1523509849.032171 mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fe1a97a5000
1523509849.032198 close(3) = 0
1523509849.032223 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
1523509849.032253 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
1523509849.032279 read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
1523509849.032306 fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
1523509849.032331 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe1a97a4000
1523509849.032362 mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fe1a91df000
1523509849.032387 mprotect(0x7fe1a939d000, 2097152, PROT_NONE) = 0
1523509849.032415 mmap(0x7fe1a959d000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7fe1a959d000
1523509849.032445 mmap(0x7fe1a95a3000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fe1a95a3000
1523509849.032474 close(3) = 0
1523509849.032504 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe1a97a2000
1523509849.032531 arch_prctl(ARCH_SET_FS, 0x7fe1a97a2740) = 0
1523509849.032591 mprotect(0x7fe1a959d000, 16384, PROT_READ) = 0
1523509849.032618 mprotect(0x606000, 4096, PROT_READ) = 0
1523509849.032645 mprotect(0x7fe1a97ca000, 4096, PROT_READ) = 0
1523509849.032669 munmap(0x7fe1a97a5000, 149391) = 0
1523509849.032751 brk(0) = 0x1776000
1523509849.032773 brk(0x1797000) = 0x1797000
1523509849.032802 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
1523509849.032829 fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
1523509849.032854 mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fe1a89c8000
1523509849.032882 close(3) = 0
1523509849.032928 getcwd("/home/mateusz/Pulpit", 4096) = 21
1523509849.032957 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
1523509849.032983 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe1a97c9000
1523509849.033009 write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21
1523509849.033044 close(1) = 0
1523509849.033067 munmap(0x7fe1a97c9000, 4096) = 0
1523509849.033092 close(2) = 0
1523509849.033116 exit_group(0) = ?
1523509849.033170 +++ exited with 0 +++10. Dołączenie czasu trwania wywołań systemowych
Podczas analizy wydajności programu bardzo istotną informacją może być czas wykonywania każdego z poleceń systemowych.
strace -T [polecenie]
$ strace -T pwd
execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0 <0.000106>
brk(0) = 0x1e44000 <0.000007>
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000009>
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000008>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000009>
fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0 <0.000008>
mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f23b7b69000 <0.000008>
close(3) = 0 <0.000007>
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000008>
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000009>
read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832 <0.000007>
fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0 <0.000007>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f23b7b68000 <0.000008>
mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f23b75a3000 <0.000009>
mprotect(0x7f23b7761000, 2097152, PROT_NONE) = 0 <0.000012>
mmap(0x7f23b7961000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f23b7961000 <0.000010>
mmap(0x7f23b7967000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f23b7967000 <0.000009>
close(3) = 0 <0.000007>
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f23b7b66000 <0.000008>
arch_prctl(ARCH_SET_FS, 0x7f23b7b66740) = 0 <0.000007>
mprotect(0x7f23b7961000, 16384, PROT_READ) = 0 <0.000009>
mprotect(0x606000, 4096, PROT_READ) = 0 <0.000008>
mprotect(0x7f23b7b8e000, 4096, PROT_READ) = 0 <0.000008>
munmap(0x7f23b7b69000, 149391) = 0 <0.000013>
brk(0) = 0x1e44000 <0.000008>
brk(0x1e65000) = 0x1e65000 <0.000008>
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 <0.000010>
fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0 <0.000007>
mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f23b6d8c000 <0.000008>
close(3) = 0 <0.000007>
getcwd("/home/mateusz/Pulpit", 4096) = 21 <0.000008>
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 <0.000009>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f23b7b8d000 <0.000009>
write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21 <0.000014>
close(1) = 0 <0.000007>
munmap(0x7f23b7b8d000, 4096) = 0 <0.000011>
close(2) = 0 <0.000008>
exit_group(0) = ?
+++ exited with 0 +++11. Dołączenie względnego czasu wywołań systemowych
W pewnych sytuacjach wygodnie będzie analizować logi, mając przed oczyma relatywny czas między początkami następujących po sobie poleceń.
strace -r [polecenie]
$ strace -r pwd
0.000000 execve("/bin/pwd", ["pwd"], [/* 79 vars */]) = 0
0.000194 brk(0) = 0x1bc6000
0.000036 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000048 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000026 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
0.000025 fstat(3, {st_mode=S_IFREG|0644, st_size=149391, ...}) = 0
0.000025 mmap(NULL, 149391, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8ccb1ca000
0.000024 close(3) = 0
0.000033 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000022 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
0.000021 read(3, "177ELF211���������3�>�1���P 2�����"..., 832) = 832
0.000021 fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
0.000020 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8ccb1c9000
0.000024 mmap(NULL, 3965632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8ccac04000
0.000021 mprotect(0x7f8ccadc2000, 2097152, PROT_NONE) = 0
0.000022 mmap(0x7f8ccafc2000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f8ccafc2000
0.000025 mmap(0x7f8ccafc8000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f8ccafc8000
0.000023 close(3) = 0
0.000025 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8ccb1c7000
0.000023 arch_prctl(ARCH_SET_FS, 0x7f8ccb1c7740) = 0
0.000056 mprotect(0x7f8ccafc2000, 16384, PROT_READ) = 0
0.000025 mprotect(0x606000, 4096, PROT_READ) = 0
0.000024 mprotect(0x7f8ccb1ef000, 4096, PROT_READ) = 0
0.000018 munmap(0x7f8ccb1ca000, 149391) = 0
0.000071 brk(0) = 0x1bc6000
0.000018 brk(0x1be7000) = 0x1be7000
0.000022 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
0.000023 fstat(3, {st_mode=S_IFREG|0644, st_size=8482320, ...}) = 0
0.000020 mmap(NULL, 8482320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8cca3ed000
0.000023 close(3) = 0
0.000043 getcwd("/home/mateusz/Pulpit", 4096) = 21
0.000022 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
0.000020 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8ccb1ee000
0.000022 write(1, "/home/mateusz/Pulpitn", 21/home/mateusz/Pulpit
) = 21
0.000030 close(1) = 0
0.000018 munmap(0x7f8ccb1ee000, 4096) = 0
0.000021 close(2) = 0
0.000018 exit_group(0) = ?
0.000046 +++ exited with 0 +++12. Raport z czasu spędzonego na poszczególnych wywołaniach systemowych
Bardzo przydatne polecenie, szczególnie jeśli szuka się problemów wydajnościowych, a nie bardzo wiadomo, od czego zacząć. Dostaniemy listę poleceń systemowych uporządkowaną malejąco pod względem czasu w nich spędzonego, wraz z podaniem tego czasu (również wyrażonego procentowo, w stosunku do całego czasu pracy procesu), oraz liczbę wystąpień poszczególnych wywołań.
strace -c [polecenie]
$ strace -c pwd /home/mateusz/Pulpit % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 27.75 0.000048 16 3 open 21.97 0.000038 5 8 mmap 12.14 0.000021 7 3 3 access 9.25 0.000016 4 4 mprotect 7.51 0.000013 7 2 munmap 5.20 0.000009 2 5 close 4.62 0.000008 2 4 fstat 3.47 0.000006 2 3 brk 2.89 0.000005 5 1 write 1.73 0.000003 3 1 read 1.73 0.000003 3 1 execve 1.16 0.000002 2 1 getcwd 0.58 0.000001 1 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000173 37 3 total
Komentarze (0) - Nikt jeszcze nie komentował - bądź pierwszy!