The critical bit in your logs below are the lines
Oct 1 15:04:08 worker1004 kernel: libceph: reset on mds0
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 closed our session
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 reconnect start
...
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 reconnect denied
I couldn't tell you why the kernel client is facing disconnects that it doesn't handle more often than the userspace client is, perhaps it (or at least this kernel's version) isn't subscribing to mdsmap updates or handling them quickly enough.
But that sequence means that the mount is busted and can't recover itself.
-Greg
Unfortunately the CentOS kernel (3.10.0-862.14.4.el7.x86_64) has issues
as well. Different ones, but the nodes end up with an unusable mount in
an hour or two. Here are some syslogs:
Oct 1 11:50:28 worker1004 kernel: INFO: task fio:29007 blocked for more
than 120 seconds.
Oct 1 11:50:28 worker1004 kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 1 11:50:28 worker1004 kernel: fio D
ffff996d86e92f70 0 29007 28970 0x00000000
Oct 1 11:50:28 worker1004 kernel: Call Trace:
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c316ec0>] ? bit_wait+0x50/0x50
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c318f39>] schedule+0x29/0x70
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c3168a9>]
schedule_timeout+0x239/0x2c0
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bcfa982>] ?
ktime_get_ts64+0x52/0xf0
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c316ec0>] ? bit_wait+0x50/0x50
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c31844d>]
io_schedule_timeout+0xad/0x130
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c3184e8>]
io_schedule+0x18/0x20
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c316ed1>]
bit_wait_io+0x11/0x50
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c316a81>]
__wait_on_bit_lock+0x61/0xc0
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bd96684>]
__lock_page+0x74/0x90
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bcbefd0>] ?
wake_bit_function+0x40/0x40
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bd971a4>]
__find_lock_page+0x54/0x70
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bd97ed5>]
grab_cache_page_write_begin+0x55/0xc0
Oct 1 11:50:28 worker1004 kernel: [<ffffffffc12798e3>]
ceph_write_begin+0x43/0xe0 [ceph]
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bd96ac4>]
generic_file_buffered_write+0x124/0x2c0
Oct 1 11:50:28 worker1004 kernel: [<ffffffffc127526e>]
ceph_aio_write+0xa3e/0xcb0 [ceph]
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bdc81be>] ?
do_numa_page+0x1be/0x250
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bdc8566>] ?
handle_pte_fault+0x316/0xd10
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8be731a3>] ?
aio_read_events+0x1f3/0x2e0
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8bed5437>] ?
security_file_permission+0x27/0xa0
Oct 1 11:50:28 worker1004 kernel: [<ffffffffc1274830>] ?
ceph_direct_read_write+0xcd0/0xcd0 [ceph]
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8be74783>]
do_io_submit+0x3c3/0x870
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8be74c40>]
SyS_io_submit+0x10/0x20
Oct 1 11:50:28 worker1004 kernel: [<ffffffff8c32579b>]
system_call_fastpath+0x22/0x27
Oct 1 11:52:28 worker1004 kernel: INFO: task fio:29007 blocked for more
than 120 seconds.
Oct 1 11:52:28 worker1004 kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 1 11:52:28 worker1004 kernel: fio D
ffff996d86e92f70 0 29007 28970 0x00000000
Oct 1 11:52:28 worker1004 kernel: Call Trace:
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c316ec0>] ? bit_wait+0x50/0x50
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c318f39>] schedule+0x29/0x70
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c3168a9>]
schedule_timeout+0x239/0x2c0
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bcfa982>] ?
ktime_get_ts64+0x52/0xf0
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c316ec0>] ? bit_wait+0x50/0x50
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c31844d>]
io_schedule_timeout+0xad/0x130
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c3184e8>]
io_schedule+0x18/0x20
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c316ed1>]
bit_wait_io+0x11/0x50
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c316a81>]
__wait_on_bit_lock+0x61/0xc0
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bd96684>]
__lock_page+0x74/0x90
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bcbefd0>] ?
wake_bit_function+0x40/0x40
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bd971a4>]
__find_lock_page+0x54/0x70
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bd97ed5>]
grab_cache_page_write_begin+0x55/0xc0
Oct 1 11:52:28 worker1004 kernel: [<ffffffffc12798e3>]
ceph_write_begin+0x43/0xe0 [ceph]
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bd96ac4>]
generic_file_buffered_write+0x124/0x2c0
Oct 1 11:52:28 worker1004 kernel: [<ffffffffc127526e>]
ceph_aio_write+0xa3e/0xcb0 [ceph]
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bdc81be>] ?
do_numa_page+0x1be/0x250
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bdc8566>] ?
handle_pte_fault+0x316/0xd10
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8be731a3>] ?
aio_read_events+0x1f3/0x2e0
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8bed5437>] ?
security_file_permission+0x27/0xa0
Oct 1 11:52:28 worker1004 kernel: [<ffffffffc1274830>] ?
ceph_direct_read_write+0xcd0/0xcd0 [ceph]
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8be74783>]
do_io_submit+0x3c3/0x870
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8be74c40>]
SyS_io_submit+0x10/0x20
Oct 1 11:52:28 worker1004 kernel: [<ffffffff8c32579b>]
system_call_fastpath+0x22/0x27
Oct 1 15:04:08 worker1004 kernel: libceph: reset on mds0
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 closed our session
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 reconnect start
Oct 1 15:04:08 worker1004 kernel: libceph: osd182 10.128.150.155:6976
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd548 10.128.150.171:6936
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd59 10.128.150.154:6918
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: ceph: mds0 reconnect denied
Oct 1 15:04:08 worker1004 kernel: ceph: dropping dirty+flushing Fw
state for ffff997ff05193b0 1099516450605
Oct 1 15:04:08 worker1004 kernel: ceph: dropping dirty+flushing Fw
state for ffff997ff0519930 1099516450607
Oct 1 15:04:08 worker1004 kernel: ceph: dropping dirty+flushing Fw
state for ffff997ff051a430 1099516450606
Oct 1 15:04:08 worker1004 kernel: ceph: dropping dirty+flushing Fw
state for ffff997ff0519eb0 1099516450608
Oct 1 15:04:08 worker1004 kernel: libceph: osd356 10.128.150.31:6844
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd120 10.128.150.154:6885
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: mds0 10.130.134.4:6800
socket closed (con state NEGOTIATING)
Oct 1 15:04:08 worker1004 kernel: libceph: osd151 10.128.150.155:6808
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd129 10.128.150.154:6845
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd363 10.128.150.31:6872
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd712 10.128.150.177:6908
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd592 10.128.150.174:6917
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd866 10.128.150.42:6976
socket error on write
Oct 1 15:04:08 worker1004 kernel: libceph: osd395 10.128.150.158:6868
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd159 10.128.150.155:6952
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd901 10.128.150.43:6936
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd658 10.128.150.176:6946
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd422 10.128.150.159:6859
socket closed (con state OPEN)
Oct 1 15:04:08 worker1004 kernel: libceph: osd718 10.128.150.177:6928
socket error on read
and similar.
These nodes have been rock solid stable with ceph-fuse 12.2.7. They
definitely have no known networking issues, and the ceph cluster was
healthy during this time. In the MDS logs there are no entries around
the problematic times either. And after all this, the mount is unusable:
[root@worker1004 ~]# ls -l /mnt/cephtest
ls: cannot access /mnt/cephtest: Permission denied
Andras
On 10/1/18 3:02 PM, Andras Pataki wrote:
> These hangs happen during random I/O fio benchmark loads. Something
> like 4 or 8 fio processes doing random reads/writes to distinct large
> files (to ensure there is no caching possible). This is all on CentOS
> 7.4 nodes. Same (and even tougher) tests run without any problems
> with ceph-fuse. We do have jobs that do heavy parallel I/O (MPI-IO,
> HDF5 via MPI-IO, etc.) - so running 8 parallel random I/O generating
> processes on nodes with 28 cores and plenty of RAM (256GB - 512GB)
> should not be excessive.
>
> I am going to test the latest CentOS kernel next (the one you are
> referencing). The RedHat/CentOS kernels are not "old kernel clients"
> - they contains various backports of hundreds of patches to all kinds
> of subsystems of Linux. What is unclear there is exactly what ceph
> client RedHat is backporting to their kernels. Any pointers there
> would be helpful.
>
> Andras
>
>
> On 10/1/18 2:26 PM, Marc Roos wrote:
>> How do you test this? I have had no issues under "normal load" with an
>> old kernel client and a stable os.
>>
>> CentOS Linux release 7.5.1804 (Core)
>> Linux c04 3.10.0-862.11.6.el7.x86_64 #1 SMP Tue Aug 14 21:49:04 UTC 2018
>> x86_64 x86_64 x86_64 GNU/Linux
>>
>>
>>
>>
>>
>> -----Original Message-----
>> From: Andras Pataki [mailto:apataki@xxxxxxxxxxxxxxxxxxxxx]
>> Sent: maandag 1 oktober 2018 20:10
>> To: ceph-users
>> Subject: cephfs kernel client stability
>>
>> We have so far been using ceph-fuse for mounting cephfs, but the small
>> file performance of ceph-fuse is often problematic. We've been testing
>> the kernel client, and have seen some pretty bad crashes/hangs.
>>
>> What is the policy on fixes to the kernel client? Is only the latest
>> stable kernel updated (4.18.x nowadays), or are fixes backported to LTS
>> kernels also (like 4.14.x or 4.9.x for example)? I've seen various
>> threads that certain newer features require pretty new kernels - but I'm
>> wondering whether newer kernels are also required for better stability -
>> or - in general, where the kernel client stability stands nowadays.
>>
>> Here is an example of kernel hang with 4.14.67. On heavy loads the
>> machine isn't even pingable.
>>
>> Sep 29 21:10:16 worker1004 kernel: INFO: rcu_sched self-detected stall
>> on CPU Sep 29 21:10:16 worker1004 kernel: #0111-...: (1 GPs behind)
>> idle=bee/140000000000001/0 softirq=21319/21319 fqs=7499 Sep 29 21:10:16
>> worker1004 kernel: #011 (t=15000 jiffies g=13989 c=13988
>> q=8334)
>> Sep 29 21:10:16 worker1004 kernel: NMI backtrace for cpu 1 Sep 29
>> 21:10:16 worker1004 kernel: CPU: 1 PID: 19436 Comm: kworker/1:42
>> Tainted: P W O 4.14.67 #1
>> Sep 29 21:10:16 worker1004 kernel: Hardware name: Dell Inc. PowerEdge
>> C6320/082F9M, BIOS 2.6.0 10/27/2017 Sep 29 21:10:16 worker1004 kernel:
>> Workqueue: ceph-msgr ceph_con_workfn [libceph] Sep 29 21:10:16
>> worker1004 kernel: Call Trace:
>> Sep 29 21:10:16 worker1004 kernel: <IRQ> Sep 29 21:10:16 worker1004
>> kernel: dump_stack+0x46/0x5f Sep 29 21:10:16 worker1004 kernel:
>> nmi_cpu_backtrace+0xba/0xc0 Sep 29 21:10:16 worker1004 kernel: ?
>> irq_force_complete_move+0xd0/0xd0 Sep 29 21:10:16 worker1004 kernel:
>> nmi_trigger_cpumask_backtrace+0x8a/0xc0
>> Sep 29 21:10:16 worker1004 kernel: rcu_dump_cpu_stacks+0x81/0xb1 Sep 29
>> 21:10:16 worker1004 kernel: rcu_check_callbacks+0x642/0x790 Sep 29
>> 21:10:16 worker1004 kernel: ? update_wall_time+0x26d/0x6e0 Sep 29
>> 21:10:16 worker1004 kernel: update_process_times+0x23/0x50 Sep 29
>> 21:10:16 worker1004 kernel: tick_sched_timer+0x2f/0x60 Sep 29 21:10:16
>> worker1004 kernel: __hrtimer_run_queues+0xa3/0xf0 Sep 29 21:10:16
>> worker1004 kernel: hrtimer_interrupt+0x94/0x170 Sep 29 21:10:16
>> worker1004 kernel: smp_apic_timer_interrupt+0x4c/0x90
>> Sep 29 21:10:16 worker1004 kernel: apic_timer_interrupt+0x84/0x90 Sep 29
>> 21:10:16 worker1004 kernel: </IRQ> Sep 29 21:10:16 worker1004 kernel:
>> RIP: 0010:crush_hash32_3+0x1e5/0x270 [libceph] Sep 29 21:10:16
>> worker1004 kernel: RSP: 0018:ffffc9000fdff5d8 EFLAGS:
>> 00000a97 ORIG_RAX: ffffffffffffff10
>> Sep 29 21:10:16 worker1004 kernel: RAX: 0000000006962033 RBX:
>> ffff883f6e7173c0 RCX: 00000000dcdcc373
>> Sep 29 21:10:16 worker1004 kernel: RDX: 00000000bd5425ca RSI:
>> 000000008a8b0b56 RDI: 00000000b1983b87
>> Sep 29 21:10:16 worker1004 kernel: RBP: 0000000000000023 R08:
>> 00000000bd5425ca R09: 00000000137904e9
>> Sep 29 21:10:16 worker1004 kernel: R10: 0000000000000000 R11:
>> 0000000000000002 R12: 00000000b0f29f21
>> Sep 29 21:10:16 worker1004 kernel: R13: 000000000000000c R14:
>> 00000000f0ae0000 R15: 0000000000000023
>> Sep 29 21:10:16 worker1004 kernel: crush_bucket_choose+0x2ad/0x340
>> [libceph] Sep 29 21:10:16 worker1004 kernel:
>> crush_choose_firstn+0x1b0/0x4c0 [libceph] Sep 29 21:10:16 worker1004
>> kernel: crush_choose_firstn+0x48d/0x4c0 [libceph] Sep 29 21:10:16
>> worker1004 kernel: crush_do_rule+0x28c/0x5a0 [libceph] Sep 29 21:10:16
>> worker1004 kernel: ceph_pg_to_up_acting_osds+0x459/0x850
>> [libceph]
>> Sep 29 21:10:16 worker1004 kernel: calc_target+0x213/0x520 [libceph] Sep
>> 29 21:10:16 worker1004 kernel: ? ixgbe_xmit_frame_ring+0x362/0xe80
>> [ixgbe] Sep 29 21:10:16 worker1004 kernel: ? put_prev_entity+0x27/0x620
>> Sep 29 21:10:16 worker1004 kernel: ? pick_next_task_fair+0x1c7/0x520 Sep
>> 29 21:10:16 worker1004 kernel:
>> scan_requests.constprop.55+0x16f/0x280 [libceph] Sep 29 21:10:16
>> worker1004 kernel: handle_one_map+0x175/0x200 [libceph] Sep 29 21:10:16
>> worker1004 kernel: ceph_osdc_handle_map+0x390/0x850 [libceph] Sep 29
>> 21:10:16 worker1004 kernel: ? ceph_x_encrypt+0x46/0x70 [libceph] Sep 29
>> 21:10:16 worker1004 kernel: dispatch+0x2ef/0xba0 [libceph] Sep 29
>> 21:10:16 worker1004 kernel: ? read_partial_message+0x215/0x880 [libceph]
>> Sep 29 21:10:16 worker1004 kernel: ? inet_recvmsg+0x45/0xb0 Sep 29
>> 21:10:16 worker1004 kernel: try_read+0x6f8/0x11b0 [libceph] Sep 29
>> 21:10:16 worker1004 kernel: ? sched_clock_cpu+0xc/0xa0 Sep 29 21:10:16
>> worker1004 kernel: ? put_prev_entity+0x27/0x620 Sep 29 21:10:16
>> worker1004 kernel: ? pick_next_task_fair+0x415/0x520 Sep 29 21:10:16
>> worker1004 kernel: ceph_con_workfn+0x9d/0x5a0 [libceph] Sep 29 21:10:16
>> worker1004 kernel: process_one_work+0x127/0x290 Sep 29 21:10:16
>> worker1004 kernel: worker_thread+0x3f/0x3b0 Sep 29 21:10:16 worker1004
>> kernel: kthread+0xf2/0x130 Sep 29 21:10:16 worker1004 kernel: ?
>> process_one_work+0x290/0x290 Sep 29 21:10:16 worker1004 kernel: ?
>> __kthread_parkme+0x90/0x90 Sep 29 21:10:16 worker1004 kernel:
>> ret_from_fork+0x1f/0x30
>>
>> Andras
>>
>> _______________________________________________
>> ceph-users mailing list
>> ceph-users@xxxxxxxxxxxxxx
>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>>
>>
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
