Uploaded image for project: 'Lustre'
  1. Lustre
  2. LU-13765

ldiskfs_mb_mark_diskspace_used:3472: aborting transaction: error 28 in __ldiskfs_handle_dirty_metadata

    Details

    • Type: Bug
    • Status: Open
    • Priority: Critical
    • Resolution: Unresolved
    • Affects Version/s: Lustre 2.14.0
    • Fix Version/s: Lustre 2.14.0
    • Labels:
      None
    • Environment:
      master (commit f3c95bb)
    • Severity:
      2
    • Rank (Obsolete):
      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
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                arshad512 Arshad Hussain
                Reporter:
                sihara Shuichi Ihara
              • Votes:
                0 Vote for this issue
                Watchers:
                8 Start watching this issue

                Dates

                • Created:
                  Updated: