O que pode disparar um sinal SIGPWR que interrompe uma chamada de sistema 'sendmsg'?

Question

Em um host do RHEL 6, tenho um servidor Cassandra procurando por conexões TCP no host local. Em paralelo, eu tenho um aplicativo cliente que envia solicitações. O cliente (C # Mono) usa sendmsg para enviar os bytes serializados.

Eu sempre vejo o retorno de sendmsg sem ter enviado todos os bytes solicitados. Eu usei strace para tentar depurar isso

sudo strace -p<pid> -s 100 -f -tt &> tmp.out

e viu (amostra filtrada para um thread tid 47605 )

[pid 47605] 16:32:13.388307 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"
[pid 46142] 16:32:13.370983 futex(0x34af8d0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 46142] 16:32:13.371061 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
[pid 46142] 16:32:13.371169 futex(0x34af8d0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 46142] 16:32:13.371221 <... futex resumed> ) = 0
[pid 46142] 16:32:13.377014 brk(0x3d45000 <unfinished ...>
[pid 46142] 16:32:13.377254 <... brk resumed> ) = 0x3d45000
[pid 46142] 16:32:13.378971 mmap(0x40696000, 65536, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_32BIT, -1, 0) = 0x40696000
[pid 46142] 16:32:13.381868 futex(0x7feb0000b88c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7feb0000b888, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 46142] 16:32:13.413922 tgkill(46142, 47605, SIGPWR) = 0
[pid 46142] 16:32:13.413992 tgkill(46142, 47599, SIGPWR <unfinished ...>
[pid 46142] 16:32:13.414221 <... tgkill resumed> ) = 0
[pid 46142] 16:32:13.414267 tgkill(46142, 46146, SIGPWR <unfinished ...>
[pid 46142] 16:32:13.414437 <... tgkill resumed> ) = 0
[pid 46142] 16:32:13.414601 futex(0x1b1e320, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 46142] 16:32:13.414718 <... futex resumed> ) = 0
[pid 46142] 16:32:13.414767 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7feb19800000
sudo strace -p<pid> -s 100 -f -tt &> tmp.out
\n
[pid 47605] 16:32:13.388307 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"
[pid 46142] 16:32:13.370983 futex(0x34af8d0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 46142] 16:32:13.371061 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
[pid 46142] 16:32:13.371169 futex(0x34af8d0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 46142] 16:32:13.371221 <... futex resumed> ) = 0
[pid 46142] 16:32:13.377014 brk(0x3d45000 <unfinished ...>
[pid 46142] 16:32:13.377254 <... brk resumed> ) = 0x3d45000
[pid 46142] 16:32:13.378971 mmap(0x40696000, 65536, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_32BIT, -1, 0) = 0x40696000
[pid 46142] 16:32:13.381868 futex(0x7feb0000b88c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7feb0000b888, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 46142] 16:32:13.413922 tgkill(46142, 47605, SIGPWR) = 0
[pid 46142] 16:32:13.413992 tgkill(46142, 47599, SIGPWR <unfinished ...>
[pid 46142] 16:32:13.414221 <... tgkill resumed> ) = 0
[pid 46142] 16:32:13.414267 tgkill(46142, 46146, SIGPWR <unfinished ...>
[pid 46142] 16:32:13.414437 <... tgkill resumed> ) = 0
[pid 46142] 16:32:13.414601 futex(0x1b1e320, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 46142] 16:32:13.414718 <... futex resumed> ) = 0
[pid 46142] 16:32:13.414767 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7feb19800000
%pre%\n%pre%%pre%]x%pre%4500152:{i14659%pre%\n%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%]Q0_1_2_3_4_5_6_7_8_9_10_11_12_13_14_15_16_17_18_19_20_21_"..., 16384}, {"3490_3491_3492_3493_3494_3495_3496_3497_3498_3499_3500_3501_3502_3503_3504_3505_3506_3507_3508_3509_"..., 7553}], msg_controllen=0, msg_flags=0}, 0 <unfinished ...>
[pid 46142] 16:32:13.413922 tgkill(46142, 47605, SIGPWR) = 0
[pid 47605] 16:32:13.414024 <... sendmsg resumed> ) = 16384
[pid 47605] 16:32:13.414094 --- SIGPWR (Power failure) @ 0 (0) ---
[pid 47605] 16:32:13.414191 rt_sigprocmask(SIG_BLOCK, [XCPU],  <unfinished ...>
[pid 47605] 16:32:13.414242 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 47605] 16:32:13.414304 rt_sigsuspend(~[XCPU RTMIN RT_1] <unfinished ...>
[pid 46142] 16:32:13.418930 tgkill(46142, 47605, SIGXCPU) = 0
[pid 47605] 16:32:13.419057 <... rt_sigsuspend resumed> ) = ? ERESTARTNOHAND (To be restarted)
[pid 47605] 16:32:13.419143 --- SIGXCPU (CPU time limit exceeded) @ 0 (0) ---
[pid 47605] 16:32:13.419236 rt_sigreturn(0x30 <unfinished ...>
[pid 47605] 16:32:13.419306 <... rt_sigreturn resumed> ) = -1 EINTR (Interrupted system call)
[pid 47605] 16:32:13.419360 rt_sigprocmask(SIG_UNBLOCK, [XCPU],  <unfinished ...>
[pid 47605] 16:32:13.419431 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 47605] 16:32:13.419481 rt_sigreturn(0xffffffff <unfinished ...>
[pid 47605] 16:32:13.419562 <... rt_sigreturn resumed> ) = 16384
%pre%]x%pre%4500152:{i14659%pre%\n%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%]Q0_1_2_3_4_5_6_7_8_9_10_11_12_13_14_15_16_17_18_19_20_21_"..., 16384}, {"3490_3491_3492_3493_3494_3495_3496_3497_3498_3499_3500_3501_3502_3503_3504_3505_3506_3507_3508_3509_"..., 7553}], msg_controllen=0, msg_flags=0}, 0 <unfinished ...>
[pid 46142] 16:32:13.413922 tgkill(46142, 47605, SIGPWR) = 0
[pid 47605] 16:32:13.414024 <... sendmsg resumed> ) = 16384
[pid 47605] 16:32:13.414094 --- SIGPWR (Power failure) @ 0 (0) ---
[pid 47605] 16:32:13.414191 rt_sigprocmask(SIG_BLOCK, [XCPU],  <unfinished ...>
[pid 47605] 16:32:13.414242 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 47605] 16:32:13.414304 rt_sigsuspend(~[XCPU RTMIN RT_1] <unfinished ...>
[pid 46142] 16:32:13.418930 tgkill(46142, 47605, SIGXCPU) = 0
[pid 47605] 16:32:13.419057 <... rt_sigsuspend resumed> ) = ? ERESTARTNOHAND (To be restarted)
[pid 47605] 16:32:13.419143 --- SIGXCPU (CPU time limit exceeded) @ 0 (0) ---
[pid 47605] 16:32:13.419236 rt_sigreturn(0x30 <unfinished ...>
[pid 47605] 16:32:13.419306 <... rt_sigreturn resumed> ) = -1 EINTR (Interrupted system call)
[pid 47605] 16:32:13.419360 rt_sigprocmask(SIG_UNBLOCK, [XCPU],  <unfinished ...>
[pid 47605] 16:32:13.419431 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 47605] 16:32:13.419481 rt_sigreturn(0xffffffff <unfinished ...>
[pid 47605] 16:32:13.419562 <... rt_sigreturn resumed> ) = 16384

