0,0
рейтинг
17 января 2014 в 16:12

Разработка → Изучаем внутреннюю кухню ядра Linux с помощью /proc для быстрой диагностики и решения проблем перевод

Данная статья касается современных линуксов. Например, RHEL6 с ядрами 2.6.3х — подойдёт, а вот RHEL5 с ядрами 2.6.18 (кстати, наиболее популярный в продакшне) — увы, нет. И ещё — здесь не будет описания ядерных отладчиков или скриптов SytemTap; только старые-добрые простые команды вида «cat /proc/PID/xyz» в отношении некоторых полезных узлов файловой системы /proc.

Диагностика «тормозящего» процесса


Вот хороший пример часто возникающей проблемы, которую я воспроизвёл на своём лаптопе: пользователь жалуется, что команда find работает «значительно медленнее», при этом не возвращая никаких результатов. Зная, в чём дело, мы решили проблему. Однако меня попросили изложить систематический подход к решению подобных задач.

К счастью, система работает под управлением OEL6, т.е. на достаточно свежем ядре (а именно — 2.6.39 UEK2)

Итак, приступим к диагностике.

Сперва проверим, жив ли ещё процесс find:

[root@oel6 ~]# ps -ef | grep find
root     27288 27245  4 11:57 pts/0    00:00:01 find. -type f
root     27334 27315  0 11:57 pts/1    00:00:00 grep find

Да, он на месте – PID 27288 (дальше в примере диагностики я буду использовать этот pid)

Начнём с основ и взглянем, что является узким местом для данного процесса. Если он ничем не заблокирован (например, читает всё ему необходимое из кэша), он должен использовать 100% CPU. Если же он в блокировке из-за IO или проблем с сетью, то нагрузка на процессор должна быть ниже, либо вообще отсутствовать.

[root@oel6 ~]# top -cbp 27288
top — 11:58:15 up 7 days, 3:38, 2 users, load average: 1.21, 0.65, 0.47
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.1%us, 0.1%sy, 0.0%ni, 99.8%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 2026460k total, 1935780k used, 90680k free, 64416k buffers
Swap: 4128764k total, 251004k used, 3877760k free, 662280k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27288 root 20 0 109m 1160 844 D 0.0 0.1 0:01.11 find. -type f

Вывод команды 'top' утверждает, что этот процесс вообще не нагружает CPU (либо нагрузка настолько мала, что её можно считать нулевой). Однако есть весьма важное различие между процессом, который полностью завис, не имея вообще шанса получить квант процессора, и процессом, который постоянно просыпается из состояния ожидания и затем сразу снова засыпает (например, некая операция опроса (poll), которая постоянно завершается по таймауту, а затем процесс по ходу выполнения вызывает её снова и засыпает). Для того, чтобы распознать эти два состояния, команды 'top', к сожалению, недостаточно. Но по крайней мере мы уже выяснили, что этот процесс не пожирает процессорное время.

Давайте попробуем другие инструменты. Обычно, если процесс кажется зависшим подобным образом (0% CPU обычно означает, что процесс находится в каком-то блокирующем системном вызове — который приводит к тому, что ядро усыпляет процесс), я запускаю strace на этом процессе чтобы отследить, на каком системном вызове он в настоящий момент застрял. Если же процесс на самом деле не совсем завис, а периодически возвращается из системного вызова и просыпается, то это тоже будет видно в выводе strace (системный вызов будет периодически завершаться, а затем вызываться снова):

[root@oel6 ~]# strace -cp 27288
Process 27288 attached — interrupt to quit

^C
^Z

[1]+ Stopped strace -cp 27288

[root@oel6 ~]# kill -9 %%
[1]+ Stopped strace -cp 27288
[root@oel6 ~]#
[1]+ Killed strace -cp 27288

Упс… Похоже, сама команда strace тоже зависла! Она достаточно долгое время ничего не выводила на экран, и даже не отвечала на нажатие CTRL+C, так что пришлось сперва отправить её в фоновый режим, нажав CTRL+Z, а затем и вовсе убить. Не очень лёгкая диагностика!

