2014-10-09 2 views
20

ОБНОВЛЕНИЕ 25 октября:Кто посылает SIGKILL в мой процесс таинственно на Ubuntu Server

Теперь я узнал, что вызывает проблему.

1) Детский процесс убивает себя, поэтому strace/perf/auditctl не может отследить его.

2) JNI-вызов для создания процесса запускается из потока Java. Когда поток в конечном итоге умирает, он также разрушает процесс, который он создает.

3) В моем коде fork и execve() дочерний процесс у меня есть код для отслеживания смерти родительского процесса и уничтожения моего дочернего процесса со следующей строкой: prctl (PR_SET_PDEATHSIG, SIGKILL); Моя вина, что я не обращал особого внимания на этот флаг до b/c, он считается ЛУЧШЕЙ ПРАКТИКОЙ для моих других проектов, где дочерний процесс разветвляется из основного потока.

4) Если я прокомментирую эту строку, проблема исчезнет. Первоначальная цель - убить дочерний процесс, когда родительский процесс исчез. Даже без этого флага, это по-прежнему правильное поведение. Похоже, что поведение по умолчанию в блоке ubuntu.

5) Наконец-то найденная ошибка ядра, исправленная в версии ядра 3.4.0, ящик Ubuntu от AWS является версией ядра 3.13.0-29-generic.

Есть несколько полезных ссылок на вопросы:

а) http://www.linuxprogrammingblog.com/threads-and-fork-think-twice-before-using-them

б) prctl(PR_SET_PDEATHSIG, SIGNAL) is called on parent thread exit, not parent process exit.

с) https://bugzilla.kernel.org/show_bug.cgi?id=43300

ОБНОВЛЕНИЯ на 15 октября:

Спасибо так много для всех предложений. Я исследую из одной области системы в другую область. Трудно найти причину.

Мне интересно 2 вещи. 1) почему мощные инструменты, такие как strace, auditctl и perf script, не способные отслеживать, кто вызвал убийство?

2) Is +++, убитый SIGKILL +++, действительно означает его убитый от сигнала?

ОРИГИНАЛЬНЫЙ ПОСТ

У меня есть длинный выполняемый процесс C, запущенный из сервера приложений Java в Ubuntu 12 через интерфейс JNI. Причина, по которой я использую интерфейс JNI для запуска процесса, а не через построитель процессов Java, - это b/c из соображений производительности. Это очень неэффективно для java process builder для IPC, особенно b/c, дополнительная буферизация вводит очень долгую задержку.

Периодически прерывается SIGKILL таинственным образом. Как я узнал через Трассирование, в котором говорится: «+++ убит SIGKILL +++»

Я проверил следующее:

  1. Это не крах.
  2. Это не ООМ. Ничего в dmesg. Мой процесс использует только 3,3% 1 Гбайт памяти.
  3. Уровень Java не убил процесс. Я помещаю журнал в код JNI, если код завершает процесс, но для этого не было записано ни одного журнала.
  4. Это не проблема разрешения. Я пытался работать как sudo или другой пользователь, оба случая заставляют процесс быть убитым.
  5. Если я запускаю процесс локально в оболочке, все работает нормально. Более того, в моем C-коде для моего долговременного процесса я игнорирую сигнал SIGHUP. Только когда он работает как дочерний процесс Java-сервера, он убивается.
  6. Процесс очень интенсивный. Он использует 30% процессора. Существует множество добровольных переключателей контекста и nonvoluntary_ctxt_switches.
  7. (NEW UPDATE) Один ВАЖНО, очень вероятно, связано с тем, почему мой процесс убит. Если процесс сделает тяжелый подъем, он не будет убит, однако иногда он делает небольшую работу с интенсивным процессором. Когда это произойдет, через некоторое время, примерно 1 мин, он будет убит. Это статус всегда S (Sleeping) вместо R (Running). Кажется, ОС решила убить процесс, если он большую часть времени простаивал, а не убивать процесс, если он был занят.
  8. Я подозреваю, что GC от GC является виновником, однако Java никогда не будет мусором собирать одноэлементный объект, связанный с JNI. (Мой объект JNI привязан к этому одиночному тону).

Я озадачен причиной его прекращения. Кто-нибудь имеет хорошее предложение, как его отслеживать?

p.s.

  1. На моем UBUNTU результате предел -a является:

    core file size   (blocks, -c) 0 
    data seg size   (kbytes, -d) unlimited 
    scheduling priority    (-e) 0 
    file size    (blocks, -f) unlimited 
    pending signals     (-i) 7862 
    max locked memory  (kbytes, -l) 64 
    max memory size   (kbytes, -m) unlimited 
    open files      (-n) 65535 
    pipe size   (512 bytes, -p) 8 
    POSIX message queues  (bytes, -q) 819200 
    real-time priority    (-r) 0 
    stack size    (kbytes, -s) 8192 
    cpu time    (seconds, -t) unlimited 
    max user processes    (-u) 7862 
    virtual memory   (kbytes, -v) unlimited 
    file locks      (-x) unlimited 
    

    Я попытался увеличить пределы, и по-прежнему не решает проблему.

    core file size   (blocks, -c) 0 
    data seg size   (kbytes, -d) unlimited 
    scheduling priority    (-e) 0 
    file size    (blocks, -f) unlimited 
    pending signals     (-i) unlimited 
    max locked memory  (kbytes, -l) unlimited 
    max memory size   (kbytes, -m) unlimited 
    open files      (-n) 65535 
    pipe size   (512 bytes, -p) 8 
    POSIX message queues  (bytes, -q) unlimited 
    real-time priority    (-r) 0 
    stack size    (kbytes, -s) 8192 
    cpu time    (seconds, -t) unlimited 
    max user processes    (-u) unlimited 
    virtual memory   (kbytes, -v) unlimited 
    file locks      (-x) unlimited 
    
  2. Вот статус прок, когда я бегу САТ/Proc/$$$/состояние

    Name: mimi_coso 
    State: S (Sleeping) 
    Tgid: 2557 
    Ngid: 0 
    Pid: 2557 
    PPid: 2229 
    TracerPid: 0 
    Uid: 0 0 0 0 
    Gid: 0 0 0 0 
    FDSize: 256 
    Groups: 0 
    VmPeak: 146840 kB 
    VmSize: 144252 kB 
    VmLck:   0 kB 
    VmPin:   0 kB 
    VmHWM:  36344 kB 
    VmRSS:  34792 kB 
    VmData: 45728 kB 
    VmStk:  136 kB 
    VmExe:  116 kB 
    VmLib:  23832 kB 
    VmPTE:  292 kB 
    VmSwap:  0 kB 
    Threads: 1 
    SigQ: 0/7862 
    SigPnd: 0000000000000000 
    ShdPnd: 0000000000000000 
    SigBlk: 0000000000000004 
    SigIgn: 0000000000011001 
    SigCgt: 00000001c00064ee 
    CapInh: 0000000000000000 
    CapPrm: 0000001fffffffff 
    CapEff: 0000001fffffffff 
    CapBnd: 0000001fffffffff 
    Seccomp: 0 
    Cpus_allowed: 7fff 
    Cpus_allowed_list: 0-14 
    Mems_allowed: 00000000,00000001 
    Mems_allowed_list: 0 
    voluntary_ctxt_switches: 16978 
    nonvoluntary_ctxt_switches: 52120 
    
  3. Трассирование показывает:

    $ strace -p 22254 -s 80 -o /tmp/debug.lighttpd.txt 
    read(0, "SGI\0\1\0\0\0\1\0c\0\0\0\t\0\0T\1\2248\0\0\0\0'\1\0\0(\0\0"..., 512) = 113 
    read(0, "SGI\0\1\0\0\0\1\0\262\1\0\0\10\0\1\243\1\224L\0\0\0\0/\377\373\222D\231\214"..., 512) = 448 
    sendto(3, "<15>Oct 10 18:34:01 MixCoder[271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 
    write(1, "SGO\0\0\0\0 \272\1\0\0\t\0\1\253\1\243\273\0\0\0\0'\1\0\0\0\0\0\1\242"..., 454) = 454 
    sendto(3, "<15>Oct 10 18:34:01 MixCoder[271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 
    write(1, "SGO\0\0\0\0 \341\0\0\0\10\0\0\322\1\254Z\0\0\0\0/\377\373R\4\0\17\21!"..., 237) = 237 
    read(0, "SGI\0\1\0\0\0\1\0)\3\0\0\t\0\3\32\1\224`\0\0\0\0'\1\0\0\310\0\0"..., 512) = 512 
    read(0, "\344u\233\16\257\341\315\254\272\300\351\302\324\263\212\351\225\365\1\241\225\3+\276J\273\37R\234R\362z"..., 512) = 311 
    read(0, "SGI\0\1\0\0\0\1\0\262\1\0\0\10\0\1\243\1\224f\0\0\0\0/\377\373\222d[\210"..., 512) = 448 
    sendto(3, "<15>Oct 10 18:34:01 MixCoder[271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 
    write(1, "SGO\0\0\0\0 %!\0\0\t\0\0+\1\243\335\0\0\0\0\27\0\0\0\0\1B\300\36"..., 8497) = 8497 
    sendto(3, "<15>Oct 10 18:34:01 MixCoder[271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 
    write(1, "SGO\0\0\0\0 \341\0\0\0\10\0\0\322\1\254t\0\0\0\0/\377\373R\4\0\17\301\31"..., 237) = 237 
    read(0, "SGI\0\1\0\0\0\1\0\262\1\0\0\10\0\1\243\1\224\200\0\0\0\0/\377\373\222d/\200"..., 512) = 448 
    sendto(3, "<15>Oct 10 18:34:01 MixCoder[271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 
    write(1, "SGO\0\0\0\0 \341\0\0\0\10\0\0\322\1\254\216\0\0\0\0/\377\373R\4\0\17\361+"..., 237) = 237 
    read(0, "SGI\0\1\0\0\0\1\0\221\0\0\0\t\0\0\202\1\224\210\0\0\0\0'\1\0\0P\0\0"..., 512) = 159 
    read(0, unfinished ...) 
    
    +++ killed by SIGKILL +++ 
    
+0

Что происходит с родителем процесс («сервер Java»)? – NPE

+0

Как настроены параметры java? Я имею в виду такие параметры, как: -Xms -Xmx и т. Д. – RaFD

+0

@NPE, родительский процесс работает нормально. Только детский процесс убит. – Howy

ответ

2

Наконец-то я выяснил причину.

Детский процесс убивает себя, и это ошибка ядра Linux.

Детали:

1) Дочерний процесс убивает себя, поэтому Трассирование/перфорация/auditctl не может отслеживать его вниз.

2) JNI-вызов для создания процесса запускается из потока Java. Когда поток в конечном итоге умирает, он также разрушает процесс, который он создает.

3) В моем коде fork и execve() дочерний процесс у меня есть код для отслеживания смерти родительского процесса и уничтожения моего дочернего процесса со следующей строкой: prctl (PR_SET_PDEATHSIG, SIGKILL); Я не обращал особого внимания на этот флаг до того, как b/c он рассматривается как ЛУЧШАЯ ПРАКТИКА для моих других проектов, где дочерний процесс разветвляется из основного потока.

4) Если я прокомментирую эту строку, проблема исчезнет. Первоначальная цель - убить дочерний процесс, когда родительский процесс исчез. Даже без этого флага, это по-прежнему правильное поведение. Похоже, что поведение по умолчанию в блоке ubuntu.

5) Из этой статьи https://bugzilla.kernel.org/show_bug.cgi?id=43300. это ошибка ядра, исправленная в версии ядра 3.4.0, мой ящик ubuntu от AWS - это версия ядра 3.13.0-29-generic.

