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

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


Две основные задачи современных операционных систем — абстракция и мультиплексирование. Абстракция означает, что когда, к примеру, программе необходимо считать данные или записать их на диск, ей не требуется уметь работать с SATA протоколом, SCSI-, IDE-, USB-дисками или же NFS. Программа использует общий язык директорий и файлов, а операционная система превращает этот абстрактный язык в то, что должно быть выполнено на вашем оборудовании.

Мультиплексирование означает, что ваша и моя программы получают справедливый доступ к оборудованию, и не могут влиять друг на друга. Это также означает, что ваша программа не может обойти ядро на самом низком уровне, и общаться с вашими SATA или SCSI дисками, даже если захочет этого.

Почти за всем, что хочет сделать программа, ей необходимо обратиться к ядру. Хочешь прочитать или записать файл? Сделай системный вызов open(), а затем вызовы read() или write(). Хочешь общаться по сети? Тебе необходимы вызовы socket(), connect() и снова read() и write(). Хочешь создать больше процессов? Сначала сделай clone() (в стандартной библиотеке Си функция fork()), потом ты, вероятно, захочешь сделать execve(), чтобы новый процесс запустился отдельной программой, и захочешь как-то взаимодействовать с ним, посредством чего-то из wait4(), kill(), pipe() и многих других. Даже для того, чтобы узнать время, необходим системный вызов — clock_gettime(). Мы обнаружим все эти вызовы, когда будем трассировать программу.

На самом деле, единственное, что процесс может делать без системных вызовов — чистые вычисления с использованием только процессора, памяти и ничего более. Именно это я, как бывший алгоритмист, считал интересной строной работы. К счастью для нас, сисадминов, очень мало реальных программ проводят много времени в этой чистой сфере между взаимодействием с файлами, сетью или какими-то другими частями системы, и вот тогда их и ловит strace.

Примеры решения проблем с использованием strace

Применение №1: Понимание реального поведения сложной программы

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

Я люблю ковыряться в коде, и немного работал с кодом Git, поэтому я потратил некоторое время, изучая исходники. Но код был довольно сложный, и я понял далеко не всё. Поэтому я решил получить правдивый, основаный на фактах ответ, на вопрос: «если я запущу `git diff`, установит ли он блокировку?».

Здесь на помощь приходит Strace. Устанавливается блокировка — файл index.lock. Всё, что попытается получить доступ к файлу, выявится в strace. Поэтому мы можем просто оттрассировать команду и использовать grep, чтобы увидеть, упоминался ли там index.lock:

1 2 3 4

$ strace git status 2>&1 >/dev/null | grep index.lock open(".git/index.lock", O_RDWR|O_CREAT|O_EXCL, 0666) = 3 rename(".git/index.lock", ".git/index") = 0 $ strace git diff 2>&1 >/dev/null | grep index.lock

Итак, `git status` использует блокировку, а `git diff` нет.

Вставка: Панель инструментов

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

Как говорится, перейдем к делу

Иногда мы не можем позволить себе роскошь запустить программу с самого начала под strace: она уже запущена, глючит, и нам надо выяснить, что происходит. К счастью, strace легко справится с этой задачей. Вместо команды на запуск и трассировку в strace вы просто указываете -p PID, где PID — это номер процесса в системе (я использую `pstree -p`, чтобы узнать его). Strace аттачится к этой программе, в то время как она продолжает работать, и начнёт сообщать вам всё, чем исследуемая программа занимается.

Секундомер

Когда я использую strace, то почти всегда пользуюсь опцией -tt. Она показывает, когда выполнялся каждый системный вызов — -t выводит время с точностью до секунд, а -tt — до микросекунд. В системном администрировании это часто помогает сопоставить работу программы с записями о её исполнении в других логах или увидеть, где программа тратит слишком много времени.

При проблеммах с производительностью будет удобной опция -T — она покажет, как долго выполнялся каждый syscall.

Данные

По умолчанию, strace выводит строки, которые программа и система передают друг другу: имена файлов, прочитанные и записанные данные и т.д. Для удобства чтения вывода строки обрезаются до 32х знаков. Вы можете увидеть больше, указав опцию -s — `-s 1024`. В этом случае вы получите вывод длиной до 1024 знаков для каждой строки. Вы можете вообще убрать вывод, указав -s 0.

Иногда вам надо видеть все данные, идущие всего в нескольких направлениях, без перемешивания трассировки с другими потоками данных. Здесь пригодятся опции `-e read=` и `-e write`.