Давайте попробуем pstack (на Linux pstack — это всего лишь скрипт-обёртка для отладчика GDB). Pstack ничего не скажет нам о внутренней кухне ядра, но по крайней мере укажет, что это там за системный вызов (обычно это выглядит как вызов функции библиотеки libc на вершине пользовательского стека):

[root@oel6 ~]# pstack 27288

^C
^Z
[1]+ Stopped pstack 27288

[root@oel6 ~]# kill %%
[1]+ Stopped pstack 27288
[root@oel6 ~]#
[1]+ Terminated pstack 27288

Pstack тоже завис без всяких объяснений!

Итак, мы до сих пор не знаем, завис ли наш процесс на 100% (увы), либо всего лишь на 99.99% (просыпается и сразу засыпает) — а также не знаем, где именно это произошло.

Куда ещё можно посмотреть? Есть ещё одно часто доступное место — поля status и WCHAN, содержимое которых можно исследовать с помощью старой-доброй команды ps (хм… возможно, стоило запустить её сразу, чтобы удостовериться, что мы имеем дело не с зомби):

[root@oel6 ~]# ps -flp 27288
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 D root 27288 27245 0 80 0 — 28070 rpc_wa 11:57 pts/0 00:00:01 find. -type f

Чтобы удостовериться, что процесс продолжает находиться в одном и том же состоянии, ps нужно запустить несколько раз подряд (вы же не хотите прийти к ложному заключению на основании единственной попытки, сделанной в неудачный момент?). Однако здесь я храбро показываю только один запуск.

Процесс находится в состоянии D («беспробудный сон»), что обычно связано с дисковым вводом-выводом (о чём так же говорит и man-страница к ps). К тому же поле WCHAN (имя функции, которая привела процесс к состоянию спячки/ожидания) немного обрезано. Я могу добавить опцию к вызову ps, чтобы сделать вывод этого поля чуть шире, однако поскольку его содержимое в любом случае идёт из системы /proc, давайте заглянем прямо в источник (опять же, было бы неплохо сделать это несколько раз, чтобы удостовериться, завис ли процесс полностью, или же просто очень часто и помногу спит):

[root@oel6 ~]# cat /proc/27288/wchan
rpc_wait_bit_killable


Хм… Похоже, процесс ожидает какой-то вызов RPC. Это обычно означает, что процесс общается с другими процессами (либо на локальной машине, либо вообще на удалённом сервере). Но мы по-прежнему не знаем, почему.

Есть ли какое-нибудь движение, или процесс совсем завис?


Перед тем, как перейти к самому «мясу» статьи, давайте определим, завис ли процесс окончательно, или нет. На современных ядрах об этом можно узнать, изучая /proc/PID/status. Я выделил для наглядности интересные нам значения:

[root@oel6 ~]# cat /proc/27288/status
Name: find
State: D (disk sleep)
Tgid: 27288
Pid: 27288
PPid: 27245
TracerPid: 0
Uid: 0 0 0 0
Gid: 0 0 0 0
FDSize: 256
Groups: 0 1 2 3 4 6 10
VmPeak: 112628 kB
VmSize: 112280 kB
VmLck: 0 kB
VmHWM: 1508 kB
VmRSS: 1160 kB
VmData: 260 kB
VmStk: 136 kB
VmExe: 224 kB
VmLib: 2468 kB
VmPTE: 88 kB
VmSwap: 0 kB
Threads: 1
SigQ: 4/15831
SigPnd: 0000000000040000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000000000
SigCgt: 0000000180000000
CapInh: 0000000000000000
CapPrm: ffffffffffffffff
CapEff: ffffffffffffffff
CapBnd: ffffffffffffffff
Cpus_allowed: ffffffff,ffffffff
Cpus_allowed_list: 0-63
Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list: 0
voluntary_ctxt_switches: 9950
nonvoluntary_ctxt_switches: 17104