Моя конфигурация машины: ===> Ubuntu 14.04 LTS ===> 3.13.0-29-родовое

Некоторые полезные ссылки на вопросы:

а) http://www.linuxprogrammingblog.com/threads-and-fork-think-twice-before-using-them

б) prctl(PR_SET_PDEATHSIG, SIGNAL) is called on parent thread exit, not parent process exit

с) https://bugzilla.kernel.org/show_bug.cgi?id=43300

13

Если предположить, что у вас есть корень доступ к вашему компьютеру, вы можете включить аудит в kill (2) syscall для сбора такой информации.

root # auditctl -a exit,always -F arch=b64 -S kill -F a1=9 
root # auditctl -l 
LIST_RULES: exit,always arch=3221225534 (0xc000003e) a1=9 (0x9) syscall=kill 

root # sleep 99999 & 
[2] 11688 
root # kill -9 11688 

root # ausearch -sc kill 
time->Tue Oct 14 00:38:44 2014 
type=OBJ_PID msg=audit(1413272324.413:441376): opid=11688 oauid=52872 ouid=0 oses=20 ocomm="sleep" 
type=SYSCALL msg=audit(1413272324.413:441376): arch=c000003e syscall=62 success=yes exit=0 a0=2da8 a1=9 a2=0 a3=0 items=0 ppid=6107 pid=6108 auid=52872 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsg 
id=0 tty=pts2 ses=20 comm="bash" exe="/bin/bash" key=(null) 

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

