Sur un hôte RHEL 6, j'ai un serveur Cassandra qui écoute les connexions TCP sur localhost. En parallèle, j'ai une application client qui lui envoie des requêtes. Le client (C# Mono) utilise sendmsg
pour envoyer les octets sérialisés.
Je vois régulièrement le sendmsg
retourner sans avoir envoyé tous les octets demandés. J'ai utilisé strace
pour essayer de déboguer ce problème
sudo strace -p<pid> -s 100 -f -tt &> tmp.out
et a vu (échantillon filtré pour un fil conducteur) 47605
)
[pid 47605] 16:32:13.388307 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"\4\0\0\1\n\0\0]x\0\20\2545\250\260\34\26152:{i\261\204\266\3759\0\n\5\0\2\0\0\0\4\0\0\0\1\0\0]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
Cela semble indiquer que le fil avec tid 46142
utilisé tgkill
pour envoyer un signal SIGPWR au thread avec tid 47605
qui était en train d'envoyer des octets avec sendmsg
. Cela l'a en quelque sorte interrompu et il n'a envoyé que 16384 des 23937 octets demandés.
J'ai essayé de voir si le fil de discussion avec tid 46142
faisait quoi que ce soit qui puisse expliquer la cause de la tgkill
mais tout ce que je vois, c'est
[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
que je n'arrive pas à comprendre dans le contexte de l'appel système du réseau.
Qu'est-ce qui peut amener un thread à envoyer un signal SIGPWR ?
Je ne sais pas si c'est pertinent, mais j'utilise une taille de tampon d'envoi de socket de 4096 et la taille MTU de l'interface loopback est fixée à 16436. Je peux reproduire de manière cohérente le problème partiel sendmsg
avec ces tailles. Cependant, si je double la taille du MTU, le problème disparaît. De même, si je fixe la taille du tampon d'envoi de ma socket à quelque chose de beaucoup plus grand, comme 24000, je ne peux plus reproduire le problème.