Translate

субота, 3 серпня 2013 р.

Debug with Strace

Іноді програма не працює як необхідно: незрозуміло які вона читає налаштування чи сегфолтиться в самий непідходящий момент. Саме тому, коли необхідної інформації недостатньо в системних логах, буває корисно скористатись якимось простим деббагером і strace гарно виконує цю роль.

Strace - трасувальник системних викликів і сигналів, інакше кажучи деббагер, котрий здатний виводити результати в системний термінал. Працює в ОС Linux та деяких Unix-системах. Робота програми можлива завдяки системному виклику ptrace ("process trace") в ядрі ОС.

Для початку його необхідно його установити:

# apt-get install strace

Розпочнемо з найбільш простого прикладу: перевіримо, які системні виклики з'являються при запуску команди ls

$ strace ls
 execve("/bin/ls", ["ls"], [/* 49 vars */]) = 0
brk(0)                                  = 0x6ef000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa60c3a3000
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=147033, ...}) = 0
mmap(NULL, 147033, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa60c37f000
close(3)                                = 0
....
write(1, "8154c50c.jpg\t\t   Desktop\t\t\t  fil"..., 618154c50c.jpg  Desktop  films out.log  walls
) = 61
close(1)                                = 0
munmap(0x7fa60c3a2000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?

Рівень розуміння виводу прямо пропорційний рівню розуміння системних викликів та сигналів, проте певні сигнали звісно говорять самі за себе. Вивід можна обмежити лише певними системними викликами, наприклад, таким чином можна дізнатись до яких файлів звертається команда ls під час запуску:

$ strace -e open ls
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libacl.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/proc/filesystems", O_RDONLY)     = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
1356091645_1761625816.gif  bbndk-2.0.0  Downloads  fun_cat_fb.png      Pictures
1.jpg   braid  Dropbox    IMG_20130417_170447.jpg  spaghetti.gif
6ODmF.gif   CentOS-6.4-x86_64-minimal.iso  FBlA4.gif  libpeerconnection.log    VirtualBox

Якщо необхідно обмежити вивід лише декількох типів системних викликів слід скористатись опцією “-e trace=”. У наступному прикладі будуть виведені системні виклики open та read:

$ strace -e trace=open,read ls /home
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200V\0\0\0\0\0\0"..., 832) = 832
open("/lib/x86_64-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
..
open("/proc/filesystems", O_RDONLY)     = 3
read(3, "nodev\tsysfs\nnodev\trootfs\nnodev\tb"..., 1024) = 455
read(3, "", 1024)                       = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
aptdaemon-V23c5w   orbit-ipeacocks qtsingleapp-smplay-ca73-3e8-lockfile
clementine-art-uI2885.jpg  pulse-PKdhtXMmr18n sni-qt_clementine_2885-GpWHJG
clementine-art-xE2885.jpg  qtsingleapp-clemen-d211-3e8 sni-qt_skype_2465-OedXfc
CRX_75DAF8CB7768   qtsingleapp-clemen-d211-3e8-lockfile  ssh-VW7itVwzp0x5
hsperfdata_ipeacocks   qtsingleapp-homeip-9044-3e8 YO4wo2bZ.part
keyring-kRH5Qz   qtsingleapp-homeip-9044-3e8-lockfile

Результати роботи starce можна перенаправити в файл, для цього необхідно використовувати опцію "-o":

$ strace -o output.txt ls
1356091645_1761625816.gif  bbndk-2.0.0  Downloads  fun_cat_fb.png      output.txt      walls
1.jpg   braid  Dropbox    IMG_20130417_170447.jpg  Pictures
6ODmF.gif   CentOS-6.4-x86_64-minimal.iso  FBlA4.gif  libpeerconnection.log    spaghetti.gif

Отже, увесь результат роботи strace потрапить в output.txt

Strace-ом можна також підключитись до програми (опція "-p PID"), що вже виконується і побачити системні виклики, що вона генерує:

$ ps -C chrome
  PID TTY          TIME CMD
 4691 ?        00:06:51 chrome
 ..
 4696 ?        00:00:09 chrome

# strace -p 4691 -o chrome_trace.txt
Process 4691 attached - interrupt to quit
^CProcess 4691 detached

Іноді зручно виводити час кожного виклику чи сигналу. Для цього буде дуже доречна опція "-t":

$ strace -t -e open nano dbwordpress.sql
17:03:40 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
17:03:40 open("/lib/x86_64-linux-gnu/libncursesw.so.5", O_RDONLY|O_CLOEXEC) = 3
17:03:40 open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
17:03:40 open("/usr/share/locale/en/LC_MESSAGES/nano.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
..
17:03:40 open("/usr/share/nano/ruby.nanorc", O_RDONLY) = 4
17:03:40 open("/usr/share/nano/java.nanorc", O_RDONLY) = 4
17:03:40 open("/root/.nanorc", O_RDONLY) = -1 ENOENT (No such file or directory)
17:03:40 open("/root/.nano_history", O_RDONLY) = -1 ENOENT (No such file or directory)
17:03:40 open("/lib/terminfo/x/xterm", O_RDONLY) = 3

А так можна зібрати статистику по системним викликам, що породжує будь-яка програма:

$ strace -c nano dbwordpress.sql
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0       136           read
  -nan    0.000000           0         7           write
  -nan    0.000000           0        38         4 open
  -nan    0.000000           0        36         2 close
  -nan    0.000000           0        33         2 stat
  -nan    0.000000           0        34           fstat
  -nan    0.000000           0         3           poll
  -nan    0.000000           0         2           lseek
  -nan    0.000000           0        45           mmap
  -nan    0.000000           0        10           mprotect
  -nan    0.000000           0        29           munmap
  -nan    0.000000           0        18           brk
  -nan    0.000000           0        19           rt_sigaction
  -nan    0.000000           0         7           rt_sigprocmask
  -nan    0.000000           0        34           ioctl
  -nan    0.000000           0         8         7 access
  -nan    0.000000           0        17           mremap
  -nan    0.000000           0         1           execve
  -nan    0.000000           0         2           fcntl
  -nan    0.000000           0         2           getcwd
  -nan    0.000000           0         1           geteuid
  -nan    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   483        15 total

Накінець додам приклад із життя:

# strace php 2>&1 | grep php.ini
open("/usr/bin/php.ini", O_RDONLY)      = -1 ENOENT (No such file or directory)
open("/etc/php5/cli/php.ini", O_RDONLY) = 3

З виводу стає зрозумілим. що php намагається прочитати спочатку /usr/bin/php.ini, проте він відсутній і читає лише /etc/php5/cli/php.ini.

http://sourceforge.net/projects/strace/
http://www.thegeekstuff.com/2011/11/strace-examples/
http://www.hokstad.com/5-simple-ways-to-troubleshoot-using-strace
http://habrahabr.ru/post/92123/
http://rus-linux.net/MyLDP/kernel/Inotify-tools.html
http://stackoverflow.com/questions/7566569/how-to-continuosly-monitor-the-directory-using-dnotify-inotify-command

Немає коментарів:

Дописати коментар