+0

Спасибо, я выполнил те же команды, что и вы упомянули выше, и, к сожалению, команда «sleep» не поймана. Вот мой результат: ubuntu @ ip-172-31-26-106: ~ $ sudo auditctl -l LIST_RULES: exit, всегда arch = 3221225534 (0xc000003e) a1 = 9 (0x9) syscall = kill LIST_RULES: выход, всегда auid = 0 syscall = all ubuntu @ ip-172-31-26-106: ~ $ sleep 99999 & [1] 10614 ubuntu @ ip-172-31-26-106: ~ $ kill -9 10614 ubuntu @ ip-172-31-26-106: ~ $ [1] + Убитый сон 99999 ubuntu @ ip-172-31-26-106: ~ $ sudo ausearch -sc kill ---- – Howy

+0

Только команда пойманную команду kill, если я запустил «sudo kill -9 pidOfSleep». Без sudo он ничего не поймает. Более того, я не мог найти, почему мой длинный процесс убивается в журнале. – Howy

+0

Возможно, вы использовали 32-битный системный вызов? 'uname -a' и 'file/bin/bash' должны дать вам некоторые подсказки. Если это так, вам нужно также выполнить аудит 32-битного ответа, например. '# auditctl -a exit, всегда -F arch = b32 -S kill -F a1 = 9'. –

2

Как я упоминал ранее, другим вариантом является использование ядра, которое может быть выполнено с помощью инструмента perf.

# apt-get install linux-tools-3.13.0-35-generic 
# perf list | grep kill 
syscalls:sys_enter_kill       [Tracepoint event] 
syscalls:sys_exit_kill        [Tracepoint event] 
syscalls:sys_enter_tgkill       [Tracepoint event] 
syscalls:sys_exit_tgkill       [Tracepoint event] 
syscalls:sys_enter_tkill       [Tracepoint event] 
syscalls:sys_exit_tkill       [Tracepoint event] 
# perf record -a -e syscalls:sys_enter_kill sleep 10 
[ perf record: Woken up 1 times to write data ] 
[ perf record: Captured and wrote 1.634 MB perf.data (~71381 samples) ] 

// Open a new shell to kill. 
$ sleep 9999 & 
[1] 2387 
$ kill -9 2387 
[1]+ Killed     sleep 9999 
$ echo $$ 
9014 

// Dump the trace in your original shell. 
# perf script 
... 
     bash 9014 [001] 1890350.544971: syscalls:sys_enter_kill: pid: 0x00000953, sig: 0x00000009 
+0

Спасибо, я попробовал, это странно. Сон уловит вашим примером, но мой убитый процесс НЕ пойман. Это действительно странно. «+++, убитый SIGKILL +++», может означать что-то еще? – Howy

+0

Быстрый просмотр кода strace указывает, что инструмент по существу вызывает signame (WTERMSIG (status)) для декодирования статуса выхода из отслеживаемого процесса, который вы также можете проверить вручную, например. '$ echo $ (($? & 0x7f))'. Вы можете также уточнить команду strace только для отслеживания событий сигнала, например. 'strace -f -v -e trace = signal -tt -p xxx'.При этом он даст вам больше информации о том, какой сигнал принимает тот сигнал, когда. –

+0

Это то же самое. Не давая мне больше деталей. Это говорит мне следующее: sudo strace -f -v -e trace = signal -tt -p18468 Процесс 18468 прилагается 22: 23: 44.705727 +++ убит SIGKILL +++ – Howy

Смежные вопросы