Ceph » Linux kernel client

The first stack trace shows a warning pop for removing an auth cap while it's still dirty. The later ones, I can't make much sense of. You're copy/pasting most of them starting with the "Modules linked in:" line, and that leaves out the lines in the logs that print the actual cause of the stack trace. Can you re-attach a more complete set of stack traces?

Thanks, that helps.

The first warning looks like it came about because the client got blocklisted. That warning is silenced in later kernels. I think we can ignore that. After that are a number of cgroup OOM kills. Those I think we can ignore too.

The next trace is this one:

Sep  1 07:57:11 core-k8s-node039 kernel: [501198.414663] NMI backtrace for cpu 6
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.415671] CPU: 6 PID: 15156 Comm: umount Tainted: G        W   E     5.10.46-ceph #2
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.417182] Hardware name: Hetzner vServer, BIOS 20171111 11/11/2017
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.418517] Call Trace:
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.419410]  <IRQ>
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.420225]  dump_stack+0x6d/0x88
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.421195]  nmi_cpu_backtrace.cold.9+0x30/0x65
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.422300]  ? lapic_can_unplug_cpu+0x80/0x80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.423414]  nmi_trigger_cpumask_backtrace+0xde/0xe0
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.424603]  rcu_dump_cpu_stacks+0xab/0xd9
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.425685]  rcu_sched_clock_irq.cold.93+0x109/0x365
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.427078]  ? trigger_load_balance+0x5c/0x240
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.428450]  ? tick_sched_do_timer+0x60/0x60
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.429771]  update_process_times+0x55/0x80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.431095]  tick_sched_handle.isra.22+0x1f/0x60
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.432494]  tick_sched_timer+0x65/0x80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.433740]  __hrtimer_run_queues+0x101/0x250
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.435052]  hrtimer_interrupt+0x100/0x210
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.436353]  ? check_preempt_curr+0x51/0x60
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.437639]  __sysvec_apic_timer_interrupt+0x5d/0xd0
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.439023]  asm_call_irq_on_stack+0x12/0x20
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.440309]  </IRQ>
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.441291]  sysvec_apic_timer_interrupt+0x73/0x80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.442630]  asm_sysvec_apic_timer_interrupt+0x12/0x20
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.444057] RIP: 0010:ceph_check_caps+0x5/0xa60 [ceph]
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.445441] Code: 68 02 00 00 31 c0 48 39 f2 76 0c 48 01 c9 48 01 f2 48 39 d1 0f 93 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 0f 1f 44 00 00 <41> 57 41 56 49 89 d6 41 55 41 54 55 89 f5 53 48 89 fb 48 81 ec 70
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.449353] RSP: 0018:ffffa0d90534fe18 EFLAGS: 00000246
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.450810] RAX: 0000000000000002 RBX: ffff8e98c989c1ec RCX: 0000000000000000
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.452530] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff8e948339e780
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.454246] RBP: ffff8e98c989e800 R08: 0000000000000000 R09: 0000000000000000
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.455936] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8e948339eae0
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.457352] R13: ffff8e98c989c008 R14: ffff8e98c989c000 R15: 0000000000000008
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.458785]  ceph_flush_dirty_caps+0xd9/0x190 [ceph]
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.459989]  ceph_mdsc_pre_umount+0xa0/0x210 [ceph]
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.461172]  ceph_kill_sb+0x1f/0x80 [ceph]
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.462263]  deactivate_locked_super+0x2f/0x70
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.463423]  cleanup_mnt+0xb8/0x140
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.464442]  task_work_run+0x76/0xb0
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.465454]  exit_to_user_mode_prepare+0x129/0x130
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.466618]  syscall_exit_to_user_mode+0x28/0x140
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.467760]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.468920] RIP: 0033:0x7f167d3ae507
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.469903] Code: 19 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 31 f6 e9 09 00 00 00 66 0f 1f 84 00 00 00 00 00 b8 a6 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 59 19 0c 00 f7 d8 64 89 01 48
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.473208] RSP: 002b:00007ffd59f6cd78 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.474665] RAX: 0000000000000000 RBX: 0000557959cb8970 RCX: 00007f167d3ae507
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.476079] RDX: 0000000000000001 RSI: 0000000000000000 RDI: 0000557959cb8b80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.477476] RBP: 0000000000000000 R08: 0000557959cb8bf0 R09: 00007f167d42fe80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.478870] R10: 0000000000000000 R11: 0000000000000246 R12: 0000557959cb8b80
Sep  1 07:57:11 core-k8s-node039 kernel: [501198.480262] R13: 00007f167d4d41c4 R14: 0000557959cb8a68 R15: 0000000000000000

So I guess an NMI fired because this CPU was stuck?

In any case, this does look a lot like #46284, but I'm at a loss as to why the patches wouldn't have helped you. It might be interesting to see the contents of /sys/kernel/debug/ceph/<fsid>/caps during this period (and maybe also the contents of mdsc and osdc files under there too).

Usually it's not possible to inspect /sys when this happens because the systems become unresponsive and requires a reset.

One thing that may be of note is these nodes connecting to Ceph are running on shared CPUs (Ceph nodes are physical machines though). One theory I had before was maybe that Ceph wasn't the problem but what if we scale up our deployments on k8s or someone else running on the same Hetzner servers starts using more CPUs and we get choked somewhat on CPU time.

I later dismissed it because whenever the k8s nodes would freeze up it would be at the same time our Ceph cluster was having problems - someone running too many operations on CephFS or hardware failure on one of our Ceph nodes. And I would expect that if it was the case that sometime later we would eventually get some CPU time and the nodes would unfreeze but they would stay stuck for multiple hours or days and the only thing you could do is reset the VM.

Is it still possible that if a Ceph process would get scheduled on a CPU that's unavailable at that time to lockup the whole VM?

David B wrote:

Is it still possible that if a Ceph process would get scheduled on a CPU that's unavailable at that time to lockup the whole VM?

That sounds pretty unlikely. It seems more likely that this task is ending up livelocked somehow. ceph_flush_dirty_caps just walks the list of dirty caps in the session and calls ceph_check_caps on each, but there is no guarantee that the cap will be removed from the list when that function is called, so it could just keep continually cycling over a set of stuck caps that can't be cleaned for some reason. Probably we need a stronger guarantee of forward progress there (or better warnings as to why we can't progress).

I'll have to look at revamping that code to at least warn us if we're continually cycling over the same set of caps.

BTW: what mount options are you using?

It's also possible that this is a result of #52283. It looks like the patch for that went into v5.10.62 stable series kernels. Note that there is a follow-on patch for that too, so you may want to pull in 05a444d3f90a3 as well if you try that kernel.

The mount options are (rw,relatime,name=storage,secret=<hidden>,acl).

I'll take a look at those other patches, thanks.