Details
-
Bug
-
Resolution: Fixed
-
Blocker
-
Lustre 2.4.0
-
3
-
6013
Description
We've had reports of IO writes hanging in Sequoia, and after some initial debugging, have narrowed the hung threads to getting stuck with the following stack trace:
sysiod S 00000fffa842633c 0 27910 3135 0x00000000 Call Trace: [c0000003ee34e480] [c0000003ee34e590] 0xc0000003ee34e590 (unreliable) [c0000003ee34e650] [c000000000009b8c] .__switch_to+0xc4/0x100 [c0000003ee34e6e0] [c0000000004364c8] .schedule+0x858/0x9c0 [c0000003ee34e990] [8000000000a720c0] .cfs_waitq_wait+0x10/0x30 [libcfs] [c0000003ee34ea00] [8000000004533560] .osc_enter_cache+0x880/0x12c0 [osc] [c0000003ee34ebd0] [800000000453b210] .osc_queue_async_io+0xd10/0x1a40 [osc] [c0000003ee34edf0] [8000000004516fe8] .osc_page_cache_add+0xf8/0x2a0 [osc] [c0000003ee34eeb0] [80000000024468b8] .cl_page_cache_add+0xe8/0x3b0 [obdclass] [c0000003ee34efe0] [8000000004facae8] .lov_page_cache_add+0xc8/0x340 [lov] [c0000003ee34f0b0] [80000000024468b8] .cl_page_cache_add+0xe8/0x3b0 [obdclass] [c0000003ee34f1e0] [80000000067ecda4] .vvp_io_commit_write+0x474/0x8a0 [lustre] [c0000003ee34f300] [800000000246098c] .cl_io_commit_write+0x11c/0x2d0 [obdclass] [c0000003ee34f3c0] [80000000067af410] .ll_commit_write+0x120/0x3e0 [lustre] [c0000003ee34f490] [80000000067d1634] .ll_write_end+0x34/0x80 [lustre] [c0000003ee34f520] [c000000000098bac] .generic_file_buffered_write+0x1ec/0x374 [c0000003ee34f660] [c000000000099290] .__generic_file_aio_write+0x374/0x3d8 [c0000003ee34f760] [c00000000009936c] .generic_file_aio_write+0x78/0xe8 [c0000003ee34f810] [80000000067eff9c] .vvp_io_write_start+0xfc/0x3e0 [lustre] [c0000003ee34f8e0] [800000000245aedc] .cl_io_start+0xcc/0x220 [obdclass] [c0000003ee34f980] [8000000002462cf4] .cl_io_loop+0x194/0x2c0 [obdclass] [c0000003ee34fa30] [800000000676a278] .ll_file_io_generic+0x498/0x670 [lustre] [c0000003ee34fb30] [800000000676a8d4] .ll_file_aio_write+0x1d4/0x3a0 [lustre] [c0000003ee34fc00] [800000000676abf0] .ll_file_write+0x150/0x320 [lustre] [c0000003ee34fce0] [c0000000000d5968] .vfs_write+0xd0/0x1c4 [c0000003ee34fd80] [c0000000000d5b58] .SyS_write+0x54/0x98 [c0000003ee34fe30] [c000000000000580] syscall_exit+0x0/0x2c
The specific line it's stuck at is here:
(gdb) l *osc_enter_cache+0x880
0x47f50 is in osc_enter_cache (/builddir/build/BUILD/lustre-2.3.56/lustre/osc/osc_cache.c:1526).
1521 /builddir/build/BUILD/lustre-2.3.56/lustre/osc/osc_cache.c: No such file or directory.
in /builddir/build/BUILD/lustre-2.3.56/lustre/osc/osc_cache.c
1523 CDEBUG(D_CACHE, "%s: sleeping for cache space @ %p for %p\n", 1524 cli->cl_import->imp_obd->obd_name, &ocw, oap); 1525 1526 rc = l_wait_event(ocw.ocw_waitq, 1527 cfs_list_empty(&ocw.ocw_entry), &lwi); 1528 1529 client_obd_list_lock(&cli->cl_loi_list_lock); 1530 cfs_list_del_init(&ocw.ocw_entry);
There were specific OSCs on a couple of the problem clients showing outstanding dirty pages for a significant amount of time:
seqlac2@root:pdsh -w vulcanio[42-43] 'grep -v 0 /proc/fs/lustre/osc/*/cur_dirty_bytes' | dshbak -c ---------------- vulcanio42 ---------------- /proc/fs/lustre/osc/ls1-OST0026-osc-c0000003c1100000/cur_dirty_bytes:65536 /proc/fs/lustre/osc/ls1-OST0027-osc-c0000003c1100000/cur_dirty_bytes:65536 /proc/fs/lustre/osc/ls1-OST0028-osc-c0000003c1100000/cur_dirty_bytes:65536 /proc/fs/lustre/osc/ls1-OST002b-osc-c0000003c1100000/cur_dirty_bytes:65536 ---------------- vulcanio43 ---------------- /proc/fs/lustre/osc/ls1-OST0053-osc-c0000003e336b000/cur_dirty_bytes:65536
Manually dropping caches on the problem clients seems to have cleared things up:
# echo 3 > /proc/sys/vm/drop_caches
In case it is useful, attached is a dump of the lustre pages taken prior to dropping caches on one of the problem clients:
# cat /proc/fs/lustre/llite/ls1-c0000003e336b000/dump_page_cache > vulcanio43-dump_page_cache-`date +%s`
I also ran the same command after dropping caches, but the file was empty, so there's no reason to post it.
