[ru] Последний довод зависшего процесса

Posted on
python gdb

Симптомы. Один из подпроцессов в поде кубернетса просто вис и не логировал данные.

Заходим в поду.

Чтобы понять про процессы:

$ top

top - 19:00:06 up 22 days, 10:42,  0 users,  load average: 0.79, 0.89, 1.11
Tasks:  13 total,   1 running,   7 sleeping,   0 stopped,   5 zombie
%Cpu(s):  1.2 us,  1.4 sy,  0.0 ni, 95.0 id,  2.1 wa,  0.2 hi,  0.1 si,  0.1 st
MiB Mem :  32165.3 total,  14305.0 free,   3202.7 used,  14657.6 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.  28626.0 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
    9 root      20   0  167064  73724   8364 S   3.0   0.2 141:45.52 python
    1 root      20   0  381020  53148  13248 S   0.0   0.2  26:46.39 python
  780 root      20   0  381020  43252   3324 S   0.0   0.1   0:00.00 python
  781 root      20   0  381020  43224   3304 S   0.0   0.1   0:00.00 python
 4498 root      20   0    5756   3656   3120 S   0.0   0.0   0:00.07 bash
 4544 root      20   0       0      0      0 Z   0.0   0.0   0:00.04 python
 4986 root      20   0  381020  43220   3300 S   0.0   0.1   0:00.00 python

Есть несколько процессов Питона. Надо понять какой соотвествует зависшему. Обычно если зависло, то упёрлось в логику бесконечного цикла или в системный вызов. Скорее всего искать надо среди тех что cpu=0.0, но для иллюстрации покажу и другой пример.

Сначала проверяем системный вызов. Я попробовал для этого трассировщик системных вызовов strace.

Взял один процесс c pid=9

$ strace -p 9
strace: Process 9 attached
select(0, NULL, NULL, NULL, {tv_sec=1, tv_usec=22746}) = 0 (Timeout)
getpid()                                = 9
write(2, "2020-03-04 19:10:43,932 nlab.arm"..., 80) = 80
sendto(5, "Q\0\0\1\235SELECT tasks.task_id AS tas"..., 414, MSG_NOSIGNAL, NULL, 0) = 414
poll([{fd=5, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "T\0\0\1<\0\ntasks_task_id\0\0\3\4\271\0\1\0\0\v\206\0"..., 16384, 0, NULL, NULL) = 337
select(0, NULL, NULL, NULL, {tv_sec=2, tv_usec=0}) = 0 (Timeout)
getpid()                                = 9
write(2, "2020-03-04 19:10:45,940 nlab.arm"..., 80) = 80
sendto(5, "Q\0\0\1\235SELECT tasks.task_id AS tas"..., 414, MSG_NOSIGNAL, NULL, 0) = 414
poll([{fd=5, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "T\0\0\1<\0\ntasks_task_id\0\0\3\4\271\0\1\0\0\v\206\0"..., 16384, 0, NULL, NULL) = 337
select(0, NULL, NULL, NULL, {tv_sec=2, tv_usec=0}^Cstrace: Process 9 detached
 <detached ...>

Ну тут идут какие-то запросы. Берём дальше pid=780.

$ strace -p 780
strace: Process 780 attached
read(4,

Во. Программа висит на инструкции чтения только не пойми какой. Ставим для отладки на боевую поду gdb прямо в контейнер с питоновскими модулями.

$ apt-get update
$ apt install gdb python3-dbg python3-dev -y

Проверяем, что питоновский модуль подключился к gdb. Должно вывестись “ok”:

$ gdb -ex 'python print("ok")' -ex quit | tail -n 1

Подключаемся к программе по pid=780.

$ gdb -p 780

Загружаются модули и появляется приветственное сообщение.

(gdb) bt

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

Нужно загрузить инструкции для питоновой отладки. У меня Python 3.7 поэтому путь такой:

source /usr/share/gdb/auto-load/usr/bin/python3.7-gdb.py

Вызываем питоновский стектрейс:

(gdb) py-bt

Показывает текущий стектрейс и место зависания:

Traceback (most recent call first):
  <built-in method read of module object at remote 0x7f0a2609d230>
  (frame information optimized out)
  (frame information optimized out)
  (frame information optimized out)
  File "/usr/local/lib/python3.7/multiprocessing/queues.py", line 352, in get
    res = self._reader.recv_bytes()
  (frame information optimized out)
  File "/usr/local/lib/python3.7/multiprocessing/process.py", line 99, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap
    self.run()
  File "/usr/local/lib/python3.7/multiprocessing/popen_fork.py", line 74, in _launch
    code = process_obj._bootstrap()
  File "/usr/local/lib/python3.7/multiprocessing/popen_fork.py", line 20, in __init__
    self._launch(process_obj)
  File "/usr/local/lib/python3.7/multiprocessing/context.py", line 277, in _Popen
    return Popen(process_obj)
  File "/usr/local/lib/python3.7/multiprocessing/process.py", line 112, in start
    self._popen = self._Popen(self)
  File "/usr/local/lib/python3.7/multiprocessing/pool.py", line 241, in _repopulate_pool
    w.start()
  File "/usr/local/lib/python3.7/multiprocessing/pool.py", line 248, in _maintain_pool
    self._repopulate_pool()
  File "/usr/local/lib/python3.7/multiprocessing/pool.py", line 412, in _handle_workers
    pool._maintain_pool()
  File "/usr/local/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()

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

Например в данном случае при использовании Popen.wait() есть замечание:

Warning Use communicate() rather than .stdin.write, .stdout.read or .stderr.read to avoid deadlocks due to any of the other OS pipe buffers filling up and blocking the child process.

Вот эти команды у меня не заработали с моим бинарем, но они показывают соответственно код рядом с текущей инструкцией и локальные переменные.

(gdb) py-list
(gdb) py-locals

References

Самая классная презентация про gdb + python. В остальных очень куцо и не поясняет что делать если что-то не грузится. https://www.slideshare.net/amd4ever/debugging-python-with-gdb (Осторожно! ОРоскомнадзорено)

Ещё про доступные команды есть здесь: https://devguide.python.org/gdb/