Linux: strace – отслеживаем выполнение процесса

Автор: | 17/02/2016
Нет комментариев
 

linux_logostrace – утилита для Linux, которая позволяет отследить выполнение системных вызовов (system call) и сигналов к ядру системы.

Для примера возьмем простую программу на С, которая выводит содержимое указанного файла:

#include <stdio.h>
#include <stdlib.h>

int main()
{
   char ch, file_name[25];
   FILE *fp;                          

   printf("Enter the name of file you wish to see\n");
   gets(file_name);
   fp = fopen(file_name,"r"); // read mode
   if( fp == NULL )
   {                       
      perror("Error while opening the file.\n");
      exit(EXIT_FAILURE);                                            
   }
                                                                   
   printf("The contents of %s file are :\n", file_name);
                                    
   while( ( ch = fgetc(fp) ) != EOF )
      printf("%c",ch);
   fclose(fp);
   return 0;
}

Ее выполнение:

[simterm]

$ ./openfile
Enter the name of file you wish to see
openfile.c                                                      
The contents of openfile.c file are :
#include <stdio.h>
#include <stdlib.h>
                              
int main()
{
...
   return 0;
}

[/simterm]

Отображение всех вызовов

Запускаем openfile с starce:

[simterm]

$ strace ./openfile
execve("./openfile", ["./openfile"], [/* 30 vars */]) = 0
brk(0)                                  = 0x85b000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e074b000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=47052, ...}) = 0
mmap(NULL, 47052, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fb7e073f000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY)      = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\356\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1920936, ...}) = 0
mmap(NULL, 3750152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb7e0199000
mprotect(0x7fb7e0323000, 2097152, PROT_NONE) = 0
mmap(0x7fb7e0523000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18a000) = 0x7fb7e0523000
mmap(0x7fb7e0528000, 18696, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fb7e0528000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e073e000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e073d000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e073c000
arch_prctl(ARCH_SET_FS, 0x7fb7e073d700) = 0
mprotect(0x7fb7e0523000, 16384, PROT_READ) = 0
mprotect(0x7fb7e074c000, 4096, PROT_READ) = 0
munmap(0x7fb7e073f000, 47052)           = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 7), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e074a000
write(1, "Enter the name of file you wish "..., 39Enter the name of file you wish to see
) = 39
fstat(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 7), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e0749000
read(0, openfile.c
"openfile.c\n", 1024)           = 11
brk(0)                                  = 0x85b000
brk(0x87c000)                           = 0x87c000
open("openfile.c", O_RDONLY)            = 3
write(1, "The contents of openfile.c file "..., 38The contents of openfile.c file are :
) = 38
fstat(3, {st_mode=S_IFREG|0664, st_size=486, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb7e0748000
read(3, "#include <stdio.h>\n#include <std"..., 4096) = 486
write(1, "#include <stdio.h>\n", 19#include <stdio.h>
)    = 19
write(1, "#include <stdlib.h>\n", 20#include <stdlib.h>
...
write(1, "   fclose(fp);\n", 15   fclose(fp);
)        = 15
write(1, "   return 0;\n", 13   return 0;
)          = 13
write(1, "}\n", 2}
)                      = 2
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7fb7e0748000, 4096)            = 0
exit_group(0)                           = ?
+++ exited with 0 +++

[/simterm]

Например, тут виден вызов mmap(), который выполняет запрос на выделение памяти:

[simterm]

...
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f115bfbb000
...

[/simterm]

Проверяем:

[simterm]

# pmap 23342 | grep 7f115bfbb
00007f115bfbb000     12K rw---    [ anon ]

[/simterm]

Или – файлы, к которым выполняется системный вызов open(), после передачи имени файла функции gets():

[simterm]

write(1, "Enter the name of file you wish "..., 39Enter the name of file you wish to see
) = 39
...
open("openfile.c", O_RDONLY)            = 3
write(1, "The contents of openfile.c file "..., 38The contents of openfile.c file are :
) = 38

[/simterm]

Отображение определенных вызовов

Что бы вывести только список интересующих системных вызовов – используйте опцию -e.

Например – отобразить только вызовы open():

[simterm]

$ strace -e open ./openfile
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libc.so.6", O_RDONLY)      = 3
Enter the name of file you wish to see
openfile.c
open("openfile.c", O_RDONLY)            = 3
The contents of openfile.c file are :
#include <stdio.h>
#include <stdlib.h>
 
int main()
{
   char ch, stpchar, file_name[25];
   FILE *fp;
...

[/simterm]

Что бы отобразить несколько определенных вызовов – добавьте -e trace=, и через запятую – список вызовов:

[simterm]

$ strace -e trace=open,mmap ./openfile
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b7a7000
open("/etc/ld.so.cache", O_RDONLY)      = 3
mmap(NULL, 47052, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fd11b79b000
open("/lib64/libc.so.6", O_RDONLY)      = 3
mmap(NULL, 3750152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fd11b1f5000
mmap(0x7fd11b57f000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18a000) = 0x7fd11b57f000
mmap(0x7fd11b584000, 18696, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fd11b584000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b79a000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b799000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b798000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b7a6000
Enter the name of file you wish to see
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd11b7a5000
...

[/simterm]

Сохранение вывода в файл

Так как текста может быть много – иногда вывод удобнее сохранить в файл.

Для этого используйте опцию -o:

[simterm]

$ strace -o openfile_strace.log -e trace=open,mmap ./openfile
Enter the name of file you wish to see
sc
Error while opening the file.

[/simterm]

Результат:

[simterm]

$ cat openfile_strace.log 
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fee12b6f000
open("/etc/ld.so.cache", O_RDONLY)      = 3
...
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fee12b6d000
open("sc", O_RDONLY)                    = -1 ENOENT (No such file or directory)
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fee12b6c000
+++ exited with 1 +++

[/simterm]

Трассировка вызовов запущенного процесса

Для подключения к уже работающему процессу – используйте опцию -p.

Например – берем любой PID:

[simterm]

$ ps -au setevoy
  PID TTY          TIME CMD
 1334 ?        00:04:17 uwsgi
 1335 ?        00:04:17 uwsgi
 1749 ?        00:13:26 uwsgi
...

[/simterm]

Подключаемся к нему, записывая вывод в файл:

[simterm]

$ sudo strace -p 1334 -o uwsgi_strace.log -e mmap
[sudo] password for setevoy: 
Process 1334 attached
^CProcess 1334 detached

[/simterm]

Проверяем:

[simterm]

$ cat uwsgi_strace.log 
lseek(2, 0, SEEK_CUR)                   = 525797
getsockopt(3, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0d\0\0\0"..., [104]) = 0
wait4(-1, 0x7ffc5a5853ac, WNOHANG, NULL) = 0
...
getsockopt(3, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0d\0\0\0"..., [104]) = 0
wait4(-1, 0x7ffc5a5853ac, WNOHANG, NULL) = 0
epoll_wait(9,  <detached ...>

[/simterm]

Отображение времени выполнения вызова

Добавим опцию -t:

[simterm]

$ strace -t -e trace=open,mmap ./openfile
14:04:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7a31229000
14:04:51 open("/etc/ld.so.cache", O_RDONLY) = 3
...
14:04:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7a3121b000
14:04:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7a3121a000
...

[/simterm]

Статистика системных вызовов

С помощью опции -c – можно получить наглядную статистику выполнения программы:

[simterm]

$ strace -c ./openfile
Enter the name of file you wish to see
openfile.c
The contents of openfile.c file are :
#include <stdio.h>
#include <stdlib.h>
.. 

   fclose(fp);
   return 0;
}
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           read
  0.00    0.000000           0        31           write
  0.00    0.000000           0         3           open
  0.00    0.000000           0         3           close
  0.00    0.000000           0         5           fstat
  0.00    0.000000           0        11           mmap
  0.00    0.000000           0         3           mprotect
  0.00    0.000000           0         2           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    68         1 total

[/simterm]

Получить подробную информацию о каждом вызове можно тут>>> .

Например, вызов:

[simterm]

...
open("openfile.c", O_RDONLY)            = 3
...

[simterm]

Описан тут>>>.

А сам вызов open() можно найти тут>>>, после чего – найти исходный код open.c, в котором и определяется open():

[simterm]

...
SYSCALL_DEFINE3(open, const char __user *, filename, int, flags, umode_t, mode)
...

[/simterm]

Ссылки по теме

http://www.digilife.be – LINUX System Call Quick Reference