search

lxc / lxcfs

FUSE filesystem for LXC
https://linuxcontainers.org/lxcfs
Other
1.04k stars 248 forks source link

Load average values are not updated(freezes) #504

Open exsver opened 2 years ago

exsver commented 2 years ago

All load average values(from /proc/loadavg) are not updated(freezes) inside containers for a long time(from a few minutes to a few hours). LA is not working for all containers simultaneously.

one container: image another container: image

grafana null options: image

This issue is reproducible for a few of the same servers with 250+ containers. Servers that run less than 250 containers work fine. All servers have the same hardware and software.

Versions:

OS:Ubuntu 20.04.3 LTS Kernel: 5.4.0-80-generic

LXC version "4.0.11" LXCFS version "4.0.11" LXD version "4.20"

Containers RUNNING: 337

Syslog

2021-12-03T03:26:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/798922/task" 2021-12-03T03:26:34+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/802521/task" 2021-12-03T03:26:34+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/802718/task" 2021-12-03T03:29:44+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/821922/task" 2021-12-03T03:30:07+02:00 lxcfs[826340]: utils.c: 290: send_creds: Invalid argument - Failed getting reply from server over socketpair: 2 2021-12-03T03:30:12+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T03:44:11+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T03:44:11+02:00 lxcfs[907178]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T03:46:08+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T03:46:08+02:00 lxcfs[918745]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T04:41:49+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1226596/task" 2021-12-03T04:42:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1227974/task" 2021-12-03T04:42:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1227977/task" 2021-12-03T04:42:59+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1231726/task" 2021-12-03T04:43:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1233693/task" 2021-12-03T04:43:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1233695/task" 2021-12-03T04:45:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1242709/task" 2021-12-03T04:45:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1246664/task" 2021-12-03T04:45:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1246665/task" 2021-12-03T04:46:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1250515/task" 2021-12-03T04:46:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1250516/task" 2021-12-03T04:46:19+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1249000/task" 2021-12-03T04:46:49+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1254582/task" 2021-12-03T04:46:54+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1255380/task" 2021-12-03T04:47:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1256138/task" 2021-12-03T04:47:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1256139/task" 2021-12-03T04:49:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1266240/task" 2021-12-03T04:50:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1271153/task" 2021-12-03T04:53:04+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T04:53:04+02:00 lxcfs[1285327]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T04:56:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1298636/task" 2021-12-03T04:56:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1298911/task" 2021-12-03T04:56:29+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1302222/task" 2021-12-03T04:57:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1306115/task" 2021-12-03T05:00:11+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T05:00:11+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T05:00:16+02:00 lxcfs[1323631]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T05:00:16+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1321932/task" 2021-12-03T05:00:16+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1321936/task" 2021-12-03T05:00:16+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1323888/task" 2021-12-03T05:00:16+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1323905/task" 2021-12-03T05:00:16+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1323909/task" 2021-12-03T05:05:28+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T05:05:28+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T05:05:32+02:00 lxcfs[1354204]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T05:05:32+02:00 lxcfs[1354202]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T05:08:54+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T06:14:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1730959/task" 2021-12-03T06:14:50+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1734712/task" 2021-12-03T06:14:50+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1734713/task" 2021-12-03T06:14:50+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1734714/task" 2021-12-03T06:17:20+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1749744/task" 2021-12-03T06:17:20+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1749745/task" 2021-12-03T06:18:17+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1753984/task" 2021-12-03T06:19:17+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1758510/task" 2021-12-03T06:20:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1760424/task" 2021-12-03T06:20:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1761060/task" 2021-12-03T06:21:14+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1768610/task" 2021-12-03T06:24:29+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/1783366/task" 2021-12-03T06:26:03+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T06:27:23+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T06:27:23+02:00 lxcfs[1796297]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:08:10+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:08:21+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:09:00+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:13:03+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:13:04+02:00 lxcfs[2025289]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:14:13+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:14:14+02:00 lxcfs[2030940]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:30:04+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:30:04+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:30:12+02:00 lxcfs[2108545]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:31:45+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:31:45+02:00 lxcfs[2116207]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:35:04+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:35:04+02:00 lxcfs[2130391]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:37:07+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T07:37:08+02:00 lxcfs[2139648]: utils.c: 315: send_creds: Connection refused - Failed at sendmsg: 2 2021-12-03T07:39:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2149637/task" 2021-12-03T07:39:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2149638/task" 2021-12-03T07:41:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2159346/task" 2021-12-03T07:42:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2163731/task" 2021-12-03T07:42:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2163732/task" 2021-12-03T07:45:06+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2176718/task" 2021-12-03T07:45:06+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2176727/task" 2021-12-03T07:46:25+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2186905/task" 2021-12-03T07:48:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2192775/task" 2021-12-03T07:48:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2192776/task" 2021-12-03T07:48:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2193908/task" 2021-12-03T07:48:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2193910/task" 2021-12-03T07:52:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2210271/task" 2021-12-03T07:52:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2210272/task" 2021-12-03T07:53:10+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2215296/task" 2021-12-03T07:55:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2224122/task" 2021-12-03T07:55:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2224123/task" 2021-12-03T07:58:05+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2234855/task" 2021-12-03T07:58:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2237000/task" 2021-12-03T07:58:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2237001/task" 2021-12-03T08:00:14+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2244597/task" 2021-12-03T08:00:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2247095/task" 2021-12-03T08:00:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2247096/task" 2021-12-03T08:00:19+02:00 lxcfs[2247630]: utils.c: 290: send_creds: Invalid argument - Failed getting reply from server over socketpair: 2 2021-12-03T08:00:26+02:00 lxcfs[1132]: utils.c: 254: recv_creds: Timed out waiting for scm_cred: No such process 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2596159/task" 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2596165/task" 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2597481/task" 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2597483/task" 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2596299/task" 2021-12-03T09:15:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2596312/task" 2021-12-03T09:16:23+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2604626/task" 2021-12-03T09:16:23+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2604627/task" 2021-12-03T09:22:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2628332/task" 2021-12-03T09:23:24+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2635785/task" 2021-12-03T09:37:04+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2697578/task" 2021-12-03T09:39:00+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2706701/task" 2021-12-03T09:40:20+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2714267/task" 2021-12-03T09:40:40+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2715691/task" 2021-12-03T09:46:20+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2744811/task" 2021-12-03T09:54:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2781129/task" 2021-12-03T09:54:15+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2781130/task" 2021-12-03T10:00:13+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2807881/task" 2021-12-03T10:00:13+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2807883/task" 2021-12-03T10:00:51+02:00 lxd[715876]: 2021/12/03 10:00:51 http: superfluous response.WriteHeader call from github.com/lxc/lxd/lxd/response.(errorResponse).Render (response.go:270) 2021-12-03T10:01:34+02:00 lxd[715876]: 2021/12/03 10:01:34 http: superfluous response.WriteHeader call from github.com/lxc/lxd/lxd/response.(errorResponse).Render (response.go:270) 2021-12-03T10:05:03+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2834016/task" 2021-12-03T10:08:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2848285/task" 2021-12-03T10:14:09+02:00 lxcfs[1132]: proc_loadavg.c: 404: refresh_load: Failed to open "/proc/2874055/task"

