facebook / hhvm

A virtual machine for executing programs written in Hack.
https://hhvm.com
Other
18.21k stars 3k forks source link

hhvm spin-locking using 3 times more system than user CPU #5081

Closed edwh closed 8 years ago

edwh commented 9 years ago

I'm running load testing on an 8 core machine, and I'm seeing hhvm use 3 times more system CPU than user. It looks like it's in a spinlock - below is some ptrace output.

Any suggestions as to whether I can improve this, e.g. by restructuring my code somehow?

[pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15957] <... futex resumed> ) = 0 [pid 15950] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15957] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15947] <... futex resumed> ) = 0 [pid 15901] <... futex resumed> ) = 0 [pid 15892] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 15947] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15995] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15947] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 15947] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15901] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 15947] <... futex resumed> ) = 0 [pid 16004] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15947] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15901] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15947] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15901] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 15957] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 1 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15957] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15957] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = 0 [pid 15957] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15957] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15995] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15995] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15995] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = 0 [pid 15957] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] <... futex resumed> ) = 0 [pid 15995] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15957] <... futex resumed> ) = 0 [pid 15947] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 15957] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15947] <... futex resumed> ) = 0 [pid 15950] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16010] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15957] <... futex resumed> ) = 0 [pid 15950] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15950] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 1 [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 15957] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15950] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15947] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15901] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16014] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16014] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16010] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16014] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15995] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15957] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15950] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16012] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15995] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 15995] <... futex resumed> ) = 0 [pid 15950] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15947] <... futex resumed> ) = 0 [pid 15901] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15892] <... futex resumed> ) = 0 [pid 15882] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15881] flock(4006, LOCK_EX <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16010] <... futex resumed> ) = 0 [pid 15950] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15882] <... futex resumed> ) = 0 [pid 15879] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16012] <... futex resumed> ) = 0 [pid 16015] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15901] <... futex resumed> ) = 0 [pid 15882] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15880] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15879] <... futex resumed> ) = 0 [pid 15875] flock(2269, LOCK_EX <unfinished ...> [pid 15873] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 15873] <... futex resumed> ) = 0 [pid 15873] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15950] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = 0 [pid 15882] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15873] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] <... futex resumed> ) = 0 [pid 16016] <... futex resumed> ) = 0 [pid 16015] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = 0 [pid 16012] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 15950] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15901] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = 0 [pid 16004] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16015] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16016] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16015] <... futex resumed> ) = 0 [pid 16004] <... futex resumed> ) = 0 [pid 15901] <... futex resumed> ) = 0 [pid 16016] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15882] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15880] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 16016] <... futex resumed> ) = 0 [pid 15879] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16012] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15950] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16012] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 16010] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15950] <... futex resumed> ) = 0 [pid 16012] <... futex resumed> ) = 0 [pid 16010] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16004] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15901] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15882] <... futex resumed> ) = 0 [pid 15901] <... futex resumed> ) = 0 [pid 15880] futex(0x7f1432f25990, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15879] <... futex resumed> ) = 0 [pid 15873] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15859] futex(0x7f1432f25990, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 16016] futex(0x7f142c118a40, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 15950] futex(0x7f142c118a40, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> [pid 15873] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15859] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) [pid 15856] flock(913, LOCK_EX <unfinished ...> [pid 15854] flock(2140, LOCK_EX <unfinished ...>

edwh commented 9 years ago

Is call_user_func known to perform badly? I have some evidence that might be the culprit.

edwh commented 9 years ago

...but even ensuring I don't use that, it's still more system than user, which is usually the sign of a bottleneck.

jwatzman commented 9 years ago

Can you attach gdb, and do th apply all bt (I think that's the syntax) to see what lock the threads are actually spinning on? (Or provide a small example case that shows the problem.)

edwh commented 9 years ago

I did that, but github was playing up. However it seemed to be inside libgcc, below the HHVM PDO, sometimes within exception handling (which is expected on this system as it's a Percona cluster). I'll get a proper backtrace on Monday.

On Sat, Mar 28, 2015 at 9:15 AM, Josh Watzman notifications@github.com wrote:

Can you attach gdb, and do th apply all bt (I think that's the syntax) to see what lock the threads are actually spinning on? (Or provide a small example case that shows the problem.)

— Reply to this email directly or view it on GitHub https://github.com/facebook/hhvm/issues/5081#issuecomment-87197060.

poige commented 9 years ago

I can confirm it too: http://etcinsider.com/blog/2015/05/11/hhvm-is-futex-abuser/

ehcpdeveloper commented 9 years ago

same situation. I got very high mem usage, with many:

futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f77964000c8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)

when these disappear, normal cpu levels are reached (returned to normal)

Similar situation: https://phabricator.wikimedia.org/T1195

any help is appreciated ..

ehcpdeveloper commented 9 years ago

Latest info:

I noticed that, when the futex contention occurs, the futex address on my server always ends with 000c8. Below some additional log and hhvm version:

# hhvm --version
HipHop VM 3.3.0-dev (rel)
Compiler: heads/master-0-gff1127b8ae0731e6329cf764674f064507aa36b8
Repo schema: 6e50b19e977ebf72128f0398efd84e944f378d6e
Extension API: 20140702

32 14:51:09.435525471 1 hhvm (5598) > switch next=7 pgft_maj=0 pgft_min=7514100 vm_size=3181208 vm_rss=579756 vm_swap=0 
46 14:51:09.436911728 2 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
47 14:51:09.436915582 1 hhvm (5598) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
48 14:51:09.436917607 1 hhvm (5598) < futex res=0 
49 14:51:09.436918032 2 hhvm (5545) < futex res=-11(EAGAIN) 
50 14:51:09.436919677 2 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
51 14:51:09.436919929 2 hhvm (5545) < futex res=0 
52 14:51:09.437295897 2 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
53 14:51:09.437297673 3 hhvm (4043) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
54 14:51:09.437303321 2 hhvm (5545) > switch next=5620(hhvm) pgft_maj=0 pgft_min=6729968 vm_size=3181208 vm_rss=579756 vm_swap=0 
55 14:51:09.437318795 2 hhvm (5620) < futex res=0 
56 14:51:09.437323623 2 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
57 14:51:09.437325678 3 hhvm (4043) < futex res=1 
58 14:51:09.437325688 2 hhvm (5620) < futex res=0 
59 14:51:09.439266604 0 hhvm (5577) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
60 14:51:09.439271542 0 hhvm (5577) < futex res=0 
61 14:51:09.439491468 2 hhvm (5620) > switch next=3965(hhvm) pgft_maj=0 pgft_min=14766450 vm_size=3181208 vm_rss=579756 vm_swap=0 
62 14:51:09.439506999 2 hhvm (3965) < epoll_wait res=0 
63 14:51:09.439519860 2 hhvm (3965) > switch next=22433 pgft_maj=0 pgft_min=4083 vm_size=3181208 vm_rss=579756 vm_swap=0 
64 14:51:09.439520824 1 hhvm (5598) > switch next=7930 pgft_maj=0 pgft_min=7514100 vm_size=3181208 vm_rss=579756 vm_swap=0 
65 14:51:09.439521213 0 hhvm (5577) > switch next=21949 pgft_maj=2 pgft_min=7195094 vm_size=3181208 vm_rss=579756 vm_swap=0 
66 14:51:09.439521388 3 hhvm (4043) > switch next=25914 pgft_maj=0 pgft_min=2794352 vm_size=3181208 vm_rss=579756 vm_swap=0 
71 14:51:09.439532089 3 hhvm (5545) < futex res=0 
72 14:51:09.439532109 2 hhvm (3965) > switch next=11 pgft_maj=0 pgft_min=4083 vm_size=3181208 vm_rss=579756 vm_swap=0 
75 14:51:09.439537441 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
76 14:51:09.439538167 3 hhvm (5545) < futex res=0 
77 14:51:09.439554108 2 hhvm (3965) > epoll_wait maxevents=32 
78 14:51:09.439559968 2 hhvm (3965) > switch next=5620(hhvm) pgft_maj=0 pgft_min=4083 vm_size=3181208 vm_rss=579756 vm_swap=0 
79 14:51:09.439579264 2 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
80 14:51:09.439581105 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
81 14:51:09.439581189 2 hhvm (5620) < futex res=-11(EAGAIN) 
82 14:51:09.439581692 3 hhvm (5545) < futex res=0 
83 14:51:09.439582767 2 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
84 14:51:09.439582993 2 hhvm (5620) < futex res=0 
85 14:51:09.439606616 3 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
86 14:51:09.439606797 2 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
87 14:51:09.439607143 2 hhvm (5620) < futex res=0 
88 14:51:09.439607226 3 hhvm (5545) < futex res=-11(EAGAIN) 
89 14:51:09.439608571 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
90 14:51:09.439608732 3 hhvm (5545) < futex res=0 
91 14:51:09.439618124 3 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
92 14:51:09.439619392 3 hhvm (5545) > switch next=4043(hhvm) pgft_maj=0 pgft_min=6729968 vm_size=3181208 vm_rss=579756 vm_swap=0 
93 14:51:09.439621739 1 hhvm (5598) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
94 14:51:09.439623606 1 hhvm (5598) < futex res=1 
95 14:51:09.439922360 2 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
96 14:51:09.439926509 0 hhvm (5577) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
97 14:51:09.439926945 2 hhvm (5620) > switch next=4308(hhvm) pgft_maj=0 pgft_min=14766450 vm_size=3181208 vm_rss=579756 vm_swap=0 
98 14:51:09.439934146 2 hhvm (4308) < futex res=1 
99 14:51:09.439937750 0 hhvm (5577) < futex res=1 
100 14:51:09.443528086 1 hhvm (5598) > switch next=7 pgft_maj=0 pgft_min=7514100 vm_size=3181208 vm_rss=579756 vm_swap=0 
102 14:51:09.443558035 1 hhvm (5545) < futex res=0 
103 14:51:09.443566658 1 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
104 14:51:09.443569944 1 hhvm (5545) < futex res=0 
105 14:51:09.443656881 1 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
106 14:51:09.443659148 3 hhvm (4043) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
107 14:51:09.443660774 1 hhvm (5545) > switch next=5598(hhvm) pgft_maj=0 pgft_min=6729968 vm_size=3181208 vm_rss=579756 vm_swap=0 
108 14:51:09.443667483 3 hhvm (4043) < futex res=1 
109 14:51:09.447524604 0 hhvm (5577) > switch next=5620(hhvm) pgft_maj=2 pgft_min=7195094 vm_size=3181208 vm_rss=579756 vm_swap=0 
110 14:51:09.447526449 1 hhvm (5598) > switch next=7 pgft_maj=0 pgft_min=7514100 vm_size=3181208 vm_rss=579756 vm_swap=0 
112 14:51:09.447543515 0 hhvm (5620) < futex res=0 
113 14:51:09.447554018 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
114 14:51:09.447557560 0 hhvm (5620) < futex res=0 
115 14:51:09.447771710 2 hhvm (4308) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
116 14:51:09.447772052 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
117 14:51:09.447773025 0 hhvm (5620) < futex res=0 
118 14:51:09.447774353 2 hhvm (4308) < futex res=-11(EAGAIN) 
119 14:51:09.447776465 2 hhvm (4308) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
120 14:51:09.447776697 2 hhvm (4308) < futex res=0 
121 14:51:09.449636628 2 hhvm (4308) > switch next=3965(hhvm) pgft_maj=0 pgft_min=10089605 vm_size=3181208 vm_rss=580280 vm_swap=0 
122 14:51:09.449658440 2 hhvm (3965) < epoll_wait res=0 
123 14:51:09.449690489 2 hhvm (3965) > epoll_wait maxevents=32 
124 14:51:09.449702346 2 hhvm (3965) > switch next=4308(hhvm) pgft_maj=0 pgft_min=4083 vm_size=3181208 vm_rss=580280 vm_swap=0 
125 14:51:09.449806332 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
126 14:51:09.449808048 1 hhvm (5598) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
127 14:51:09.449810075 1 hhvm (5598) < futex res=0 
128 14:51:09.449810433 0 hhvm (5620) < futex res=-11(EAGAIN) 
129 14:51:09.449811253 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
130 14:51:09.449811490 0 hhvm (5620) < futex res=0 
131 14:51:09.450871715 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
132 14:51:09.450876831 1 hhvm (5598) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
133 14:51:09.450876880 0 hhvm (5620) < futex res=-11(EAGAIN) 
134 14:51:09.450878937 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
135 14:51:09.450879559 0 hhvm (5620) < futex res=0 
136 14:51:09.450879584 1 hhvm (5598) < futex res=0 
137 14:51:09.450935886 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
138 14:51:09.450936508 0 hhvm (5620) < futex res=-11(EAGAIN) 
139 14:51:09.450936694 3 hhvm (4043) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
140 14:51:09.450937949 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
141 14:51:09.450938084 0 hhvm (5620) < futex res=0 
142 14:51:09.450938702 3 hhvm (4043) < futex res=0 
143 14:51:09.451525133 3 hhvm (4043) > switch next=25914 pgft_maj=0 pgft_min=2794352 vm_size=3181208 vm_rss=580280 vm_swap=0 
144 14:51:09.451525141 1 hhvm (5598) > switch next=7930 pgft_maj=0 pgft_min=7514100 vm_size=3181208 vm_rss=580280 vm_swap=0 
145 14:51:09.451525148 2 hhvm (4308) > switch next=22433 pgft_maj=0 pgft_min=10089605 vm_size=3181208 vm_rss=580280 vm_swap=0 
146 14:51:09.451525154 0 hhvm (5620) > switch next=21949 pgft_maj=0 pgft_min=14766474 vm_size=3181208 vm_rss=580280 vm_swap=0 
152 14:51:09.451539282 3 hhvm (5545) < futex res=0 
153 14:51:09.451545597 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
154 14:51:09.451546719 3 hhvm (5545) < futex res=0 
155 14:51:09.451772129 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
156 14:51:09.451772670 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
157 14:51:09.451773840 3 hhvm (5545) < futex res=0 
158 14:51:09.451774440 0 hhvm (5620) < futex res=-11(EAGAIN) 
159 14:51:09.451775879 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
160 14:51:09.451776056 0 hhvm (5620) < futex res=0 
161 14:51:09.451825549 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
162 14:51:09.451826178 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
163 14:51:09.451831033 0 hhvm (5620) > switch next=5577(hhvm) pgft_maj=0 pgft_min=14766474 vm_size=3181208 vm_rss=580280 vm_swap=0 
164 14:51:09.451847683 3 hhvm (5545) < futex res=1 
165 14:51:09.451849707 0 hhvm (5577) > switch next=5620(hhvm) pgft_maj=2 pgft_min=7195094 vm_size=3181208 vm_rss=580280 vm_swap=0 
166 14:51:09.451853495 0 hhvm (5620) < futex res=0 
167 14:51:09.451855006 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
168 14:51:09.451855378 0 hhvm (5620) < futex res=0 
169 14:51:09.451909419 2 hhvm (4308) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
170 14:51:09.451910165 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
171 14:51:09.451910703 0 hhvm (5620) < futex res=0 
172 14:51:09.451910905 2 hhvm (4308) < futex res=-11(EAGAIN) 
173 14:51:09.451912046 2 hhvm (4308) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
174 14:51:09.451912330 2 hhvm (4308) < futex res=0 
175 14:51:09.451945647 3 hhvm (5545) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
176 14:51:09.451946366 0 hhvm (5620) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
177 14:51:09.451946464 3 hhvm (5545) < futex res=-11(EAGAIN) 
178 14:51:09.451946615 0 hhvm (5620) < futex res=0 
179 14:51:09.451947913 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
180 14:51:09.451948113 3 hhvm (5545) < futex res=0 
181 14:51:09.451960838 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
182 14:51:09.451961135 0 hhvm (5620) < futex res=-11(EAGAIN) 
183 14:51:09.451961396 1 hhvm (5598) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
184 14:51:09.451961411 0 hhvm (5620) > futex addr=7FC3178000C8 op=128(FUTEX_PRIVATE_FLAG) val=2 
185 14:51:09.451961902 3 hhvm (5545) > futex addr=7FC3178000C8 op=129(FUTEX_PRIVATE_FLAG|FUTEX_WAKE) val=1 
186 14:51:09.451962753 0 hhvm (5620) > switch next=5577(hhvm) pgft_maj=0 pgft_min=14766474 vm_size=3181208 vm_rss=580280 vm_swap=0 
poige commented 9 years ago

It's time to confess -- I noticed that problem only on DigitalOcean's host. My wild guess this can be related to under-hypervisor-run (in a way? O_o) Does anybody here use any hypervisor-based virtualization too?

fredemmott commented 9 years ago

Have any of you tried with more recent versions? While we still support 3.3, it would be useful to know if this has already been fixed in a later release.

poige commented 9 years ago

What are those "more recent versions"? O_o

poige commented 9 years ago

@fredemmott

$ apt-cache show hhvm|fgrep Version
Version: 3.7.0~trusty

as I told you, try running under Hypervisor such as KVM, for e. g..

fredemmott commented 9 years ago

Thanks; the only version previously mentioned appeared to be HipHop VM 3.3.0-dev (rel) :)

fredemmott commented 9 years ago

So, for next steps:

Either of these should show what's triggering it, and that'll hopefully be enough for us to fix it.

fredemmott commented 9 years ago

as I told you, try running under Hypervisor such as KVM, for e. g..

Issues that need involved setup are near the bottom of the pile; issues with isolated reproduction cases and backtraces are more likely to be worked on soon, as they're a much more efficient use of time.

mhdali commented 9 years ago

I'm having the same issue as the guys do which is high number of futex calls.

My HHVM version is HipHop VM 3.7.0 (rel). My configs: server.ini

pid = /var/run/hhvm/pid
hhvm.server.port = 9000
hhvm.server.type = fastcgi
hhvm.server.default_document = index.php
hhvm.log.use_syslog = true
hhvm.repo.central.path = /var/run/hhvm/hhvm.hhbc
hhvm.libxml.ext_entity_whitelist = file,http

php.ini

session.save_handler = files
session.save_path = /var/lib/php5
session.gc_maxlifetime = 1440
hhvm.log.level = Warning
hhvm.log.always_log_unhandled_exceptions = true
hhvm.log.runtime_error_reporting_level = 8191
hhvm.mysql.typed_results = false
hhvm.libxml.ext_entity_whitelist = file,http

I'm running hhvm + nginx stack in one docker container, both controlled by runit process supervision.

I'm doing benchmark on my server, the first time it went very smooth, but when I run it for the second time the performance of the server dropped, below is the ab benchmark request per second outputs: 1st time

Requests per second:    78.19 [#/sec] (mean)

2nd time

Requests per second:    7.48 [#/sec] (mean)

I tried to strace hhvm and find out that futex calls is very high and taking too much time, that lead me to this thread.

Tried to upgrade HHVM version to latest one 3.7.1 version, but still this issue happening.

I also tried to do perf, but the data file is almost 100MB, do you want me to upload it somewhere or you want me to run something on it?

fredemmott commented 9 years ago

expand it, look at what's calling futex. A screenshot of the expanded call tree would be useful.

poige commented 9 years ago

Issues that need involved setup are near the bottom of the pile; issues with isolated reproduction cases and backtraces are more likely to be worked on soon, as they're a much more efficient use of time.

don't get me wrong — I don't demand or insist. In my case the issue's been solved when switched from DigitalOcean (which implies KVM™). So, as to me that's been solved already and all's cool. ;)

ehcpdeveloper commented 9 years ago

Here is my info, that you requested:

HipHop VM 3.3.0-dev (rel) Compiler: heads/master-0-gff1127b8ae0731e6329cf764674f064507aa36b8 Repo schema: 6e50b19e977ebf72128f0398efd84e944f378d6e Extension API: 20140702

I am not running inside a virtual machine, kvm, hypervisor or docker,

I am running hhvm+nginx, I am Not using digitalocean..

I will try to backtrace using gdb or other tools, althaugh not easy in production environment. simpler/practical methods for debugging would be good, if you can recommend.

This situation is very common for me now, I am having heavy trouble.

poige commented 9 years ago

@bvidinli uname -r ?

ehcpdeveloper commented 9 years ago

here are more info, I managed to record a sample, I saw small intervals of futex contention while runnign hhvm, Now, I will try to analyse recorded perf.data file. it is a 1.1 G file. The run was normal for about 90% of time, but was stuck at futex in the remaining time of 10%, with futex calls to an address ending with 000C8. This relatively small amount of futex calls causes whole server to go load of 100% cpu. The cpu is going up for some time, then, goes down for some time. I will try to find what is causign that futex calls. Please note the warning in the perf output.. You may guide me in finding right information in perf.data file. Until you guide me, I will try on my own.

# perf record -g /usr/bin/hhvm --config /etc/hhvm/php.ini --config /etc/hhvm/server.ini --user www-data -vPidFile=/var/run/hhvm/pid -vEval.JitASize=350000001 -vEval.JitGlobalDataSize=350000002 -vEval.PerfPidMap=0 -m server
^C[ perf record: Woken up 4270 times to write data ]
[ perf record: Captured and wrote 1068.853 MB perf.data (~46698910 samples) ]
Warning:
Processed 5804262 events and lost 4 chunks!

Check IO/CPU overload!

/usr/bin/hhvm: Interrupt
#

# ls perf* -lh
-rw------- 1 root root 1.1G Jun 18 10:36 perf.data

# hhvm --version
HipHop VM 3.3.0-dev (rel)
Compiler: heads/master-0-gff1127b8ae0731e6329cf764674f064507aa36b8
Repo schema: 6e50b19e977ebf72128f0398efd84e944f378d6e
Extension API: 20140702

# uname -a
Linux y0ia3qq39t 3.13.0-55-generic #92-Ubuntu SMP Sun Jun 14 18:32:20 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
ehcpdeveloper commented 9 years ago

I loaded perf.data using: perf report perf.data

the screen was almost blank, no events seen, most probably because of many events. I filtered futex using / key, here is result:

Samples: 1K of event 'cycles', Event count (approx.): 1333457052
+  14.36%  hhvm  [kernel.kallsyms]  [k] get_futex_key
+  14.18%  hhvm  [kernel.kallsyms]  [k] futex_wake
+  13.86%  hhvm  [kernel.kallsyms]  [k] futex_wait
+  12.20%  hhvm  [kernel.kallsyms]  [k] get_futex_key_refs.isra.13 
+  10.70%  hhvm  [kernel.kallsyms]  [k] do_futex
+   8.24%  hhvm  [kernel.kallsyms]  [k] futex_wait_queue_me        
+   8.13%  hhvm  [kernel.kallsyms]  [k] sys_futex
+   7.99%  hhvm  [kernel.kallsyms]  [k] futex_wait_setup
+   6.93%  hhvm  [kernel.kallsyms]  [k] wake_futex
+   1.28%  hhvm  [kernel.kallsyms]  [k] drop_futex_key_refs.isra.14
+   1.06%  hhvm  [kernel.kallsyms]  [k] get_futex_value_locked     
+   0.95%  hhvm  [kernel.kallsyms]  [k] futex_wake_op              
+   0.13%  hhvm  [kernel.kallsyms]  [k] __unqueue_futex 

the percent information are in red, for percentages greater than 5

more coming. (does perf.data file contain private info ? can I share it by email or similar ? )

ehcpdeveloper commented 9 years ago

Now I managed to record perf stats only when "high cpu load" occurs. I will share my findings.

ehcpdeveloper commented 9 years ago

after I record, I inspect it using perf report filename, then press / and enter, to show all events, as I guessed to use perf report command.

Below are some outputs of perf report command, multiple output in one, I only included top-n lines, which have percertage higher than %1 approx, that is, I ignored little events, while including here,

My first findings: (I am not expert in hhvm or perf command, just learning) I think perf-8395.map are generated because of my "perf" command. They should not be executed without perf. There are no perf files in /tmp, I checked.

there are two suspects: memcpy and libjemalloc.so.1

These are just guesses that I made. Now, I am waiting for your thoughts. What else, I can do ? I will record and share here, some more outputs too..

Samples: 121K of event 'cycles', Event count (approx.): 95794025774 
+  41.37%  hhvm  perf-8395.map                  [.] 0x00007fb1f58612f1
+  27.62%  hhvm  hhvm                           [.] memcpy          
+   4.69%  hhvm  libjemalloc.so.1               [.] 0x000000000000a148
+   3.08%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   1.85%  hhvm  hhvm                           [.] HPHP::jit::FrameState* std::__uninitialized_copy<false>::__uninit_copy<__gnu_cxx::__normal_iterator<HPHP::jit::FrameSt
+   1.80%  hhvm  hhvm                           [.] HPHP::jit::FrameStateMgr::pauseBlock(HPHP::jit::Block*)            
+   1.49%  hhvm  hhvm                           [.] std::vector<HPHP::jit::SlotState<true>, std::allocator<HPHP::jit::SlotState<true> > >::operator=(std::vector<HPHP::jit
+   1.35%  hhvm  hhvm                           [.] std::vector<HPHP::jit::SlotState<false>, std::allocator<HPHP::jit::SlotState<false> > >::operator=(std::vector<HPHP::j
+   0.87%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   0.68%  hhvm  [kernel.kallsyms]              [k] clear_page_c_e  
+   0.60%  hhvm  hhvm                           [.] void std::vector<HPHP::jit::Vinstr, std::allocator<HPHP::jit::Vinstr> >::_M_range_insert<__gnu_cxx::__normal_iterator<
+   0.59%  hhvm  libjemalloc.so.1               [.] free            
+   0.52%  hhvm  [kernel.kallsyms]              [k] page_fault      
+   0.52%  hhvm  hhvm                           [.] HPHP::jit::FrameStateMgr::collectPostConds(HPHP::jit::Block*)      

Samples: 82K of event 'cycles', Event count (approx.): 68367511525  
+  27.10%  hhvm  perf-8395.map                  [.] 0x00007fb1f58618ca
+  13.93%  hhvm  hhvm                           [.] memcpy          
+   7.75%  hhvm  libjemalloc.so.1               [.] 0x000000000000c55c
+   5.13%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   2.77%  hhvm  hhvm                           [.] HPHP::jit::FrameState* std::__uninitialized_copy<false>::__uninit_copy<__gnu_cxx::__normal_iterator<HPHP::jit::FrameSt
+   2.72%  hhvm  hhvm                           [.] std::vector<HPHP::jit::SlotState<true>, std::allocator<HPHP::jit::SlotState<true> > >::operator=(std::vector<HPHP::jit
+   2.69%  hhvm  hhvm                           [.] HPHP::jit::FrameStateMgr::pauseBlock(HPHP::jit::Block*)            
+   2.67%  hhvm  [kernel.kallsyms]              [k] clear_page_c_e  
+   2.65%  hhvm  hhvm                           [.] std::vector<HPHP::jit::SlotState<false>, std::allocator<HPHP::jit::SlotState<false> > >::operator=(std::vector<HPHP::j
+   2.36%  hhvm  [kernel.kallsyms]              [k] page_fault      
+   1.59%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   1.47%  hhvm  [kernel.kallsyms]              [k] __mem_cgroup_commit_charge
+   1.18%  hhvm  [kernel.kallsyms]              [k] flush_tlb_func  
+   0.96%  hhvm  [kernel.kallsyms]              [k] flush_tlb_mm_range
+   0.94%  hhvm  [kernel.kallsyms]              [k] unmap_page_range
+   0.94%  hhvm  [kernel.kallsyms]              [k] __rmqueue

Samples: 107K of event 'cycles', Event count (approx.): 89180026738 
+  59.84%  hhvm  hhvm                           [.] memcpy          
+  34.55%  hhvm  perf-8395.map                  [.] 0x00007fb1f58618d2
+   0.78%  hhvm  libjemalloc.so.1               [.] 0x000000000000d99c
+   0.28%  hhvm  [heap]                         [.] 0x000000001948c6dd
+   0.16%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   0.15%  hhvm  hhvm                           [.] HPHP::StringData::Make(char const*, unsigned long, HPHP::CopyStringMode)     
+   0.11%  hhvm  hhvm                           [.] HPHP::preg_match_impl(HPHP::String const&, HPHP::String const&, HPHP::Variant*, int, int, bool) [clone .constprop.208]
+   0.10%  hhvm  hhvm                           [.] HPHP::jit::FrameState* std::__uninitialized_copy<false>::__uninit_copy<__gnu_cxx::__normal_iterator<HPHP::jit::FrameSt
+   0.10%  hhvm  hhvm                           [.] HPHP::jit::FrameStateMgr::pauseBlock(HPHP::jit::Block*)            
+   0.09%  hhvm  libjemalloc.so.1               [.] free            
+   0.05%  hhvm  hhvm                           [.] HPHP::PCRECache::find(HPHP::PCRECache::Accessor&, HPHP::String const&, std::unique_ptr<HPHP::LRUCacheKey, std::default
+   0.05%  hhvm  libjemalloc.so.1               [.] malloc          
+   0.05%  hhvm  hhvm                           [.] std::vector<HPHP::jit::SlotState<true>, std::allocator<HPHP::jit::SlotState<true> > >::operator=(std::vector<HPHP::jit
+   0.04%  hhvm  [kernel.kallsyms]              [k] e1000_irq_enable

Samples: 158K of event 'cycles', Event count (approx.): 130152492060
+  68.94%  hhvm  hhvm                   [.] memcpy                  
+  28.79%  hhvm  perf-8395.map          [.] 0x00007fb1f5861e15      
+   0.59%  hhvm  libjemalloc.so.1       [.] 0x000000000000a888      
+   0.17%  hhvm  hhvm                   [.] HPHP::StringData::Make(char const*, unsigned long, HPHP::CopyStringMode)   
+   0.15%  hhvm  hhvm                   [.] HPHP::preg_match_impl(HPHP::String const&, HPHP::String const&, HPHP::Variant*, int, int, bool) [clone .constprop.208]        
+   0.14%  hhvm  [heap]                 [.] 0x000000001948cf21      
+   0.06%  hhvm  libjemalloc.so.1       [.] free                    
+   0.04%  hhvm  hhvm                   [.] HPHP::PCRECache::find(HPHP::PCRECache::Accessor&, HPHP::String const&, std::unique_ptr<HPHP::LRUCacheKey, std::default_delete<
+   0.03%  hhvm  hhvm                   [.] HPHP::EmptyArray::Append(HPHP::ArrayData*, HPHP::Variant const&, bool)     
+   0.03%  hhvm  libjemalloc.so.1       [.] malloc          

Samples: 154K of event 'cycles', Event count (approx.): 126121871378
+  67.89%  hhvm  hhvm                           [.] memcpy          
+  25.71%  hhvm  perf-8395.map                  [.] 0x00007fb1f58618d2
+   0.79%  hhvm  libjemalloc.so.1               [.] 0x000000000000aa06
+   0.29%  hhvm  [heap]                         [.] 0x000000001940002b
+   0.18%  hhvm  hhvm                           [.] HPHP::StringData::Make(char const*, unsigned long, HPHP::CopyStringMode)     
+   0.15%  hhvm  libjemalloc.so.1               [.] free            
+   0.15%  hhvm  hhvm                           [.] HPHP::preg_match_impl(HPHP::String const&, HPHP::String const&, HPHP::Variant*, int, int, bool) [clone .constprop.208]
+   0.10%  hhvm  libjemalloc.so.1               [.] malloc          
+   0.06%  hhvm  [kernel.kallsyms]              [k] ipt_do_table    
+   0.06%  hhvm  hhvm                           [.] std::_Rb_tree<HPHP::jit::TypeSource, HPHP::jit::TypeSource, std::_Identity<HPHP::jit::TypeSource>, std::less<HPHP::jit
+   0.05%  hhvm  hhvm                           [.] HPHP::PCRECache::find(HPHP::PCRECache::Accessor&, HPHP::String const&, std::unique_ptr<HPHP::LRUCacheKey, std::default
+   0.05%  hhvm  hhvm                           [.] HPHP::MixedArray::NvGetStr(HPHP::ArrayData const*, HPHP::StringData const*)  
+   0.05%  hhvm  libz.so.1.2.8                  [.] 0x0000000000002b76
ehcpdeveloper commented 9 years ago

when I filter perf report using / futex :

-  14.36%  hhvm  [k] get_futex_key                                                                                                                                       ▒
   - get_futex_key                                                                                                                                                       ▒
      - 38.71% futex_wake                                                                                                                                                ▒
           do_futex                                                                                                                                                      ▒
         - sys_futex                                                                                                                                                     ▒
            - 99.01% system_call_fastpath                                                                                                                                ▒
               - __lll_unlock_wake                                                                                                                                       ▒
                  + 86.06% HPHP::preg_match(HPHP::String const&, HPHP::String const&, HPHP::Variant&, int, int)                                                          ▒
                  + 2.58% 0x7effe4c001c9                                                                                                                                 ▒
                  + 2.50% 0x7effe4c00479                                                                                                                                 ▒
                  + 2.48% 0x7effe4c00348                                                                                                                                 ▒
                  + 2.40% 0x7effe4c00349                                                                                                                                 ▒
                  + 2.32% 0x7effd8003048                                                                                                                                 ▒
                  + 1.67% HPHP::AsyncFuncImpl::ThreadFunc(void*)                                                                                                         ▒
            + 0.99% tracesys                                                                                                                                             ◆
      + 35.14% futex_wait_setup                                                                                                                                          ▒
      + 15.64% do_futex                                                                                                                                                  ▒
      + 9.88% futex_wait                                                                                                                                                 ▒
      + 0.62% futex_wake_op                                                                                                                                              ▒
-  14.18%  hhvm  [k] futex_wake                                                                                                                                          ▒
   - futex_wake                                                                                                                                                          ▒
      - 80.47% do_futex                                                                                                                                                  ▒
         - sys_futex                                                                                                                                                     ▒
            - 99.05% system_call_fastpath                                                                                                                                ▒
               - __lll_unlock_wake                                                                                                                                       ▒
                  + 60.96% HPHP::preg_match(HPHP::String const&, HPHP::String const&, HPHP::Variant&, int, int)                                                          ▒
                  + 13.55% 0x7effe4c001c8                                                                                                                                ▒
                  + 7.07% 0x7effe4c001c9                                                                                                                                 ▒
                  + 3.81% 0x7effe4c003e1                                                                                                                                 ▒
                  + 2.86% 0x7effe4c00348                                                                                                                                 ▒
                  + 2.59% HPHP::Scanner::~Scanner()                                                                                                                      ▒
                  + 1.45% 0x7effe4c00349                                                                                                                                 ▒
                  + 1.44% 0x7effe4c002b1                                                                                                                                 ▒
                    1.39% 0                                                                                                                                              ▒
                  + 1.36% 0x7effbe803259                                                                                                                                 ▒
                  + 1.30% 0x7effe4c006d9                                                                                                                                 ▒
                    1.27% 0x2e66ffffc9eee8ff                                                                                                                             ▒
                  + 0.96% 0x7effe4c003e0                                                                                                                                 ▒
            + 0.95% tracesys                                                                                                                                             ▒
      + 19.53% sys_futex                                                                                       

More detailed tree:

-  14.36%  hhvm  [kernel.kallsyms]  [k] get_futex_key                                                                                                                    ◆
   - get_futex_key                                                                                                                                                       ▒
      - 38.71% futex_wake                                                                                                                                                ▒
           do_futex                                                                                                                                                      ▒
         - sys_futex                                                                                                                                                     ▒
            - 99.01% system_call_fastpath                                                                                                                                ▒
               - __lll_unlock_wake                                                                                                                                       ▒
                  - 86.06% HPHP::preg_match(HPHP::String const&, HPHP::String const&, HPHP::Variant&, int, int)                                                          ▒
                     - HPHP::f_preg_match(HPHP::String const&, HPHP::String const&, HPHP::VRefParamValue const&, int, int)                                               ▒
                        - 81.50% 0x1a2925f2                                                                                                                              ▒
                             0x1a292329                                                                                                                                  ▒
                           - 0x1a2921fa                                                                                                                                  ▒
                              - 48.13% 0x1ab70d35                                                                                                                        ▒
                                 - 65.76% 0x1a63eac9                                                                                                                     ▒
                                      0x33000000                                                                                                                         ▒
                                      0x1a200001                                                                                                                         ▒
                                      HPHP::jit::x64::(anonymous namespace)::BackEnd::enterTCHelper(unsigned char*, HPHP::ActRec*)                                       ▒
                                      HPHP::jit::MCGenerator::enterTC(unsigned char*, HPHP::ActRec*)                                                                     ▒
                                      HPHP::enterVM(HPHP::ActRec*, HPHP::StackArgsState, HPHP::Resumable*, HPHP::ObjectData*)                                            ▒
                                      HPHP::ExecutionContext::invokeFunc(HPHP::TypedValue*, HPHP::Func const*, HPHP::Variant const&, HPHP::ObjectData*, HPHP::Class*, HPH▒
                                      HPHP::ExecutionContext::invokeUnit(HPHP::TypedValue*, HPHP::Unit const*)                                                           ▒
                                      HPHP::invoke_file(HPHP::String const&, bool, char const*)                                                                          ▒
                                      HPHP::include_impl_invoke(HPHP::String const&, bool, char const*)                                                                  ▒
                                      HPHP::hphp_invoke(HPHP::ExecutionContext*, std::string const&, bool, HPHP::Array const&, HPHP::VRefParamValue const&, std::string c▒
                                      HPHP::HttpRequestHandler::executePHPRequest(HPHP::Transport*, HPHP::RequestURI&, HPHP::SourceRootInfo&, bool)                      ▒
                                      HPHP::HttpRequestHandler::handleRequest(HPHP::Transport*)                                                                          ▒
                                      HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJobImpl(std::shared_ptr<HPHP::FastCGIJob>, b▒
                                      HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJob(std::shared_ptr<HPHP::FastCGIJob>)      ▒
                                      HPHP::JobQueueWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::Server*, true, false, HPHP::JobQueueDropVMStack>::start()            ▒
                                      HPHP::AsyncFuncImpl::ThreadFunc(void*)                                                                                             ▒
                                      HPHP::start_routine_wrapper(void*)                                                                                                 ▒
                                      start_thread                                                                                                                       ▒
                                 - 19.96% 0x1ac7e949                                                                                                                     ▒
                                      0x33000000                                                                                                                         ▒
                                      0x1a200001                                                                                                                         ▒
                                      HPHP::jit::x64::(anonymous namespace)::BackEnd::enterTCHelper(unsigned char*, HPHP::ActRec*)                                       ▒
                                      HPHP::jit::MCGenerator::enterTC(unsigned char*, HPHP::ActRec*)                                                                     ▒
                                      HPHP::enterVM(HPHP::ActRec*, HPHP::StackArgsState, HPHP::Resumable*, HPHP::ObjectData*)                                            ▒
                                      HPHP::ExecutionContext::invokeFunc(HPHP::TypedValue*, HPHP::Func const*, HPHP::Variant const&, HPHP::ObjectData*, HPHP::Class*, HPH▒
                                      HPHP::ExecutionContext::invokeUnit(HPHP::TypedValue*, HPHP::Unit const*)

-  23.65%  hhvm  [kernel.kallsyms]  [k] wake_futex                                                                                                                       ◆
   - wake_futex                                                                                                                                                          ▒
      - 74.83% futex_wake                                                                                                                                                ▒
           do_futex                                                                                                                                                      ▒
           sys_futex                                                                                                                                                     ▒
           system_call_fastpath                                                                                                                                          ▒
         - __lll_unlock_wake                                                                                                                                             ▒
            - 100.00% HPHP::preg_match(HPHP::String const&, HPHP::String const&, HPHP::Variant&, int, int)                                                               ▒
                 HPHP::f_preg_match(HPHP::String const&, HPHP::String const&, HPHP::VRefParamValue const&, int, int)                                                     ▒
                 0x1a4b3872                                                                                                                                              ▒
                 0x1a4b35a9                                                                                                                                              ▒
                 0x1a4b16b1                                                                                                                                              ▒
                 0x1a8a3c35                                                                                                                                              ▒
                 0x1a6608c0                                                                                                                                              ▒
                 0x1a400001                                                                                                                                              ▒
                 HPHP::jit::x64::(anonymous namespace)::BackEnd::enterTCHelper(unsigned char*, HPHP::ActRec*)                                                            ▒
                 HPHP::jit::MCGenerator::enterTC(unsigned char*, HPHP::ActRec*)                                                                                          ▒
                 HPHP::enterVM(HPHP::ActRec*, HPHP::StackArgsState, HPHP::Resumable*, HPHP::ObjectData*)                                                                 ▒
                 HPHP::ExecutionContext::invokeFunc(HPHP::TypedValue*, HPHP::Func const*, HPHP::Variant const&, HPHP::ObjectData*, HPHP::Class*, HPHP::VarEnv*, HPHP::Str▒
                 HPHP::ExecutionContext::invokeUnit(HPHP::TypedValue*, HPHP::Unit const*)                                                                                ▒
                 HPHP::invoke_file(HPHP::String const&, bool, char const*)                                                                                               ▒
                 HPHP::include_impl_invoke(HPHP::String const&, bool, char const*)                                                                                       ▒
                 HPHP::hphp_invoke(HPHP::ExecutionContext*, std::string const&, bool, HPHP::Array const&, HPHP::VRefParamValue const&, std::string const&, std::string co▒
                 HPHP::HttpRequestHandler::executePHPRequest(HPHP::Transport*, HPHP::RequestURI&, HPHP::SourceRootInfo&, bool)                                           ▒
                 HPHP::HttpRequestHandler::handleRequest(HPHP::Transport*)                                                                                               ▒
                 HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJobImpl(std::shared_ptr<HPHP::FastCGIJob>, bool)                 ▒
                 HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJob(std::shared_ptr<HPHP::FastCGIJob>)                           ▒
                 HPHP::JobQueueWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::Server*, true, false, HPHP::JobQueueDropVMStack>::start()                                 ▒
                 HPHP::AsyncFuncImpl::ThreadFunc(void*)                                                                                                                  ▒
                 HPHP::start_routine_wrapper(void*)                                                                                                                      ▒
                 start_thread                                                               
ehcpdeveloper commented 9 years ago

same on other perf.data files. All futex calls are happening in preg_match functions.

-  24.43%  hhvm  [kernel.kallsyms]  [k] get_futex_key                                                                                                                    ◆
   - get_futex_key                                                                                                                                                       ▒
      - 43.37% futex_wake                                                                                                                                                ▒
           do_futex                                                                                                                                                      ▒
           sys_futex                                                                                                                                                     ▒
           system_call_fastpath                                                                                                                                          ▒
         - __lll_unlock_wake                                                                                                                                             ▒
            - 100.00% HPHP::preg_match(HPHP::String const&, HPHP::String const&, HPHP::Variant&, int, int)                                                               ▒
                 HPHP::f_preg_match(HPHP::String const&, HPHP::String const&, HPHP::VRefParamValue const&, int, int)                                                     ▒
                 0x1a4b3872                                                                                                                                              ▒
                 0x1a4b35a9                                                                                                                                              ▒
                 0x1a4b16b1                                                                                                                                              ▒
                 0x1a8a3c35                                                                                                                                              ▒
                 0x1a6608c0                                                                                                                                              ▒
                 0x1a400001                                                                                                                                              ▒
                 HPHP::jit::x64::(anonymous namespace)::BackEnd::enterTCHelper(unsigned char*, HPHP::ActRec*)                                                            ▒
                 HPHP::jit::MCGenerator::enterTC(unsigned char*, HPHP::ActRec*)                                                                                          ▒
                 HPHP::enterVM(HPHP::ActRec*, HPHP::StackArgsState, HPHP::Resumable*, HPHP::ObjectData*)                                                                 ▒
                 HPHP::ExecutionContext::invokeFunc(HPHP::TypedValue*, HPHP::Func const*, HPHP::Variant const&, HPHP::ObjectData*, HPHP::Class*, HPHP::VarEnv*, HPHP::Str▒
                 HPHP::ExecutionContext::invokeUnit(HPHP::TypedValue*, HPHP::Unit const*)                                                                                ▒
                 HPHP::invoke_file(HPHP::String const&, bool, char const*)                                                                                               ▒
                 HPHP::include_impl_invoke(HPHP::String const&, bool, char const*)                                                                                       ▒
                 HPHP::hphp_invoke(HPHP::ExecutionContext*, std::string const&, bool, HPHP::Array const&, HPHP::VRefParamValue const&, std::string const&, std::string co▒
                 HPHP::HttpRequestHandler::executePHPRequest(HPHP::Transport*, HPHP::RequestURI&, HPHP::SourceRootInfo&, bool)                                           ▒
                 HPHP::HttpRequestHandler::handleRequest(HPHP::Transport*)                                                                                               ▒
                 HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJobImpl(std::shared_ptr<HPHP::FastCGIJob>, bool)                 ▒
                 HPHP::ServerWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::FastCGITransportTraits>::doJob(std::shared_ptr<HPHP::FastCGIJob>)                           ▒
                 HPHP::JobQueueWorker<std::shared_ptr<HPHP::FastCGIJob>, HPHP::Server*, true, false, HPHP::JobQueueDropVMStack>::start()                                 ▒
                 HPHP::AsyncFuncImpl::ThreadFunc(void*)                                                                                                                  ▒
                 HPHP::start_routine_wrapper(void*)                                                                                                                      ▒
                 start_thread                                                                                               
jwatzman commented 9 years ago

For the folks that are reporting this, what code are you running? Some OSS framework, or custom code, or what? (Apologies if I missed this, but I don't see it in the info above.)

The futex calls coming from preg_match are interesting, that's definitely something to go on when we get a chance.

edwh commented 9 years ago

Do you mean what application is the PHP code? In my case it's a custom application written from scratch, not a standard one.

On 19 June 2015 17:57:32 BST, Josh Watzman notifications@github.com wrote:

For the folks that are reporting this, what code are you running? Some OSS framework, or custom code, or what? (Apologies if I missed this, but I don't see it in the info above.)

The futex calls coming from preg_match are interesting, that's definitely something to go on when we get a chance.


Reply to this email directly or view it on GitHub: https://github.com/facebook/hhvm/issues/5081#issuecomment-113575315

paulbiss commented 9 years ago

There are a variety of different PCRE cache options. The default cache is static, does setting hhvm.pcre_cache_type to lru or scalable still produce this deadlock?

ehcpdeveloper commented 9 years ago

Now, I set hhvm.pcre_cache_type to lru in server.ini, But I am not sure this setting is in effect, because, in past, I saw situations where something is not working in server.ini or php.ini, so, I had to run hhvm in command line like:

/usr/bin/hhvm --config /etc/hhvm/php.ini --config /etc/hhvm/server.ini --user www-data -vPidFile=/var/run/hhvm/pid -vEval.JitASize=350000001 -vEval.JitGlobalDataSize=350000002 -vEval.PerfPidMap=0 -m server

So, how can I simply dump config of hhvm ?

@jwatzman : I am using a general purpose php software, that is used by many people around world, but, I can say: it has many files, I do not know which file/code produces this error. I can try to find, if you guide me in locating the code. Actually I wonder what the preg_match code has something to do with futex locking mechanism.

Please also note that, I am not expert on hhvm and perf, so, the guess of problem, "preg_match" may be wrong, I wrote what I find. we need to make sure the location of problem.

ehcpdeveloper commented 9 years ago

same situation continues, with setting hhvm.pcre_cache_type to lru in server.ini, (I assume lru is in effect now) high cpu occurs, new perf.data files are produced when high cpu occurs. I looked with perf report, searched in that prog using / futex, futex calls established in preg_match, just like above..

By the way, there are tens of files in application, many preg_match in php code.

I can send to you, some perf.data files.. I continue to save them.

ehcpdeveloper commented 9 years ago

any info ? I am trying to find source of error, trying to locate related code, but not found yet. What you think ?

ehcpdeveloper commented 9 years ago

I noticed that, I am using an old version of hhvm, 3.3.0 I tried to install hhvm 3.6 using https://github.com/facebook/hhvm/wiki/Prebuilt-packages-on-Ubuntu-14.04 but, I was unable to install it. It does not install hhvm 3.6 but, 3.3

Where are 3.6 packages for Ubuntu ? or how can I install hhvm 3.6 onto ubuntu ? 3.8 is also ok ?

ehcpdeveloper commented 9 years ago

managed to install hhvm 3.8, There were no packages for Ubuntu, I had to compile,

# hhvm --version
HipHop VM 3.8.0-dev (rel)
Compiler: heads/master-0-g996f7a7ff3443002eefb42641d556e223c62d691
Repo schema: b921f793b7c4b3a3035d156c96059d8fdf787bff

now, watching system.

iMaxopoly commented 9 years ago

@bvidinli hhvm-nightly package is available on ubuntu.

ziruizhuang commented 9 years ago

HipHop VM 3.7.3 (rel) Compiler: tags/HHVM-3.7.3-0-g08c64d25f6c2cd316730b1d37db9eb33744cb306 Repo schema: 6ba408ef27e1fc7820c8bd6352989f40c1acb812

Same problem, will try nightly

ehcpdeveloper commented 9 years ago

With the install of 3.8, the problem on the server is reduced. The cpu load still increases sometime above normal levels, many futex calls ocurs again, but, it is not lasting too much, it recovers from the deadlock, somehow, within a reasonable time.

Nothing changed in runned php programs.

jwatzman commented 9 years ago

I wasn't able to reproduce this locally with a master build of HHVM. I was trying this script:

<?php

function f() {
  echo "hi\n";
  for ($i = 0; $i < 1000000; $i++) {}

  $pat = uniqid();
  $target = uniqid() . $pat . uniqid();

  var_dump(preg_match('/'.$pat.'/', $target));
}

f();

Running HHVM with ~/local/hhvm/hphp/hhvm/hhvm -m server -d hhvm.server.type=proxygen -p 8080, and hitting it with siege -b -c 500 http://localhost:8080/pcre.php. Doing a perf record -g -p [pid] then a perf report didn't show futexes showing up anywhere interesting, even when I searched for them (well less than 1% of total time).

@ehcpdeveloper One thing that might be useful is if you set -vEval.PerfPidMap=1 -d hhvm.keep_perf_pid_map=1 -- that would re-enable the perf pid map and keep it around, which might tell us what PHP-level code is ultimately causing the futex calls -- and then you will hopefully be able to paste that snippet of code to get some representative example, which might help us find a repro case.

Yermo commented 9 years ago

I am seeing this problem repeatedly under Ubuntu 14.04 running:

HipHop VM 3.8.1 (rel) Compiler: tags/HHVM-3.8.1-0-g3006bc45691762b5409fc3a510a43093968e9660 Repo schema: 253b3802ce1bcd19e378634342fc9c245ac76c33

Official pre-compiled binary.

The application that I am running is a large one I have built from scratch. It makes fairly extensive use of preg_match() FWIW.

I am happy to do whatever testing necessary to help but would need a little guidance to provide you the information you need.

jwatzman commented 9 years ago

The most useful thing would be an isolated repro case :)

Failing that, try this. It will get data similar to what @ehcpdeveloper above provided; along with being a useful second data point, it will also hopefully have a few extra stack frames in the middle.

Yermo commented 9 years ago

@jwatzman Thank you. The problem manifests itself several times a day so I should be able to easily reproduce this. Coming up with a small test case is going to be challenging since my platform is a bit monstrous and I have, to date, only witnessed this on a live site and never my development machine.

I will, however, make an attempt.

jwatzman commented 9 years ago

@Yermo cool thanks, looking forward to the data :) The perf tool is lightweight enough you should be fine just running it on a production machine when you see the issue, no need to restart HHVM before or after.

Yermo commented 9 years ago

@jwatzman "a watched for bug never reproduces". Today is the first day I've checked the server in the morning without the load being over 4. Clearly just having 'perf' at the ready scares the bug into hiding. :) I'll keep an eye on it and get you the info as soon as it recurs.

Yermo commented 9 years ago

I did receive this error when running perf:

Failed to open /tmp/perf-2861.map, continuing without symbols

in addition to this one:

Processed 3498 events and lost 1 chunks!
Check IO/CPU overload! 

The load on the system according to 'top' was around 3.97. I should note that once it starts to spin up the load it doesn't stop until I restart hhvm. Sometimes the load spikes back immediately, sometimes it stays down for over 24 hours.

The site in question can handle some down time and experimentation. I have from time to time helped debug portions of hhvm and have even submitted a patch that was accepted. While this particular bug is probably out of my reach to track down alone in any kind of reasonable time frame, I am more than willing to run whatever tests you would like me to even involving debugging builds, etc. I am motivated to help.

2015-08-25-114010_1920x1054_scrot 2015-08-25-114049_1920x1054_scrot 2015-08-25-114208_1920x1054_scrot

Yermo commented 9 years ago

Reading through the comment thread here I noticed the suggested "thread apply all bt" test so I ran that and here is the output:

Thread 6 (Thread 0x7f7dfb3ff700 (LWP 2864)):

0 0x00007f7e0bc2fb13 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81

1 0x00007f7e0d3f1813 in ?? () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5

2 0x00007f7e0d3dd907 in event_base_loop () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5

3 0x00000000028e0406 in folly::EventBase::loopBody(int) ()

4 0x00000000028e2969 in folly::EventBase::loopForever() ()

5 0x00000000022d0afa in proxygen::WorkerThread::runLoop() ()

6 0x00000000022d0d3f in std::thread::_Impl<std::_Bind_simple<proxygen::WorkerThread::start()::{lambda()#1} ()> >::_M_run() ()

7 0x00007f7e0c4c7a40 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

8 0x00007f7e0c722182 in start_thread (arg=0x7f7dfb3ff700) at pthread_create.c:312

9 0x00007f7e0bc2f47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 5 (Thread 0x7f7df67ff700 (LWP 2865)):

0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

1 0x000000000204c178 in HPHP::SynchronizableMulti::waitImpl(int, int, bool, timespec_) ()

2 0x0000000000ebf9ea in HPHP::JobQueueWorkerstd::sharedptr<HPHP::FastCGIJob, HPHP::Server, true, false, HPHP::JobQueueDropVMStack>::start() ()

3 0x0000000002076c97 in HPHP::AsyncFuncImpl::ThreadFunc(void_) ()

4 0x0000000000c73867 in HPHP::start_routinewrapper(void) ()

5 0x00007f7e0c722182 in start_thread (arg=0x7f7df67ff700) at pthread_create.c:312

6 0x00007f7e0bc2f47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 4 (Thread 0x7f7df1bff700 (LWP 2866)):

0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

1 0x000000000204c178 in HPHP::SynchronizableMulti::waitImpl(int, int, bool, timespec_) ()

2 0x0000000000ebf9ea in HPHP::JobQueueWorkerstd::sharedptr<HPHP::FastCGIJob, HPHP::Server, true, false, HPHP::JobQueueDropVMStack>::start() ()

3 0x0000000002076c97 in HPHP::AsyncFuncImpl::ThreadFunc(void_) ()

4 0x0000000000c73867 in HPHP::start_routinewrapper(void) ()

5 0x00007f7e0c722182 in start_thread (arg=0x7f7df1bff700) at pthread_create.c:312

6 0x00007f7e0bc2f47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 3 (Thread 0x7f7dfa7ff700 (LWP 2867)):

0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

1 0x000000000204c178 in HPHP::SynchronizableMulti::waitImpl(int, int, bool, timespec_) ()

2 0x0000000000ebf9ea in HPHP::JobQueueWorkerstd::sharedptr<HPHP::FastCGIJob, HPHP::Server, true, false, HPHP::JobQueueDropVMStack>::start() ()

3 0x0000000002076c97 in HPHP::AsyncFuncImpl::ThreadFunc(void_) ()

4 0x0000000000c73867 in HPHP::start_routinewrapper(void) ()

5 0x00007f7e0c722182 in start_thread (arg=0x7f7dfa7ff700) at pthread_create.c:312

6 0x00007f7e0bc2f47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 2 (Thread 0x7f7df9bff700 (LWP 2868)):

0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

1 0x000000000204c178 in HPHP::SynchronizableMulti::waitImpl(int, int, bool, timespec_) ()

2 0x0000000000ebf9ea in HPHP::JobQueueWorkerstd::sharedptr<HPHP::FastCGIJob, HPHP::Server, true, false, HPHP::JobQueueDropVMStack>::start() ()

3 0x0000000002076c97 in HPHP::AsyncFuncImpl::ThreadFunc(void_) ()

4 0x0000000000c73867 in HPHP::start_routinewrapper(void) ()

5 0x00007f7e0c722182 in start_thread (arg=0x7f7df9bff700) at pthread_create.c:312

6 0x00007f7e0bc2f47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 1 (Thread 0x7f7dfbbff700 (LWP 2861)):

0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

---Type to continue, or q to quit---

1 0x0000000000ea6f38 in HPHP::HttpServer::runOrExitProcess() ()

2 0x0000000000d49a1a in HPHP::execute_program_impl(int, char**) ()

3 0x0000000000d4a29f in HPHP::execute_program(int, char**) ()

4 0x0000000000add481 in main ()

(gdb)

fredemmott commented 9 years ago

@Yermo:

Yermo commented 9 years ago

@fredemmott 3.8 Ubuntu installed from the official repositories.

I agree completely with regard to eval(). I'm reducing string expressions down to constants and throwing them at eval() to get a result for legacy reasons. I need to come up with a more efficient way of handling my custom expressions.

However, the high load problem is not related to my use of eval(). This code has been running perfectly even under load for ages. With recent versions of hhvm, hhvm will occasionally get into this state where it sits and spins at high load without any page requests at all. It will sit in this state for hours.

I submitted the thread list simply in an attempt to be helpful based on comments above on the off chance it might show something. All my requests are getting answered however when this sit and spin bug appears, it becomes very slow.

As an example, my server is now sitting at a load of 0.13 according to top. I can throw a wget at the site pulling all pages as fast as it can (local gigabit ethernet) and most pages, according to wget, pull in under 0.1 seconds. (hhvm rocks). The load will barely touch 1 in this case (old 2007 vintage slow blade server. Yea, I'm running bare metal.) However, the same pages can take 20 or more seconds when this spin and sit problem occurs and server load, according to top, will sit at over 4 with no requests coming in and hhvm using 100% cpu.

Now I completely suspect there may be something in my code that is exercising this bug in hhvm. But since others are reporting identical symptoms I figure it's something that needs to be tracked down and fixed. I'm seeing this problem multiple times per day.

I am more than happy to help track it down. I just need some guidance on what tests to run when it happens.

fredemmott commented 9 years ago

Is your perf and gdb output from when it is having high load? If not, can you do them again in that situation?

https://cloud.githubusercontent.com/assets/854565/9471451/5dc44886-4b1e-11e5-80c1-381d1f115eea.png is what I was basing the eval comment on - it shows ~ 15% of HHVMs CPU usage being spent dealing with brand new code - both the RepoTxnQuery::exec and HPHP::Scanner entries.

Yermo commented 9 years ago

@fredemmott As I mention in the comment, the load was at 3.97 without any requests coming in and hhvm was at 100% cpu according to top. It sat like this for over half and hour. When I attached gdb to it, the load obviously went down. Interestingly, when I detached from gdb the load remained down so the act of attaching gdb and releasing it stops the sit and spin cycle.

I did notice the "Failed to open /tmp/perf-2861.map" error. Is that in any way significant? (in terms of giving you the info you need from perf?)

Yermo commented 9 years ago

@fredemmott Yea, my code does spend a bunch of time in eval. :( But all I'm sending to eval are constant arithmetic and logical expressions. Things like 4 > 3 or 1 + 5. I'm not eval'ing anything other than short constant strings.

fredemmott commented 9 years ago

If the perf map can't be opened, JITted code will show up, but only as memory addresses, not function names. These don't appear to be showing up highly (due to the eval), so it's not a practical issue for you at the moment.

Perf can be ran via sudo to avoid this problem.