|
MDS2 traces have a very characteristic signature of "waiting for obd_unlinked_exports more than XX" - there a bunch of bug about this, they hit from tiem to time on unmount.
|
|
It looks like there is some kind of problem in cleaning up the OSP device, and this has been causing a significant number of failures recently (about 10% for both review-zfs and review-dne-part-1).
It may be that this is a new type of failure caused by a recently landed patch, or it could be the same failure that Oleg describes that has been made worse by some other patch.
|
|
Emoly
Could you please look into this one?
Thanks
Peter
|
|
Emoly,
could you please look into the recent sanity test_132 failures to see when the above failures started in osp_device_free(). I think this particular failure mode started fairly recently, and is different from older failures reported in LU-4062/LU-3665. If we can track down when the more recent failures started we could see if they relate to a particular patch landing.
|
|
I can hit this "hang" issue on zfs in my local test, but not every time. I will investigate it.
|
|
Yesterday I happened to hit this problem, and its call trace is same to the one shown in LU-4062. But unfortunately, I can't reproduce it today.
I am checking the recent maloo test reports to see when the failure started.
|
|
I checked and vetted recent two months sanity.sh test_132 failure logs and the logs show that there are three kinds of timeout failure.
1) LU-4062/LU-3665, as Oleg said, its signature is "XXX is waiting for obd_unlinked_exports more than xxx seconds". It really does happen from time to time, even in yesterday's test on the latest master branch https://testing.hpdd.intel.com/test_logs/1a2b5a56-00e2-11e4-b331-5254006e85c2/show_text .
This issue will be probably fixed by the patch http://review.whamcloud.com/#/c/9350 .
2) LU-5242, as Andreas said, its signature is “(osp_dev.c:858:osp_device_free()) } header@” and
Seems this problem has gone since June-15.
3) LU-5277, I just file this in a new ticket. Its signature is
Seems this problem also has gone since June-17.
The frequency of these issues is 1) > 3) > 2). BTW, unfortunately, many tests have no test logs, so I can't tell which situation they belong to.
|
|
Emoly, thank you for your detailed investigation. When you write that the problem #2 and #3 "have gone since June NN" do you mean they have "gone away" == no longer happening, or "have gone on" == started on?
Could you check if patches were landed on those days (or a day before) that might have caused these failures? Even better is to find if the very first failures were happening on a patch before it was landed to master. You can check https://old-testing.hpdd.intel.com/ for the old failure logs.
|
|
Andreas, sorry for my unclear expression, I mean problem #2 and #3 have gone away since the middle of June.
I will check those old failure logs and see if the failure is related to some patches landed on those days, and then give an update.
|
|
Since problem #3 LU-5277 only happened in a daos-regression group, I re-filed it to FF-273. So we can only force on problem #2.
|
|
I checked the test logs one by one and only found two instances with problem #2 (I mean the console logs show “(osp_dev.c:858:osp_device_free()) } header@” obviously).
They are https://testing.hpdd.intel.com/test_sets/f19d7516-f433-11e3-9db1-5254006e85c2 and https://testing.hpdd.intel.com/test_sets/1a7d3012-f4c9-11e3-b233-5254006e85c2 , which are from the same build https://build.hpdd.intel.com/job/lustre-reviews/24535 triggered by wangdi.
If I am right, problem #1 is the only problem.
|
|
Hmm, problem #2 (LBUG during umount mdt ) only happened 2 times and it seems it had not happen since June 15th, so it was probably already being fixed.
I checked the all of test_132 timeout status, it seems most of them happened in ZFS and umount -f ost, maybe some one familiar with OST stack should have a look, Thanks.
|
|
Di, the reason that this failure was not hit since June 15 is because that is the last time your patch http://review.whamcloud.com/10673 for LU-5163 was tested. This problem has only been hit when testing that patch.
|
|
Ah, ok. I will fix the patch 10673 in LU-5163. Alex, Could you please comment on this one, not so familiar with ZFS.
|
|
I checked on log - https://testing.hpdd.intel.com/test_logs/846317de-f434-11e3-9db1-5254006e85c2/show_text:
2:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) header@ffff88006a3c3980[0x0, 1, [0x1:0x0:0x0] hash exist]
{
12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) ....local_storage@ffff88006a3c39d0
12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) ....osd-ldiskfs@ffff880061e9dc80osd-ldiskfs-object@ffff880061e9dc80(i:ffff8800578a97e8:144/3738986019)[plain]
12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) }
header@ffff88006a3c3980
doesn't seem to be specific to ZFS backend?
|
2:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) header@ffff88006a3c3980[0x0, 1, [0x1:0x0:0x0] hash exist]
12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) ....local_storage@ffff88006a3c39d0 12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free()) ....osd-ldiskfs@ffff880061e9dc80osd-ldiskfs-object@ffff880061e9dc80(i:ffff8800578a97e8:144/3738986019)[plain] 12:34:53:LustreError: 7776:0:(osp_dev.c:858:osp_device_free())
Oh, this is caused by my patch http://review.whamcloud.com/#/c/10673/ , which is not being landed yet, I will update the patch anyway.
But this ticket is about umount on ZFS, https://testing.hpdd.intel.com/sub_tests/query?utf8=✓&test_set%5Btest_set_script_id%5D=f9516376-32bc-11e0-aaee-52540025f9ae&sub_test%5Bsub_test_script_id%5D=12fcb374-32be-11e0-b685-52540025f9ae&sub_test%5Bstatus%5D=TIMEOUT&sub_test%5Bquery_bugs%5D=&test_session%5Btest_host%5D=&test_session%5Btest_group%5D=&test_session%5Buser_id%5D=&test_session%5Bquery_date%5D=&test_session%5Bquery_recent_period%5D=&test_node%5Bos_type_id%5D=&test_node%5Bdistribution_type_id%5D=&test_node%5Barchitecture_type_id%5D=&test_node%5Bfile_system_type_id%5D=&test_node%5Blustre_branch_id%5D=&test_node_network%5Bnetwork_type_id%5D=&commit=Update+results
please check.
|
|
this is "known" issue with no resolution yet 
ll_ost00_004 D 0000000000000001 0 26767 2 0x00000080
ffff88007946f970 0000000000000046 000000016fef8aa0 0000000000000001
ffff88006dcc01f0 0000000000000082 ffff88007946f950 ffff88007607bd80
ffff88006fef9058 ffff88007946ffd8 000000000000fbc8 ffff88006fef9058
Call Trace:
[<ffffffff8109b14e>] ? prepare_to_wait_exclusive+0x4e/0x80
[<ffffffffa014347d>] cv_wait_common+0xed/0x100 [spl]
[<ffffffff8109af00>] ? autoremove_wake_function+0x0/0x40
[<ffffffffa01434e5>] __cv_wait+0x15/0x20 [spl]
[<ffffffffa0242f7b>] txg_wait_open+0x7b/0xa0 [zfs]
[<ffffffffa020a95e>] dmu_tx_wait+0x29e/0x2b0 [zfs]
[<ffffffff8152965e>] ? mutex_lock+0x1e/0x50
[<ffffffffa020aa01>] dmu_tx_assign+0x91/0x490 [zfs]
[<ffffffffa0e9656c>] osd_trans_start+0x9c/0x410 [osd_zfs]
[<ffffffffa0f9e79c>] ofd_trans_start+0x7c/0x100 [ofd]
[<ffffffffa0f9f4c3>] ofd_object_destroy+0x203/0x680 [ofd]
[<ffffffffa0f9afed>] ofd_destroy_by_fid+0x35d/0x620 [ofd]
[<ffffffffa0973e80>] ? ldlm_blocking_ast+0x0/0x180 [ptlrpc]
[<ffffffffa09754e0>] ? ldlm_completion_ast+0x0/0x930 [ptlrpc]
[<ffffffffa0f948d2>] ofd_destroy_hdl+0x2e2/0xb80 [ofd]
[<ffffffffa0a01a7c>] tgt_request_handle+0x23c/0xac0 [ptlrpc]
[<ffffffffa09b129a>] ptlrpc_main+0xd1a/0x1980 [ptlrpc]
[<ffffffffa09b0580>] ? ptlrpc_main+0x0/0x1980 [ptlrpc]
ffff88006fe55ba0 0000000000000046 00000000ffffffff 000015e4f4d9c106
ffff88006fe55b10 ffff88007034b910 000000000045358e ffffffffac457b12
ffff8800797a2638 ffff88006fe55fd8 000000000000fbc8 ffff8800797a2638
Call Trace:
[<ffffffff810a6d01>] ? ktime_get_ts+0xb1/0xf0
[<ffffffff815287f3>] io_schedule+0x73/0xc0
[<ffffffffa014341c>] cv_wait_common+0x8c/0x100 [spl]
[<ffffffff8109af00>] ? autoremove_wake_function+0x0/0x40
[<ffffffffa01434a8>] __cv_wait_io+0x18/0x20 [spl]
[<ffffffffa02890ab>] zio_wait+0xfb/0x1b0 [zfs]
[<ffffffffa021ebe3>] dsl_pool_sync+0x2b3/0x3f0 [zfs]
[<ffffffffa0236e4b>] spa_sync+0x40b/0xa60 [zfs]
[<ffffffffa0243916>] txg_sync_thread+0x2e6/0x510 [zfs]
[<ffffffff810591a9>] ? set_user_nice+0xc9/0x130
[<ffffffffa0243630>] ? txg_sync_thread+0x0/0x510 [zfs]
there are many duplicates, actually.. for exaple, LU-4716
we discussed this few times with Brian B., but the root cause is still unclear..
|
|
[Andreas Dilger] Deleted this comment because this problem is actually LU-3665 and didn't want this incorrectly appearing in search results.
|
|
Fortunately, these two failures only happened once since July, so maybe it should be remark it as major?
|
|
More instance on master branch:
https://testing.hpdd.intel.com/test_sets/33f21012-098c-11e4-a512-5254006e85c2
|
|
It does happen more frequently on ZFS eg:
https://testing.hpdd.intel.com/test_sets/b575d130-0dc1-11e4-b3f5-5254006e85c2
but it does also happen on DNE:
https://testing.hpdd.intel.com/test_sets/f019ab4a-0ae2-11e4-8ed2-5254006e85c2
Failure rate for review-zfs is 22% over the last week
|
|
Hmm, the failure on DNE is mostly about amount MGS
Probably deserve a new ticket, but it only happened once in July, so probably not serious enough to be a critical ticket here?
|
|
Hmm, this umount mgs failure only happens for http://review.whamcloud.com/#/c/10249/, so I am not sure this is related with that patch or not. I will create a new ticket if I saw more failures.
|
|
Bobijam
Could you please look into this issue?
Thanks
Peter
|
|
failure with signature of "waiting for obd_unlinked_exports more than XX" is dup of LU-3665, and its fix patch is tracked at http://review.whamcloud.com/#/c/9350.
|
|
I agree the symptom is the same, but fixing obdfilter-survey (LU-3665) doesn't seem like it will fix the failure in sanity/132. LU-3665 is caused by an extra objects created and not cleaned up via "lctl create"
|
|
from the 1st report http://maloo.whamcloud.com/test_sets/e5783778-f887-11e3-b13a-52540035b04c.
There are MGS_CONNECT and MDS_CONNECT RPCs being issued again and again (not resend), it seems that the reconnect engine does not honor that the obd device (mgc obd and lwp obd) has been cleaned and keeps trying to reconnect the device.
|
|
I think the root issue comes from this message:
Which basically means the obd has some extra references and it's those references that don't let it go away and so it tries to reconnect still?
This sort of a message is what is seen in all of bugs of this class.
|
|
One more instance on master branch: https://testing.hpdd.intel.com/test_sets/a0ca0910-23fe-11e4-84ee-5254006e85c2
|
|
Is it possible the result of the un-dying connect requests being kept re-generating and they hold the obd refcount?
|
Hmm, this umount mgs failure only happens for http://review.whamcloud.com/#/c/10249/, so I am not sure this is related with that patch or not. I will create a new ticket if I saw more failures.
While testing patch http://review.whamcloud.com/11539 on Lustre b2_5 branch, sanity-lfsck test 0 hit the unmounting mgs failure. I created a new ticket LU-5539.
|
|
While testing patch http://review.whamcloud.com/11574 on Lustre b2_5 branch with FSTYPE=zfs, sanity test 132 hit the same failure in this ticket.
Maloo report: https://testing.hpdd.intel.com/test_sets/271e44e8-2d5c-11e4-b550-5254006e85c2
|
|
I checked the Maloo report above and found a deadlock on the OSS very similar to the latest ones in LU-4950:
- ZFS had completed writing new blocks in the syncing txg, and updated the new uberblocks, but got stuck some where in the middle of doing a WRITE_FLUSH_FUA, to make sure the uberblocks do hit persistent storage I guess.
- So txg_sync couldn't complete, the syncing thread got stuck there.
- As the transaction groups couldn't move forward, the ll_ost00_008 thread also got stuck in txg_wait_open().
I haven't figured out why ZFS stuck at doing WRITE_FLUSH_FUA, but there's two things to move forward at this point:
1. Set zfs_nocacheflush:
options zfs zfs_nocacheflush=1
This makes DKIOCFLUSHWRITECACHE a noop. Then the deadlock may move elsewhere or simply disappear.
2. Whether zfs_nocacheflush is set or not, once the timeout happens, it'd be useful to gather "zpool events -v" outputs on the OSS, which'd give more details on the state of the stuck zio.
|
|
Isaac, can you explain what signs point to WRITE_FLUSH_FUA, please ?
|
|
Alex, in the OSS stack dump:
z_ioctl_iss/0 S 0000000000000001 0 10013 2 0x00000080
Call Trace:
[<ffffffffa024aa46>] ? vdev_disk_io_start+0x156/0x1b0 [zfs]
The z_ioctl_iss thread handles ZIO_TYPE_IOCTL and the only command is DKIOCFLUSHWRITECACHE, which is handled by vdev_disk_io_flush(). I suspected that vdev_disk_io_flush() was blocking in: bio = bio_alloc(GFP_NOIO, 0) - which blocks until there's memory to return. Also, txg_sync thread was waiting spa_sync()->zio_wait(probably the IOCTL zio); and ll_ost00_008 thread was blocking in txg_wait_open(). That's why I suspected the DKIOCFLUSHWRITECACHE ioctl was blocking and preventing the txgs from moving forward - WRITE_FLUSH_FUA bio was probably not submitted yet.
|
|
Isaac, have a look here - https://testing.hpdd.intel.com/test_logs/c2a5b9e6-2d5c-11e4-b550-5254006e85c2/show_text
I didn't notice anything except these:
Sep 12 19:57:07 shadow-11vm3 kernel: ll_ost00_001 D 0000000000000000 0 9264 2 0x00000080
Sep 12 19:57:07 shadow-11vm3 kernel: ffff88007c5c7960 0000000000000046 000000007223d500 0000000000000001
Sep 12 19:57:07 shadow-11vm3 kernel: ffff88006e41a1f0 0000000000000082 ffff88006fd1cae8 ffff8800736e5d80
Sep 12 19:57:07 shadow-11vm3 kernel: ffff88007223dab8 ffff88007c5c7fd8 000000000000fbc8 ffff88007223dab8
Sep 12 19:57:07 shadow-11vm3 kernel: Call Trace:
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8109b1ee>] ? prepare_to_wait_exclusive+0x4e/0x80
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa014347d>] cv_wait_common+0xed/0x100 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8109afa0>] ? autoremove_wake_function+0x0/0x40
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa01434e5>] __cv_wait+0x15/0x20 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0242f7b>] txg_wait_open+0x7b/0xa0 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa020a95e>] dmu_tx_wait+0x29e/0x2b0 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8152ad0e>] ? mutex_lock+0x1e/0x50
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa020aa01>] dmu_tx_assign+0x91/0x490 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0e8154d>] osd_trans_start+0xed/0x430 [osd_zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0f81fac>] ofd_trans_start+0x7c/0x100 [ofd]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0f835c0>] ofd_object_destroy+0x3b0/0x850 [ofd]
Sep 12 19:57:07 shadow-11vm3 kernel: txg_quiesce S 0000000000000000 0 307 2 0x00000080
Sep 12 19:57:07 shadow-11vm3 kernel: ffff8800736e5d70 0000000000000046 000007989b5d2dfd 0000000000000000
Sep 12 19:57:07 shadow-11vm3 kernel: 0000000000000000 0000000000000001 ffff8800736e5d50 0000000000000086
Sep 12 19:57:07 shadow-11vm3 kernel: ffff88006fd1d058 ffff8800736e5fd8 000000000000fbc8 ffff88006fd1d058
Sep 12 19:57:07 shadow-11vm3 kernel: Call Trace:
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8109b1ee>] ? prepare_to_wait_exclusive+0x4e/0x80
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa014347d>] cv_wait_common+0xed/0x100 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8109afa0>] ? autoremove_wake_function+0x0/0x40
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff81058bd3>] ? __wake_up+0x53/0x70
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa01434c5>] __cv_wait_interruptible+0x15/0x20 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa02432fd>] txg_thread_wait+0x1d/0x40 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0243629>] txg_quiesce_thread+0x299/0x2a0 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: txg_sync D 0000000000000001 0 308 2 0x00000080
Sep 12 19:57:07 shadow-11vm3 kernel: ffff8800736e7ba0 0000000000000046 00000000ffffffff 000019aa6a2a17f0
Sep 12 19:57:07 shadow-11vm3 kernel: ffff8800736e7b10 ffff8800717ffc20 000000000038aee4 ffffffffabecd08f
Sep 12 19:57:07 shadow-11vm3 kernel: ffff88006fd1c5f8 ffff8800736e7fd8 000000000000fbc8 ffff88006fd1c5f8
Sep 12 19:57:07 shadow-11vm3 kernel: Call Trace:
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff810a6d31>] ? ktime_get_ts+0xb1/0xf0
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff81529ea3>] io_schedule+0x73/0xc0
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa014341c>] cv_wait_common+0x8c/0x100 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffff8109afa0>] ? autoremove_wake_function+0x0/0x40
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa01434a8>] __cv_wait_io+0x18/0x20 [spl]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa02890ab>] zio_wait+0xfb/0x1b0 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa021ebe3>] dsl_pool_sync+0x2b3/0x3f0 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0236e4b>] spa_sync+0x40b/0xa60 [zfs]
Sep 12 19:57:07 shadow-11vm3 kernel: [<ffffffffa0243916>] txg_sync_thread+0x2e6/0x510 [zfs]
|
|
My previous analysis might be inaccurate as I neglected the '?' in the stack entry:
Which meant that the vdev_disk_io_start() function likely returned and the WRITE_FLUSH_FUA bio was already submitted - the z_ioctl_iss thread was waiting for more work to do. I checked the OSS stack dumps, and the z_* threads were all idle, so there was no more IO left to do. These led me to believe that:
1. IO for syncing the txg were all done, and WRITE_FLUSH_FUA was submitted as an IO barrier, i.e. to make sure all previous writes do hit persistent storage.
2. But the WRITE_FLUSH_FUA somehow didn't complete, causing txg_sync to wait and hang.
Suggestions to troubleshoot stay the same: on the OSS, set zfs_nocacheflush, and gather "zpool events -v" outputs.
|
|
why do you think vdev_disk_io_start() was already used in this txg? that could be a leftover from the previous txg?
|
|
Alex, it was only a guess. If we had "zpool events -v" outputs, that'd provide a lot more information on the stuck zio.
Also I had a hunch that the stuck zio had something to do with the way the zpool was configured. There seemed to be too many levels of indirection - the use of /dev/lvm-Role_OSS/ indicated LVM which seemed not necessary as zfs could manage its own volumes.
|
|
Seems this is the major cause of review-zfs test failures.
|
|
Isaac
This issue continues to disrupt zfs testing. What do you advise?
Thanks
Peter
|
|
Peter,
The auto-test results unfortunately didn't include sufficient ZFS debug information, see TEI-1729. I'm working with Jian to manually start a test session and reproduce the failure so I'd be able to collect the debug information needed.
|
|
It seemed like LVM+deadline scheduler could be the cause of IO timeouts, see LU-4950 for latest results.
|
|
While verifying http://review.whamcloud.com/12001 on Lustre b2_5 branch with FSTYPE=zfs, sanity test 900 hung at unmounting MDS.
Console log on MDS:
Maloo report: https://testing.hpdd.intel.com/test_sets/6f56a29c-4a07-11e4-95b1-5254006e85c2
|
|
The failure above was different from the zio timeout here in this ticket. The OSS zpools were idle, and on the MDS the zpool seemed to have been exported already (because the txg_sync thread already quit). It might have something to do with the patch being tested, but I want to focus on the zio timeout issue here.
|
|
Hi Isaac,
According to problem 2) in the earlier comments https://jira.hpdd.intel.com/browse/LU-5242?focusedCommentId=87897&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-87897 in this ticket, I reported the above failure here.
I also saw the failure was reported in LU-3623. So, let me track the failure over there then.
|
|
One more instance on master branch:
https://testing.hpdd.intel.com/test_sets/b2697762-4e12-11e4-9581-5254006e85c2
|
|
Same failure has occurred on master branch for test_23a: https://testing.hpdd.intel.com/test_sets/90cd3a7e-53d7-11e4-9c8a-5254006e85c2
|
|
Looks like another instance, on master: https://testing.hpdd.intel.com/test_sets/a40e6a14-5a2f-11e4-8dbb-5254006e85c2
|
|
One more instance on master branch: https://testing.hpdd.intel.com/test_sets/b8f4813c-5c25-11e4-b9ce-5254006e85c2
|
|
I was able to reproduce it today and kept the system live for debugging. The txg_sync thread stuck in zio_wait() but the weird thing was there was no IO pending/running at either the ZFS vdev queue or the Linux block dev queue. At this point I tend to think it's a ZFS issue rather than Lustre issue.
|
|
One more instance on Lustre b2_5 branch:
https://testing.hpdd.intel.com/test_sets/91627324-5fa7-11e4-895a-5254006e85c2
|
|
Likely it can be fixed by this ZFS patch:
https://github.com/zfsonlinux/zfs/pull/2828
I'll test it soon.
|
|
One more failure on master: https://testing.hpdd.intel.com/sub_tests/bee79924-6861-11e4-a1b6-5254006e85c2
|
|
Isaac, any update on testing this patch? While we prefer to stick with the upstream releases, we are also able to land a patch into our own ZFS Git repo so that our own testing passes. If this fixes the problem we are seeing, it is also worthwhile to update the issue on GitHub with this information so that it will speed up the patch landing into a release.
|
|
I'm still troubleshooting some local ZFS test failures after merging the patch. I'll apply it to Jenkins ZFS build once all tests pass.
|
|
More instance on Lustre b2_5 branch:
https://testing.hpdd.intel.com/test_sets/e3f3287e-7b0c-11e4-8c6d-5254006e85c2
|
|
I've been testing with a patched ZFS build and so far haven't been able to reproduce it. But strange thing is, I can't reproduce it either with a previous build where I could easily reproduce it with sanity test_132. So now I'm not sure whether the patch fixed it, or some other change made it much harder to reproduce. I'm now looking into why I can't reproduce it any more with the same build/test hw where I was able to easily reproduce it.
|
|
Is it possible to push the upstream GitHub patch into our local ZFS git repository, so that we are always testing with that patch? That would allow us to get better testing, to see if it fixes this problem, and to see if it introduces some other problems or not. This is one of the last issues that is preventing review-zfs to be enforced for all patches.
|
|
here is an example how to add a patch: http://git.whamcloud.com/ff/daos_lustre.git/commit/21f403380e365b083cf4e48003e863a1661a5a60
|
|
Nathaniel Clark (nathaniel.l.clark@intel.com) uploaded a new patch: http://review.whamcloud.com/13050
Subject: LU-5242 build: Add zfs patch for Illumos 5244
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: e5b4e4305c9cdf7375ad5542a7118f3deb4cf7e4
|
|
Andreas Dilger (andreas.dilger@intel.com) uploaded a new patch: http://review.whamcloud.com/13093
Subject: LU-5242 tests: except sanity test_132 for ZFS
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 5c867565cdc8d4b1da41ef17e9bc821b63809151
|
|
Based on the test results in https://testing.hpdd.intel.com/test_sessions/f8d48678-84d7-11e4-985f-5254006e85c2 it appears that the 13050 patch does not resolve the problem being seen here. Is there anything new that can be learned from the logs in these failed tests?
This problem and LU-4536 are really blocking the ability to enable review-zfs in enforcing mode. It is passing a large fraction of tests, but these ones are causing the most failures. Normally I'd say this test should be disabled, but I guess the hang would happen again at some later unmount, though I don't see that? Is there something special that this test does with the backing storage that is causing ZFS grief, or is it possible there is a bug in the SOM codepath that is causing a reference leak and hanging the unmount?
For now, I've pushed a patch to disable this test, because SOM is not a supported feature, and it will continue to be tested with ldiskfs anyway.
|
|
Andreas Dilger (andreas.dilger@intel.com) merged in patch http://review.whamcloud.com/13093/
Subject: LU-5242 tests: except sanity test_132 for ZFS
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 12bfc80b08d2b70c0052b271bfa2d34995b5892e
|
|
Sadly, it seems now that test_132() was added to the ALWAYS_EXCEPT list, test_133() has now started causing timeouts at OST unmount time:
https://testing.hpdd.intel.com/test_sets/7e564d44-85dd-11e4-b909-5254006e85c2
This makes me wonder if there is something happening in an earlier test that is causing a problem (e.g. refcount leak) and any later unmount will hit the problem? If we could hit this reliably in a shorter test (e.g. just sanity in a loop, even if it only hit 1/5 times), then we might be able to bisect which subtest is causing the problem to isolate the root cause.
|
|
we could change t-f to remount OST after every sub-test (or randomly) ?
|
|
There used to be the ability to do this in sanity.sh, by defining the "setup" and "cleanup" macros, but I suspect that is long gone.
|
|
Nathaniel Clark (nathaniel.l.clark@intel.com) uploaded a new patch: http://review.whamcloud.com/13130
Subject: LU-5242 tests: DEBUG ONLY unmount/remount every test
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 48c4b3ea65ae7cf69c84df61c3b76f15bb336f5f
|
|
Another failure instance:
https://testing.hpdd.intel.com/test_sets/c687c060-8bb5-11e4-8220-5254006e85c2
|
|
If diagnosing this problem requires some extra data that autotest framework does not collect - a patch needs to be created to collect this data if this is something not easily reproduceable on other systems.
|
|
Looking into the OST syslog from one of the recent LU-5242 failures, I see that sanity test_133g is hanging at OST unmount because of increased refcounts on the export structure, and again this can be traced back to OST threads blocked on starting a ZFS TXG.
Previous suggestions in this bug and LU-4716 included:
1. Set zfs_nocacheflush:
options zfs zfs_nocacheflush=1
This makes DKIOCFLUSHWRITECACHE a noop. Then the deadlock may move elsewhere or simply disappear.
2. Whether zfs_nocacheflush is set or not, once the timeout happens, it'd be useful to gather "zpool events -v" outputs on the OSS, which'd give more details on the state of the stuck zio.
I think it makes sense to make sure that our test system:
1. Use whole disks for zfs pools on guest VMs.
2. Use noop IO scheduler for corresponding disks on host OS.
Can any of these options be tested/implemented in some reasonable manner?
Minh, is there some way to check what the IO scheduler is for the VM host system?
I'd like to get some forward progress on these issues.
|
|
I've noticed in the test_133g hangs that there is a watchdog timeout in test_116a that indicates the source of the deadlock is at that point or earlier (this is easily seen in the OST dmesg log, but doesn't have any timestamps):
Unfortunately the timestamps on the console logs are not very accurate (they appear to only update once a minute or so), and this is a long-running test (about 200s), so test_116a may in fact be the source of the problem itself.
I looked at all 20 of the test_133g hang OST dmesg logs from the past two weeks, and in every case the first test that is reporting this watchdog is test_116a, which itself takes about 200s to run. That makes it very likely that test_116a (or a test run just before it) is the source of the problem, since the previous tests can vary by a few seconds, so if it were a long time before the start of test_116a in some cases the watchdog message would have appeared during an earlier test.
|
|
Andreas Dilger (andreas.dilger@intel.com) uploaded a new patch: http://review.whamcloud.com/13264
Subject: LU-5242 tests: skip sanity test_116a for ZFS
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 691009c5c0e38317724cdac764080fa45ad96667
|
|
I just managed to reproduce it and the symptoms matched ZoL bug 2523, which was recently fixed by SPL patch:
https://github.com/zfsonlinux/spl/commit/a3c1eb77721a0d511b4fe7111bb2314686570c4b
Nathaniel is working on updating our ZFS/SPL version to 0.6.3-1.2 in LU-6105, which includes the fix above.
|
|
Unfortunately, the upgrade to ZFS 0.6.3-1.2 doesn't seem to have solved this problem:
https://testing.hpdd.intel.com/test_sets/19c8b610-9bc1-11e4-857a-5254006e85c2
https://testing.hpdd.intel.com/test_sets/deca9712-9bc1-11e4-857a-5254006e85c2
It might be that there are multiple issues at work here? I haven't checked the latest failures to see if they have different symptoms or not.
|
|
The failures looked similar - txg_sync thread stuck in zio_wait(). Either there were multiple causes of this same symptom or the upstream fix didn't completely close the race. I'm looking into that. Meanwhile, I think we'd go ahead and land it and see if it'd reduce its occurrences, since quite some ZoL users reported that the fix did seem to work for them.
|
|
Nathaniel Clark (nathaniel.l.clark@intel.com) uploaded a new patch: http://review.whamcloud.com/13416
Subject: LU-5242 tests: DEBUG ONLY obd exports after every test
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: b19ed84cad9fe49f79bfc1096ec15141f70d16f0
|
|
I just had a close look at:
https://testing.hpdd.intel.com/test_sets/deca9712-9bc1-11e4-857a-5254006e85c2
Although the txg_sync thread was stuck in D state in zio_wait(), it probably wan't the cause of the test hang. Here's what happened:
1. At the start of sanity test 116a, 20:16:13, both ll_ost00_013 and ll_ost00_015 were blocked in D state in osd_object_write_lock().
2. And they kept blocked there and never recovered. These two threads would probably hold some references that prevented the OST from being umounted.
It was unlikely that the two threads hanged because of txg_sync hang in zio_wait, as we've seen previously, because if so:
- There'd have been similar messages like the txg_sync thread blocked for more than 120 seconds, but there was none.
- With the txg_sync thread blocked, no write to the ost could complete, in fact no transaction would be open. The OST would simply get stuck there. However, the tests went on OK until sanity test 133g at 20:27.
So I'd tend to say that the test hang was a result of the hanged ll_ost threads, rather than the txg_sync zio_wait deadlock.
The txg_sync thread did show as D state in zio_wait at the stack dump after sanity test 133g wouldn't complete. But very likely it just happened to be there waiting for some IOs to complete on the slow VM disks. It's quite often to see the txg_sync thread blocked for IO completion for more than 20 seconds on the test VMs. On the same OSS I saw ll_ost00_011 blocked for 40 seconds in txg_wait_open() at 20:09:38 and then recovered - so the txg_sync thread must have been blocked for IO roughly 40 seconds and moved on. That's long enough a window for the txg_sync thread to just happen to be in D state in zio_wait() when the stacks are dumped.
So, I'd still suggest to merge the patch to upgrade to ZFS 0.6.3-1.2. So far there's been no new report of zio_wait hang on ZoL since the SPL fix was merged.
|
|
I tried commenting out test_116a in http://review.whamcloud.com/13264, but that also hit stuck threads with the same stack trace in test_120g (twice, and that test runs for about 55s), and in test_120b (once, and it only runs for 1s - https://testing.hpdd.intel.com/test_sets/6903d29a-983e-11e4-8f7b-5254006e85c2). Using the test_120b stack dump time, it puts the hang back in test_103c or earlier. Using the test_120g stack dump time (start/end window) it puts the failure in test_118c-test_118k or earlier, so there is no overlap. It seems like there is a specific test or behaviour that is triggering this, since the stacks are always dumped in test_116a (except when I had excluded it). If it was just a random race condition, it would appear in other tests as well.
|
|
I just noticed that the ORI-616 fix was missing on master. I've asked for confirmation whether it'd be needed still. If yes, then that might explain some of the symptoms here as a refcount was missing.
|
|
Isaac Huang (he.huang@intel.com) uploaded a new patch: http://review.whamcloud.com/13431
Subject: LU-5242 osd-zfs: verify ref counting
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 22dc2ec61c815d532c507c68e871f4aa0471c423
|
|
Isaac, given how often this bug is being hit (about 50% of all review-zfs test runs), it is worthwhile to just try porting the patch to master and running a bunch of sanity tests via Test-Parameters: to see if it passes or fails.
|
|
Unfortunately, I don't think that the ORI-616 patch is relevant. It looks like the ORI-616 patch http://review.whamcloud.com/2560 that adds the lu_object_get() call in osd_bufs_get() is later dropped by ORI-645 patch http://review.whamcloud.com/2607 (presumably intentionally).
|
|
I've just hit this on my local VM setup and txg_sync is what seems to be holding up the umount of the OST. Attached is a dump of `zpool events -v` from the OSS.
Below is a dump I created blocked processes using sysrq:
iotop shows that txg_sync running writes to disk and top shows this:
|
|
Call Trace:
[<ffffffff81061d12>] ? default_wake_function+0x12/0x20
[<ffffffff810546b9>] ? __wake_up_common+0x59/0x90
[<ffffffff810a6d21>] ? ktime_get_ts+0xb1/0xf0
[<ffffffff81529433>] io_schedule+0x73/0xc0
[<ffffffffa02d841c>] cv_wait_common+0x8c/0x100 [spl]
[<ffffffff8109afa0>] ? autoremove_wake_function+0x0/0x40
[<ffffffffa02d84a8>] __cv_wait_io+0x18/0x20 [spl]
[<ffffffffa041e0ab>] zio_wait+0xfb/0x1b0 [zfs]
[<ffffffffa03b3be3>] dsl_pool_sync+0x2b3/0x3f0 [zfs]
[<ffffffffa03cbe4b>] spa_sync+0x40b/0xa60 [zfs]
[<ffffffff810546b9>] ? __wake_up_common+0x59/0x90
[<ffffffffa03d8916>] txg_sync_thread+0x2e6/0x510 [zfs]
so, it's still in DMU doing I/O ..
|
|
Nathan, if iotop showed txg_sync issuing writes, it could be just wait for IO on the slow VM. It's quite often to see txg_sync to block for 10s of seconds waiting for IO to complete on VMs. The important thing is how long it keeps blocked there. If it blocks there for hours and there was no active IO going on, then it's an instance of the zio race we've seen previously. Otherwise it could be just a red herring.
Also, it's not clear whether ll_ost01_014 and ll_ost01_016 blocked before the txg_sync or after. In the case of https://testing.hpdd.intel.com/test_sets/deca9712-9bc1-11e4-857a-5254006e85c2 the two ost threads blocked in similar places but far before the txg_sync thread was blocked.
|
|
Alex, yes it's still in DMU doing I/O. But it's quite often to see txg_sync to block for 10s of seconds waiting for IO to complete on VMs. In the case of https://testing.hpdd.intel.com/test_sets/deca9712-9bc1-11e4-857a-5254006e85c2 the two ost threads blocked in similar places but far before the txg_sync thread was blocked.
|
|
true, but then I'd expect only those to left at some point? while in all the cases we get that txg_sync() and another thread with zio_wait()?
|
|
would it be possible to get a crash dump?
|
|
I just reproduced it and ll_ost00_017 was stuck in D state (umount ost1 also stuck):
However, it was actually running in D rather than sleeping, using lots of CPU time:
8058 root 20 0 0 0 0 D 8.3 0.0 68:01.97 ll_ost00_017
So it looked like cv_wait_common() was actually spinning on a damaged lock. Also the txgs of both ost pools were moving forward so it's not the txg_sync hang we've seen previously.
I've never seen any report like this on ZoL, so I'd tend to think it's related to the way we use ZoL. I wonder whether it could be some shutdown race where umount process had freed some resource that ll_ost00_017 was trying to use, then cv_wait_common() just got stuck on a damaged lock. The umount stack:
It appeared that class_cleanup()=>obd_precleanup() has been called, and if ldto_device_fini() was called as well, i.e. osd_device_fini() was called and dmu_objset_disown(o->od_os) called. At the same time, osd_trans_start() could still access od_os from dmu_tx_assign(oh->ot_tx, TXG_WAIT).
If there could be a race between osd_device_fini() and osd_trans_start(), that'd explain what I see here. Comments very welcomed.
|
|
Also, the pool that umount was trying to umount seemed to be messed up:
The TXG # increased by 2186 in just 1 second - at the same time, LNet sent/got no message and all OST threads were idle - very weird. Again, no similar report was found on ZoL. Likely we're doing something wrong here.
|
|
class_cleanup() calls class_disconnect_exports() before going into precleanup process. so all the exports should be disconnected, then obd_exports_barrier() is called to ensure all exports are gone. and only after that in ofd_stack_fini() we disconnect from OSD so OSD can start to umount. I think there should be no racing dmu_objset_disown() here. also notice that dsl_dataset_disown() doesn't really do anything like "umount", it just mark the objset as "not used" while all txg logic is driven a level higher - as a whole pool.
|
|
Brian and Olaf were looking at this bug on Friday and was going to post, but since he didn't get a chance to do so yet I'll recap their findings as best I can. When ZFS is compiled with ASSERT checks enabled there is a test failure around sanity subtest 100 that shows a bonus buffer being modified without a lock held on it. Judging by the stack traces in test_116, this shows a possible root cause for the stuck threads and later unmount failure.
|
|
Brian filed that as LU-6155 but it is worthwhile investigating as the root cause of this bug also, because this systematically hits only in sanity and not randomly in other tests.
|
|
I had debugging on for SPL/ZFS, but was able to hit the hang without hitting any ZFS assertion.
I checked the kernel hung task watcher code and it looked like it'd not warn for tasks running in D state. The ll_ost00_017 thread likely hung on txg_wait_open() long before the umount started, judging from the CPU time it had used. That'd also explain why there were two other OST threads hanging in osd_object_write_lock() but there was no error message for any thread blocked holding the lock.
I'll try to narrow down to subtests earlier than 133. Would it be possible to force OST umount/remount after each test? That'd pinpoint exactly when SHTF.
|
|
Isaac, how recent was your testing? I wonder if we were hitting multiple different problems here, maybe one was fixed with 0.6.3-1.2 and there is a second problem causing the threads to be stuck and dump in test_116?
Unfortunately, Nathaniel already ran tests with an unmount after every subtest (see his debug patch earlier in this bug) but AFAIK this didn't find the problem that said, I didn't check the results of this patch myself. It may be that unmounting after every subtest didn't allow memory pressure to build up and his the problem.
I also had a patch on this bug to disable test_116 to see if it was the source of the problem, since it runs more than 120 seconds itself and the watchdogs could be triggered by hangs after the start of the test. However, the stack traces moved to test_118, but at least have me a bit better idea where the stuck threads first got stuck. It looks like it was around test_103 or so, but it is hard to know because the console messages do not have any timestamps.
It might be more productive to try a few patches to disable groups of subtests around 100 to 103, each with Test-Parameters that have 6-10 sanity runs to have a high confidence that the problem is caught.
|
|
The one where txg_sync hanged in D state while there's no pending IO was fixed - I was able to hit it often before 0.6.3-1.2 but not once after. Now I'm seeing one OST thread blocked in D state in txg_wait_open() forever, while txg_sync was busy doing IO and TXGs of the pool were moving forward.
I'm now testing with a temporary workaround for LU-6155. I was able to reproduce it roughly 1 out of 4 sanity runs, so we'll soon know whether LU-6155 is to blame or not.
|
|
The LU-6155 workaround didn't work, hit the same hang 1 out of 6 sanity runs.
|
|
Attempting to bisect cause, umount/mount of osts works prior to test 50 and fails prior to test 100:
http://review.whamcloud.com/#/c/13130/7
https://testing.hpdd.intel.com/test_sets/e8dac624-9ce2-11e4-b50c-5254006e85c2
|
|
I wrote a script to watch for stuck OSS threads and found in one failed test:
1. At test 56w about 02:52, the OSS began to get busy, with threads stuck waiting for IO in txg_wait_synced(). But threads would still recover and go on.
2. At test 79 about 03:25, one OSS thread (21277) got stuck in txg_wait_open() and it never recovered. It was in D state but actually running, which was why the kernel hung task watcher never warned about it.
3. At test 103b about 03:40, OST thread 21285 got stuck in ofd_object_destroy()=>osd_object_write_lock()=>call_rwsem_down_write_failed() and never recovered, at the same time OSS dmesg showed:
4. Later at 133g umount would block forever
I tend to think the hang thread in txg_wait_open() was the real cause, and the later hang threads in osd_object_write_lock() a consequence of it:
- The txg_wait_open() hang always preceded the osd_object_write_lock() hang.
- Stack trace showed that the txg_wait_open() thread might hold a lock which the later threads tried to get:
- I ran "sanity --start-at 100 --stop-at 140" for more than 60 times without reproducing the hang, so the cause should precede test 100.
- This is also in line with Nathaniel's observation that "umount/mount of osts works prior to test 50 and fails prior to test 100".
|
|
Now I can reproduce the txg_wait_open() hang with "sanity --only 78,79,80". It seemed to be the smallest subset of tests to trigger it - I haven't been able to reproduce it if any one test is removed. Once a thread got stuck in txg_wait_open(), umount on OSS would block forever just like at the end of 133g.
|
|
I found a possible bug LU-6195 in osd_declare_object_destroy() while looking at the code today, although I haven't fully understood its consequences to determine whether it could have something to do with this bug.
|
|
If you're able to reproduce this bug it might be useful to check the following proc variables.
First I'd look at dmu_tx, it shows a list of counters which indicate why a TX can't be assigned to a TXG. From the stacks which have been posted it looks like dmu_tx_assign() may just be failing repeatedly (maybe an incorrectly constructed TX?) and thus blocking in dmu_tx_wait() forever. Knowing why would help narrow things down. On a healthy system you should see almost everything in dmu_tx_assigned (success), the other common cases are dmu_tx_dirty_throttle and dmu_tx_dirty_delay. These indicate that the txg_sync thread can't write data as fast as the processes are creating it and it's injecting a delay to slow them down to keep things in balance. If you see more than a handful of something else it should be investigated.
The other thing I'd look at is /proc/spl/kstat/zfs/<pool>/txgs. This contains of a history of the last N TXGs which were committed. How long they took, how much IO was performed, how many IOPs were issued, etc. To enable this you'll need to set the history size using the zfs_txg_history module parameter, by default it's disabled. But if you want to log the last say 10 TXGs set it to 10. In particular, I'm curious if TXGs continue to roll forward at the usual rate while this thread is stuck (it sounds like it). If so then the TXG engine itself would seem to be working fine and there's just something wrong with the specific TX which is blocked.
|
|
well, we're supposed to get a message in that case:
rc = dmu_tx_assign(oh>ot_tx, TXG_WAIT);
if (unlikely(rc != 0))
{
struct osd_device *osd = osd_dt_dev(d);
/* dmu will call commit callback with error code during abort */
if (!lu_device_is_md(&d->dd_lu_dev) && rc == -ENOSPC)
CERROR("%s: failed to start transaction due to ENOSPC. "
"Metadata overhead is underestimated or "
"grant_ratio is too low.\n", osd->od_svname);
else
CERROR("%s: can't assign tx: rc = %d\n",
osd->od_svname, rc);
}
|
|
Well not exactly. When calling dmu_tx_assign() with TXG_WAIT it should only fail in the case where we're over quota. For all other errors it will retry and we should be assigned to the next TXG (assuming the TX is sane). So checking the dmu_tx proc file would show if we're hitting any of the ERESTART cases.
|
|
Brian, you nailed it! Thanks a lot!
Every time the hang happened, the TXGs would move forward, but unusually fast:
In this case, 5141 in one second.
Here's dmu_tx:
And dmu_tx_memory_reserve is still rapidly growing even though there's now no IO from Lustre at all:
So the counter grew by 5519 in a second, roughly the same as the increase in TXG #. Looks like that's why the thread is still hanging in txg_wait_open().
The only place where that counter gets bumped is dmu_tx_try_assign()=>dsl_dir_tempreserve_space()=>arc_tempreserve_space(). So I increased zfs_arc_max by about 500M, waited for the arc_adapt thread to pick up the change, and then a few seconds later the thread recovered from the hang and everything looked normal! Even umount worked!
Before I increased zfs_arc_max, there was about 800M available from arc_sz to arc_c, and the hanged tx was only trying to remove one object (and update OI and accounting ZAPs) so clearly something was wrong with that TX (maybe LU-6195). I'll find out.
|
|
Whoa, that's definitely going to be a problem! It sounds like Lustre constructed a massive TX relative to the target ARC size and therefore could never assign it to a TXG. Something like LU-6195 could cause this with an incorrect hold. You might want to build ZFS with --enable-debug-dmu-tx, this will enable some additional statistics about the TX and some more sanity checking.
|
|
iirc, we got -ENOSPC from dmu_tx_assign() if TX is too big. for example, when we tried to destroy a file with lots of stripes.
|
|
Alex that can happen (along with EDQUOT) if the pool is low on space but it's not guaranteed to happen even for very large TXs. It's entirely possible that you'll fall in to this ERESTART retry loop first. The DMU expects that individual TXs will be relatively small (~10MB at most) but that a TXG may contain many TXs. If Lustre is creating TXs much larger than this I can see how this deadlock could happen. It would be best if we could put an upper bound of the size of a Lustre TX.
|
|
Kudos to everyone for the excellent work in tracking down this tricky problem. Nathaniel, while a solution is being working on, could you please submit a patch to sanity to re-enable subtest 132 and exclude subtests 78, 79, and 80 for ZFS OSTs with a Test-Parameters: line that runs sanity enough times to be confident of the result (maybe 6-10 times)? That would allow us to start enforcing the review-zfs test results while the fix for this new issue is prepared, and ensure we don't regress in other areas in the meantime. Excluding sanity test_133g failures we would have passed 27 of 30 recent review-zfs test sessions (one failued due to a problem in the patch, one failed due to timeouts in sanity-quota and ost-pools, and one had an additional failure in sanity-quota ).
There is a similar check in ext4 to limit the size of a single transaction handle to be < 1/4 of the total journal size. I don't think it unreasonable to put some upper bound on the size of a single ZFS tx, but what that size should be is unclear. I recall the 10MB tx limit also, but I think it was just recently increased? Related to this, llog updates (appends) they may be quite large in theory but in practice will only affect a small number of blocks, and since an unlink of a widely-striped file may update a lot of llog files (up to 2000 stripes) it could cause very large theoretical transaction sizes that aren't seen in practice, so we don't want to cause them to gratuitously fail due to this check. That is what LU-2160 "Implement ZFS dmu_tx_hold_append() declarations for llog" is about, but that hasn't been implemented yet.
|
|
Working on the patch to disable 78, 79, and 80...
|
|
Isaac Huang (he.huang@intel.com) uploaded a new patch: http://review.whamcloud.com/13600
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: f45c320eeeeaff849ba2e97da0f6fe5185d1e149
|
|
I just reproduced it again (with a LU-6195 workaround, so that's ruled out), and I found one fishy object on the OST:
An object with only 4 indirect blocks, despite its lsize of 1T. I guessed it's the object the hanged OST thread was trying to remove. The arc_c was 938M when it hanged, then I gradually increased it and the hang disappeared when arc_c was increased to 1.0G. Then that object also disappeared:
So my guess was right: the thread tried to remove the object with 1T lsize, and dmu_tx_hold_free() estimated the memory overhead of freeing the object to be about 1G, then dmu_tx_assign() hanged in dmu_tx_try_assign()=>dsl_dir_tempreserve_space()=>arc_tempreserve_space(). I also kept watching arcsz, and it grew by only a few MBs (it never grew over 60M).
So it looked like dmu_tx_count_free() severely over-estimated txh_memory_tohold for dmu_tx_hold_free().
|
|
cool catch! I guess it should be possible to reproduce this with a regular truncate to, say 2-4TB ?
|
|
also, would it make sense to have own copy of dmu_tx_assign() with some checks like if we're trying for too long, then print an error?
|
|
This looks like it is caused by sanity.sh test_80 "Page eviction is equally fast at high offsets too", which writes 1MB at a 1TB offset in a sparse file to test client page cache truncation performance. I guess it is also testing OSD-side block truncation...
I don't think making our own version of dmu_tx_assign() is the right solution, but rather fixing the upstream ZFS code. I'm not sure if this should fail outright (leaving a user with an unremovable object?) or only print an error that the arc_c limit should be increased (preferably with some advice on how large it needs to be).
As for the proper solution, I'd expect that the DMU code shouldn't be so pessimistic about TX size when deleting this sparse file. I'd imagine it only really needs a few hundred KB of dirty blocks, so maybe it needs a bit better accounting? Is it accounting for a dense file and not realizing the file is sparse? Is it possible to short-circuit all of the calculations in dmu_tx_count_free() by checking the allocated block count from the dnode (dn_used?), or is that a layering violation?
|
|
I agree that the proper fix can be done only in DMU. but there might be another similar overestimation leading to a livelock in some corner cases which will be hard to recognize given it's a silent loop within dmu_tx_assign().
|
|
Last night I changed the seek=1M to seek=5K in test_80, and so far I've run 5 iterations of sanity and 64 iterations of "sanity --only 78,79,80" without reproducing it. So it looks like we can work around it by reducing seek in test_80 (probably test_34g as well) without skipping any sub-test, while working on a proper fix.
As to the fix:
- In arc_tempreserve_space():
- An error/debug message here would help.
- Also I think the code should be changed to:
The code just tried to grow ARC to the max possible in "arc_c = MIN(arc_c_max, reserve * 4);", and if that's still not enough ERESTART doesn't seem to be the right choice - unless the admin would show up and bump zfs_arc_max, which in my opinion isn't a case for ERESTART.
- The dmu_tx_count_free() caused problems in the past with sparse file and was improved to be less over-estimating:
https://github.com/zfsonlinux/zfs/commit/ff80d9b142826c15fa84e3c4b9ef1795fd6e9485
Looks like there's more work there.
- Investigate whether to limit the size of a single TX. The ZPL does exactly this in zfs_write():
|
|
take into account that with wide-striping we may need to modify upto ~2K objects (and each llog is modified twice: 8K header and record itself).
|
|
Patch to disable test(s): http://review.whamcloud.com/#/c/13600
|
|
Isaac, we cannot change the seek value in test_80, because that is testing VM cache invalidation specific to the client, so changing the file size will break this test on the client.
Oleg's suggestion is to only exclude subtest 80 if the ARC size is too small, so that it still runs on other systems that have enough RAM to pass this subtest. It might be useful to check pass/fail rates against VM clusters to see if some VMs are failing more often because they have less RAM? It doesn't seem that we need to exclude subtest 78 or 79 at all, but we're landing this patch anyway to allow review-ZFS to begin passing.
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/13600/
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 298916a319e1c5da4be0df3609e4773fe70a4026
|
|
Failing tests disabled. Fix will be included in 2.8.
|
|
Andreas, DMU wanted about 1G ARC size for the object delete. Most of our VMs are configured with 1.85G memory so ARC size defaults at 938M. So they'll all run into this problem. We can increase ARC size a bit to let the object delete pass, because only a couple of MBs were really needed. But that'd likely run into other issues, e.g. LU-5809. So I think our best workaround would be to only exclude 80. I'm now testing that on Eagle - will push a patch shortly.
|
|
Isaac Huang (he.huang@intel.com) uploaded a new patch: http://review.whamcloud.com/13620
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 39acc43a443a23f3e92dab63155ad658fdeb8cf2
|
|
Isaac Huang (he.huang@intel.com) uploaded a new patch: http://review.whamcloud.com/13630
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 13cc94af090e0b1279c2987840a0e6de685e03ee
|
|
It looked like the preferred DMU API to remove large/sparse objects is dmu_free_long_range(). The ZPL was able to remove any large/sparse objects I threw at it where it'd just choke up osd-zfs:
I created a simple patch and my tests showed it worked:
But two things I'm not sure about:
- I had to call it in do_declare_destroy() because it must be called before dmu_tx_hold_free() is called, that means when do_declare_destroy() returns the data in the object has already been freed. Is it OK for Lustre/OSD?
- The dmu_free_long_range() frees data in the object in several TXs, so it might fail in the middle leaving the data in the object partially freed. If do_declare_destroy() fails for this reason, what would OSD layer do? The object itself and the OI and accounting ZAPs are still freed/updated in a single TX so that's consistent but the object data can be partially freed already.
We can work on dmu_tx_count_free() to correctly estimate memory overhead for the particular sparse file created by test_80(). But we'd have to deal with any large/sparse object anyway, so I think in the long run it'd be better to go with dmu_free_long_range().
|
|
Nice find, that neatly explains everything. Thanks Issac for opening issue 3064 at zfsonlinux so we can decide of what should be done on the ZFS side. We should certainly investigate improving the quality of the worst case estimate. But it really does need to be a worst case estimate or we risk potentially stalling the txg engine in the worst (but very unlikely) case. Anyway, I'm open to ideas!
https://github.com/zfsonlinux/zfs/issues/3064
|
|
Isaac, this is usually done using an additional index/list containing object to be freed. so OSD's destroy put an object on the list (plus, say, OI removal), then a separate thread (or osd_trans_stop()) truncates the object, frees it and remove from the list/index using as many transactions as needed.
|
|
Yes, what Alex said. This is exactly how the Posix layer also works, the object to be removed is placed on an unlinked listed for handling latter in as many transaction as needed. Only once the blocks are all freed in the obejct removed from the list. See zfs_unlinked_drain().
|
|
Note that by the time that the OST object is being destroyed it has already been unlinked from the MDS namespace, and that unlink is committed on the MDS. The OFD has also revoked client locks and discarded any cached dirty pages on the clients, so there is no danger to destroy the object in stages. That is what ext4 is doing internally (truncating blocks in small chunks from the end of the file).
Since the MDT is already logging the object destroy locally and will resend it if the OSS crashes. The OST object hasn't been deleted from the OST namespace yet, so I don't see a requirement for more infrastructure to handle this at the OSD level. It is fine to truncate the object before destroy FOR THE OST ONLY, and higher layers will handle it.
That said, since the OSD code is common, we shouldn't be exposing truncated-but-not-unlined objects on the MDT, so it may be easiest to truncate to zero explicitly from the OFD before the object destroy?
|
|
well, that would mean we can't atomically destroy huge objects using OUT which I'd like to do to batch OST object destroy's from MDT.
|
|
How about:
- An object (maybe a ZAP) is created per OST/MDT, to hold objects to be freed. Let's call it the deathrow object.
- In declare_object_destroy() and object_destroy(), within a single TX, move the object to the deadthrow, and update OI and accounting ZAPs as well. So the object disappears from OST/MDT namespace atomically.
- If an object is small enough, it can be destroyed in the old way.
- A separate thread works on the deathrow object, truncating and freeing every object in it.
- This may break some tests that wait for free space to increase after object removal. We may also do at least the truncating in osd_trans_stop().
All implemented at the osd-zfs layer.
|
|
from Lustre point of view, the object is destroyed when it can't be found with lu_object_find(). IOW, when corresponding FID is removed from OI - this should be a part of object destroy. space accounting shouldn't be an issue as it's not released immediately in any case: grants/quota can release reserved space upon commit, but a new reserve can be made only with new statfs. truncate/dnode destroy in osd_trans_stop() looks OK.
|
|
It makes sense to keep this compatible with ZFS ZPL if at all possible, so that if large files are unlinked under ZPL and then mounted as Lustre, or vice versa, we don't defer deleting them forever. I see this is handled in zfs_unlinked_add() and zfs_unlinked_drain() with a ZAP named "DELETE_QUEUE" (ZFS_UNLINKED_SET) in the MASTER_NODE_OBJ. Even if we need to implement our own routines to handle this, it makes sense to use the same ZAP and zap format (zap_add_int()).
|
|
I like Andreas's idea of keeping the unlink behavior compatible with the ZPL. It would be ideal if you could reuse the existing ZPL functions but those functions are tied quite closely to ZPL specific data structures so that's probably not workable. But the ZFS_UNLINKED_SET object itself is just a ZAP containing a list of object ids. And since objects on disk are already constructed to be compatible with the ZPL we should be able to safely use it. Isaac's design is nice, but let me suggest a few minor tweaks:
- Use the existing ZFS_UNLINKED_SET object linked the MASTER_NODE_OBJ as the deathrow object.
- In declare_object_destroy() and object_destroy() just handle moving the object to the ZFS_UNLINKED_SET in a single TX.
- In a dedicated thread, taskq, or generic linux worker thread regularly walk the ZFS_UNLINKED_SET and rely on dmu_free_long_range() to split the free over as many TXGs as required.
- I don't think there's any advantage in handling small object destruction synchronously in object_destroy(). It's simpler and probably more efficient to always do this asynchronously.
- Start draining the ZFS_UNLINKED_SET right away when remounting the OSD (this happening during mount for the ZPL).
|
|
I'd think that the optimization for small objects (notice most of MDT's objects are literally empty) make sense as we don't need to modify yet another ZAP twice. I guess there is no strong requirement to implement this right away, but still.
|
|
I could see a case for zero length files as an possible optimization. But I suspect that even for the MDT it would be more efficient to handle the freeing asynchronously outside of any request processing. Even if the file is zero length you're still going to be freeing a spill block for the xattrs and updating a dbuf for the dnode object. Personally I'd keep it as simple and concise as possible until it's clear something more is required. But that's just my preference.
Keep in mind that none of this free space will be available for a couple TXGs anyway.
|
|
I have no objection to do this as simple as possible. my point was that MDT is known to be CPU-bound and ZAP (even micro ZAP) isn't free.
|
|
Thanks all. I'll work on a patch first without the small object optimization to get this bug fixed; then will benchmark to figure out whether to optimize the small object path or not.
|
|
I would agree with Alex on this. By deferring unlink of small files it will probably double or triple the total IO that the MDT is doing because in addition to the actual dnode deletion it also needs to insert the dnode into the deathrow ZAP in one TXG and then delete it from the same ZAP in a different txg. If there are a large number of objects being deleted at once (easily possible on the MDT), then the deathrow ZAP may get quite large (and never shrink) and updates would become less efficient than if it is kept small.
|
|
another seen on b2_5 with zfs:
https://testing.hpdd.intel.com/test_sessions/435c3152-b816-11e4-9ecb-5254006e85c2
|
|
Nathaniel Clark (nathaniel.l.clark@intel.com) uploaded a new patch: http://review.whamcloud.com/13805
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: b2_5
Current Patch Set: 1
Commit: 817cf8a2e781d546508929a9f58b44561ae3361c
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/13630/
Subject: LU-5242 osd-zfs: umount hang in sanity 133g
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 9b704e4088d867851cdb011f0a2560b1e622555c
|
|
Landed for 2.8
|
Generated at Sat Feb 10 01:49:45 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
zpool-events.txt