Например, у вас есть программа, которая обращается к серверу базы данных, и вы хотите увидеть SQL-запросы, но не объёмные данные, идущие обратно. Запросы и ответы выполняются посредством системных вызовов write() и read() с сокетом, связанным с базой данных. Чтобы увидеть как выполняются эти системные вызовы, сначала взгляните на трассировку:

1 2 3 4 5 6 7 8 9

$ strace -p 9026 Process 9026 attached - interrupt to quit read(3, "\1\0\0\1\1A\0\0\2\3def\7youtomb\tartifacts\ta"..., 16384) = 116 poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout) write(3, "0\0\0\0\3SELECT timestamp FROM artifa"..., 52) = 52 read(3, "\1\0\0\1\1A\0\0\2\3def\7youtomb\tartifacts\ta"..., 16384) = 116 poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout) write(3, "0\0\0\0\3SELECT timestamp FROM artifa"..., 52) = 52 [...]

Вызовы write() — SQL-запросы: мы можем разглядеть исчезающие "SELECT foo FROM bar". Чтобы увидеть остальные, заметьте дескриптор файла, к которому обращены системные вызовы — первый аргумент команд read() и write(), в нашем примере это 3. Передайте дескриптор файла через параметр `-e write=`:

1 2 3 4 5 6 7 8 9

$ strace -p 9026 -e write=3 Process 9026 attached - interrupt to quit read(3, "\1\0\0\1\1A\0\0\2\3def\7youtomb\tartifacts\ta"..., 16384) = 116 poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout) write(3, "0\0\0\0\3SELECT timestamp FROM artifa"..., 52) = 52 | 00000 30 00 00 00 03 53 45 4c 45 43 54 20 74 69 6d 65 0....SEL ECT time | | 00010 73 74 61 6d 70 20 46 52 4f 4d 20 61 72 74 69 66 stamp FR OM artif | | 00020 61 63 74 73 20 57 48 45 52 45 20 69 64 20 3d 20 acts WHE RE id = | | 00030 31 34 35 34 1454 |

и мы увидим весь запрос. Вне зависимости от того в каком виде запрос(шестнадцатеричном или бинарном), он выводится в шестнадцатеричной системе счисления. Так же мы можем получить весь запрос при помощи опции '-s 1024', но тогда мы увидим все данные возвращаемые read() — использование -e write= позволяет выделять и выбирать нужные именно нам.

Фильтрация вывода

Иногда полная трассировка системных вызовов занимает слишком много усилий— вы просто хотите видеть, к каким файлам обращается программа, или когда пишет и читает данные, или что-то ещё. Для этого была сделана опция -e trace=. Вы можете выбрать именованную группу системных вызовов, например -e trace=file (для системных вызовов, упоминающих имена файлов) или -e trace=desc (для read() и write() и им похожих, которые упоминают файловые дескрипторы), или упоминая отдельные системные вызовы вручную. Мы используем это в следующем примере.

Дочерние процессы

Иногда процесс, который вы исследуете, в действительности ничего не делает сам, но поручает какую-то работу своим дочерним процессы. Shell-скрипты и Make — известные крайности такого поведения. Если это ваш случай, нужно передать опцию -f, чтобы заставить strace "следовать форкам" и трассировать также и дочерние процессы по мере их появления.

Например, вот результат трассировки простого шелл-скрипта без -f:

1 2 3 4 5 6 7 8

$ strace -e trace=process,file,desc sh -c \ 'for d in .git/objects/*; do ls $d >/dev/null; done' [...] stat("/bin/ls", {st_mode=S_IFREG|0755, st_size=101992, ...}) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f4b68af5770) = 11948 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 11948 --- SIGCHLD (Child exited) @ 0 (0) --- wait4(-1, 0x7fffc3473604, WNOHANG, NULL) = -1 ECHILD (No child processes)

Здесь почти не на что смотреть — настоящая работа была сделана внутри процесса 11948, созданного системным вызовом clone().

Вот тот же скрипт, но с параметром -f (и вывод был отредактирован для краткости):

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27