Процесс находится в состоянии D — дисковый сон («беспробудный» сон). Также обратите внимание на значения voluntary_ctxt_switches и nonvoluntary_ctxt_switches — они подскажут нам, сколько раз процессор получал кванты CPU (или отдавал назад). Затем, спустя несколько секунд, запустите команду повторно и проверьте, не увеличились ли значения. В моём случае числа не увеличились, и потому я бы предположил, что процесс завис намертво (ну, или по крайней мере ни разу не просыпался в течение тех нескольких секунд между командами). Итак, теперь я могу быть более уверен в том, что процесс полностью завис (а не просто летит ниже радаров, постоянно потребляя 0.04% времени процессора).

Кстати, есть ещё два места, где можно посмотреть количество переключений контекста (а второе из них, вдобавок, доступно и на древних ядрах):

[root@oel6 ~]# cat /proc/27288/sched
find (27288, #threads: 1)
— se.exec_start: 617547410.689282
se.vruntime: 2471987.542895
se.sum_exec_runtime: 1119.480311
se.statistics.wait_start: 0.000000
se.statistics.sleep_start: 0.000000
se.statistics.block_start: 617547410.689282
se.statistics.sleep_max: 0.089192
se.statistics.block_max: 60082.951331
se.statistics.exec_max: 1.110465
se.statistics.slice_max: 0.334211
se.statistics.wait_max: 0.812834
se.statistics.wait_sum: 724.745506
se.statistics.wait_count: 27211
se.statistics.iowait_sum: 0.000000
se.statistics.iowait_count: 0
se.nr_migrations: 312
se.statistics.nr_migrations_cold: 0
se.statistics.nr_failed_migrations_affine: 0
se.statistics.nr_failed_migrations_running: 96
se.statistics.nr_failed_migrations_hot: 1794
se.statistics.nr_forced_migrations: 150
se.statistics.nr_wakeups: 18507
se.statistics.nr_wakeups_sync: 1
se.statistics.nr_wakeups_migrate: 155
se.statistics.nr_wakeups_local: 18504
se.statistics.nr_wakeups_remote: 3
se.statistics.nr_wakeups_affine: 155
se.statistics.nr_wakeups_affine_attempts: 158
se.statistics.nr_wakeups_passive: 0
se.statistics.nr_wakeups_idle: 0
avg_atom: 0.041379
avg_per_cpu: 3.588077
nr_switches: 27054
nr_voluntary_switches: 9950
nr_involuntary_switches: 17104
se.load.weight: 1024
policy: 0
prio: 120
clock-delta: 72

Здесь нужно смотреть на число nr_switches (которое равно nr_voluntary_switches + nr_involuntary_switches).

Общее число nr_switches — 27054 в приведённом выше куске, а также находится в третьем поле в выводе /proc/PID/schedstat:

[root@oel6 ~]# cat /proc/27288/schedstat
1119480311 724745506 27054


И оно не увеличивается…

Исследуем внутреннюю кухню ядра с помощью файловой системы /proc


Похоже, наш процесс весьма крепко завис :). Strace и pstack бесполезны. Они используют системный вызов ptrace() для подключения к процессу и внедрения в его память, но поскольку процесс безнадёжно завис, скорее всего в каком-то системном вызове, я предполагаю, что и вызов ptrace() тоже зависает сам по себе (кстати, я как-то попробовал запустить strace на сам strace в тот момент, когда он подключается к целевому процессу. И это привело к крэшу процесса. Я предупредил! :)

Как же мы узнаем, в каком системном вызове мы зависли, не имея ни strace, ни pstack? К счастью мы работаем на современном ядре! Поприветсвуем /proc/PID/syscall!

[root@oel6 ~]# cat /proc/27288/syscall
262 0xffffffffffffff9c 0x20cf6c8 0x7fff97c52710 0x100 0x100 0x676e776f645f616d 0x7fff97c52658 0x390e2da8ea

