company_banner

Strace в Linux: история, устройство и использование


    В Unix-подобных операционных системах общение программы с внешним миром и операционной системой происходит через небольшой набор функций — системных вызовов. А значит, в отладочных целях полезно бывает подсмотреть за выполняемыми процессами системными вызовами.


    Следить за «интимной жизнью» программ на Linux помогает утилита strace, которой и посвящена эта статья. К примерам использования «шпионского» оборудования прилагаются краткая история strace и описание устройства подобных программ.


    Содержание



    Происхождение видов


    Главный интерфейс между программами и ядром OC в Unix — системные вызовы (англ. system calls, syscalls), взаимодействие программ с внешним миром происходит исключительно через них.


    Но в первой публичной версии Unix (Version 6 Unix, 1975 год) удобных способов отслеживания поведения пользовательских процессов не было. Для решения этой проблемы Bell Labs к следующей версии (Version 7 Unix, 1979 год) предложили новый системный вызов — ptrace.


    Разрабатывался ptrace прежде всего для интерактивных отладчиков, но к концу 80-х (в эпоху коммерческого уже System V Release 4) на этой основе появились и получили широчайшее распространение узконаправленные отладчики — трассировщики системных вызовов.


    Первая же версия strace была опубликована Полом Кроненбургом в рассылке comp.sources.sun в 1992 году в качестве альтернативы закрытой утилите trace от Sun. Как клон, так и оригинал предназначались для SunOS, но к 1994 году strace была портирована на System V, Solaris и набирающий популярность Linux.


    Сегодня strace поддерживает только Linux и опирается на всё тот же ptrace, обросший множеством расширений.


    Современный (и весьма активный) мейнтейнер straceДмитрий Левин. Благодаря ему утилита обзавелась продвинутыми возможностями вроде инъекции ошибок в системные вызовы, поддержкой широкого спектра архитектур и, главное, маскотом. Неофициальные источники утверждают, что выбор пал на страуса из-за созвучности русского слова «страус» и английского "strace".


    Немаловажно и то, что системный вызов ptrace и трассировщики так и не были включены в POSIX, несмотря на долгую историю и наличие реализации в Linux, FreeBSD, OpenBSD и традиционных Unix.


    Устройство strace в двух словах: Piglet Trace


    "You are not expected to understand this" (Деннис Ричи, комментарий в исходном коде Version 6 Unix)

    С раннего детства я терпеть не могу чёрные ящики: с игрушками я не играл, а пытался разобраться в их устройстве (взрослые употребляли слово «ломал», но не верьте злым языкам). Возможно, поэтому мне так близки неформальная культура первых Unix и современного open-source-движения.


    В рамках этой статьи разбирать исходный код раздобревшей за десятилетия strace неразумно. Но и тайн для читателей оставаться не должно. Поэтому, чтобы показать принцип работы подобных strace программ, я приведу код миниатюрного трассировщика — Piglet Trace (ptr). Ничего особенного он делать не умеет, но главное — системные вызовы программы — выводит:


    $ gcc examples/piglet-trace.c -o ptr
    $ ptr echo test > /dev/null
    BRK(12) -> 94744690540544
    ACCESS(21) -> 18446744073709551614
    ACCESS(21) -> 18446744073709551614
    unknown(257) -> 3
    FSTAT(5) -> 0
    MMAP(9) -> 140694657216512
    CLOSE(3) -> 0
    ACCESS(21) -> 18446744073709551614
    unknown(257) -> 3
    READ(0) -> 832
    FSTAT(5) -> 0
    MMAP(9) -> 140694657208320
    MMAP(9) -> 140694650953728
    MPROTECT(10) -> 0
    MMAP(9) -> 140694655045632
    MMAP(9) -> 140694655070208
    CLOSE(3) -> 0
    unknown(158) -> 0
    MPROTECT(10) -> 0
    MPROTECT(10) -> 0
    MPROTECT(10) -> 0
    MUNMAP(11) -> 0
    BRK(12) -> 94744690540544
    BRK(12) -> 94744690675712
    unknown(257) -> 3
    FSTAT(5) -> 0
    MMAP(9) -> 140694646390784
    CLOSE(3) -> 0
    FSTAT(5) -> 0
    IOCTL(16) -> 18446744073709551591
    WRITE(1) -> 5
    CLOSE(3) -> 0
    CLOSE(3) -> 0
    unknown(231)
    Tracee terminated

    Piglet Trace распознает порядка сотни системных вызовов Linux (см. таблицу) и работает только на архитектуре x86-64. Для учебных целей этого достаточно.


    Давайте разберём работу нашего клона. В случае с Linux для отладчиков и трассировщиков используется, как упоминалось выше, системный вызов ptrace. Он работает посредством передачи в первом аргументе идентификаторов команд, из которых нам нужны только PTRACE_TRACEME, PTRACE_SYSCALL и PTRACE_GETREGS.


    Работа трассировщика начинается в обычном Unix-стиле: fork(2) запускает дочерний процесс, а тот в свою очередь с помощью exec(3) запускает исследуемую программу. Единственная тонкость здесь — вызов ptrace(PTRACE_TRACEME) перед exec: процесс-потомок ожидает, что процесс-родитель будет его отслеживать:


    pid_t child_pid = fork();
    switch (child_pid) {
    case -1:
        err(EXIT_FAILURE, "fork");
    case 0:
        /* Child here */
        /* A traced mode has to be enabled. A parent will have to wait(2) for it
         * to happen. */
        ptrace(PTRACE_TRACEME, 0, NULL, NULL);
        /* Replace itself with a program to be run. */
        execvp(argv[1], argv + 1);
        err(EXIT_FAILURE, "exec");
    }

    Процесс-родитель теперь должен вызвать wait(2) в дочернем процессе, то есть убедиться, что переключение в режим трассировки произошло:


    /* Parent */
    
    /* First we wait for the child to set the traced mode (see
     * ptrace(PTRACE_TRACEME) above) */
    if (waitpid(child_pid, NULL, 0) == -1)
        err(EXIT_FAILURE, "traceme -> waitpid");

    На этом приготовления закончены и можно приступать непосредственно к отслеживанию системных вызовов в бесконечном цикле.


    Вызов ptrace(PTRACE_SYSCALL) гарантирует, что последующий wait родителя завершится либо перед исполнением системного вызова, либо сразу после его завершения. Между двумя вызовами можно осуществить какие-либо действия: заменить вызов на альтернативный, изменить аргументы или возвращаемое значение.


    Нам же достаточно дважды вызвать команду ptrace(PTRACE_GETREGS), чтобы получить состояние регистра rax до вызова (номер системного вызова) и сразу после (возвращаемое значение).


    Собственно, цикл:


    /* A system call tracing loop, one interation per call. */
    for (;;) {
        /* A non-portable structure defined for ptrace/GDB/strace usage mostly.
         * It allows to conveniently dump and access register state using
         * ptrace. */
        struct user_regs_struct registers;
    
        /* Enter syscall: continue execution until the next system call
         * beginning. Stop right before syscall.
         *
         * It's possible to change the system call number, system call
         * arguments, return value or even avoid executing the system call
         * completely. */
      if (ptrace(PTRACE_SYSCALL, child_pid, NULL, NULL) == -1)
          err(EXIT_FAILURE, "enter_syscall");
      if (waitpid(child_pid, NULL, 0) == -1)
          err(EXIT_FAILURE, "enter_syscall -> waitpid");
    
      /* According to the x86-64 system call convention on Linux (see man 2
       * syscall) the number identifying a syscall should be put into the rax
       * general purpose register, with the rest of the arguments residing in
       * other general purpose registers (rdi,rsi, rdx, r10, r8, r9). */
      if (ptrace(PTRACE_GETREGS, child_pid, NULL, &registers) == -1)
          err(EXIT_FAILURE, "enter_syscall -> getregs");
    
      /* Note how orig_rax is used here. That's because on x86-64 rax is used
       * both for executing a syscall, and returning a value from it. To
       * differentiate between the cases both rax and orig_rax are updated on
       * syscall entry/exit, and only rax is updated on exit. */
      print_syscall_enter(registers.orig_rax);
    
      /* Exit syscall: execute of the syscall, and stop on system
       * call exit.
       *
       * More system call tinkering possible: change the return value, record
       * time it took to finish the system call, etc. */
      if (ptrace(PTRACE_SYSCALL, child_pid, NULL, NULL) == -1)
          err(EXIT_FAILURE, "exit_syscall");
      if (waitpid(child_pid, NULL, 0) == -1)
          err(EXIT_FAILURE, "exit_syscall -> waitpid");
    
      /* Retrieve register state again as we want to inspect system call
       * return value. */
      if (ptrace(PTRACE_GETREGS, child_pid, NULL, &registers) == -1) {
          /* ESRCH is returned when a child terminates using a syscall and no
           * return value is possible, e.g. as a result of exit(2). */
          if (errno == ESRCH) {
              fprintf(stderr, "\nTracee terminated\n");
              break;
          }
          err(EXIT_FAILURE, "exit_syscall -> getregs");
      }
    
      /* Done with this system call, let the next iteration handle the next
       * one */
      print_syscall_exit(registers.rax);
    }

    Вот и весь трассировщик. Теперь вы знаете, с чего начинать очередное портирование DTrace на Linux.


    Азы: запуск программы под управлением strace


    В качестве первого примера использования strace, пожалуй, стоит привести самый простой способ — запуск приложения под управлением strace.


    Чтобы не копаться в бесконечном списке вызовов типичной программы, напишем минимальную программу вокруг write:


    int main(int argc, char *argv[])
    {
        char str[] = "write me to stdout\n";
        /* write(2) is a simple wrapper around a syscall so it should be easy to
         * find in the syscall trace. */
        if (sizeof(str) != write(STDOUT_FILENO, str, sizeof(str))){
            perror("write");
            return EXIT_FAILURE;
        }
        return EXIT_SUCCESS;
    }
    

    Соберем программу и убедимся, что она работает:


    $ gcc examples/write-simple.c -o write-simple
    $ ./write-simple
    write me to stdout

    И наконец запустим ее под управлением strace:


    $ strace ./write-simple
    pexecve("./write", ["./write"], 0x7ffebd6145b0 /* 71 vars */) = 0
    brk(NULL)                               = 0x55ff5489e000
    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)
    openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
    fstat(3, {st_mode=S_IFREG|0644, st_size=197410, ...}) = 0
    mmap(NULL, 197410, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7a2a633000
    close(3)                                = 0
    access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
    openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
    mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7a2a631000
    mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7a2a04c000
    mprotect(0x7f7a2a233000, 2097152, PROT_NONE) = 0
    mmap(0x7f7a2a433000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f7a2a433000
    mmap(0x7f7a2a439000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7a2a439000
    close(3)                                = 0
    arch_prctl(ARCH_SET_FS, 0x7f7a2a6324c0) = 0
    mprotect(0x7f7a2a433000, 16384, PROT_READ) = 0
    mprotect(0x55ff52b52000, 4096, PROT_READ) = 0
    mprotect(0x7f7a2a664000, 4096, PROT_READ) = 0
    munmap(0x7f7a2a633000, 197410)          = 0
    write(1, "write me to stdout\n\0", 20write me to stdout
    )  = 20
    exit_group(0)                           = ?

    Очень «многословно» и не очень познавательно. Проблемы здесь две: вывод программы смешан с выводом strace и изобилие системных вызовов, которые нас не интересуют.


    Разделить стандартный поток вывода программы и вывод ошибок strace можно при помощи ключа -o, перенаправляющего список системных вызовов в файл-аргумент.


    Осталось разобраться с проблемой «лишних» вызовов. Предположим, что нас интересуют только вызовы write. Ключ -e позволяет указывать выражения, по которым будут фильтроваться системные вызовы. Самый популярный вариант условия — естественно, trace=*, при помощи которого можно оставить только интересующие нас вызовы.


    При одновременном использовании -o и -e мы получим:


    $ strace -e trace=write -owrite-simple.log ./write-simple
    write me to stdout
    $ cat write-simple.log
    write(1, "write me to stdout\n\0", 20
    )  = 20
    +++ exited with 0 +++

    Так, согласитесь, намного проще читается.


    А ещё можно убирать системные вызовы — например, связанные с выделением и освобождением памяти:


    $ strace -e trace=\!brk,mmap,mprotect,munmap -owrite-simple.log ./write-simple
    write me to stdout
    $ cat write-simple.log
    execve("./write-simple", ["./write-simple"], 0x7ffe9972a498 /* 69 vars */) = 0
    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)
    openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
    fstat(3, {st_mode=S_IFREG|0644, st_size=124066, ...}) = 0
    close(3)                                = 0
    access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
    openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
    close(3)                                = 0
    arch_prctl(ARCH_SET_FS, 0x7f00f0be74c0) = 0
    write(1, "write me to stdout\n\0", 20)  = 20
    exit_group(0)                           = ?
    +++ exited with 0 +++

    Обратите внимание на экранированный восклицательный знак в списке исключённых вызовов: этого требует командная оболочка (англ. shell).


    В моей версии glibc завершает исполнение процесса системный вызов exit_group, а не традиционный _exit. В этом состоит сложность работы с системными вызовами: интерфейс, с которым работает программист, не имеет прямого отношения к системным вызовам. Более того, он регулярно меняется в зависимости от реализации и платформы.


    Азы: присоединение к процессу на лету


    Изначально системный вызов ptrace, на котором построена strace, можно было использовать только при запуске программы в специальном режиме. Такое ограничение, быть может, звучало разумно во времена Version 6 Unix. В наши же дни этого уже недостаточно: бывает, нужно исследовать проблемы работающей программы. Типичный пример — заблокированный на дескрипторе или спящий процесс. Поэтому современная strace умеет присоединяться к процессам на лету.


    Пример зависающей программы:


    int main(int argc, char *argv[])
    {
        (void) argc; (void) argv;
    
        char str[] = "write me\n";
    
        write(STDOUT_FILENO, str, sizeof(str));
    
        /* Sleep indefinitely or until a signal arrives */
        pause();
    
        write(STDOUT_FILENO, str, sizeof(str));
    
        return EXIT_SUCCESS;
    }

    Соберём программу и убедимся в том, что она зависла:


    $ gcc examples/write-sleep.c -o write-sleep
    $ ./write-sleep
    ./write-sleep
    write me
    ^C
    $

    А теперь попробуем присоединиться к ней:


    $ ./write-sleep &
    [1] 15329
    write me
    $ strace -p 15329
    strace: Process 15329 attached
    pause(
    ^Cstrace: Process 15329 detached
     <detached ...>

    Программа заблокирована вызовом pause. Посмотрим, как она отреагирует на сигналы:


    $ strace -o write-sleep.log -p 15329 &
    strace: Process 15329 attached
    $
    $ kill -CONT 15329
    $ cat write-sleep.log
    pause()                                 = ? ERESTARTNOHAND (To be restarted if no handler)
    --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=14989, si_uid=1001} ---
    pause(
    $
    $ kill -TERM 15329
    $ cat write-sleep.log
    pause()                                 = ? ERESTARTNOHAND (To be restarted if no handler)
    --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=14989, si_uid=1001} ---
    pause()                                 = ? ERESTARTNOHAND (To be restarted if no handler)
    --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=14989, si_uid=1001} ---
    +++ killed by SIGTERM +++

    Мы запустили зависнувшую программу и присоединились к ней при помощи strace. Выяснились две вещи: системный вызов pause игнорирует сигналы без обработчиков и, что интереснее, strace отслеживает не только системные вызовы, но и входящие сигналы.


    Пример: отслеживание дочерних процессов


    Работа с процессами через вызов fork — основа всех Unix. Давайте посмотрим, как strace работает с деревом процессов на примере несложной «плодящейся» программы:


    int main(int argc, char *argv[])
    {
        pid_t parent_pid = getpid();
        pid_t child_pid = fork();
        if (child_pid == 0) {
            /* A child is born! */
            child_pid = getpid();
    
            /* In the end of the day printf is just a call to write(2). */
            printf("child (self=%d)\n", child_pid);
            exit(EXIT_SUCCESS);
        }
    
        printf("parent (self=%d, child=%d)\n", parent_pid, child_pid);
    
        wait(NULL);
    
        exit(EXIT_SUCCESS);
    }

    Здесь исходный процесс создаёт дочерний процесс, оба пишут в стандартный поток вывода:


    $ gcc examples/fork-write.c -o fork-write
    $ ./fork-write
    parent (self=11274, child=11275)
    child (self=11275)

    По умолчанию мы увидим только системные вызовы родительского процесса:


    $ strace -e trace=write -ofork-write.log ./fork-write
    child (self=22049)
    parent (self=22048, child=22049)
    $ cat fork-write.log
    write(1, "parent (self=22048, child=22049)"..., 33) = 33
    --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=22049, si_uid=1001, si_status=0, si_utime=0, si_stime=0} ---
    +++ exited with 0 +++

    Отслеживать дерево процессов целиком помогает флаг -f, с которым strace отслеживает системные вызовы в процессах-потомках. К каждой строке вывода при этом добавляется pid процесса, делающего системный вывод:


    $ strace -f -e trace=write -ofork-write.log ./fork-write
    parent (self=22710, child=22711)
    child (self=22711)
    $ cat fork-write.log
    22710 write(1, "parent (self=22710, child=22711)"..., 33) = 33
    22711 write(1, "child (self=22711)\n", 19) = 19
    22711 +++ exited with 0 +++
    22710 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=22711, si_uid=1001, si_status=0, si_utime=0, si_stime=0} ---
    22710 +++ exited with 0 +++

    В этом контексте может пригодиться фильтрация по группам системных вызовов:


    $ strace -f -e trace=%process -ofork-write.log ./fork-write
    parent (self=23610, child=23611)
    child (self=23611)
    $ cat fork-write.log
    23610 execve("./fork-write", ["./fork-write"], 0x7fff696ff720 /* 63 vars */) = 0
    23610 arch_prctl(ARCH_SET_FS, 0x7f3d03ba44c0) = 0
    23610 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3d03ba4790) = 23611
    23610 wait4(-1,  <unfinished ...>
    23611 exit_group(0)                     = ?
    23611 +++ exited with 0 +++
    23610 <... wait4 resumed> NULL, 0, NULL) = 23611
    23610 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=23611, si_uid=1001, si_status=0, si_utime=0, si_stime=0} ---
    23610 exit_group(0)                     = ?
    23610 +++ exited with 0 +++

    Кстати, какой системный вызов используется для создания нового процесса?


    Пример: пути к файлам вместо дескрипторов


    Знать файловые дескрипторы, безусловно, полезно, но имена конкретных файлов, к которым обращается программа, тоже могут пригодиться.


    Следующая программа пишет строку во временный файл:


    void do_write(int out_fd)
    {
        char str[] = "write me to a file\n";
    
        if (sizeof(str) != write(out_fd, str, sizeof(str))){
            perror("write");
            exit(EXIT_FAILURE);
        }
    }
    
    int main(int argc, char *argv[])
    {
        char tmp_filename_template[] = "/tmp/output_fileXXXXXX";
    
        int out_fd = mkstemp(tmp_filename_template);
        if (out_fd == -1) {
            perror("mkstemp");
            exit(EXIT_FAILURE);
        }
    
        do_write(out_fd);
    
        return EXIT_SUCCESS;
    }

    При обычном вызове strace покажет значение числа-дескриптора, переданного в системный вызов:


    $ strace -e trace=write -o write-tmp-file.log ./write-tmp-file
    $ cat write-tmp-file.log
    write(3, "write me to a file\n\0", 20)  = 20
    +++ exited with 0 +++

    С флагом -y утилита показывает путь к файлу, которому соответствует дескриптор:


    $ strace -y -e trace=write -o write-tmp-file.log ./write-tmp-file
    $ cat write-tmp-file.log
    write(3</tmp/output_fileCf5MyW>, "write me to a file\n\0", 20) = 20
    +++ exited with 0 +++

    Пример: отслеживание обращений к файлам


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


    void do_write(int out_fd)
    {
        char str[] = "write me to a file\n";
    
        if (sizeof(str) != write(out_fd, str, sizeof(str))){
            perror("write");
            exit(EXIT_FAILURE);
        }
    }
    
    int main(int argc, char *argv[])
    {
        /*
         * Path will be provided by the first program argument.
         *  */
        const char *path = argv[1];
    
        /*
         * Open an existing file for writing in append mode.
         *  */
        int out_fd = open(path, O_APPEND | O_WRONLY);
        if (out_fd == -1) {
            perror("open");
            exit(EXIT_FAILURE);
        }
    
        do_write(out_fd);
    
        return EXIT_SUCCESS;
    }
    

    По умолчанию strace выводит много лишней информации. Флаг -P с аргументом заставляет strace выводить только обращения к указанному файлу:


    $ strace -y -P/tmp/test_file.log -o write-file.log ./write-file /tmp/test_file.log
    $ cat write-file.log
    openat(AT_FDCWD, "/tmp/test_file.log", O_WRONLY|O_APPEND) = 3</tmp/test_file.log>
    write(3</tmp/test_file.log>, "write me to a file\n\0", 20) = 20
    +++ exited with 0 +++

    Пример: многопоточные программы


    Утилита strace может помочь и при работе с многопоточной программой. Следующая программа пишет в стандартный поток вывода из двух потоков:


    void *thread(void *arg)
    {
        (void) arg;
    
        printf("Secondary thread: working\n");
        sleep(1);
        printf("Secondary thread: done\n");
    
        return NULL;
    }
    
    int main(int argc, char *argv[])
    {
        printf("Initial thread: launching a thread\n");
    
        pthread_t thr;
        if (0 != pthread_create(&thr, NULL, thread, NULL)) {
            fprintf(stderr, "Initial thread: failed to create a thread");
            exit(EXIT_FAILURE);
        }
    
        printf("Initial thread: joining a thread\n");
        if (0 != pthread_join(thr, NULL)) {
            fprintf(stderr, "Initial thread: failed to join a thread");
            exit(EXIT_FAILURE);
        };
    
        printf("Initial thread: done");
    
        exit(EXIT_SUCCESS);
    }

    Собирать её надо, естественно, со специальным приветом линковщику — флагом -pthread:


    $ gcc examples/thread-write.c -pthread -o thread-write
    $ ./thread-write
    /thread-write
    Initial thread: launching a thread
    Initial thread: joining a thread
    Secondary thread: working
    Secondary thread: done
    Initial thread: done
    $

    Флаг -f, как и в случае с обычными процессами, добавит в начало каждой строки pid процесса.


    Естественно, речь идёт не об идентификаторе потока в смысле реализации стандарта POSIX Threads, а о номере, используемом планировщиком задач в Linux. С точки зрения последнего нет никаких процессов и потоков — есть задачи, которые надо распределить по доступным ядрам машины.

    При работе в несколько потоков системных вызовов становится слишком много:


    $ strace -f -othread-write.log ./thread-write
    $ wc -l thread-write.log
    60 thread-write.log

    Имеет смысл ограничиться только управлением процессами и системным вызовом write:


    $ strace -f -e trace="%process,write" -othread-write.log ./thread-write
    $ cat thread-write.log
    18211 execve("./thread-write", ["./thread-write"], 0x7ffc6b8d58f0 /* 64 vars */) = 0
    18211 arch_prctl(ARCH_SET_FS, 0x7f38ea3b7740) = 0
    18211 write(1, "Initial thread: launching a thre"..., 35) = 35
    18211 clone(child_stack=0x7f38e9ba2fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f38e9ba39d0, tls=0x7f38e9ba3700, child_tidptr=0x7f38e9ba39d0) = 18212
    18211 write(1, "Initial thread: joining a thread"..., 33) = 33
    18212 write(1, "Secondary thread: working\n", 26) = 26
    18212 write(1, "Secondary thread: done\n", 23) = 23
    18212 exit(0)                           = ?
    18212 +++ exited with 0 +++
    18211 write(1, "Initial thread: done", 20) = 20
    18211 exit_group(0)                     = ?
    18211 +++ exited with 0 +++

    Кстати, вопросы. Какой системный вызов используется для создания нового потока? Чем такой вызов для потоков отличается от вызова для процессов?


    Мастер-класс: стек процесса в момент системного вызова


    Одна из недавно появившихся в strace возможностей — отображение стека вызовов функций в момент системного вызова. Простой пример:


    void do_write(void)
    {
        char str[] = "write me to stdout\n";
        if (sizeof(str) != write(STDOUT_FILENO, str, sizeof(str))){
            perror("write");
            exit(EXIT_FAILURE);
        }
    }
    
    int main(int argc, char *argv[])
    {
        do_write();
        return EXIT_SUCCESS;
    }

    Естественно, вывод программы при этом становится очень объёмным, и, помимо флага -k (отображение стека вызовов), имеет смысл фильтровать системные вызовы по имени:


    $ gcc examples/write-simple.c -o write-simple
    $ strace -k -e trace=write -o write-simple.log ./write-simple
    write me to stdout
    $ cat write-simple.log
    write(1, "write me to stdout\n\0", 20)  = 20
     > /lib/x86_64-linux-gnu/libc-2.27.so(__write+0x14) [0x110154]
     > /home/vkazanov/projects-my/strace-post/write-simple(do_write+0x50) [0x78a]
     > /home/vkazanov/projects-my/strace-post/write-simple(main+0x14) [0x7d1]
     > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
     > /home/vkazanov/projects-my/strace-post/write-simple(_start+0x2a) [0x65a]
    +++ exited with 0 +++

    Мастер-класс: инъекция ошибок


    И ещё одна новая и очень полезная возможность: инъекция ошибок. Вот программа, пишущая две строки в поток вывода:


    #include <unistd.h>
    #include <stdio.h>
    #include <stdlib.h>
    
    void do_write(const char *str, ssize_t len)
    {
        if (len != write(STDOUT_FILENO, str, (size_t)len)){
            perror("write");
            exit(EXIT_FAILURE);
        }
    }
    
    int main(int argc, char *argv[])
    {
        (void) argc; (void) argv;
    
        char str1[] = "write me 1\n";
        do_write(str1, sizeof(str1));
    
        char str2[] = "write me 2\n";
        do_write(str2, sizeof(str2));
    
        return EXIT_SUCCESS;
    }

    Отслеживаем оба вызова write:


    $ gcc examples/write-twice.c -o write-twice
    $ ./write-twice
    write me 1
    write me 2
    $ strace -e trace=write -owrite-twice.log ./write-twice
    write me 1
    write me 2
    $ cat write-twice.log
    write(1, "write me 1\n\0", 12)          = 12
    write(1, "write me 2\n\0", 12)          = 12
    +++ exited with 0 +++

    А теперь используем выражение inject, чтобы вставить ошибку EBADF во все вызовы write:


    $ strace -e trace=write -e inject=write:error=EBADF -owrite-twice.log ./write-twice
    $ cat write-twice.log
    write(1, "write me 1\n\0", 12)          = -1 EBADF (Bad file descriptor) (INJECTED)
    write(3, "write: Bad file descriptor\n", 27) = -1 EBADF (Bad file descriptor) (INJECTED)
    +++ exited with 1 +++

    Интересно, что ошибки возвращают все вызовы write, включая вызов, скрытый за perror. Имеет смысл возвращать ошибку только для первого из вызовов:


    $ strace -e trace=write -e inject=write:error=EBADF:when=1 -owrite-twice.log ./write-twice
    write: Bad file descriptor
    $ cat write-twice.log
    write(1, "write me 1\n\0", 12)          = -1 EBADF (Bad file descriptor) (INJECTED)
    write(3, "write: Bad file descriptor\n", 27) = 27
    +++ exited with 1 +++

    Или второго:


    $ strace -e trace=write -e inject=write:error=EBADF:when=2 -owrite-twice.log ./write-twice
    write me 1
    write: Bad file descriptor
    $ cat write-twice.log
    write(1, "write me 1\n\0", 12)          = 12
    write(1, "write me 2\n\0", 12)          = -1 EBADF (Bad file descriptor) (INJECTED)
    write(3, "write: Bad file descriptor\n", 27) = 27
    +++ exited with 1 +++

    Тип ошибки указывать не обязательно:


    $ strace -e trace=write -e fault=write:when=1 -owrite-twice.log ./write-twice
    $ cat write-twice.log
    write(1, "write me 1\n\0", 12)          = -1 ENOSYS (Function not implemented) (INJECTED)
    write(3, "write: Function not implemented\n", 32) = 32
    +++ exited with 1 +++

    В сочетании с другими флагами можно «ломать» обращения к конкретному файлу. Пример:


    $ strace -y -P/tmp/test_file.log -e inject=file:error=ENOENT -o write-file.log ./write-file /tmp/test_file.log
    open: No such file or directory
    $ cat write-file.log
    openat(AT_FDCWD, "/tmp/test_file.log", O_WRONLY|O_APPEND) = -1 ENOENT (No such file or directory) (INJECTED)
    +++ exited with 1 +++

    Помимо инъекций ошибок, можно вводить задержки при выполнении вызовов или получении сигналов.


    Послесловие


    Утилита strace — простой и надёжный инструмент. Но помимо системных вызовов отлаживать случается и другие аспекты работы программ и операционной системы. Например, отслеживать вызовы динамически линкуемых библиотек умеет ltrace, заглянуть в работу операционной системы могут SystemTap и ftrace, а глубоко исследовать производительность программ позволяет perf. Тем не менее именно strace — первая линия обороны в случае проблем с собственными и чужими программами, и использую я её минимум пару раз в неделю.


    Словом, любите Unix, читайте man 1 strace и не стесняйтесь подглядывать за вашими программами!

    Badoo
    Big Dating

    Comments 9

      +9
      Классная статья, спасибо! В тестировании тоже периодически приходится использовать strace.
      Может быть удобно использовать флаг -ff, который вместе с -o распределяет весь вывод по файлам с постфиксом ".%PID%"
      Также стоит упомянуть и про -s — иначе все строки обрезаются до 32 символов, а иногда хочется иметь весь вывод, чтобы что-нибудь погрепать в нём.
        0

        Точно, спасибо! :-) Про -ff не знал, да, удобно.


        А вот про -s знал, но всего и не напишешь. В большей степени я эту статью задумывал ради демонстрации новых возможностей: инъекций ошибок и отображения стека в момент вызова.

        +3
        strace иногда незаменим, особенно когда запущенный процесс никуда не пишет, но и не функционирует. Очень часто выручает. Спасибо за статью!
          +2

          точно, на этот случай приходится процентов 80 из всех моих запусков strace. :-)

          +4
          Огромное и большое вам человеческое спасибо! Извините за мой не особо информативный комментарий, много приходится трейсить и бОльшую только исключительно на чисто интуитивном уровне понимал.
            +1

            Так ли нужен теперь dtrace когда eBPF шагает по планете? :)

              +2

              Я не евангелист DTrace, это была больше шутка про несколько существующих портов и клонов под Линуксами.


              Но при чем здесь eBPF? :-) Dtrace — полный комплект для трассировки и программирования поведения ядра, включающий как пользовательские утилиты, так и изменения в ядре ОС. eBPF же — достаточно низкоуровневая штука, сама по себе пользователям ничего не дающая.

                +2

                Я понимаю референс и шутку, многие годы dtrace был неким философским камнем в мире трейсинга Linux, нюанс скорее в том, что вокруг eBPF уже выстроен тулинг, дающий намного больше возможностей чем strace и даже dtrace — например bpftrace или sysdig. Последний например у нас развернут по всей инфре и очень часто выручает.

                  +2

                  Да уж, воистину eBPF — отдельная вселенная прораммируемых ядер :-)

            Only users with full accounts can post comments. Log in, please.