|
Waiting on Jinshan - moving out to next month
|
|
bad test configuration resulted in this issue. fixed the test
|
|
We have seen this come even with 1 file ager process on each client with its own top level directory:
Server
Client:
...etc..
This is followed by a crash
https://jira.hpdd.intel.com/browse/LU-9304
Also some similar messages as:
https://jira.hpdd.intel.com/browse/LDEV-199
|
|
Has started reproducing again
|
|
John is seeing this often now, crash results are above. Please comment in the ticket or reach out to John S if you have any questions.
|
|
John, since the server-side checksum is re-validated after the data was submitted to ZFS (to ensure it is overlapping with ZFS computing its own data checksum), this appears to be a problem with the data on the OST being modified after it arrives at the OSS.
What features are enabled for this testing? Does this include dRAID, 16MB RPC, 16MB recordsize, anything else? If those features are enabled, have you tried reproducing this with vanilla ZFS + 1MB RPC + 1MB recordsize to see if it reproduces there, and if not isolating it to one of the new CORAL features?
We obviously don't see this with our normal testing, but it could potentially also be workload related, so getting a description of the IO pattern your filesystem aging tool might help.
|
|
Greetings,
Here were the settings for the runs that are not default. I have not observed that brwsize is automatic though I haven't tried recently.
ZFS OSS
echo "16777216" > /sys/module/zfs/parameters/zfs_max_recordsize
echo "65536" > /sys/module/spl/parameters/spl_kmem_alloc_warn
zpool create -f -o ashift=12 -o cachefile=none -O recordsize=16MB ost0 draid2 cfg=test_2_5_4_18_draidcfg.nvl mpathaa mpathab mpathac mpathad mpathae mpathaf mpathag mpathah mpathai mpathaj mpathak mpathal mpatham mpathan mpathao mpathap mpathaq mpathar
Lustre OSS
mkfs.lustre --backfstype=zfs --reformat --fsname=lsdraid --ost --index=0 --mgsnode=192.168.1.5@o2ib ost0/ost0
lctl set_param obdfilter.lsdraid-OST0000.brw_size=16
Lustre client
/usr/bin/mount -o flock -t lustre 192.168.1.5@o2ib:/lsdraid /mnt/lustre/
/usr/sbin/lctl set_param osc.*.max_pages_per_rpc=1024
or
/usr/sbin/lctl set_param osc.*.max_pages_per_rpc=4096
I have seen this on RAIDz pools as well it is not specific to dRAID. I will attach fileager python script to this bug
|
|
What would we like to try first – on raidz, 1MB RPCs, or 1MB bwrsize/record size?
|
|
John - there are too much new code in your test. I would prefer to start with ZFS(with ABD) + 1M RPC, and then add 16M RPC, and then add DRAID, and then MD class.
This series of problems, for example LU-9279 and LU-7280, can also narrow down this way.
|
|
Yes, indeed although perhaps one solutions fixes them all 
I should be able to start this testing tomorrow and will update this ticket with the results of the lowest factor thing that still shows this. These checksum errors are actually the hardest to produce of all of these bugs. But I have seen on and off for a while now – almost 9 months now.
|
|
Lustre 2.9.0 + 0.7.0 RC3 (none of our patches) record size 1M on OST0 and 16M on OST1. brw_size=16 on both raidz – messages but no crash manual dumps: 10.8.1.4-2017-04-15-00:26:17 10.8.1.4-2017-04-15-01:47:43 10.8.1.3-2017-04-15-13:22:45 10.8.1.4-2017-04-15-13:22:47
wolf-4 OSS
wolf-3 OSS
[root@wolf-4 combined]# ps aux |grep 9096
root 9096 0.6 0.0 0 0 ? S 01:55 4:21 [ll_ost_io01_003]
root 77386 0.0 0.0 112656 976 pts/0 S+ 12:56 0:00 grep --color=auto 9096
[root@wolf-4 combined]# man ps
[root@wolf-4 combined]# ps aux |grep 8509
root 8509 4.3 0.0 0 0 ? D 01:55 28:56 [ll_ost_io01_001]
root 84813 0.0 0.0 112656 976 pts/0 S+ 12:57 0:00 grep --color=auto 8509
[root@wolf-4 combined]# cat /proc/9096/stack
[<ffffffffa0d8dff5>] ptlrpc_wait_event+0x325/0x340 [ptlrpc]
[<ffffffffa0d93fcb>] ptlrpc_main+0x80b/0x1de0 [ptlrpc]
[<ffffffff810a5b8f>] kthread+0xcf/0xe0
[<ffffffff81646a98>] ret_from_fork+0x58/0x90
[<ffffffffffffffff>] 0xffffffffffffffff
[root@wolf-4 combined]# cat /proc/8509/stack
[<ffffffff8108c04f>] usleep_range+0x4f/0x70
[<ffffffffa269c99a>] dmu_tx_wait+0x33a/0x360 [zfs]
[<ffffffffa269ca45>] dmu_tx_assign+0x85/0x3f0 [zfs]
[<ffffffffa0f94fea>] osd_trans_start+0xaa/0x3c0 [osd_zfs]
[<ffffffffa10960db>] ofd_trans_start+0x6b/0xe0 [ofd]
[<ffffffffa109c0a3>] ofd_commitrw_write+0x943/0x1c20 [ofd]
[<ffffffffa109ff2d>] ofd_commitrw+0x51d/0xa40 [ofd]
[<ffffffffa0e0f8d2>] obd_commitrw+0x2ec/0x32f [ptlrpc]
[<ffffffffa0de7f71>] tgt_brw_write+0xea1/0x1640 [ptlrpc]
[<ffffffffa0de4225>] tgt_request_handle+0x915/0x1320 [ptlrpc]
[<ffffffffa0d901ab>] ptlrpc_server_handle_request+0x21b/0xa90 [ptlrpc]
[<ffffffffa0d94260>] ptlrpc_main+0xaa0/0x1de0 [ptlrpc]
[<ffffffff810a5b8f>] kthread+0xcf/0xe0
[<ffffffff81646a98>] ret_from_fork+0x58/0x90
[<ffffffffffffffff>] 0xffffffffffffffff
|
|
Yesterday I tried the following combinations:
Lustre 2.9.0 + latest coral_beta_combined record size 16M brw_size=16 draid zfs_abd_scatter_enabled = 0, max_pages_per_rpc=4096 – crash 10.8.1.3-2017-04-14-22:46:09
Lustre 2.9.0 + latest coral_beta_combined record size 16M brw_size=16 draid zfs_abd_scatter_enabled = 0, max_pages_per_rpc=256 – crash 10.8.1.3-2017-04-15-00:39:07
wolf-3 OSS 10.8.1.3-2017-04-14-22:46:09
wolf-3 OSS 10.8.1.3-2017-04-15-00:39:07
|
|
The above dumps are now on onyx:
/scratch/johnsali/
rw-rr- 1 johnsali johnsali 430M Apr 15 08:24 10.8.1.3-2017-04-14-224609.tgz
rw-rr- 1 johnsali johnsali 142M Apr 15 08:24 10.8.1.3-2017-04-15-003907.tgz
rw-rr- 1 johnsali johnsali 707M Apr 15 08:26 10.8.1.3-2017-04-15-132245.tgz
rw-rr- 1 johnsali johnsali 274M Apr 15 08:27 10.8.1.4-2017-04-15-002617.tgz
rw-rr- 1 johnsali johnsali 485M Apr 15 08:29 10.8.1.4-2017-04-15-014743.tgz
rw-rr- 1 johnsali johnsali 782M Apr 15 08:31 10.8.1.4-2017-04-15-132247.tgz
|
|
I did a mostly successful run with Lustre 2.9.0 + 0.7.0 RC3 (none of our patches) record size 1M on both OSS which forces a max RPC size of 1MB both raidz. With this combination set I did not not see BAD WRITE CHECKSUM. It is my assumption based on these runs that the ZFS record size and associated brw size of 16MB is the issue. I suppose the one outstanding question is this only caused by FileAger. I will do some runs today without this application and see if I can produce it with any others. If it is helpful I could narrow it to a routine in FileAger.
|
|
Here is a test case:
#!/usr/bin/python3.4
import os
import uuid
import tempfile
def WriteFileBasic(multiplysize, blocksize, writechar, path):
"""
Writes a basic file in a sequanetial fashion and fills it with writechar with the size of the file
being equal to writechar * multiplysize and written in chunks at time based on blocksize.
"""
writethis = writechar * multiplysize
unique_filename = uuid.uuid4()
filetowrite = path + '/basic-' + str(unique_filename)
fd = open(filetowrite, 'wb')
for x in range(blocksize):
fd.write(bytes(writethis, 'UTF-8'))
fd.close()
directory = tempfile.mkdtemp(dir="/mnt/lustre")
if not os.path.exists(directory):
os.makedirs(directory)
print("Writing files to: {0}".format(directory))
for i in range(100):
for x in range(2):
WriteFileBasic(multiplysize=204800, blocksize=1024, writechar='0123456', path=directory)
WriteFileBasic(multiplysize=204800, blocksize=1024, writechar='0123456', path=directory)
WriteFileBasic(multiplysize=204800, blocksize=128, writechar='0', path=directory)
WriteFileBasic(multiplysize=204800, blocksize=128, writechar='0', path=directory)
WriteFileBasic(multiplysize=204800, blocksize=1024, writechar='0123456', path=directory)
WriteFileBasic(multiplysize=124, blocksize=1024, writechar='0', path=directory)
I start multiple copies of that on one client node at least 2 but 4 sometimes seems to make this come out a little quicker
Here is an example from tonight running this.
mpirun -np 4 -wdir /mnt/lustre -machinefile hosts -env I_MPI_EXTRA_FILESYSTEM=on -env I_MPI_EXTRA_FILESYSTEM_LIST=lustre /home/johnsali/wolf-3/ior/src/ior -a POSIX -F -N 4 -d 2 -i 1 -s 20480 -b 8m -t 8m
./testcase_pagestate.py &
./testcase_pagestate.py &
almost immediately:
[103132.581173] LustreError: 168-f: BAD WRITE CHECKSUM: lsdraid-OST0000 from 12345-192.168.1.6@o2ib inode [0x200000bd0:0xa98:0x0] object 0x0:1018 extent [83886080-92979199]: client csum 3e2f59b2, server csum cf13a5a5
But it took several minutes to get:
[103332.411485] BUG: Bad page state in process ll_ost_io01_000 pfn:171cd2c
[103332.420695] page:ffffea005c734b00 count:-1 mapcount:0 mapping: (null) index:0x0
[103332.431396] page flags: 0x6fffff00000000()
[103332.437504] page dumped because: nonzero _count
...etc...
The case is basically writing large file, large file, very small file or large file, very small file while stream IO is going on from ior.
The client sees:
|
|
Thanks for the test case - I'm looking at it now
|
|
I strongly suspect this is a use-after-free bug based on the crash occurred in:
where %r12 is supposed to a pointer to struct page, but now the value is 3534333231303635.
The bad page not only occurred in free page, but also in the page allocation path.
even wild pointer is hardly to point to page array.
|
|
as Don and John pointed out, the page pointer was actually overwritten by data, that is ascii code of "54321065".
This page pointer is in the array of bulk buffer descriptor. I would strongly suggest to try other RPC size and see how it goes.
|
|
Jinshan Xiong (jinshan.xiong@intel.com) uploaded a new patch: https://review.whamcloud.com/26749
Subject: LU-9305 target: debug patch for memory problem
Project: fs/lustre-release
Branch: b2_9
Current Patch Set: 1
Commit: 3db1d6171732665b5b99e47899cc5a1edd63901d
|
|
Will work on getting dump uploaded
|
|
after cfs_fail_loc 718 is set:
/scratch/dumps/wolf-4.wolf.hpdd.intel.com/10.8.1.4-2017-04-20-16:21:36/
|
|
with patchset 2
Dump is on wolf: /scratch/dumps/wolf-3.wolf.hpdd.intel.com/10.8.1.3-2017-04-20-22:07:48/
|
|
second hit with patchset 2
/scratch/dumps/wolf-3.wolf.hpdd.intel.com/10.8.1.3-2017-04-20-22:27:43
|
|
first hit with patchset 4
Dump is at: /scratch/dumps/wolf-3.wolf.hpdd.intel.com/10.8.1.3-2017-04-21-01:49:25/
|
|
second hit with patchset4
Dump is in /scratch/dumps/wolf-3.wolf.hpdd.intel.com/10.8.1.3-2017-04-21-01:55:40/
SPL
module/spl/spl-kmem-cache.c:1439).
1434 * Allocate an object from the per-cpu magazine, or if the magazine
1435 * is empty directly allocate from a slab and repopulate the magazine.
1436 */
1437 void *
1438 spl_kmem_cache_alloc(spl_kmem_cache_t *skc, int flags)
1439 {
1440 spl_kmem_magazine_t *skm;
1441 void *obj = NULL;
1442
1443 ASSERT0(flags & ~KM_PUBLIC_MASK);
ZFS
module/zfs/zio.c:287).
279 /*
280 * Use zio_data_buf_alloc to allocate data. The data will not appear in a
281 * crashdump if the kernel panics. This exists so that we will limit the amount
282 * of ZFS data that shows up in a kernel crashdump. (Thus reducing the amount
283 * of kernel heap dumped to disk when the kernel panics)
284 */
285 void *
286 zio_data_buf_alloc(size_t size)
287 {
288 size_t c = (size - 1) >> SPA_MINBLOCKSHIFT;
289
290 VERIFY3U(c, <, SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT);
291
292 return (kmem_cache_alloc(zio_data_buf_cache[c], KM_PUSHPAGE));
293
abd_alloc_linear+0xac/0xf0
abd_alloc+0x30c/0x470
arc_hdr_alloc_pabd+0x6e/0x110
arc_hdr_alloc+0xbc/0x120
arc_loan_buf+0x23/0x30 module/zfs/arc.c:2441).
2433 /*
2434 * Loan out an anonymous arc buffer. Loaned buffers are not counted as in
2435 * flight data by arc_tempreserve_space() until they are "returned". Loaned
2436 * buffers must be returned to the arc before they can be used by the DMU or
2437 * freed.
2438 */
2439 arc_buf_t *
2440 arc_loan_buf(spa_t *spa, boolean_t is_metadata, int size)
2441
{
2442 ▸ arc_buf_t *buf = arc_alloc_buf(spa, arc_onloan_tag,
2443 ▸ is_metadata ? ARC_BUFC_METADATA : ARC_BUFC_DATA, size);
2444
2445 ▸ atomic_add_64(&arc_loaned_bytes, size);
2446 ▸ return (buf);
2447 }
2448
2449 arc_buf_t *
2450 arc_loan_compressed_buf(spa_t *spa, uint64_t psize, uint64_t lsize,
2451 enum zio_compress compression_type)
2452
{
2453 ▸ arc_buf_t *buf = arc_alloc_compressed_buf(spa, arc_onloan_tag,
2454 ▸ psize, lsize, compression_type);
2455
2456 ▸ atomic_add_64(&arc_loaned_bytes, psize);
2457 ▸ return (buf);
2558 }
dmu_request_arcbuf+0x1a/0x20 module/zfs/dmu.c:1379).
1374 /*
1375 * Allocate a loaned anonymous arc buffer.
1376 */
1377 arc_buf_t *
1378 dmu_request_arcbuf(dmu_buf_t *handle, int size)
1379
{
1380 dmu_buf_impl_t *db = (dmu_buf_impl_t *)handle;
1381
1382 return (arc_loan_buf(db->db_objset->os_spa, B_FALSE, size));
1383 }
osd
lustre/osd-zfs/osd_io.c:498).
493 }
494
495 static int osd_bufs_get(const struct lu_env *env, struct dt_object *dt,
496 loff_t offset, ssize_t len, struct niobuf_local *lnb,
497 int rw)
498 {
499 struct osd_object *obj = osd_dt_obj(dt);
500 int rc;
501
502 LASSERT(dt_object_exists(dt));
|
|
dump 3 from patchset 4
/scratch/dumps/wolf-3.wolf.hpdd.intel.com/10.8.1.3-2017-04-21-02:01:36/
|
|
it turned out the block size of the file in question is only 128KB.
The page table was overwritten by other thread
{
{noformat}
crash> rd -64 0xffff881ffc24e000 64
ffff881ffc24e000: 3534333231303635 3635343332313036 5601234560123456
ffff881ffc24e010: 3036353433323130 3130363534333231 0123456012345601
ffff881ffc24e020: 3231303635343332 3332313036353433 2345601234560123
ffff881ffc24e030: 3433323130363534 3534333231303635 4560123456012345
ffff881ffc24e040: 3635343332313036 3036353433323130 6012345601234560
ffff881ffc24e050: 3130363534333231 3231303635343332 1234560123456012
ffff881ffc24e060: 3332313036353433 3433323130363534 3456012345601234
even before this thread started to do RDMA transfer.
I also checked the local_nb and bulk descriptor and they all look good.
|
|
Jinshan Xiong (jinshan.xiong@intel.com) uploaded a new patch: https://review.whamcloud.com/26784
Subject: LU-9305 target: debug patch for memory problem
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 8be516a5a091c108a2e7b8e57cff5cc7933d2381
|
|
After debug kernel is loaded, the kernel crashed differently:
and this:
I suspect that there are something with avl tree in ZFS.
|
|
Attached are some old patches against old versions of Lustre, SPL, and the kernel that were used for debugging similar issues in the past. They originate from https://bugzilla.lustre.org/show_bug.cgi?id=22471 for the backstory, if interested.
|
|
Jinshan Xiong (jinshan.xiong@intel.com) uploaded a new patch: https://review.whamcloud.com/26895
Subject: LU-9305 osd-zfs: set minimum block size to (PAGE_SIZE << 2)
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 46010a8b21c9b542094086bc48759fcafcd4b2ff
|
|
With patch https://review.whamcloud.com/26895 or https://github.com/zfsonlinux/zfs/pull/6084 applied, there is no memory corruption problem any more. However, there are still BAD WRITE CHECKSUM problem I discovered there are known problem with kernel crypto framework, where it could cause out-of-bound access. At least I have seen it twice as follows:
I turned on page allocation debug so it crashed kernel when this occurred. Otherwise it would just include wrong data in checksum computation. Another occurrence is:
This matches the bug description at https://www.spinics.net/lists/linux-crypto/msg22859.html and the corresponding redhat bug is https://bugzilla.redhat.com/show_bug.cgi?id=1399754 but unfortunately I don't have permission to look into the detail.
I tend to think this is a kernel BUG and this piece of code has been changed in rh 7.3 kernels. I also exercised the same code on centos 7.3 and didn't see the issue, so I would recommend to upgrade our distro to 7.3.
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/26895/
Subject: LU-9305 osd-zfs: arc_buf could be non-pagesize aligned
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 3800d05641158608e5a139336c00a781fa9fb8c7
|
|
Landed for 2.10
|
|
We have moved to Centos 7.3 and rebased our ZFS patches on 0.4.0 which contains Jinshan's zfs fix for this issue. However, we still see this issue while running with large RPCs, large blocks:
[ 3874.558287] LustreError: 168-f: BAD WRITE CHECKSUM: lsdraid-OST0000 from 12345-192.168.1.6@o2ib inode [0x200000409:0x1cb7:0x0] object 0x0:1972 extent [33554432-40140799]: client csum aa4dd555, server csum 7aa8a961
[ 4251.083446] perf: interrupt took too long (5080 > 4966), lowering kernel.perf_event_max_sample_rate to 39000
[ 5708.667871] perf: interrupt took too long (6430 > 6350), lowering kernel.perf_event_max_sample_rate to 31000
[ 7819.451501] perf: interrupt took too long (8170 > 8037), lowering kernel.perf_event_max_sample_rate to 24000
[ 8255.183667] BUG: Bad page state in process ll_ost_io01_020 pfn:1e50eea
[ 8255.192884] page:ffffea007943ba80 count:-1 mapcount:0 mapping: (null) index:0x0
[ 8255.203581] page flags: 0x6fffff00000000()
[ 8255.209724] page dumped because: nonzero _count
[ 8255.216322] Modules linked in: osp(OE) ofd(OE) lfsck(OE) ost(OE) mgc(OE) osd_zfs(OE) lquota(OE) fid(OE) fld(OE) ko2iblnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE) libcfs(OE) rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache rpcrdma ib_isert iscsi_target_mod ib_iser libiscsi scsi_transport_iscsi ib_srpt target_core_mod ib_srp scsi_transport_srp scsi_tgt ib_ipoib rdma_ucm ib_ucm ib_uverbs ib_umad rdma_cm ib_cm iw_cm mlx4_ib ib_core zfs(POE) zunicode(POE) zavl(POE) icp(POE) zcommon(POE) znvpair(POE) spl(OE) zlib_deflate dm_service_time ses enclosure intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel kvm irqbypass crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd mpt3sas raid_class scsi_transport_sas iTCO_wdt ipmi_devintf ipmi_ssif iTCO_vendor_support ipmi_si sg ipmi_msghandler
[ 8255.305720] mei_me sb_edac mei wmi shpchp lpc_ich edac_core ioatdma i2c_i801 acpi_pad acpi_power_meter pcspkr nfsd dm_multipath dm_mod nfs_acl lockd binfmt_misc grace auth_rpcgss sunrpc ip_tables ext4 mbcache jbd2 mlx4_en sd_mod crc_t10dif crct10dif_generic mgag200 drm_kms_helper syscopyarea sysfillrect sysimgblt igb fb_sys_fops crct10dif_pclmul ttm crct10dif_common ptp crc32c_intel ahci pps_core drm mlx4_core libahci dca i2c_algo_bit libata i2c_core devlink fjes
[ 8255.356725] CPU: 23 PID: 9463 Comm: ll_ost_io01_020 Tainted: P IOE ------------ 3.10.0-514.16.1.el7.x86_64 #1
[ 8255.370500] Hardware name: Intel Corporation S2600WT2/S2600WT2, BIOS SE5C610.86B.01.01.0008.021120151325 02/11/2015
[ 8255.383755] ffffea007943ba80 00000000b9135f7a ffff881ed71f7910 ffffffff81686ac3
[ 8255.393696] ffff881ed71f7938 ffffffff81681cf8 ffffea007943ba80 0000000000000000
[ 8255.403640] 000fffff00000000 ffff881ed71f7980 ffffffff811893dd fff00000fe000000
[ 8255.413528] Call Trace:
[ 8255.417780] [<ffffffff81686ac3>] dump_stack+0x19/0x1b
[ 8255.425063] [<ffffffff81681cf8>] bad_page.part.75+0xdf/0xfc
[ 8255.432845] [<ffffffff811893dd>] free_pages_prepare+0x16d/0x190
[ 8255.441047] [<ffffffff81189e54>] free_hot_cold_page+0x74/0x160
[ 8255.449077] [<ffffffff8118a005>] __free_pages+0x25/0x30
[ 8255.456423] [<ffffffffa0d80373>] osd_bufs_put+0x123/0x1f0 [osd_zfs]
[ 8255.464931] [<ffffffffa0e074ea>] ofd_commitrw_write+0xea/0x1c80 [ofd]
[ 8255.473594] [<ffffffffa0e0bc3f>] ofd_commitrw+0x4af/0xa80 [ofd]
[ 8255.481667] [<ffffffffa0b44589>] ? lprocfs_counter_add+0xf9/0x160 [obdclass]
[ 8255.491039] [<ffffffffa127057c>] obd_commitrw+0x2ed/0x330 [ptlrpc]
[ 8255.499374] [<ffffffffa1244290>] tgt_brw_write+0x1010/0x1700 [ptlrpc]
[ 8255.508017] [<ffffffff810ce474>] ? update_curr+0x104/0x190
[ 8255.515546] [<ffffffff810c9ba8>] ? __enqueue_entity+0x78/0x80
[ 8255.523505] [<ffffffffa11968a0>] ? target_send_reply_msg+0x170/0x170 [ptlrpc]
[ 8255.532921] [<ffffffffa1240615>] tgt_request_handle+0x915/0x1320 [ptlrpc]
[ 8255.541949] [<ffffffffa11e8eab>] ptlrpc_server_handle_request+0x21b/0xa90 [ptlrpc]
[ 8255.551821] [<ffffffffa09f89a8>] ? lc_watchdog_touch+0x68/0x180 [libcfs]
[ 8255.560938] [<ffffffffa11e6a58>] ? ptlrpc_wait_event+0x98/0x340 [ptlrpc]
[ 8255.569835] [<ffffffff810c54d2>] ? default_wake_function+0x12/0x20
[ 8255.578105] [<ffffffff810ba628>] ? __wake_up_common+0x58/0x90
[ 8255.585892] [<ffffffffa11eced0>] ptlrpc_main+0xaa0/0x1de0 [ptlrpc]
[ 8255.594199] [<ffffffffa11ec430>] ? ptlrpc_register_service+0xe60/0xe60 [ptlrpc]
[ 8255.603645] [<ffffffff810b0a4f>] kthread+0xcf/0xe0
[ 8255.610217] [<ffffffff810b0980>] ? kthread_create_on_node+0x140/0x140
[ 8255.618602] [<ffffffff816970d8>] ret_from_fork+0x58/0x90
[ 8255.625702] [<ffffffff810b0980>] ? kthread_create_on_node+0x140/0x140
[ 8264.352388] LustreError: 168-f: BAD WRITE CHECKSUM: lsdraid-OST0000 from 12345-192.168.1.8@o2ib inode [0x20000040b:0x30e:0x0] object 0x0:7751 extent [83886080-91357183]: client csum a25342f0, server csum ec458710
We have verified we see this on: draid pools, raidz pools, 16MB blocks, 4MB blocks.
|
|
This is unfortunate. And the symptom looks exactly as before. Let me take a look.
|
|
After I loaded a debug kernel, I'm seeing the same issue in the crypto framework as follows:
I can confirm that this issue is not yet fixed in reel 7.3 kernel.
|
|
There is nothing we can do but disable checksum at this moment
|
|
Is there danger of bad data being written to disk if we disable checksums?
I suppose that could allow us to test some other Lustre things.
|
|
With checksum disabled, the server can no longer detect data corruption. However, it can allow us to do perform tests.
I have disabled PAGEALLOC debug and see if I can discover new issues.
|
|
Can we apply a patch from the upstream kernel to RHEL to verify that this problem is fixed?
If an upstream patch fixes the problem for us, we can still apply the patch to our Lustre kernels, and also request RH to include the fix into their RHEL kernels.
|
|
We can – which patch did you have in mind?
|
|
Somehow this issue is hardly to be reproduced.
A new backtrace was seen today:
I have enabled PAGEALLOC debug so this backtrace clearly shows the page was somehow freed in dmu_write(). I have disabled checksum.
|
|
You hit this after checksums were disabled?
|
|
Yes.
|
|
So where in the dmu_write there is a mem copy that trips across this how many of those are there? I don't see a dump is that still having issues?
zfs dmu_write_impl -> module/zfs/dmu.c:974).
969 }
970
971 static void
972 dmu_write_impl(dmu_buf_t **dbp, int numbufs, uint64_t offset, uint64_t size,
973 const void *buf, dmu_tx_t *tx)
974 {
975 int i;
976
977 for (i = 0; i < numbufs; i++) {
978 uint64_t tocpy;
zfs dmu_write -> module/zfs/dmu.c:1006).
1001 buf = (char *)buf + tocpy;
1002 }
1003 }
1004
1005 void
1006 dmu_write(objset_t *os, uint64_t object, uint64_t offset, uint64_t size,
1007 const void *buf, dmu_tx_t *tx)
1008 {
1009 dmu_buf_t **dbp;
1010 int numbufs;
osd_zfs osd_write_commit -> lustre/osd-zfs/osd_io.c:762).
757 }
758
759 static int osd_write_commit(const struct lu_env *env, struct dt_object *dt,
760 struct niobuf_local *lnb, int npages,
761 struct thandle *th)
762 {
763 struct osd_object *obj = osd_dt_obj(dt);
764 struct osd_device *osd = osd_obj2dev(obj);
765 struct osd_thandle *oh;
766 uint64_t new_size = 0;
ofd_commitrw -> lustre/ofd/ofd_io.c:1190).
1185 */
1186 int ofd_commitrw(const struct lu_env *env, int cmd, struct obd_export *exp,
1187 struct obdo *oa, int objcount, struct obd_ioobj *obj,
1188 struct niobuf_remote *rnb, int npages,
1189 struct niobuf_local *lnb, int old_rc)
1190 {
1191 struct ofd_thread_info *info = ofd_info(env);
1192 struct ofd_mod_data *fmd;
1193 __u64 valid;
1194 struct ofd_device *ofd = ofd_exp(exp);
|
|
It's in dmu_write_impl() at line 994.
989 if (tocpy == db->db_size)
990 dmu_buf_will_fill(db, tx);
991 else
992 dmu_buf_will_dirty(db, tx);
993
994 (void) memcpy((char *)db->db_data + bufoff, buf, tocpy);
995
996 if (tocpy == db->db_size)
997 dmu_buf_fill_done(db, tx);
By analyzing registers and stack, ffff8814eef5a000 was the value of buf, and the size is 4096 that one page size.
|
|
Jinshan reports that he is not able to reproduce this bug with a debug kernel.
John, is this something that you can still reproduce?
|
|
Per John is this failing on every run without debug kernel enabled.
John will try to reproduce with a debug kernel. John, do you need anything from us to do that?
|
|
Where is the debug kernel?
|
|
Is this a Lustre issue, or an issue with the coral patches? It's very hard to understand from the comments here.
John, could you please edit the issue description to include the kernel version, Lustre version, ZFS version, and any patches applied?
|
|
This is an issue with Lustre when running with ZFS. It is probably worth your time to go read the other bugs mentioned so you can get a sense of the work that has been done on this bug and various software combinations and configurations that have been tried.
We have tracked this bug back at least as far as Lustre 2.7-current master. My theory is that it has been their since the very beginning if when we started using ZFS.
It has noting to do with CORAL patches it fails with vanilla ZFS On Linux + Lustre (any version we have tried). It is easy to reproduce and their are several known ways to reproduce it – one of them attached in this bug. I have never been able to run a system configure as it would be for CORAL without hitting this for me it it fails 100% of the time, every run and complete blocks my Lustre testing.
I have multiple dumps from last night if it would be helpful I can attach those as well. Jinshan has done the most work no this bug have you talked to him?
|
|
I updated the env. field with some version information.
|
|
Nathaniel Clark (nathaniel.l.clark@intel.com) uploaded a new patch: https://review.whamcloud.com/27568
Subject: LU-9305 tests: Run Reproducer
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 161e89a5b5de1f231bc73c84ae6a10095af61495
|
|
The symptom of this issue is that the pages allocated from osd_bufs_get_write() by alloc_page(OSD_GFP_IO) were somehow freed so that the attempt to access this page later will trigger checksum error or kernel crash(when page alloc debug is enabled).
It's easier to observe this issue by enabling DEBUG_PAGEALLOC. It doesn't help by enabling KASAN that implies it's not caused by buffer overflow or access memory after free.
I also ran the test script with DEBUG_VM because I would expect to catch the problem that the pages are double freed. It didn't help either.
|
|
After KASAN is enabled I can no longer reproduce the issue with the same test script. I guess this is because it makes everything slower.
I suspect that there would exist race in kernel page allocator that caused pages are reallocated before they are really freed.
|
|
I've got an idea to load a 4.11 vanilla kernel w/o KASAN enabled and see if we can still see this issue.
|
|
I saw LU-9305 with ZFS 0.7.0-rc4 and master, but with this breakdown:
| ZFS Record Size |
ZPOOL Record Size |
brw_size |
|
BAD WRITE CHECKSUM |
|
| 16M |
128K |
16 |
|
YES |
|
| 8M |
8M |
8 |
|
NO |
|
| 16M |
16M |
16 |
|
NO |
|
I have hit a crash, but it appears to be identical to LU-6649.
|
|
Reproducer caused issue at 4MB: https://testing.hpdd.intel.com/test_sets/24865c18-507f-11e7-a743-5254006e85c2
This is with stock ZFS 0.7.0-rc4 and Lustre master
OST1/2 console log:
EDIT: I've uploaded a new version of reproducer that will run with stock settings prior to setting up large blocks
|
|
Has anyone been able to reproduce this problem with ZFS 0.6.5 and/or 1MB recordsize? If it always requires larger than 1MB recordsize, then my understanding is that this requires a custom ZFS build to enable, so it isn't something that could be hit during normal usage.
|
|
We have produced with ZFS 0.6.5.7 not sure about 0.6.5. My test case did not reproduce on 1MB record size. Only 2,4,8,16. We debated on if this because it actually works with 1MB or it just takes forever and a day to see it at that record size.
No, there is no special ZFS build for recent ZFS builds for large record sizes (up to 16MB is supported out of the box).
|
|
Wei Liu (wei3.liu@intel.com) uploaded a new patch: https://review.whamcloud.com/27693
Subject: LU-9305 tests: Run Reproducer
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: e2ae8c3f2d95a154336a3e9e96e0070ff16a7983
|
|
The above patch is the reproducer based on current zfs version which master is using (zfs-0.6.5.9-1.el7.x86_64)
|
|
any success on reproducing this with very few (ideally 1) clients?
|
|
I could not reproduce with a client that was on the OSS node – however, with 1 client and 1 sos is reproduces easily.
|
|
I've reproduced this with 4 clients with records size of 4MB (retesting with 1 client):
https://testing.hpdd.intel.com/test_sets/4ff95cfc-56be-11e7-9221-5254006e85c2
OST3,OST4 console:
|
|
I think it makes sesne to try the following scenarios:
1) fixed blocksize
a) I/O match blocksize
b) I/O don't match blocksize
2) growing blocksize
a) I/O match blocksize
b) I/O don't match blocksize
hopefully we'll be able to nail it down to 0-copy or copy IO.
|
|
One thought I had (though I haven't done any investigation on it) is if recordsize > RPC size and/or DLM lock size, then it is possible that multiple OSS threads are modifying the same ZFS block at one time. Do we have protections in place to avoid this? With ldiskfs, the underlying blocksize is always smaller than the RPC and DLM lock size.
|
|
well, if it was just a rewrite, then no any kind of issues with page structures could happen?
also, if this is a pure ZFS issues, then I'd expect to reproduce it with obdfilter-survey?
|
|
Reproduced with 16M recordsize on 0.6.5.9
https://testing.hpdd.intel.com/test_sets/26671780-56e1-11e7-a749-5254006e85c2
|
|
This doesn't seem to reproduce with single client (several runs - no reproduction, still trying though). But the multi-client tests don't write to the same files. They all write to separate files in the same directory. So there shouldn't be multiple writes coming into the same block, unless the blocks from single clients aren't aligned? But then single client should be able to cause error...
|
|
Alex Zhuravlev (alexey.zhuravlev@intel.com) uploaded a new patch: https://review.whamcloud.com/27785
Subject: LU-9305 tests: Run Reproducer
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 5226fcc3fa788615bebd2eab204d25c1fcc9bc07
|
|
the patch above will be trying to reproduce with a fixed (big) blocksize.
|
|
Nathaniel, even a single client will have multiple RPCs in flight at one time. If the client RPC size is below the ZFS recordsize, then it is possible that multiple threads are processing IO for the same block. It should be possible to record (at least) the DLMTRACE and RPCTRACE messages in the Lustre debug log (possibly using "lctl debug_daemon" if this takes a while to be hit and the logs are large), and then after the bad checksum message is hit go back through the logs to find what threads are accessing that object.
That said, given that there is also list_head corruption hit at the same time, this looks more like memory corruption (e.g. use after free) than a Lustre-level problem, unless there is some kind of bug in the BAD WRITE CHECKSUM handling that is causing the list_head corruption.
|
|
I have tried most of the ideas above well it won't lose by doing it one more time.
I have ever loaded 4.11 kernel with KASAN enabled and I could no longer reproduce the problem. So I have an idea to try vanilla 4.11 kernel and see how it goes.
I have talked with John S. about the idea but unfortunately he has no time to perform it.
|
|
Now that the CORAL team is past their customer demo, it makes sense that John would reproduce this problem on one of his test systems and work with Alex and Jinshan to debug there.
|
|
is it possible to get a dumped log from autotest/maloo ?
|
|
Alex, for your patch #27785, Maloo only has console and test log since tests passed. I think autotest only collects debug/dmesg etc when test fails. Is that what you need?
|
|
well, I have this line in the logs:
12:20:31:[11737.507659] LustreError: dumping log to /tmp/lustre-log.1498220428.13468
and the test failed with TIMEOUT (as OST crashed)
is it possible to get /tmp/lustre-log.1498220428.13468 ?
|
|
unfortunately I can't reproduce this locally. so it becomes vital to access dumped logs.
|
|
Alex
I suggest that you connect with John Salinas and see if you can get direct access to the system that he can 100% reporoduce this on
Peter
|
|
sure, it's great to access that system. but having debugging logs is still useful, IMO. as we can do many tests concurrently, trying diffferent ideas, etc. and for sure this is not the last situation when that can help.
|
|
hi Alex, can you please point to me which link/logs do you refer to?
|
|
for example: https://testing.hpdd.intel.com/test_sessions/1bf95369-a387-4d1e-bdb3-51f394f95749
trevis-36vm4 dumped a lustre log:
12:20:31:[11737.507659] LustreError: dumping log to /tmp/lustre-log.1498220428.13468
|
|
Alex, please go to trevis and check the following dir, hope it has what you are looking for
When a autotest node crashes, the core dump location will be in /scratch/dumps/<hostname>
|
|
thanks. did you upload those files or autotest did automatically?
|
|
it is automatically generated if a node crashes. please refer to https://wiki.hpdd.intel.com/display/TEI/Core+dump+location+for+autotest+nodes
|
|
I added few CDEBUG() and BUG() in tgt_warn_on_cksum() ..
00080000:00080000:1.0:1498681682.290436:0:13445:0:(osd_io.c:541:osd_bufs_get()) pages: ffffea00003ac3c0/4096@12582912
00000020:00080000:1.0:1498681682.363189:0:13445:0:(tgt_handler.c:2121:tgt_warn_on_cksum()) pages: ffffea00003ac3c0/4096@12582912
00080000:00080000:0.0:1498681682.396783:0:14108:0:(osd_io.c:541:osd_bufs_get()) pages: ffffea00003ac3c0/4096@20086784
so tgt_warn_on_cksum in thread 13445 did hit BUG and couldn't proceed to osd_bufs_put() to release page ffffea00003ac3c0 - in theory. but thread 14108 was able to get this page few cycles after.
|
|
Alex:
That's a good finding. What would be the next step?
|
|
may I ask to run https://review.whamcloud.com/27913 on a real iron, please?
I'm not sure about the real sequence, but my theory is that osd_bufs_put() may try to release pages already released by dmu_assign_arcbuf() when blocksize mismatch.
|
|
wolf cluster should be available to use. Do you have access to wolf?
|
|
No, i'm not familiar with wolf cluster.
|
|
Alex Zhuravlev (alexey.zhuravlev@intel.com) uploaded a new patch: https://review.whamcloud.com/27950
Subject: LU-9305 osd: do not release pages twice
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 12d3b3dcfbc17fc201dc9de463720e3a3a994f49
|
|
with https://review.whamcloud.com/27950 I can't reproduce the issue.
|
|
This is indeed a race condition. I wonder why I couldn't catch the race by enabling VM_BUG_ON_PAGE() in put_page_testzero().
|
|
The patch should be able to fix the problem - I have run the patched lustre for several hours w/o hitting the problem. Without the patch it died quickly.
|
|
Jinshan, thanks for testing.
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/27950/
Subject: LU-9305 osd: do not release pages twice
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 6d039389735c52f965505643de9d8e4772e3f87f
|
|
Do we think that this bug is inherently to blame for the "Error -14" / put_page crash that I see referenced in a couple of the comments?
19:00:33:[ 2346.715685] LNetError: 6844:0:(socklnd_cb.c:1149:ksocknal_process_receive()) [ffff880061190000] Error -14 on read from 12345-10.9.4.124@tcp ip 10.9.4.124:1021
19:00:33:[ 2346.766822] CPU: 1 PID: 6842 Comm: socknal_reaper Tainted: P OE ------------ 3.10.0-514.21.1.el7_lustre.x86_64 #1
19:00:33:[ 2346.766822] RIP: 0010:[<ffffffff8118edaa>] [<ffffffff8118edaa>] put_page+0xa/0x60
(I give up trying to get it to format correctly)
?
We've hit this crash about 20 times in the past month in normal production use (ZFS 0.7.1-1 / Lustre 2.9.51_45_g3b3eeeb), but generally without a "BAD WRITE CHECKSUM" error anywhere in sight.
|
|
Hi Phil,
The problem discovered in this ticket is about memory corruption, so I wouldn't be surprised if the symptom is related to this bug. Please go ahead and try the patch and see how it goes.
|
|
Thanks, Jinshan! After another 20x crashes yesterday, we installed the patch about 12 hours ago. So far so good.
|
Generated at Sat Feb 10 02:25:00 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
BasicLibs.py
Linux_x64_Memory_Address_Mapping.pdf
debug_vmalloc.patch