stgraber commented 2 years ago

@brauner thoughts?

brauner commented 2 years ago

This is with --enable-loadavg?

brauner commented 2 years ago

The failures to open these individual task directories is probably due to the fact that the threads exit to fast, i.e. by the time the opendir() is called the proc entry for that process is already cleaned up.

brauner commented 2 years ago

Would you be ok with sharing the cpu layout, i.e. how many sockets, threads etc?

brauner commented 2 years ago

I would think that loadavg could get problematic with increasing number of container as it uses a lot of locking.

exsver commented 2 years ago

Would you be ok with sharing the cpu layout, i.e. how many sockets, threads etc?

# lscpu 
Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   46 bits physical, 48 bits virtual
CPU(s):                          40
On-line CPU(s) list:             0-39
Thread(s) per core:              2
Core(s) per socket:              10
Socket(s):                       2
NUMA node(s):                    2
Vendor ID:                       GenuineIntel
CPU family:                      6
Model:                           62
Model name:                      Intel(R) Xeon(R) CPU E5-2690 v2 @ 3.00GHz
Stepping:                        4
CPU MHz:                         3300.091
CPU max MHz:                     3600.0000
CPU min MHz:                     1200.0000
BogoMIPS:                        6000.26
Virtualization:                  VT-x
L1d cache:                       640 KiB
L1i cache:                       640 KiB
L2 cache:                        5 MiB
L3 cache:                        50 MiB
NUMA node0 CPU(s):               0-9,20-29
NUMA node1 CPU(s):               10-19,30-39
Vulnerability Itlb multihit:     KVM: Mitigation: Split huge pages
Vulnerability L1tf:              Mitigation; PTE Inversion; VMX conditional cache flushes, SMT vulnerable
Vulnerability Mds:               Mitigation; Clear CPU buffers; SMT vulnerable
Vulnerability Meltdown:          Mitigation; PTI
Vulnerability Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl and seccomp
Vulnerability Spectre v1:        Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2:        Mitigation; Full generic retpoline, IBPB conditional, IBRS_FW, STIBP conditional, RSB filling
Vulnerability Srbds:             Not affected
Vulnerability Tsx async abort:   Not affected
Flags:                           fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est 
                                 tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm cpuid_fault epb pti ssbd ibrs ibpb stibp tpr_shadow vnmi flexpriority ept vpid fsgsbase smep erms xsaveopt dtherm ida arat pln pts md_clear flush_l1d
free -h
              total        used        free      shared  buff/cache   available
Mem:          377Gi       164Gi        32Gi        60Gi       181Gi       151Gi
Swap:         8.0Gi       4.0Gi       4.0Gi

host loadavg:

# cat /proc/loadavg 
51.53 42.53 47.69 28/21144 2139040
exsver commented 2 years ago

This is with --enable-loadavg?

Yes.

# ps aux | grep lxcfs
root        1132 14.2  0.0 21033784 51940 ?      Ssl  Aug18 22893:40 /usr/bin/lxcfs -l /var/lib/lxcfs/
mihalicyn commented 5 months ago

Hi @exsver !

Really sorry for a long delay with reply on this.

Unfortunately, I can't remember any related fixes in LXCFS which can address your specific problem. We had this https://github.com/lxc/lxcfs/commit/362a5d52bf67ff58e07f970abd0e642b3bf8279b but it's about deadlock, in your case we (probably) met with a heavy lock contention. And interesting question why and how.

I would recommend to try trace LXCFS process with strace -o strace.log -f -p <lxcfs daemon pid> and post results of tracing (5 min of tracing or 10 minutes). It's interesting to see why critical section between locks is executing so long or it's just a bad locking problem.