Зашибись! И что мне с этим делать???
Ну, обычно эти числа для чего-то нужны. Если мы видим что-нибудь вроде “0xAVeryBigNumber” то это обычно адрес в памяти (и их можно использовать с утилитами вроде pmap), а если число маленькое — скорее всего это индекс к какому-нибудь массиву. Например, массив дескрипторов открытых файлов (который вы можете лицезреть в /proc/PID/fd), или, в этом случае, поскольку мы имеем дело с системными вызовами — это номер системного вызова, в котором находится процесс! Итак, мы теперь знаем, что процесс завис в системном вызове #262!

Заметьте, что номера системных вызовов могут различаться между разными ОС, версиями ОС и платформами, а потому вам понадобится правильный заголовочный файл от вашей ОС. Неплохо начать с поиска “syscall*” в папке /usr/include. На моей версии и платформе Linux (64bit) системные вызовы определены в файле /usr/include/asm/unistd_64.h:

[root@oel6 ~]# grep 262 /usr/include/asm/unistd_64.h
#define __NR_newfstatat 262


Мы почти у цели! Системный вызов 262 это нечто под именем newfstatat. Осталось запустить man и узнать, что это. Дам небольшую подсказку по именам системных вызовов: если страница man не находит нужного имени, попробуйте поискать без всевозможных суффиксов и префиксов (например, “man pread” вместо “man pread64″) – а в данном случае запустите man без префикса «new» – man fstatat. Ну или просто загуглите.

Как бы то ни было, этот системный вызов — “new-fstat-at” — даёт возможность читать свойства файла очень похоже на то, как это делает обычный системный вызов stat. И мы зависли как раз в операции чтения метаданных файла. Итак, мы продвинулись ещё на шаг дальше. Однако мы до сих пор так и не знаем, почему случилось зависание!

Ну что ж, пришло время поприветствовать моего маленького друга /proc/PID/stack, который позволит вам просматривать цепочку ядерного стека процесса просто распечатывая содержимое proc-файла!!!

[root@oel6 ~]# cat /proc/27288/stack
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]
[] __rpc_execute+0xf5/0x1d0 [sunrpc]
[] rpc_execute+0x43/0x50 [sunrpc]
[] rpc_run_task+0x75/0x90 [sunrpc]
[] rpc_call_sync+0x42/0x70 [sunrpc]
[] nfs3_rpc_wrapper.clone.0+0x35/0x80 [nfs]
[] nfs3_proc_getattr+0x47/0x90 [nfs]
[] __nfs_revalidate_inode+0xcc/0x1f0 [nfs]
[] nfs_revalidate_inode+0x36/0x60 [nfs]
[] nfs_getattr+0x5f/0x110 [nfs]

[] vfs_getattr+0x4e/0x80
[] vfs_fstatat+0x70/0x90
[] sys_newfstatat+0x24/0x50
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff

Верхняя функция — это то место в коде ядра, где мы зависли. Это в точности то, о чём нам уже сказало поле WCHAN (однако заметьте, что на самом деле там выше есть ещё некоторые функции, такие как ядерная функция schedule(), которая усыпляет или будит процессы по мере необходимости. Однако эти функции здесь не показаны, возможно, потому что они являются уже результатом самого состояния ожидания, а не его причиной).

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

Вызов system_call_fastpath — это стандартный обработчик системных вызовов ядра, который привёл к вызову кода, реализующего системный вызов newfstatat (sys_newfstatat), с которым мы имеем дело. Двигаясь дальше вглубь «дочерних» функций мы видим несколько штук, связанных с NFS. Это уже 100% неопровержимое доказательство, что мы находимся где-то в районе кода обработки NFS! Я не говорю «в коде NFS», покуда ещё выше мы видим, как крайняя из этих функций NFS, в свою очередь, вызывает некую функцию RPC (rpc_call_sync), чтобы связаться с другим процессом. В этом случае это, вероятно, [kworker/N:N], [nfsiod], [lockd] или [rpciod] IO-потоки ядра. И какой-то из этих потоков по какой-то причине никак не отвечает (обычно следует подозревать оборванное сетевое соединение, потерю пакетов или просто какие-то проблемы с сетью).

