|
also hit on master branch, zfs DNE
https://testing.hpdd.intel.com/test_sets/d05367b0-2799-11e8-9e0e-52540065bddc
mds dmesg
|
|
The error being returned is -71 = -EREMOTE, which suggests that there is some problem sending the RPC to the wrong MDT. However, that may also be some kind of fallout from "loghandle XXX with no header", which implies that the llogfile is zero length and wasn't written correctly? It's hard to see why the -EREMOTE problem could relate to only DNE+ZFS, while the second one seems more plausible.
|
|
Lai, could you please take a look? James reports that this is failing 100% of the time with review-dne-zfs-part-4, which is currently an optional test run, but we want to make it a required test.
|
|
Lai Siyao (lai.siyao@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/32976
Subject: LU-10740 test: test replay-single 2d with full debug
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 958da17e9abf0504a802963ba8a7fa0a9afc075b
|
|
The failed call trace is:
but loghandle->lgh_hdr is NULL, which caused llog_write_rec() return -EPROTO (-71). But I don't understand why it fails on ZFS only.
|
|
I found something strange in the log:
The scenario is as below:
1. setdirstripe allocated [0x200001b70:0x1:0x0] for its first stripe on MDT0, and it also allocated a new meta sequence.
2. replay barrier
3. replay setdirstripe, MDT0 got update logs from MDT1, and it needed to create an update log, now it allocated fid for this update log, but it allocated the same meta sequence as step 1, and allocated the same fid as the first stripe.
4. llog_osd_create() > osd_create() -> osd_zap_add() found the fid in OI, so it skipped llog_init_handle(), which cause loghandle>lgh_hdr not set, and finally llog_write_rec() return -EPROTO.
I'm not sure whether it's related with ZFS, because seq_store_update() has updated FLDB with th_sync set.
|
|
Is it possible the MDT is running with osd_object_sync_delay_us=0? This was being proposed in a recent patch, but I didn't think it was landed yet, and was initially limited to a single test.
|
|
It doesn't look to be related with osd_object_sync_delay_us. I added some debug log, the result shows th_sync doesn't work on ZFS, the debug log shows seq file was sync written (osd_trans_commit_cb() was called before osd_trans_stop()), but after replay barrier, server read stale seq file on start up. I also tweaked the code to do create in sync mode, the result also shows file not exist after restart.
Is there a simple way to verify this?
|
|
One problem we have with ZFS TXG sync is that this doesn't force a commit, only block the thread until the TXG commit happens. That should be equivalent from the point of view of the client, but it is possible the test doesn't expect this?
Until we have ZIL support, it would be nice to have a way to force TXG commit, especially with flash devices that have no seek latency.
|
|
FID seq file is updated in sync mode, so upon MDS fail, it won't allocate duplicate FID.
replay-single.sh 2d failed because it happens to allocate a new super sequence before fail, If it's run separately it can pass.
|
|
Andreas, I added a simple debugging data - print time it takes to commit TXG upon enforced commit and initiated that many times during sanity.sh:
sync took 8276 usec
sync took 26489 usec
sync took 15471 usec
sync took 8526 usec
sync took 36187 usec
sync took 16634 usec
sync took 283 usec
sync took 8142 usec
sync took 7335 usec
sync took 609 usec
sync took 641 usec
sync took 660 usec
sync took 9278 usec
sync took 396 usec
sync took 17179 usec
sync took 401 usec
sync took 455 usec
sync took 403 usec
sync took 532 usec
sync took 424 usec
sync took 9057 usec
sync took 444 usec
sync took 11116 usec
sync took 16007 usec
sync took 16611 usec
sync took 680 usec
sync took 240 usec
sync took 289 usec
sync took 256 usec
sync took 289 usec
sync took 311 usec
sync took 7353 usec
sync took 285 usec
sync took 9369 usec
sync took 13867 usec
sync took 275 usec
sync took 6440 usec
sync took 327 usec
sync took 14827 usec
sync took 15640 usec
sync took 17490 usec
sync took 113 usec
sync took 524 usec
sync took 268 usec
sync took 375 usec
sync took 15034 usec
sync took 297 usec
sync took 247 usec
sync took 401 usec
sync took 9492 usec
|
|
Alex, what are you using to force a TXG commit in your tests, and are you sure that the commit is actually making it to disk? It seems very fast in some cases, 0.1ms for a commit...
static int osd_trans_stop(const struct lu_env *env, struct dt_device *dt,
struct thandle *th)
{
if (sync) {
if (osd_txg_sync_delay_us < 0)
txg_wait_synced(dmu_objset_pool(osd->od_os), txg);
else
udelay(osd_txg_sync_delay_us);
}
My understanding is that txg_wait_synced() will just wait for the TXG commit to happen, it can't necessarily force a TXG commit like jbd2_journal_stop() can. While we don't want every thread to be forcing a TXT commit, IMHO the jbd2 code has it right - wait a short time for more threads to join the TXG and commit, then force the commit. The length of time to wait should be based on the current storage commit time, as jbd2_journal_stop() does, so that it is fast on flash and slower on disks to be most efficient.
|
|
the patch I used:
@@ -276,6 +276,17 @@ static int zfs_osd_mntdev_seq_show(struct seq_file *m, void *data)
}
LPROC_SEQ_FOPS_RO(zfs_osd_mntdev);
+struct osd_sync_cb_data {
+ ktime_t time;
+};
+
+static void osd_sync_cb(void *cb_data, int error)
+{
+ struct osd_sync_cb_data *cb = cb_data;
+ printk("sync took %llu usec\n", ktime_us_delta(ktime_get(), cb->time));
+ OBD_FREE_PTR(cb);
+}
+
static ssize_t
lprocfs_osd_force_sync_seq_write(struct file *file, const char __user *buffer,
size_t count, loff_t *off)
@@ -288,6 +299,19 @@ lprocfs_osd_force_sync_seq_write(struct file *file, const char __user *buffer,
rc = lu_env_init(&env, LCT_LOCAL);
if (rc)
return rc;
+ {
+ struct osd_device *osd = osd_dt_dev(dt);
+ struct osd_sync_cb_data *cb;
+ dmu_tx_t *tx;
+
+ OBD_ALLOC_PTR(cb);
+ cb->time = ktime_get();
+ tx = dmu_tx_create(osd->od_os);
+ dmu_tx_assign(tx, TXG_WAIT);
+ dmu_tx_callback_register(tx, osd_sync_cb, cb);
+ dmu_tx_commit(tx);
+ }
i.e. I registered a commit callback and just calc/printk when it's called.
txg_wait_synced() asks sync thread to initiate txg commit:
if (tx->tx_sync_txg_waiting < txg)
tx->tx_sync_txg_waiting = txg;
...
cv_broadcast(&tx->tx_sync_more_cv);
|
|
Alex, is your testing running with an HDD or SSD or ramdisk? On an HDD I can't see how a TXG commit could ever complete in less than 4x seek time (just for the überblock writes, 2x each at the start and end of the device), which is about 32-40 ms.
|
|
Andreas Dilger (adilger@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/33106
Subject: LU-10740 tests: disable tests for replay-dne-zfs-part-4
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: a7675ca33ec579525b4d39ad114b54ca3b462a62
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/33106/
Subject: LU-10740 tests: disable tests for replay-dne-zfs-part-4
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 16e92e2d01a71c2a97cae89c70c58abf409c12c0
|
|
adilger, sorry, missed your question.. I'm using ramdisk.
|
|
I think this is a dup of LU-10143
|
Generated at Sat Feb 10 02:37:46 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
5a935964f72e62d872670430.zip