varnishcache
Child killed as it was unresponsive - stuck in deadlock with __GI___lll_lock_wait during vsl_get?
Expected Behavior
Children should not get killed ;)
Current Behavior
Children get killed, likely due to a deadlock, potentially with the master process?
Possible Solution
No response
Steps to Reproduce (for bugs)
Unfortunately, this has been a one off AFAICT and we can't reproduce at this moment.
Context
We've seen random stuck children every now and then but only received a decipherable core dump now.
Interestingly we had to restart the master process as well to get this unstuck.
Jun 05 09:57:11 xxx varnishd[679713]: Error: Unexpected reply from ping: 400 CLI communication error (hdr)
Jun 05 09:57:11 xxx varnishd[679713]: Child (2168345) not responding to CLI, killed it.
Jun 05 09:57:11 xxx varnishd[679713]: Unexpected reply from ping: 400 CLI communication error (hdr)
Jun 05 09:57:57 xxx systemd-coredump[4051844]: Could not parse number of program headers from core file: invalid `Elf' handle
Jun 05 09:57:57 xxx systemd-coredump[4051594]: [🡕] Process 2168345 (cache-main) of user 75 dumped core.
Module /var/spool/varnish/xxx/vmod_cache/_vmod_std.974d8b4da76817f9997109be9ede98ec6f04539caf6eee61b9c40b2529081113 without build-id.
Module /var/spool/varnish/xxx/vcl_boot.1707858351.045632/vgc.so without build-id.
Module /var/spool/varnish/xxx/vcl_boot.1707858351.045632/vgc.so
Module libgcc_s.so.1 without build-id.
Module libstdc++.so.6 without build-id.
Module libjemalloc.so.2 without build-id.
Module libpcre2-8.so.0 without build-id.
Module .varnishd-wrapped without build-id.
Stack trace of thread 2168345:
#0 0x00007fbc8ef52d0f __GI___lll_lock_wait (libc.so.6 + 0x82d0f)
#1 0x00007fbc8ef59122 __pthread_mutex_lock@GLIBC_2.2.5 (libc.so.6 + 0x89122)
#2 0x0000000000457990 vsl_get (.varnishd-wrapped + 0x57990)
#3 0x0000000000457d67 vslr (.varnishd-wrapped + 0x57d67)
#4 0x0000000000457f19 VSLv (.varnishd-wrapped + 0x57f19)
#5 0x000000000045811f VSL (.varnishd-wrapped + 0x5811f)
#6 0x0000000000428dbe cli_cb_before (.varnishd-wrapped + 0x28dbe)
#7 0x00000000004ca412 cls_exec (.varnishd-wrapped + 0xca412)
#8 0x00000000004caa4c VCLS_Poll (.varnishd-wrapped + 0xcaa4c)
#9 0x0000000000428ef4 CLI_Run (.varnishd-wrapped + 0x28ef4)
#10 0x00000000004464a7 child_main (.varnishd-wrapped + 0x464a7)
#11 0x000000000048e4bc mgt_launch_child (.varnishd-wrapped + 0x8e4bc)
#12 0x000000000048f207 mgt_reap_child (.varnishd-wrapped + 0x8f207)
#13 0x000000000048f3ce child_listener (.varnishd-wrapped + 0x8f3ce)
#14 0x00000000004cc4c4 VEV_Once (.varnishd-wrapped + 0xcc4c4)
#15 0x00000000004cc6b8 VEV_Loop (.varnishd-wrapped + 0xcc6b8)
#16 0x000000000041c258 main (.varnishd-wrapped + 0x1c258)
#17 0x00007fbc8eef3b0e __libc_start_call_main (libc.so.6 + 0x23b0e)
#18 0x00007fbc8eef3bc9 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x23bc9)
#19 0x000000000041c6e5 _start (.varnishd-wrapped + 0x1c6e5)
Stack trace of thread 2168373:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168384:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168377:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168464:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168491:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168473:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168483:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168520:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168492:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168534:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168500:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2187590:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2168502:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2653258:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
...
Stack trace of thread 2785251:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2921912:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2785254:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
Stack trace of thread 2785261:
#0 0x00007fbc8ef52ad6 __futex_abstimed_wait_common (libc.so.6 + 0x82ad6)
#1 0x00007fbc8ef552c8 pthread_cond_wait@@GLIBC_2.3.2 (libc.so.6 + 0x852c8)
#2 0x0000000000445584 Lck_CondWaitUntil (.varnishd-wrapped + 0x45584)
#3 0x000000000047271c WRK_Thread (.varnishd-wrapped + 0x7271c)
#4 0x0000000000472b47 pool_thread (.varnishd-wrapped + 0x72b47)
#5 0x00007fbc8ef55ec4 start_thread (libc.so.6 + 0x85ec4)
#6 0x00007fbc8efd7b20 __clone3 (libc.so.6 + 0x107b20)
ELF object binary architecture: AMD x86-64
Jun 05 09:57:58 xxx varnishd[679713]: Error: Child (2168345) not responding to CLI, killed it.
Jun 05 09:57:58 xxx varnishd[679713]: Error: Unexpected reply from ping: 400 CLI communication error (hdr)
Jun 05 09:57:58 xxx varnishd[679713]: Child (2168345) not responding to CLI, killed it.
Jun 05 09:57:58 xxx varnishd[679713]: Unexpected reply from ping: 400 CLI communication error (hdr)
Jun 05 09:57:58 xxx varnishd[679713]: Error: Child (2168345) not responding to CLI, killed it.
Jun 05 09:57:58 xxx varnishd[679713]: Error: Unexpected reply from ping: 400 CLI communication error
Jun 05 09:57:58 xxx varnishd[679713]: Child (2168345) not responding to CLI, killed it.
Jun 05 09:57:58 xxx varnishd[679713]: Unexpected reply from ping: 400 CLI communication error
Jun 05 09:57:58 xxx varnishd[679713]: Error: Child (2168345) died signal=3 (core dumped)
Jun 05 09:57:58 xxx varnishd[679713]: Child (2168345) died signal=3 (core dumped)
Jun 05 09:57:58 xxx varnishd[679713]: Debug: Child cleanup complete
Jun 05 09:57:58 xxx varnishd[679713]: Child cleanup complete
Varnish Cache version
varnishd (varnish-7.2.1 revision 399fa7ed46d68f4c4f42a8fd2748339750d99a8b)
Operating system
NixOS 23.11
Source of binary packages used (if any)
No response
There seems to be lock contention when writing to the shared memory.
Please confirm that you have mounted /var/lib/varnish as tmpfs.
Otherwise, writing to the shared memory would invoke disk IO and this would kill performance.
Do you collect MAIN.shm_* metrics? Do you have trends before incidents?
What is the value of the vsl_buffer parameter?
Also, please consider upgrading to a supported release, or downgrading to 6.0 for a long-term support release.
Sorry for the silence - this got lost in the firehose of notifications unfortunately ...
So the shm_metrics all look regularly busy around the time of the crash.
bytes: going up and down cont: going up and down cycles: flat line 0 flushes flat line 0 recordings: going up and down writes: going up an down
The active graphs look very similar to each other so I guess those are correlated. I can get you screenshots/specific numbers if you like.
vsl_buffer:
varnish> param.show vsl_buffer
200
vsl_buffer
Value is: 16k [bytes] (default)
Minimum is: 267
@asadsa92 afaict this is on a regular xfs volume.
I have a few tmpfs mounts on this machine, including /dev/shm/ but /var/spool/varnish (in our case - not /var/lib) resides on the root filesystem.
We could consider downgrading to 6.0, alternatively we'd update to 7.4 with the distro upgrade to 24.05 in the next weeks.
@asadsa92 afaict this is on a regular xfs volume.
I have a few tmpfs mounts on this machine, including
/dev/shm/but/var/spool/varnish(in our case - not/var/lib) resides on the root filesystem.
That could explain it. Do you happen to have graphs of disk performance for your root filesystem? If the high load on the disk correlate to when SHM counters increase then you got your answers. Either way, working directory of Varnish (usually /var/lib/varnish) should be mounted as tmpfs.
Thanks! I'll double check.
We did see related issues in situations where we took fsfreeze based snapshots where children were killed due to unresponsiveness. I was under the impression that memorymapped/shm structures were excempt from those effects, though.
That's very likely the source of this. If the snapshot takes long time to produce then the manager process of Varnish will observe the child not responding as the backtrace shows the child holding the CLI mutex while performing the write to VSL. Have a look at the cli_timeout parameter of Varnish (I don't recommend you increasing this but rather move working directory to tmpfs).
Varnish creates VSL space here: https://github.com/varnishcache/varnish-cache/blob/master/bin/varnishd/cache/cache_shmlog.c#L673-L674
Following the calls, you end up here: https://github.com/varnishcache/varnish-cache/blob/master/bin/varnishd/common/common_vsmw.c#L297-L306
The Linux kernel does not support the hint MAP_NOSYNC : https://elixir.bootlin.com/linux/v6.10.3/source/include/uapi/asm-generic/mman-common.h#L20
Which is also why this workaround is needed: https://github.com/varnishcache/varnish-cache/blob/master/bin/varnishd/common/common_vsmw.c#L63-L65
Moving the working directory to tmpfs backed filesystem would solve your problem:
- You can either create a mount-point at current location, usually
/var/lib/varnish. - You can specify
-n nameto a location which has tmpfs.
BTW, this is also why this is a W.I.P: https://github.com/varnishcache/varnish-cache/pull/4141 With this PR, you would get a message from Varnish that the working directory is not backed by tmpfs: https://github.com/varnishcache/varnish-cache/pull/4141/files#diff-ec8a0ac531b1891de9c210325340c7005d6c2ba946074caae9edc0702c8c3d6fR92
(Grr. Github or Firefox ate my comment that I already thought I posted).
Thanks for the thorough explanation - that matches my understanding so far with what we're seeing.
I'm happy to adjust our installation and will suggest a NixOS upstream patch so our whole distribution gets moved to tmpfs in the future.
@asadsa92 When you write /var/lib/varnish, do you mean /var/run/varnish? Because this seems to be the default working directory according to docs iirc.
We now have the jail warning for linux if the working directory is not on tmpfs, and a warning if mlock() fails, so can we close this issue?