Чтобы разобраться, не завис ли какой-нибудь из этих вспомогательных потоков в коде, связанном с сетью, вам также нужно рассмотреть и их стеки, хотя, например, kworker-ы выполняют гораздо больше функций, чем просто соединение RPC для NFS. Во время отдельного эксперимента (просто копируя большой файл через NFS) я поймал одного из kworker-ов, ожидающего в коде общения с сетью:

[root@oel6 proc]# for i in `pgrep worker`; do ps -fp $i; cat /proc/$i/stack; done
UID PID PPID C STIME TTY TIME CMD
root 53 2 0 Feb14? 00:04:34 [kworker/1:1]

[] __cond_resched+0x2a/0x40
[] lock_sock_nested+0x35/0x70
[] tcp_sendmsg+0x29/0xbe0
[] inet_sendmsg+0x48/0xb0
[] sock_sendmsg+0xef/0x120
[] kernel_sendmsg+0x41/0x60
[] xs_send_kvec+0x8e/0xa0 [sunrpc]
[] xs_sendpages+0x173/0x220 [sunrpc]
[] xs_tcp_send_request+0x5d/0x160 [sunrpc]
[] xprt_transmit+0x83/0x2e0 [sunrpc]
[] call_transmit+0xa8/0x130 [sunrpc]
[] __rpc_execute+0x66/0x1d0 [sunrpc]
[] rpc_async_schedule+0x15/0x20 [sunrpc]
[] process_one_work+0x13e/0x460
[] worker_thread+0x17c/0x3b0
[] kthread+0x96/0xa0
[] kernel_thread_helper+0x4/0x10

Вероятно, не составит труда включить трассировку ядра и узнать, какие именно потоки ядра общаются между собой, но в данной статье я не хочу этим заниматься. Пусть это будет практическим (и простым) диагностическим упражнением!

Разбираемся и «чиним»


В любом случае, благодаря возможности очень легко получить распечатку стека ядра в современных Linux (не могу точно сказать, в какой именно версии ядра это появилось), мы смогли последовательно заключить, где именно зависла наша команда find — а именно, в коде NFS в ядре Linux. А когда вы имеете дело с зависанием, связанном с NFS, скорее всего следует подозревать проблемы с сетью. Если вам любопытно, каким образом я воспроизвёл указанную проблему, то всё очень просто: я смонтировал том NFS из виртуальной машины, запустил команду find, а затем приостановил машину. Это привело к тем же симптомам, как если бы имелась сетевая (конфигурация, firewall) проблема, где соединение молча обрывается без уведомления концевых узлов TCP, или где пакеты по какой-то причине просто не проходят.

Поскольку на вершине стека находится одна из «убиваемых» функций (которую можно безопасно прервать, rpc_wait_bit_killable), мы можем убить её командой kill -9:

[root@oel6 ~]# ps -fp 27288
UID PID PPID C STIME TTY TIME CMD
root 27288 27245 0 11:57 pts/0 00:00:01 find. -type f
[root@oel6 ~]# kill -9 27288

[root@oel6 ~]# ls -l /proc/27288/stack
ls: cannot access /proc/27288/stack: No such file or directory

[root@oel6 ~]# ps -fp 27288
UID PID PPID C STIME TTY TIME CMD
[root@oel6 ~]#

процесс завершён.

Профилирование потоков ядра «на коленке»


Заметьте, что файл /proc/PID/stack выглядит как обычный текстовый файл. А потому вы можете легко получить профиль потоков ядра! Вот, как можно «на коленке» узнать текущий системный вызов, а также раскрутку стека ядра (если находимся в системном вызове), а затем объединить всё это в полуиерархический профиль:

[root@oel6 ~]# export LC_ALL=C; for i in {1..100}; do cat /proc/29797/syscall | awk '{ print $1 }'; cat /proc/29797/stack | /home/oracle/os_explain -k; usleep 100000; done | sort -r | uniq -c

     69 running
      1 ffffff81534c83
      2 ffffff81534820
      6 247
     25 180

    100    0xffffffffffffffff 
      1     thread_group_cputime 
     27     sysenter_dispatch 
      3     ia32_sysret 
      1      task_sched_runtime 
     27      sys32_pread 
      1      compat_sys_io_submit 
      2      compat_sys_io_getevents 
     27       sys_pread64 
      2       sys_io_getevents 
      1       do_io_submit 
     27        vfs_read 
      2        read_events 
      1        io_submit_one 
     27         do_sync_read 
      1         aio_run_iocb 
     27          generic_file_aio_read 
      1          aio_rw_vect_retry 
     27           generic_file_read_iter 
      1           generic_file_aio_read 
     27            mapping_direct_IO 
      1            generic_file_read_iter 
     27             blkdev_direct_IO 
     27              __blockdev_direct_IO 
     27               do_blockdev_direct_IO 
     27                dio_post_submission 
     27                 dio_await_completion 
      6                  blk_flush_plug_list


Это позволит очень грубо оценить, где в ядре процесс проводит своё время (если вообще проводит). Номера системных вызовов выделены отдельно сверху. «running» означает, что во время диагностики процесс работал в пространстве пользователя (а не в системных вызовах). Так, 69% времени процесс находился в пользовательском коде; 25% в системном вызове #180 (nfsservctl на моей системе), и 6% в системном вызове #247 (waitid).

Выше автор использует вызов некоего скрипта /home/oracle/os_explain. Раздобыть его можно по ссылке — прим. перев.

В выводе видно ещё две «функции», по какой-то причине они не отобразились по именам. Однако их адреса известны, поэтому мы можем проверить их вручную:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff81534c83
ffffffff81534c83 t ia32_sysret

Похоже, что это возврат из системного вызова для 32-битной подсистемы, однако поскольку эта функция не является сама по себе системным вызовом (это всего лишь внутренняя вспомогательная функция), видимо, обработчик /proc/stack не отобразил её имя. Возможно также, что эти адреса показаны, поскольку состояние /proc не консистентно для читателя: пока один поток модифицирует эти структуры памяти и элементы, читающие потоки иногда видят устаревшие данные.

Проверим заодно второй адрес:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff81534820
[root@oel6 ~]#

Ничего не нашли? Хорошо, однако отладка на этом не закончена! Поищем что-нибудь инересное вокруг данного адреса. Например, удалим пару последних цифр в конце адреса:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff815348
ffffffff8153480d t sysenter_do_call
ffffffff81534819 t sysenter_dispatch
ffffffff81534847 t sysexit_from_sys_call
ffffffff8153487a t sysenter_auditsys
ffffffff815348b9 t sysexit_audit

Выглядит так, что функция sysenter_dispatch начинается буквально одним байтом ранее первоначального адреса, отображённого в /proc/PID/stack. Поэтому мы вероятнее всего почти выполнили один байт (возможно, команду NOP, расположенную там для динамической отладки). Тем не менее, похоже, что эти куски стека находятся в функции sysenter_dispatch, которая не является сама по себе системным вызовом, а является вспомогательной функцией. (Если чуть докопаться — там всё же разница не в 1, а в 7 байт. Числа то шестнадцатеричные! — прим. перев.)

Ещё о профилировании стека


Заметьте, что существующие различные утилиты раскрутки стека — Perf на Linux, утилиты Oprofile и profile из DTrace на Solaris фиксируют регистры указателя инструкций (EIP на 32-битном Intel, или RIP на x64), а также указателя стека (ESP на 32бит и RSP на x64) для текущего потока на процессоре, а затем проходят по указателям стека назад. Таким образом, эти утилиты способны показать лишь те потоки, которые выполняются на CPU в момент тестирования! Это, безусловно, замечательно, когда мы ищем проблемы с высокой нагрузкой процессора, однако совершенно бесполезно для диагностики намертво зависших, либо находящихся в длительном ожидании/спячке процессов.

