View process stack linux

Using /proc to get a process’ current stack trace

Check out how you can use the proc filesystem to retrieve the kernel stack trace of a given process

by Ciro S. Costa — Oct 14, 2018

The file covered in this article, /proc/

/stack , is the one that motivated me to learn more about /proc and get The Month of Proc .

It’s such a useful thing when you’re unaware of what is the state of a given process. Meanwhile, I’ve noticed that it’s not very well known by people getting started with Linux.

Here in this post, you’ll get to know more about how procfs can gather a process’ stack trace, as well as get an idea of its usefulness.

This is the fifth article in a series of 30 articles around procfs: A Month of /proc.

If you’d like to keep up to date with it, make sure you join the mailing list!

A process that blocks

To kick things off, let’s start with the tailoring of a process that blocks — a TCP server.

In its most simplistic form, we can have a single-threaded TCP server that just receives traffic in a given thread and then processes its results.

Naturally, there are two places where we can see the server blocking: at the accept(2) phase, of the read(2) phase — the first blocks until a client finishes the TCP handshake; the second, until data is available for read.

Here’s how a simplistic implementation in C would look like considering just the first blocking part ( accept ing):

If you’re not into how a TCP server can be implemented in C, make sure you check A TCP Server in C for a complete description of it.

Run the server, and then see it blocking!

Viewing the process kernel stack trace

Once the server is blocked, we can jump into /proc and check out what’s going on in the Kernel and figure out that it’s blocked on the accept syscall:

Although it might look like a weird stack trace at first, the structure is very straightforward to reason about.

Each line represents a function that was called (from looking at the stack calls), having the first part, that [ ] thing, being the kernel address of the function, while the second, that do_syscall_64+. being the symbol name with the corresponding offset.

If [ ] looks weird (like, not an actual address at all), it’s because it’s intended to be like that.

When fs/proc/base.c#proc_pid_stack (the method that gets called by the /proc implementation of the virtual filesystem) iterates over the stack frames, we can see that it hardcodes [ ] as the address to be displayed:

Looking at the file where the function is defined, we can git blame that seq_printf and see who’s there to blame for putting that hardcoded [ ] .

Guess what — Torvalds did the change!

Not being a Kernel expert (at all!), I tried to understand what that %pB and %pK are all about — I’ve never used such kind of formatting with printf after all.

Looking at the docs for printk format specifiers, we can see what that very specialized formatting is all about:

The B specifier results in the symbol name with offsets and should be used when printing stack backtraces.

[The K specifier is used …] For printing kernel pointers which should be hidden from unprivileged users.

Meaning that yeah, previously you could retrieve the kernel addresses, but not anymore, for the reasons presented by Linus.

When the stack does not help much

While it’s very clear why knowing the in-kernel stack trace in the example above was useful, it’s not all that much when it comes to servers that make use of async io (like most of the modern web servers do).

Here’s how a code that is very similar to the TCP acceptor we wrote above in C looks like in Go:

Although in the code above we spawn no goroutines other than the main one, under the hood, the Go runtime ends up setting a single event pool file that allows us to monitor multiple file descriptors and not block on them individually.

By the way, Julia Evans has a great blog post on async IO — make sure you check it out! It’s called Async IO on Linux: select, poll, and epoll.

We can notice that by looking at which syscall the Kernel is blocked at when our process runs:

Notice that differently from the C code, here I’m looking at the stack of each task under the task group identified by the PID of the go_accept command.

Given that Go will run more than one thread when it starts (so that we can schedule goroutines to run across the poll of actual threads), we can take a look at the stack across all of the threads and see their stack (in the end, each thread is a task , so we can take the stack of each of them).

If we use dlv , we can see why it’s the case that we have those 5 threads just waiting with a futex_wait , while there’s another one blocked on ep_poll (the actual block on async IO):

Having now both the userspace and kernelspace stacks, we can properly identify what’s going on with the Go application.

Closing thoughts

The conclusion? IMO, /proc/

/stack (or the equivalent /proc/

/task/ /stack ) is great, but it only takes us so far.

In the end, we need a mix of userspace and kernel space tools that can help us debug the state in which a system is present.

Luckily, from time to time new tools like dlv show up, pprof improves, and even more powerful tools to inspect the Kernel emerge.

I hope this article was useful for you! Please let me know if you have any questions.

I’m @cirowrc on Twitter, and I’d love to chat!

Have a good one!

Recommended articles

If you’ve gotten some knowledge from this article, these are some others that you might take advatange of as well!

Stay in touch!

From time to time I’ll deliver some content to you.

The emails are not automatic — it’s all about things I thought were worth sharing that I’d personally like to receive.

If you’re into Twitter, reach me at @cirowrc.

Источник

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

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

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

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

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

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

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

]# 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 или проблем с сетью, то нагрузка на процессор должна быть ниже, либо вообще отсутствовать.

]# 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 (системный вызов будет периодически завершаться, а затем вызываться снова):

]# strace -cp 27288
Process 27288 attached — interrupt to quit

^C
^Z
[1]+ Stopped strace -cp 27288

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

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

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

^C
^Z
[1]+ Stopped pstack 27288

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

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

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

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

]# 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, давайте заглянем прямо в источник (опять же, было бы неплохо сделать это несколько раз, чтобы удостовериться, завис ли процесс полностью, или же просто очень часто и помногу спит):

]# cat /proc/27288/wchan
rpc_wait_bit_killable

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

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

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

]# 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% времени процессора).

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

]# 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:

]# cat /proc/27288/schedstat
1119480311 724745506 27054

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

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

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

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

]# 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 :

]# 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-файла.

]# 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 :

]# 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

]# ls -l /proc/27288/stack
ls: cannot access /proc/27288/stack: No such file or directory

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

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

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

]# 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

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

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

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

]# cat /proc/kallsyms | grep -i ffffff81534c83
ffffffff81534c83 t ia32_sysret

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

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

]# cat /proc/kallsyms | grep -i ffffff81534820
[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)

Источник