$ strace -f -e trace=process,file,desc sh -c \ 'for d in .git/objects/*; do ls $d >/dev/null; done' [...] stat("/bin/ls", {st_mode=S_IFREG|0755, st_size=101992, ...}) = 0 clone(Process 10738 attached child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5a93f99770) = 10738 [pid 10682] wait4(-1, Process 10682 suspended     [pid 10738] open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 [pid 10738] dup2(3, 1) = 1 [pid 10738] close(3) = 0 [pid 10738] execve("/bin/ls", ["ls", ".git/objects/28"], [/* 25 vars */]) = 0 [... setup of C standard library omitted ...] [pid 10738] stat(".git/objects/28", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 10738] open(".git/objects/28", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3 [pid 10738] getdents(3, /* 40 entries */, 4096) = 2480 [pid 10738] getdents(3, /* 0 entries */, 4096) = 0 [pid 10738] close(3) = 0 [pid 10738] write(1, "04102fadac20da3550d381f444ccb5676"..., 1482) = 1482 [pid 10738] close(1) = 0 [pid 10738] close(2) = 0 [pid 10738] exit_group(0) = ? Process 10682 resumed Process 10738 detached <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 10738 --- SIGCHLD (Child exited) @ 0 (0) ---

Теперь этот вывод будет миниатюрным учебником по Unix - чем не тема для следующего поста? Главное - вы видите работу ls, при этом за вызовом open() следует getdents().

Если исследуется несколько процессов за раз, вывод быстро засоряется, так что иногда вам пригодится параметр -ff, он заставляет strace писать дамп каждого процесса в отдельный файл.

Применение №2: Где и почему программа зависла?

Иногда программа, казалось бы, ничего не делает. Скорее всего, это значит, что она заблокирована на каком-то системном вызове. Исследуем её, чтобы избавиться от этого.

1 2 3

$ strace -p 22067 Process 22067 attached - interrupt to quit flock(3, LOCK_EX

Вот заблокированная попытка установить блокировку, это эксклюзивная блокировка (LOCK_EX) на файл с дескриптором 3. Что это за файл?

1 2	$ readlink /proc/22067/fd/3 /tmp/foobar.lock

Ага, этот файл /tmp/foobar.lock. И какой процесс удерживает эту блокировку?

1 2 3

$ lsof | grep /tmp/foobar.lock command 21856 price 3uW REG 253,88 0 34443743 /tmp/foobar.lock command 22067 price 3u REG 253,88 0 34443743 /tmp/foobar.lock

Процесс 21856 удерживает блокировку. Теперь мы можем узнать, почему он держит ее так долго, в то время как эта блокировка нужна 21856 и 22067.

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

• Прослушивание сети. Используйте lsof, чтобы узнать имя удалённого хоста и порт.
• 
  
• Попытка прочитать директорию. Не смейтесь — это действительно может произойти, когда у вас огромная директория с тысячами файлов. И если директория раньше была огромной, а теперь мала, то на типичных файловых системах, таких, как ext3, она становится длинным списком записей вроде "нечего тут смотреть", поэтому один системный вызов может занять минуты на сканирование удалённых файлов перед тем, как вернуть список выживших.
• 
  
• Отсутствие системных вызовов вообще. Это значит, что программа делает чистые вычисления, возможно ряд каких-то математических вычислений. Вы вне strace зоны; удачи.
• 
  

Остальные примеры использования.

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

• В качестве прогрессбара. Когда программа в середине длинной задачи, и требуется оценить, осталось ещё три часа или три дня, strace скажет вам, что происходит прямо сейчас — а чуть-чуть смекалки поможет рассчитать время до завершения задачи.
• 
  
• Измерение задержек. Нет лучшего способа узнать сколько времени требуется вашему приложению для обращения к удаленному серверу, чем следить за тем, как оно выполняет вызовы read() к серверу, с помощью `strace -T` в качестве секундомера.
• 
  
• Определение тонких мест. Профилировщики хороши, но они не всегда отражают структуру вашей программы. Вы когда нибудь пробовали профилировать shell скрипт? Иногда самые лучшие результаты получаются при записи результатов `strace -tt` в файл. Просмотрев его, вы поймете где начинается и заканчивается каждый этап вашей программы.
• 
  
• Как инструмент для обучения и изучения. На границе "пользователь/ядро" происходит много чего интересного в вашей системе. Поэтому, если вы хотите узнать больше о том, как ваша система работает — почему бы не погрузиться в man и результаты вывода strace?
• 
  

Оригинал (английский)
Переведено при помощи сервиса translated.by инициативной группой переводчиков welinux при участии пользователей mhspace, wiz, Zereal, Transmitter, Pipeliner, dr_lo, settler.