Утилиты вроде pstack на Linux,Solaris,HP-UX, procstack (на AIX), ORADEBUG SHORT_STACK и просто чтение псевдофайла /proc/PID/stack являются хорошим дополнением (но не заменой) утилит профилирования CPU — покуда они дают доступ к памяти процесса независимо от его состояния в планировщике и читают стек прямо оттуда. Если процесс спит и не касается CPU, то вершина стека процесса может быть прочитана из сохранённого контекста — который сохраняется в памяти ядра планировщиком ОС во время переключения контекстов.

Безусловно, утилиты профилирования событий процессора зачастую могут дать гораздо больше, чем просто pstack, OProfile, Perf и даже провайдер CPC в DTrace (на Solaris11). Например, устанавливать и считывать внутренние счётчики процессора, чтобы оценить такие вещи, как количество пропущенных циклов CPU при ожидании доступа к памяти; количество промахов кэшей L1/L2 и т.д. Но лучше почитайте, что пишет по этому поводу Kevin Closson: (Perf, Oprofile)

Удачи :-)

Связанные темы


Перевод: Tanel Poder
Алексей Виноградов @klirichek
карма
43,2
рейтинг 0,0
Реклама помогает поддерживать и развивать наши сервисы

Подробнее
Реклама

Самое читаемое Разработка

