Details
-
Bug
-
Resolution: Fixed
-
Critical
-
Lustre 2.14.0
-
None
-
master (commit f3c95bb)
-
2
-
9223372036854775807
Description
OSS showed the following traces and remounted OSTs with readonly if client calls fallocate().
Jul 8 23:44:21 es400nv-vm1 kernel: ------------[ cut here ]------------ Jul 8 23:44:21 es400nv-vm1 kernel: WARNING: CPU: 0 PID: 6870 at /tmp/rpmbuild-lustre-root-DUtheNY7/BUILD/lustre-2.13.54_60_gf3c95bb/ldiskfs/ext4_jbd2.c:266 __ldiskfs_handle_dirty_metadata+0x1c2/0x220 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: Modules linked in: ofd(OE) ost(OE) osp(OE) mdd(OE) lod(OE) mdt(OE) lfsck(OE) mgs(OE) mgc(OE) osd_ldiskfs(OE) lquota(OE) ldiskfs(OE) ksocklnd(OE) lustre(OE) lmv(OE) mdc(OE) osc(OE) lov(OE) fid(OE) fld(OE) ko2iblnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE) libcfs(OE) rdma_ucm(OE) ib_ucm(OE) rdma_cm(OE) iw_cm(OE) ib_ipoib(OE) ib_cm(OE) ib_umad(OE) mlx5_ib(OE) mlx4_en(OE) mlx4_ib(OE) ib_uverbs(OE) ib_core(OE) mlx4_core(OE) sunrpc iTCO_wdt ppdev iTCO_vendor_support nfit libnvdimm iosf_mbi crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd pcspkr i2c_i801 joydev parport_pc lpc_ich sg parport i6300esb ip_tables ext4 mbcache jbd2 sr_mod sd_mod cdrom crc_t10dif crct10dif_generic bochs_drm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm virtio_net Jul 8 23:44:21 es400nv-vm1 kernel: virtio_blk virtio_scsi(OE) ahci drm libahci mlx5_core(OE) libata crct10dif_pclmul crct10dif_common mlxfw(OE) ptp crc32c_intel iavf pps_core virtio_pci devlink serio_raw virtio_ring mlx_compat(OE) virtio drm_panel_orientation_quirks dm_mirror dm_region_hash dm_log dm_mod Jul 8 23:44:21 es400nv-vm1 kernel: CPU: 0 PID: 6870 Comm: ll_ost00_000 Kdump: loaded Tainted: G OE ------------ T 3.10.0-1062.1.1.el7_lustre.ddn3.x86_64 #1 Jul 8 23:44:21 es400nv-vm1 kernel: Hardware name: DDN SFA400NVXE, BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014 Jul 8 23:44:21 es400nv-vm1 kernel: Call Trace: Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb57792c2>] dump_stack+0x19/0x1b Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb509a878>] __warn+0xd8/0x100 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb509a9bd>] warn_slowpath_null+0x1d/0x20 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc107c5b2>] __ldiskfs_handle_dirty_metadata+0x1c2/0x220 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc108b88b>] ldiskfs_mb_mark_diskspace_used+0x2bb/0x510 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc108fb10>] ldiskfs_mb_new_blocks+0x350/0xb20 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc10932e5>] ? __read_extent_tree_block+0x55/0x1e0 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb522454b>] ? __kmalloc+0x1eb/0x230 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc1094d44>] ? ldiskfs_ext_find_extent+0x134/0x340 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc10987b6>] ldiskfs_ext_map_blocks+0x4a6/0xf60 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb5287fff>] ? bdev_evict_inode+0x8f/0xc0 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc105c53c>] ldiskfs_map_blocks+0x12c/0x6a0 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc109382c>] ? ldiskfs_alloc_file_blocks.isra.36+0xbc/0x310 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc109384f>] ldiskfs_alloc_file_blocks.isra.36+0xdf/0x310 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc109ac8d>] ldiskfs_fallocate+0x85d/0x8f0 [ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb52b74da>] ? __dquot_initialize+0x3a/0x240 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc02fba93>] ? jbd2__journal_start+0xf3/0x1f0 [jbd2] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc1179ac3>] osd_fallocate+0x243/0x530 [osd_ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc115beb5>] ? osd_trans_start+0x235/0x4e0 [osd_ldiskfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc1562077>] ofd_object_fallocate+0x5a7/0x810 [ofd] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc154d196>] ofd_fallocate_hdl+0x236/0x960 [ofd] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0bf35af>] ? lustre_pack_reply_flags+0x6f/0x1e0 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0c5ecda>] tgt_request_handle+0x96a/0x1640 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0c36111>] ? ptlrpc_nrs_req_get_nolock0+0xd1/0x170 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc07c902e>] ? ktime_get_real_seconds+0xe/0x10 [libcfs] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0c002c6>] ptlrpc_server_handle_request+0x256/0xb10 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50d20a0>] ? task_rq_unlock+0x20/0x20 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50d2643>] ? __wake_up+0x13/0x20 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0c047f4>] ptlrpc_main+0xbb4/0x1550 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50d3efe>] ? finish_task_switch+0x4e/0x1c0 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffc0c03c40>] ? ptlrpc_register_service+0xf90/0xf90 [ptlrpc] Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50c50d1>] kthread+0xd1/0xe0 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50c5000>] ? insert_kthread_work+0x40/0x40 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb578cd1d>] ret_from_fork_nospec_begin+0x7/0x21 Jul 8 23:44:21 es400nv-vm1 kernel: [<ffffffffb50c5000>] ? insert_kthread_work+0x40/0x40 Jul 8 23:44:21 es400nv-vm1 kernel: ---[ end trace a9da39c17d13d034 ]--- Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs: ldiskfs_mb_mark_diskspace_used:3472: aborting transaction: error 28 in __ldiskfs_handle_dirty_metadata Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS: jbd2_journal_dirty_metadata failed: handle type 0 started at line 1914, credits 41/0, errcode -28 Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs warning (device sdf): ldiskfs_mb_new_blocks:5099: Updating bitmap error: [err -28] [pa ffff8aed20b08068] [phy 1572864] [logic 1277952] [len 32768] [free 32768] [error 1] [inode 115] Jul 8 23:44:21 es400nv-vm1 kernel: Quota error (device sdf): qtree_write_dquot: dquota write failed Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdf) in ldiskfs_write_dquot:5561: error 28 Jul 8 23:44:21 es400nv-vm1 kernel: Aborting journal on device sdf-8. Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs (sdf): Remounting filesystem read-only Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdf) in ldiskfs_reserve_inode_write:5332: Journal has aborted Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdf) in ldiskfs_alloc_file_blocks:4773: error 28 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_internal.h:1237:osd_trans_exec_op()) ai400-OST0000: opcode 7: before 0 < left 8, rollback = 7 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_handler.c:1809:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_handler.c:1816:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/15/0 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_handler.c:1826:osd_trans_dump_creds()) write: 1/8/0, punch: 0/0/0, quota 3/3/0 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_handler.c:1833:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 Jul 8 23:44:21 es400nv-vm1 kernel: Lustre: 6870:0:(osd_handler.c:1840:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 Jul 8 23:44:21 es400nv-vm1 kernel: LustreError: 6870:0:(osd_io.c:1785:osd_ldiskfs_write_record()) journal_get_write_access() returned error -30 Jul 8 23:44:21 es400nv-vm1 kernel: LustreError: 6870:0:(osd_handler.c:2017:osd_trans_stop()) ai400-OST0000: failed in transaction hook: rc = -30 Jul 8 23:44:21 es400nv-vm1 kernel: LustreError: 6864:0:(osd_handler.c:1723:osd_trans_commit_cb()) transaction @0xffff8af8613a8300 commit error: 2 Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdf) in osd_trans_stop:2024: error 28 Jul 8 23:44:21 es400nv-vm1 kernel: LustreError: 6870:0:(osd_handler.c:2027:osd_trans_stop()) ai400-OST0000: failed to stop transaction: rc = -28 Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs: ldiskfs_mb_mark_diskspace_used:3472: aborting transaction: error 28 in __ldiskfs_handle_dirty_metadata Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS: jbd2_journal_dirty_metadata failed: handle type 0 started at line 1914, credits 41/0, errcode -28 Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs warning (device sdg): ldiskfs_mb_new_blocks:5099: Updating bitmap error: [err -28] [pa ffff8aee29932f70] [phy 4751360] [logic 1212416] [len 32768] [free 32768] [error 1] [inode 115] Jul 8 23:44:21 es400nv-vm1 kernel: Quota error (device sdg): qtree_write_dquot: dquota write failed Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdg) in ldiskfs_write_dquot:5561: error 28 Jul 8 23:44:21 es400nv-vm1 kernel: Aborting journal on device sdg-8. Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs (sdg): Remounting filesystem read-only Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdg) in ldiskfs_reserve_inode_write:5332: Journal has aborted Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdg) in ldiskfs_alloc_file_blocks:4773: error 28 Jul 8 23:44:21 es400nv-vm1 kernel: LDISKFS-fs error (device sdg) in osd_trans_stop:2024: error 28 Jul 8 23:44:24 es400nv-vm1 kernel: LDISKFS-fs warning (device sdf): kmmpd:186: kmmpd being stopped since filesystem has been remounted as readonly. Jul 8 23:44:24 es400nv-vm1 kernel: LDISKFS-fs warning (device sdg): kmmpd:186: kmmpd being stopped since filesystem has been remounted as readonly. Jul 8 23:44:25 es400nv-vm1 kernel: LustreError: 6874:0:(ofd_dev.c:1815:ofd_destroy_hdl()) ai400-OST0000: error destroying object [0x100000000:0x12:0x0]: -30 Jul 8 23:44:25 es400nv-vm1 kernel: LustreError: 6874:0:(ofd_dev.c:1815:ofd_destroy_hdl()) Skipped 31 previous similar messages Jul 8 23:44:46 es400nv-vm1 kernel: LustreError: 6870:0:(tgt_lastrcvd.c:1160:tgt_client_del()) ai400-OST0000: failed to update server data, skip client 9a3ea305-a278-48e5-87a1-1f3e457a205c zeroing, rc -30
Here is a reproducer. enabling fallocate with fio caused problem.
# fio --name=write --directory=/ai400/fio --rw=write --ioengine=libaio --bs=128K --numjobs=32 --filesize=200G --filename=test --time_based --runtime=100 --fallocate=1
