Debian // Call Trace
Последний Stable Debian. На борту: squid, postfix, dovecot, LAMP. Вот что выдаёт в логе. С Дебианом вожусь впервые и многое непонятно, но стараюсь вроде всё найти в нете. С этим маюсь уже неделю. Никак не пойму что это, критично ли это. Понимаю что что-то с сидюком, но он работает нормально. Что сие может означать?
Aug 13 22:11:36 gateway kernel: [17795.124760] Call Trace:
Aug 13 22:11:36 gateway kernel: [17795.124790] [] :ide_cd_mod:cdrom_do_newpc_cont+0x0/0x2b
Aug 13 22:11:36 gateway kernel: [17795.124799] [] schedule_timeout+0x1e/0xad
Aug 13 22:11:36 gateway kernel: [17795.124816] [] :ide_core:ide_do_request+0x8cd/0x930
Aug 13 22:11:36 gateway kernel: [17795.124825] [] :ide_cd_mod:cdrom_newpc_intr+0x0/0x5e1
Aug 13 22:11:36 gateway kernel: [17795.124840] [] :ide_core:ide_do_request+0x1c/0x930
Aug 13 22:11:36 gateway kernel: [17795.124847] [] wait_for_common+0xcf/0x13a
Aug 13 22:11:36 gateway kernel: [17795.124852] [] default_wake_function+0x0/0xe
Aug 13 22:11:36 gateway kernel: [17795.124870] [] :ide_core:ide_do_drive_cmd+0xe2/0x109
Aug 13 22:11:36 gateway kernel: [17795.124882] [] :ide_cd_mod:ide_cd_queue_pc+0x42/0xca
Aug 13 22:11:36 gateway kernel: [17795.124889] [] :ide_cd_mod:ide_cd_queue_pc+0x42/0xca
Aug 13 22:11:36 gateway kernel: [17795.124895] [] blk_rq_init+0x1c/0x85
Aug 13 22:11:36 gateway kernel: [17795.124905] [] :ide_cd_mod:cdrom_read_tocentry+0xb1/0xc3
Aug 13 22:11:36 gateway kernel: [17795.124927] [] blk_end_sync_rq+0x0/0x2e
Aug 13 22:11:36 gateway kernel: [17795.124938] [] :ide_cd_mod:ide_cd_read_toc+0x101/0x3c8
Aug 13 22:11:36 gateway kernel: [17795.124952] [] :ide_cd_mod:idecd_revalidate_disk+0x14/0x1b
Aug 13 22:11:36 gateway kernel: [17795.124959] [] __invalidate_device+0x3a/0x42
Aug 13 22:11:36 gateway kernel: [17795.124964] [] check_disk_change+0x4f/0x76
Aug 13 22:11:36 gateway kernel: [17795.124973] [] :cdrom:cdrom_open+0x983/0xa14
Aug 13 22:11:36 gateway kernel: [17795.124980] [] dput+0x1c/0xdd
Aug 13 22:11:36 gateway kernel: [17795.124984] [] kobject_get+0x12/0x17
Aug 13 22:11:36 gateway kernel: [17795.124989] [] get_disk+0x40/0x5b
Aug 13 22:11:36 gateway kernel: [17795.124994] [] exact_lock+0xc/0x14
Aug 13 22:11:36 gateway kernel: [17795.125003] [] :ide_cd_mod:idecd_open+0x5b/0x89
Aug 13 22:11:36 gateway kernel: [17795.125007] [] blkdev_open+0x0/0x5d
Aug 13 22:11:36 gateway kernel: [17795.125012] [] do_open+0xd1/0x2e8
Aug 13 22:11:36 gateway kernel: [17795.125019] [] blkdev_open+0x0/0x5d
Aug 13 22:11:36 gateway kernel: [17795.125023] [] blkdev_open+0x2e/0x5d
Aug 13 22:11:36 gateway kernel: [17795.125029] [] __dentry_open+0x12c/0x238
Aug 13 22:11:36 gateway kernel: [17795.125037] [] do_filp_open+0x3d7/0x7c4
Aug 13 22:11:36 gateway kernel: [17795.125045] [] :cdrom:cdrom_release+0x1a7/0x1e4
Aug 13 22:11:36 gateway kernel: [17795.125055] [] iput+0x27/0x60
Aug 13 22:11:36 gateway kernel: [17795.125062] [] get_unused_fd_flags+0x71/0x115
Aug 13 22:11:36 gateway kernel: [17795.125070] [] do_sys_open+0x46/0xc3
Aug 13 22:11:36 gateway kernel: [17795.125076] [] system_call_after_swapgs+0x8a/0x8f
Aug 13 22:11:36 gateway kernel: [17795.125085]
Aug 13 22:13:45 gateway kernel: [17923.972736] hald-addon-st D0000000000000000 0 3459 3431
Aug 13 22:13:45 gateway kernel: [17923.972742] ffff81002c105878 0000000000000082 0000000000000000 ffffffffa0117b00
Aug 13 22:13:45 gateway kernel: [17923.972747] ffff81002c0c94f0 ffffffff804f8480 ffff81002c0c9778 0000000037987400
Aug 13 22:13:45 gateway kernel: [17923.972752] ffffffffa0117b90 0000000000000000 00000000ffffffff 0000000000000000
nvariec
14.08.09 09:19:23 MSD
Трассировка ядра с ftrace
Проблемы трассировки и профилирования ядра мы уже затрагивали в предыдущих публикациях. Для анализа событий на уровне ядра существует много специализированных инструментов: SystemTap, Ktap, Sysdig, LTTNG и другие. Об этих инструментах опубликовано много подробных статей и обучающих материалов.
Гораздо меньше информации можно найти о «родных» механизмах Linux, с помощью которых можно отслеживать системные события, получать и анализировать отладочную информацию. Эту тему мы хотели бы рассмотреть в сегодняшней статье. Особое внимание мы уделим ftrace — первому и пока что единственному инструменту трассировки, добавленному в ядро. Начнём с определения основных понятий.
Профилирование и трассировка ядра
Профилирование ядра — это выявление «узких мест» в производительности. С помощью профилирования можно определить, где именно произошла потеря производительности в той или иной программе. Специальные программы генерируют профиль — сводку событий, на основе которой можно выяснить, на выполнение каких функций ушло больше всего времени. Эти программы, однако, не помогают выявить причину снижения производительности.
«Узкие места» очень часто возникают при определённых условиях, которые при профилировании выявить невозможно. Чтобы понять, почему произошло то или иное событие, требуется восстанавливать контекст. В свою очередь, для восстановления контекста требуется трассировка.
Под трассировкой понимается получение информации о том, что происходит внутри работающей системы. Для этого используются специальные программные инструменты. Они регистрируют все события в системе подобно тому, как магнитофон записывает все звуки окружающей среды.
Программы-трассировщики могут одновременно отслеживать события как на уровне отдельных приложений, так и на уровне операционной системы. Полученная в ходе трассировки информация может оказаться полезной для диагностики и решения многих системных проблем.
Трассировку иногда сравнивают с логгированием. Сходство между этими двумя процедурами действительно есть, но есть и различия.
Во время трассировки записывается информация о событиях, происходящих на низком уровне. Их количество исчисляется сотнями и даже тысячами. В логи же записывается информация о высокоуровневых событиях, которые случаются гораздо реже: например, вход пользователей в систему, ошибки в работе приложений, транзакции в базах данных и другие.
Как и логи, файлы с данными трассировки можно читать «с листа». Гораздо интереснее и полезнее, однако, извлекать из них информацию, которая относится к работе конкретных приложений. Соответствующие функции есть у всех программ-трассировщиков.
В ядре Linux существует три основных механизма, при помощи которых осуществляются процедуры трассировки и профилирования ядра:
- tracepoints — механизм, работающий через статическое инструментирование кода;
- kprobes — механизм динамической трассировки, с помощью которого можно прервать выполнение кода ядра в любом месте, вызвать собственный обработчик и по завершении всех необходимых операций вернуться обратно;
- perf_events — интерфейс доступа к PMU (Performance Monitoring Unit).
Подробно расписывать особенности всех этих механизмов не будем; заинтересованных читателей отсылаем к статье компании «НТЦ МетроТек», а также к блогу Брендана Грегга.
С помощью ftrace можно взаимодействовать с этими механизмами и получать отладочные данные, находясь в пользовательском пространстве. Более подробно об этом мы поговорим ниже. Все примеры команд приводятся для ОС Ubuntu 14.04, ядро версии 3.13.0-24.
Ftrace: общая информация
Название ftrace представляет собой сокращение от Function Trace — трассировка функций. Однако возможности этого инструмента гораздо шире: с его помощью можно отслеживать контекстные переключения, измерять время обработки прерываний, высчитывать время на активизацию заданий с высоким приоритетом и многое другое.
Ftrace был разработан Стивеном Ростедтом и добавлен в ядро в 2008 году, начиная с версии 2.6.27. Это — фреймворк, предоставляющий отладочный кольцевой буфер для записи данных. Собирают эти данные встроенные в ядро программы-трассировщики.
Работает ftrace на базе файловой системы debugfs, которая в большинстве современных дистрибутивов Linux смонтирована по умолчанию. Чтобы приступить к работе с ftrace, нужно просто перейти в директорию sys/kernel/debug/tracing (она доступна только для root-пользователя):
# cd /sys/kernel/debug/tracing
Подробно рассказывать обо всех содержащихся в ней файлах и поддиректориях мы не будем — это уже сделано в официальной документации. Кратко опишем лишь те из них, которые представляют интерес в контексте нашего рассмотрения:
- available_tracers — доступные программы-трассировщики;
current_tracer — программа-трассировщик, активная в текущий момент; - tracing_on — служебный файл, отвечающий за включение и отключение записи данных в кольцевой буфер (чтобы включить запись, нужно записать в этот файл цифру 1, а чтобы отключить — 0);
- trace — файл, где хранятся данные трассировки в человекочитаемом формате.
Доступные трассировщики
Просмотреть список доступных трассировщиков можно с помощью команды
root@andrei:/sys/kernel/debug/tracing#: cat available_tracers blk mmiotrace function_graph wakeup_rt wakeup function nop
Приведём краткую характеристику для каждого трассировщика:
- function — трассировщик функций вызовов ядра без возможности получения аргументов;
- function_graph — трассировщик функций вызовов ядра с подвызовами;
- blk — трассировщик вызовов и событий, связанных с вводом-выводом на блочные устройства; именно он используется в утилите blktrace, о которой мы уже писали;
- mmiotrace — трассировщик операций ввода-вывода, отражаемых в память.
- nop — самый простой трассировщик, который, как и следует из названия, ничего не делает (однако в некоторых ситуациях и он может быть полезен, о чём ещё пойдёт речь ниже).
Трассировщик function
Знакомство с ftrace мы начнём с трассировщика function. Рассматривать его мы будем на материале вот такого тестового скрипта:
#!/bin/sh dir=/sys/kernel/debug/tracing sysctl kernel.ftrace_enabled=1 echo function > $/current_tracer echo 1 > $/tracing_on sleep 1 echo 0 > $/tracing_on less $/trace
крипт очень простой и в целом понятный, однако в нём есть моменты, на которые стоит обратить внимание.
Команда sysctl ftrace.enabled=1 включает трассировку функций. Далее мы устанавливаем текущий трассировщик, записывая его имя в файл current_tracer.
После этого мы записываем 1 в файл tracing_on и тем самым активируем обновление кольцевого буфера. Важная особенность синтаксиса: между 1 и знаком > обязательно должен быть пробел: команда вида echo1> tracing_on не сработает. Буквально через одну строку мы его отключаем (обратите внимание: если в файл tracing_on записать 0, кольцевой буфер не будет очищен; не будет отключен и ftrace).
Зачем мы это делаем? Между двумя командами echo находится команда sleep 1. Мы включаем обновление буфера, выполняем эту команду и затем сразу же его отключаем. Благодаря этому в трассировку будет включена информация обо всех системных вызовах, которые имели место во время выполнения этой команды.
В последней строке скрипта мы даём команду вывести данные трассировки на консоль.
В результате выполнения этого скрипта мы увидим следующий вывод (приводим лишь небольшой фрагмент):
# tracer: function # # entries-in-buffer/entries-written: 29571/29571 #P:2 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | trace.sh-1295 [000] . 90.502874: mutex_unlock
Вывод начинается с информации о количестве записей событий в буфере (entries in buffer) и общем количестве записанных событий (entries written). Разница между этими двумя цифрами — это количество событий, утерянных при заполнении буфера (в нашем случае никаких утерянных событий нет).
Далее идёт перечень функций, включающий следующую информацию:
- идентификатор процесса (PID);
- номер процессорного ядра, на котором выполняется трассировка(СPU#);
- метка времени (TIMESTAMP; указывает время, когда произошёл вход в функцию);
- имя трассируемой функции и имя родительской функции, которая её вызвала(FUNCTION); например, в самой первой строке приведённого нами вывода функцию mutex-unlock вызывает функция rb_simple_write.
Трассировщик function_graph
Трассировщик function_graph работает точно так же, как function, но отслеживает функции более подробно: для каждой функции он указывает точку входа и точку выхода. С помощью этого трассировщика можно отслеживать функции с подвызовами и измерять время выполнения для каждой функции.
Отредактируем использованный в предыдущем примере скрипт:
#!/bin/sh dir=/sys/kernel/debug/tracing sysctl kernel.ftrace_enabled=1 echo function_graph > $/current_tracer echo 1 > $/tracing_on sleep 1 echo 0 > $/tracing_on less $/trace
В результате выполнения этого скрипта мы получим следующий вывод:
# tracer: function_graph # # CPU DURATION FUNCTION CALLS # | | | | | | | 0) 0.120 us | > /* resched_task */ 0) 1.877 us | > /* check_preempt_curr */ 0) 4.264 us | > /* ttwu_do_wakeup */ 0) + 29.053 us | > /* ttwu_do_activate.constprop.74 */ 0) 0.091 us | _raw_spin_unlock(); 0) 0.260 us | ttwu_stat(); 0) 0.133 us | _raw_spin_unlock_irqrestore(); 0) + 37.785 us | > /* try_to_wake_up */ 0) + 38.478 us | > /* default_wake_function */ 0) + 39.203 us | > /* pollwake */ 0) + 40.793 us | > /* __wake_up_common */ 0) 0.104 us | _raw_spin_unlock_irqrestore(); 0) + 42.920 us | > /* __wake_up_sync_key */ 0) + 44.160 us | > /* sock_def_readable */ 0) ! 192.850 us | > /* tcp_rcv_established */ 0) ! 197.445 us | > /* tcp_v4_do_rcv */ 0) 0.113 us | _raw_spin_unlock(); 0) ! 205.655 us | > /* tcp_v4_rcv */ 0) ! 208.154 us | > /* ip_local_deliver_finish */
В графе DURATION указывается время, затраченное на выполнение функции. Особое внимание следует обратить на пункты, отмеченные значками + и! Знак + означает, что выполнение функции заняло более 10 микросекунд, а восклицательный знак — более 100.
В графе FUNCTION_CALLS с информацией о вызовах функций.
Начало и конец выполнения каждой функции обозначаются в ней так, как это принято в языке C: фигурная скобка в начале функции и ещё одна — в конце. Функции, которые являются листьями графа и не вызывают никаких других функций, обозначаются точкой с запятой (;).
Фильтры для функций
Вывод ftrace порой может быть очень большим, и найти в нём нужную информацию крайне затруднительно. Упростить поиск можно с помощью фильтров: в вывод будет попадать информация не обо всех функциях, а лишь о тех, которые нас действительно интересуют. Для этого достаточно просто записать в файл set_ftrace_filter имена нужных функций, например:
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_filter
Чтобы отключить фильтр, нужно записать в этот же файл пустую строку:
root@andrei:/sys/kernel/debug/tracing# echo > set_ftrace_filter
В результате выполнения команды
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_notrace
мы получим совершенно противоположный результат: в вывод будет попадать информация обо всех функциях, кроме kfree().
Ещё одна полезная опция — set_ftrace_pid. Она предназначена для трассировки функций, вызываемых во время выполнения указанного процесса.
Возможности фильтрации в ftrace гораздо шире; подробнее о них можно прочитать в статье Стивена Ростедта на LWN.net.
Трассировка событий
Выше мы уже упоминали о механизме tracepoints. Слово tracepoint в переводе означает «точка трассировки». Точка трассировки — это специальная вставка в код, регистрирующая определённые системные события. Точка трассировки могут быть активной (это значит, что за ней закреплена некоторая проверка) или неактивной (никакой проверки за ней не закреплено).
Неактивная точка трассировки никакого влияния на работу системы не оказывает; она лишь добавляет несколько байт для вызова трассировочной функции в конце инструментированной функции, а также добавляет структуру данных в отдельную секцию.
Когда точка трассировки активна, при выполнении соответствующего фрагмента кода вызывается трассировочная функция. Данные трассировки записываются в отладочный кольцевой буфер.
Точки трассировки могут быть вставлены в любое место в коде. Они уже присутствуют в коде многих ядерных функций. Рассмотрим, например, функцию kmem_cache_alloc (взято отсюда):
< void *ret = slab_alloc(cachep, flags, _RET_IP_); trace_kmem_cache_alloc(_RET_IP_, ret, cachep->object_size, cachep->size, flags); return ret; >
Обратите внимание на строку trace_kmem_cache_alloc — это как раз и есть точка трассировки. Количество подобных примеров можно умножить, обратившись к исходному коду других функций ядра.
В ядре Linux имеется специальный API, с помощью которого можно работать с точками трассировки из пользовательского пространства. В директории /sys/kernel/debug/tracing есть поддиректория events, в которой хранятся доступные для отслеживания системные события. Системное событие в данном контексте — не что иное, как включенные в ядро точки трассировки.
Их список можно просмотреть с помощью команды:
root@andrei:/sys/kernel/debug/tracing# cat available_events
На консоль будет выведен длинный список, просматривать который довольно неудобно. Вывести этот же список в более структурированном формате можно так:
root@andrei:/sys/kernel/debug/tracing# ls events
Прежде чем приступать к отслеживанию событий, проверим, включена ли запись событий в кольцевой буфер:
root@andrei:/sys/kernel/debug/tracing# cat tracing_on
Если после выполнения этой команды на консоль будет выведена цифра 0, выполним:
root@andrei:/sys/kernel/debug/tracing# echo 1 > tracing_on
В прошлой статье мы писали о системном вызове chroot() — вход в этом системный вызов мы и будем отслеживать. В качестве трассировщика мы выберем nop: function и function_graph записывают слишком много информации, в том числе и не имеющей отношения к интересующему нас событию.
root@andrei:/sys/kernel/debug/tracing# echo nop > current_tracer
Все события, связанные с системными вызовами, хранятся в директории syscalls. В ней, в свою очередь, хранятся директории для входа и выхода из различных системных вызовов. Активируем нужную нам точку трассировки, записав 1 в её enable-файл:
root@andrei:/sys/kernel/debug/tracing# echo 1 > events/syscalls/sys_enter_chroot/enable
Затем создадим изолированную файловую систему с помощью команды chroot (подробности см. в предыдущем посте). После выполнения интересующих нас команд отключим трассировку, чтобы в вывод не попадала информация о лишних и не имеющих отношения к делу событиях:
root@andrei:/sys/kernel/debug/tracing# echo 0 > tracing_on
Далее просмотрим содержимое кольцевого буфера. В самом конце вывода будет содержаться информация об интересующем нас системном вызове (приводим небольшой фрагмент):
root@andrei:/sys/kernel/debug/tracing# сat trace . chroot-11321 [000] . 4606.265208: sys_chroot(filename: 7fff785ae8c2) chroot-11325 [000] . 4691.677767: sys_chroot(filename: 7fff242308cc) bash-11338 [000] . 4746.971300: sys_chroot(filename: 7fff1efca8cc) bash-11351 [000] . 5379.020609: sys_chroot(filename: 7fffbf9918cc)
Более подробно о настройках трассировки событий можно почитать здесь.
Заключение
В этой статье мы проделали общий обзор возможностей ftrace. Будем признательны за любые замечания и дополнения. Если вы хотите глубже погрузиться в тему, рекомендуем ознакомиться со следующими источниками:
- https://www.kernel.org/doc/Documentation/trace/tracepoints.txt — подробное описание механизма tracepoints;
- https://www.kernel.org/doc/Documentation/trace/events.txt — руководство по трассировке системных событий в Linux;
- https://www.kernel.org/doc/Documentation/trace/ftrace.txt — официальная документация ftrace;
- https://lttng.org/files/thesis/desnoyers-dissertation-2009-12-v27.pdf — диссертация Матьё Денуайе (создателя механизма tracepoints и автора LTTNG) о трассировке и профилировании ядра;
- https://lwn.net/Articles/370423/ — статья Стивена Родстедта о возможностях ftrace;
- http://alex.dzyoba.com/linux/profiling-ftrace.html — обзорная статья об ftrace c разбором практического кейса;
- http://panda-nox.livejournal.com/2235.html — единственная подробная публикация об ftrace на русском языке.
Как увеличить количество функций в call trace при kernel panic
Пытаюсь выяснить причины kerenel panic на arm машине. Дамп ядра приведен ниже:
[ 5.632773] systemd-udevd[239]: starting version 204 [ 6.595872] Unable to handle kernel paging request at virtual address 80de1cd0 [ 6.598784] pgd = ed56c000 [ 6.601764] [80de1cd0] *pgd=00000000 [ 6.604730] Internal error: Oops: 5 [#1] PREEMPT SMP [ 6.607874] CPU: 0 Not tainted (3.0.8+ #1) [ 6.611001] PC is at get_page_from_freelist+0x124/0x498 [ 6.614031] LR is at zone_watermark_ok+0x1c/0x20 [ 6.617015] pc : [] lr : [] psr: 60070093 [ 6.617020] sp : ed56be20 ip : 00000001 fp : eee77008 [ 6.623190] r10: 00000000 r9 : c06ce000 r8 : c06d0190 [ 6.623198] r7 : 60070013 r6 : c0e2b540 r5 : c0e2b540 r4 : 00000000 [ 6.623205] r3 : 00000000 r2 : 80de1cd0 r1 : 00000000 r0 : ed56be20 [ 6.623216] Flags: nZCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment user [ 6.623224] Control: 10c53c7d Table: 8d56c04a DAC: 00000015 [ 6.623247] [ 6.623249] PC: 0xc074d6c0: [ 6.623253] d6c0 e59d1010 ebffb7fc e3500000 0a0000df e59d207c e3120004 1a000008 e59d004c [ 6.623269] d6e0 e2023003 e58d2000 e1a01004 e7902103 e59d3034 ebfffa53 e3500000 0a0000d3 [ 6.623282] d700 e59d604c e59d3010 e7e03453 e58d3020 e3540000 1a00005e e10f7000 f10c0080 [ 6.623296] d720 e59f337c e1a0000d e59d1084 e596801c e7992003 e3c03d7f e3c3303f e5933014 [ 6.623315] d740 e792a103 e2813001 e088200a e0823183 e58d3018 e59d0018 e2833004 e58d3024 [ 6.623328] d760 e59d1024 e5903004 e1530001 1a000036 e798000a e2861020 e5922008 e1a0b004 [ 6.623341] d780 e58d300c e58d0038 e1a00001 e58d203c e58d1028 eb137898 e59d300c e1a05003 [ 6.623354] d7a0 ea000018 e1a00006 e3a01000 e59d2084 e58d300c ebfffd64 e59d300c e3500000 [ 6.623368] [ 6.623370] LR: 0xc074bfe4: [ 6.623373] bfe4 e12fff1e 00002bc4 e59f000c e3a01000 e3a02001 e79f0000 eaff7986 0063b11c [ 6.623397] c004 e5903000 e3130902 1590300c 01a03000 e5933004 e3a03001 e1a01113 e1a02003 [ 6.623410] c024 ea000003 e2833001 e590c000 e590c004 e5802004 e1530001 e2800020 bafffff8 [ 6.623424] c044 e12fff1e e92d4007 e59de010 e590c268 e58de000 e1cccfcc e58dc004 ebfffe31 [ 6.623437] c064 e8bd800e e92d45f7 e1a08003 e590300c e1a04000 e5907268 e1a06001 e3530000 [ 6.623450] c084 e1a05002 e1c77fc7 0a000019 e1570003 2a000017 e59f3078 e3e02000 e5907268 [ 6.623463] c0a4 e79f3003 e593a000 ea000006 e59f1064 e594301c e79f1001 e7911102 e0833001 [ 6.623476] c0c4 e1d332d5 e0877003 e2822001 e1a0000a e3a01002 eb052a50 e59f303c e79f3003 [ 6.623491] [ 6.623494] SP: 0xed56bda0: [ 6.623497] bda0 ed54aa00 c07484a8 00000024 00000024 c2022aa0 22a03649 00000050 00000000 [ 6.623515] bdc0 ed56bde8 ffffffff ed56be0c c0e2b540 60070013 c06d346c ed56be20 00000000 [ 6.623528] bde0 80de1cd0 00000000 00000000 c0e2b540 c0e2b540 60070013 c06d0190 c06ce000 [ 6.623541] be00 00000000 eee77008 00000001 ed56be20 c074c064 c074d740 60070093 ffffffff [ 6.623554] be20 00000041 ee0fc640 ee88fcc0 ed54a320 000280d0 00000001 ee88fcc0 c0e2be4c [ 6.623567] be40 00000000 c0791d9c 00000000 00000000 c0ec8bd0 00000000 000a0000 00000000 [ 6.623579] be60 ffffffff c0d17a31 ed54a320 c0e2b540 ee9dcc38 000080d0 ed56a000 00000000 [ 6.623592] be80 007fffff c0e2be40 00000000 00000000 eee77008 c074e200 00000000 00000041 [ 6.623609] [ 6.623611] FP: 0xeee76f88: [ 6.623614] 6f88 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.623630] 6fa8 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.623648] 6fc8 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.623660] 6fe8 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ed88d0c0 [ 6.623673] 7008 ed88afc0 eee7720c eee76e0c eed1e900 eec0e5c0 c0e38328 eee78150 00000002 [ 6.623686] 7028 00000007 00000000 00000000 00000001 00000000 00000000 eee77040 eee77040 [ 6.623702] 7048 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.623715] 7068 eee77268 eee76e68 7fffffff 00000000 00000000 eee7707c eee7707c 00000000 [ 6.623731] [ 6.623733] R0: 0xed56bda0: [ 6.623737] bda0 ed54aa00 c07484a8 00000024 00000024 c2022aa0 22a03649 00000050 00000000 [ 6.623750] bdc0 ed56bde8 ffffffff ed56be0c c0e2b540 60070013 c06d346c ed56be20 00000000 [ 6.623763] bde0 80de1cd0 00000000 00000000 c0e2b540 c0e2b540 60070013 c06d0190 c06ce000 [ 6.623776] be00 00000000 eee77008 00000001 ed56be20 c074c064 c074d740 60070093 ffffffff [ 6.623789] be20 00000041 ee0fc640 ee88fcc0 ed54a320 000280d0 00000001 ee88fcc0 c0e2be4c [ 6.623802] be40 00000000 c0791d9c 00000000 00000000 c0ec8bd0 00000000 000a0000 00000000 [ 6.623814] be60 ffffffff c0d17a31 ed54a320 c0e2b540 ee9dcc38 000080d0 ed56a000 00000000 [ 6.623827] be80 007fffff c0e2be40 00000000 00000000 eee77008 c074e200 00000000 00000041 [ 6.623840] [ 6.623843] R5: 0xc0e2b4c0: [ 6.623846] b4c0 00000000 00000004 c0e47624 c0e2b4ec c0e47664 666e6f63 00006769 00000000 [ 6.623859] b4e0 00000000 00000001 c0e47624 c0e2b50c c0e2b4cc 6e616373 00000000 00000000 [ 6.623872] b500 00000000 00000002 c0e47624 c0e2b4ac c0e2b4ec 75676572 6f74616c 00007972 [ 6.623889] b520 00000000 00000003 00000005 000001f4 00000002 00000000 00000000 00000000 [ 6.623902] b540 0000036b 00000445 00000520 00000000 00000000 000004b6 000004b6 c06d0190 [ 6.623914] b560 00000000 00000000 00000000 c0e2b56c c0e2b56c c0e2b574 c0e2b574 c1e23238 [ 6.623927] b580 c1e23238 c0e2b584 c0e2b584 c0e2b58c c0e2b58c 00000001 c1dddcd8 c1ddf0d8 [ 6.623940] b5a0 c1e12758 c1e12758 c1e23258 c1e23258 c0e2b5b0 c0e2b5b0 c0e2b5b8 c0e2b5b8 [ 6.623954] [ 6.623956] R6: 0xc0e2b4c0: [ 6.623960] b4c0 00000000 00000004 c0e47624 c0e2b4ec c0e47664 666e6f63 00006769 00000000 [ 6.623973] b4e0 00000000 00000001 c0e47624 c0e2b50c c0e2b4cc 6e616373 00000000 00000000 [ 6.623986] b500 00000000 00000002 c0e47624 c0e2b4ac c0e2b4ec 75676572 6f74616c 00007972 [ 6.623998] b520 00000000 00000003 00000005 000001f4 00000002 00000000 00000000 00000000 [ 6.624011] b540 0000036b 00000445 00000520 00000000 00000000 000004b6 000004b6 c06d0190 [ 6.624024] b560 00000000 00000000 00000000 c0e2b56c c0e2b56c c0e2b574 c0e2b574 c1e23238 [ 6.624037] b580 c1e23238 c0e2b584 c0e2b584 c0e2b58c c0e2b58c 00000001 c1dddcd8 c1ddf0d8 [ 6.624050] b5a0 c1e12758 c1e12758 c1e23258 c1e23258 c0e2b5b0 c0e2b5b0 c0e2b5b8 c0e2b5b8 [ 6.624063] [ 6.624066] R8: 0xc06d0110: [ 6.624069] 0110 ea000001 e2933000 13a03001 e6ef0073 e3500000 01a0e000 13a0e001 13a00000 [ 6.624083] 0130 e2122503 1a000003 e3130c01 03a0207f 13a02080 ea00000b e3520503 03a02000 [ 6.624096] 0150 0a000008 e1d150b2 e2955000 13a05001 e3520501 11a02005 02252001 e3520000 [ 6.624109] 0170 13a020ff 03a02000 e1720003 22035001 22800001 218530a3 21a020a2 e31300ff [ 6.624122] 0190 13844010 e35000fd da000008 e3520000 e3844014 03a030fd 13a030ff 01c130b0 [ 6.624136] 01b0 03e03102 11c130b0 13a03000 ea000009 e0823003 e1b02423 01a00002 e3530102 [ 6.624149] 01d0 93500000 1a000001 e35e0000 13844008 e1a030a3 e1c100b0 e5813004 e1d130f0 [ 6.624162] 01f0 e1d120b2 e5910004 e1a0100c e1a03b83 e0833802 e08303a0 ebfffc55 e1a00004 [ 6.624176] [ 6.624178] R9: 0xc06cdf80: [ 6.624181] df80 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.624196] dfa0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.624208] dfc0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.624224] dfe0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 6.624236] e000 e92d45f8 e1a06000 e59f40a0 e59f20a0 e08f4004 e59f309c e7948002 e1a0200d [ 6.624251] e020 e3c25d7f e794a003 e3c5503f e5952014 e1a0300a e7982102 e7937002 e7831002 [ 6.624264] e040 eb00d580 e59f3070 e7943003 e5933000 e1560003 3a00000e e59f0060 e08f0000 [ 6.624279] e060 eb00bd60 e3500000 0a000003 e59f0050 e1a01006 e08f0000 eb1558c2 e59f3044 [ 6.624328] Process systemd-udevd (pid: 239, stack limit = 0xed56a2f0) [ 6.624348] Stack: (0xed56be20 to 0xed56c000) [ 6.624358] be20: 00000041 ee0fc640 ee88fcc0 ed54a320 000280d0 00000001 ee88fcc0 c0e2be4c [ 6.624368] be40: 00000000 c0791d9c 00000000 00000000 c0ec8bd0 00000000 000a0000 00000000 [ 6.624379] be60: ffffffff c0d17a31 ed54a320 c0e2b540 ee9dcc38 000080d0 ed56a000 00000000 [ 6.624390] be80: 007fffff c0e2be40 00000000 00000000 eee77008 c074e200 00000000 00000041 [ 6.624400] bea0: c0e2b540 00000000 6b8d0c0d dfe08938 5f805169 00000000 c06ce000 5936e17f [ 6.624411] bec0: c0e2be44 2a30b8dc f15a4cfe 000280d0 00000000 c06ce000 00000001 00000001 [ 6.624421] bee0: 00000000 c0debb28 00000000 c0e2b540 ed523580 c07656b8 ed51bbd0 ed523580 [ 6.624432] bf00: 00000000 eee78180 ed616fc0 ed56bf88 ed616fd8 c0e58224 00001000 400d4000 [ 6.624443] bf20: eee77008 c074e7a8 00000000 c07ca394 ed54a320 400d4000 00001000 00001000 [ 6.624454] bf40: ed54a320 400d4000 ed56bf88 00001000 ed56a000 00000000 00000000 c077fbc8 [ 6.624464] bf60: ed54a320 400d4000 ed54a320 400d4000 00000000 00000000 00001000 c077fc78 [ 6.624475] bf80: 0000000c 00000000 00000000 00000000 0004b4c0 402d6c04 00003ffe 00000003 [ 6.624485] bfa0: c06d3b44 c06d39c0 0004b4c0 402d6c04 0000000c 400d4000 00001000 00000000 [ 6.624496] bfc0: 0004b4c0 402d6c04 00003ffe 00000003 be8d4534 0000000a be8d4534 00000000 [ 6.624506] bfe0: 00000000 be8d4074 402437c7 4027dce6 40070030 0000000c 00000000 00000000 [ 6.624584] [] (get_page_from_freelist+0x124/0x498) from [] (__alloc_pages_nodemask+0x14c/0x6dc) [ 6.624608] [] (__alloc_pages_nodemask+0x14c/0x6dc) from [] (__get_free_pages+0x18/0x2c) [ 6.624649] [] (__get_free_pages+0x18/0x2c) from [] (sysfs_read_file+0x64/0x124) [ 6.624685] [] (sysfs_read_file+0x64/0x124) from [] (vfs_read+0xac/0x124) [ 6.624701] [] (vfs_read+0xac/0x124) from [] (sys_read+0x38/0x64) [ 6.624739] [] (sys_read+0x38/0x64) from [] (ret_fast_syscall+0x0/0x30) [ 6.624756] Code: e7992003 e3c03d7f e3c3303f e5933014 (e792a103) [ 6.630217] ---[ end trace 27dfcc79f2dafc3e ]---
Система MK808b tv stick: armhf7 Rockchip RK3066 with 1Gb RAM. Работает ubuntu 14.04 c ядром 3.0.8+ собранным из исходников. Соответственно могу пофиксить обвалы системы, если найду источник проблем. В приведенном call trace видны только 6 последних вызванных функций, а какие функции вызывались до этого - нет. Подскажите - есть ли способ увеличить число выводимых функций в call trace до 10-15 шт, чтобы отследить источник проблемы, который явно находится до указанных в дампе 6 функций.
Отслеживать
122k 24 24 золотых знака 124 124 серебряных знака 297 297 бронзовых знаков
задан 3 мая 2017 в 9:39
1 2 2 бронзовых знака
Пишите на русском языке. Либо размещайте вопрос на англ Stack Overflow ресурсе.
3 мая 2017 в 9:49
Так всё же правильно. До этого был user space. Ядру неизвестно, что там было.
3 мая 2017 в 20:44
0
Сортировка: Сброс на вариант по умолчанию
Знаете кого-то, кто может ответить? Поделитесь ссылкой на этот вопрос по почте, через Твиттер или Facebook.
- linux
- отладка
- kernel
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, ®isters) == -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, ®isters) == -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, ) = 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, ) = 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, ) = 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, ) = 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
Программа заблокирована вызовом 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 --- pause( $ $ kill -TERM 15329 $ cat write-sleep.log pause() = ? ERESTARTNOHAND (To be restarted if no handler) --- SIGCONT --- pause() = ? ERESTARTNOHAND (To be restarted if no handler) --- SIGTERM --- +++ 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 --- +++ 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 --- 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, 23611 exit_group(0) = ? 23611 +++ exited with 0 +++ 23610 NULL, 0, NULL) = 23611 23610 --- SIGCHLD --- 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, "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 write(3, "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[])
Естественно, вывод программы при этом становится очень объёмным, и, помимо флага -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 #include #include 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[])
Отслеживаем оба вызова 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
- Настройка Linux
- Системное администрирование
- Программирование
- *nix