Комментарии (28)

  • +1
    Вы молодец! Спасибо за статью!
    • +2
      Это перевод, но тем не менее, да, подробное описание, интересные инструменты. Хоть это и не общеприменимый гайд, а конкретный пример, все равно полезно.
  • +4
    Есть более удобный способ посмотреть WCHAN, не дергая ps сто раз: top, жмем «f», выбираем WCHAN, жмем пробел, чтобы выделить его и выходим по ESC.

    И получаем в итоге:
  • –1
    Так что, процессы не зависают сами по себе, и у зависаний всегда есть причина!?
    • +8
      Да. Только она, на самом деле, не всегда жизненно интересна.
      Тут дядька поупражнялся-поупражнялся, да в итоге и жахнул kill -9. Я могу сделать (и скорее всего сделал бы) ровно то же самое и без шатаний по стеку ядра. Типа, скальпель не помог, давай кувалду!
      Но в случае удалённой отладки/разработки с целью устранения багов, подход весьма хорош!
  • +3
    Спасибо, статья хорошая. А вот что виновато nfs я понял сразу после того, как увидел 'D'. Подвисающий неубиваемый процесс, который ничем не занимается может заниматься только одним — тупить в цветоче в NFS. Все остальные сетевые файловые системы менее процессораздирающие.
    • 0
      Ну не обязательно NFS. Может залипнуть и на любой другой FS из-за жесткого диска или бага FS. Сам я правда не сталкивался, от коллег слышал.
      • +5
        Залипания из-за глюков на диске обычно очень хорошо видны — страшный срач в dmesg'е. Другие сетевые fs тоже обычно имеют явные средства диагностики. Только nfs отличается молчаливым режимом «японского партизана, сражающегося 40 лет спустя после капитуляции страны».
  • 0
    спасибо огромное автору за статью, подчерпнул для себя пару интересных моментов, о которых еще не знал, век живи — век учись )
  • 0
    А с какой стороны копать, если приложение автоматически закрывается и в консоль печатается слово Killed?
    Я купил NAS: Seagate Central
    Внутри оказался Cavium Econa CNS3420 SoC
    Есть доступ по SSH, root. Установлен Montavista Linux
    Более опытные чем я люди с компилированием софта под этого зверя обломались
    Я нашел там mono — проверил, программы на .net 2 нормально исполняются :)
    Есть python… много чего есть. Но gcc нет :(

    Диск интересно размечен:
    Partition Table: gpt

    Number Start End Size File system Name Flags
    1 1049kB 22.0MB 21.0MB ext2 Kernel_1
    2 22.0MB 43.0MB 21.0MB ext2 Kernel_2
    3 43.0MB 1117MB 1074MB ext4 Root_File_System_1
    4 1117MB 2190MB 1074MB ext4 Root_File_System_2
    5 2190MB 3264MB 1074MB ext4 Config
    6 3264MB 4338MB 1074MB linux-swap(v1) Swap
    7 4338MB 5412MB 1074MB ext4 Update
    8 5412MB 3001GB 2995GB Data lvm

    И руководства, как пользоваться устройством «по назначению» пока нет.
    Куда копать? Чего читать/качать/ставить/запускать?
    • 0
      посмотрите в syslog
      часто такое соощение выдается в случаи если память закончилась и oom killer грохает процесы
      • 0
        Да мне для начала что-нибудь скомпилить надо.
        Я надеялся, что в природе есть способ скомпилировать что-нибудь и без особых проблем.
        • 0
          Ищите тулчейн для вашей железки. Скорее всего где-нибудь на форумах поддержки нароете!
          Посмотрите uname -a — очень часто в отпечатке ядра остаётся «автограф» от системы, где его собирали (вроде red hat, debian или ubuntu). А потом гуглите по сочетанию имени железки + найденного отпечатка + слов вроде «toolchain» или «cross toolchain».
          Универсального рецепта нет!
        • +1
          Попробуйте начать с того, чтобы запустить hello world собранный статически любым компилятором для arm linux.
    • 0
      Dmesg можно для начала посмотреть. Ну и более общие логи, вроде /var/log/syslog или /var/log/messages.
    • 0
      Возможно, ошибка с выравниванием или неправильная архитектура бинарника. Я бы запустил приложение из gdb и посмотрел, где оно упадёт.
  • 0
    У Вас что-то с примером про strace/pstack — оба вывода одинаковые. Может напутали что-то?
  • +1
    Хорошая статья, спасибо!

    Можете подсказать, имеются ли готовые утилиты для лёгкого профилирования всего ядра Linux, а не конкретных модулей/процессов?
    Интересуют решения, работающие в x86_64 архитектуре.

    Пример, чего хотелось бы видеть в качестве output'а утилиты:

    3032 conntrack_mt_origsrc
    1053 pppoe_seq_next
    560 pppox_sock
    32 something_else
    31 something_else2
    10 __etc

    Просто боюсь, что скоро без такой утилиты у встанет работа и придётся её писать самому. :)
    • +1
      oprofile? perf?
    • 0
      C этим на linux проблема. Я работаю с HP-UX, там есть такая профилировка. По окончании каждого тайм слайса генерится per cpu эвент и в ring buffer скидывается чем занимался процессор (PID, функция ядра, стек !). Очень полезная функция для изучения чем занимаются процессоры. На Linux, насколько знаю, код в ядре для реализации есть, но с утилитами дефицит.
      • 0
        Везёт вам! Я вот всё не дойду до того чтобы perf посмотреть.
        Походу придётся адовыми хаками на nmi_timer вешаться и через dmesg, через dmesg, да башем агрегировать. :)
  • 0
    Похоже, сама команда strace тоже зависла!


    Потому что strace'у нужно переключать контекст на трассируемую программу. Потому что в Linux нет трассировщика, который бы получал данные о syscall'ах напрямую из ядра. В *BSD есть ktrace для этих целей. Задачи из статьи им решаются очень быстро и без риска уронить процесс.

    Однако, много интересного узнал о /proc. Надо будет сравнить с FreeBSD.
  • 0
    Объясните, пожалуйста, почему 2.6.3х является актуальным ядром?
    • 0
      Новых фитч в нем нет, но оно поддерживается, т.е. баги правятся.
      • +1
        Я бы даже поправил слегка — это актуальная версия ядра Red Hat, а потому — единственная стабильная версия (в умах многих людей).
        • 0
          Учитывая его стабильность, актуальность фич и фиксов, срок поддержки дистрибутивов на этом ядре…
          Для продакшена альтернатив особо и нет.
  • +2
    странно, у меня пока ни одного процесса в непрерывном D состоянии убить kill-ом не получилось (даже с -9)
    есть какой-то секрет? :)
  • 0
    Автору, огромное спасибо! Уйдет в документацию саппорта.

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