Isso parece indicar que o encadeamento com tid 46142 usou tgkill para enviar um sinal SIGPWR para encadear com tid 47605 , que estava no processo de envio de bytes com sendmsg . Isso de alguma forma interrompeu e só acabou enviando 16384 dos 23937 bytes solicitados.

Eu tentei ver se o thread com tid 46142 estava fazendo algo que pudesse explicar a causa do tgkill , mas tudo que vejo é

%pre%

que não consigo entender no contexto da chamada do sistema de rede.

O que poderia fazer com que um thread enviasse um sinal SIGPWR?

Não tenho certeza se isso é relevante, mas estou usando um tamanho de buffer de envio de soquete de 4096 e o tamanho da MTU da interface de loopback está definido como 16436. Posso reproduzir consistentemente o% parcial sendmsg com esses tamanhos. Se, no entanto, duplicar o tamanho da MTU, o problema desaparece. Da mesma forma, se eu definir o tamanho do buffer de envio do meu soquete como algo muito maior, como 24000, não consigo mais reproduzir o problema.

    

Answer 1

Tudo o que as threads fazem é apenas parte do código próprio do programa, ou de alguma biblioteca que ele usa. Então a resposta para "O que poderia causar um segmento para enviar um sinal SIGPWR?" vai variar de programa para programa.

No seu caso, é o Mono runtime que usa esses recursos internamente. Pelo que pude descobrir, o SIGPWR e o SIGXCPU estão acostumados a acionar o coletor de lixo .