Details
-
Bug
-
Resolution: Fixed
-
Minor
-
Lustre 2.5.3
-
None
-
Centos 6.5
Linux 2.6.32-431.23.3.el6_lustre.x86_64
-
3
-
9223372036854775807
Description
We're having an issue with our mds crashing. This is after recovering from a full md filesystem. We've been deleting from storage to free up metadata space, but have run into these kernel panics.
dmesg logs have the following:
<2>LDISKFS-jfs error (device md0): ldiskfs_mb_check_ondisk_bitmap: on-disk bitmap for group 0corrupted: 57 blocks free in bitmap, 6 - in gd <4> <3>Aborting journal on device md0-8. <2>LDISKFS-fs error (device md0): ldiskfs_journal_start_sb: Detected aborted journal <2>LDISKFS-fs error (device md0) in iam_txn_add: Journal has aborted <2>LDISKFS-fs (md0): Remounting filesystem read-only <2>LDISKFS-fs (md0): Remounting filesystem read-only <3>LustreError: 6919:0:(osd_io.c:1173:osd_ldiskfs_write_record()) journal_get_write_access() returned error -30 <3>LustreError: 6919:0:(osd_handler.c:1054:osd_trans_stop()) Failure in transaction hook: -30 <3>LustreError: 6919:0:(osd_handler.c:1063:osd_trans_stop()) Failure to stop transaction: -30 <2>LDISKFS-fs error (device md0): ldiskfs_mb_new_blocks: Updating bitmap error: [err -30] [pa ffff8860350c8ba8] [phy 34992896] [logic 256] [len 256] [free 256] [error 1] [inode 1917] <3>LustreError: 8967:0:(osd_io.c:1166:osd_ldiskfs_write_record()) md0: error reading offset 2093056 (block 511): rc = -30 <3>LustreError: 8967:0:(llog_osd.c:156:llog_osd_write_blob()) echo-MDT0000-osd: error writing log record: rc = -30 <2>LDISKFS-fs error (device md0) in start_transaction: Journal has aborted <2>LDISKFS-fs error (device md0) in start_transaction: Journal has aborted <3>LustreError: 8967:0:(llog_cat.c:356:llog_cat_add_rec()) llog_write_rec -30: lh=ffff88601d1e4b40 <4> <3>LustreError: 5801:0:(osd_handler.c:863:osd_trans_commit_cb()) transaction @0xffff882945fc28c0 commit error: 2 <0>LustreError: 6145:0:(osp_sync.c:874:osp_sync_thread()) ASSERTION( rc == 0 || rc == LLOG_PROC_BREAK ) failed: 11 changes, 31 in progress, 0 in flight: -5 <0>LustreError: 6145:0:(osp_sync.c:874:osp_sync_thread()) LBUG <4>Pid: 6145, comm: osp-syn-98-0 <4> <4>Call Trace: <4> [<ffffffffa03b3895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs] <4> [<ffffffffa03b3e97>] lbug_with_loc+0x47/0xb0 [libcfs] <4> [<ffffffffa0eff2e3>] osp_sync_thread+0x753/0x7d0 [osp] <4> [<ffffffff81528df6>] ? schedule+0x176/0x3b0 <4> [<ffffffffa0efeb90>] ? osp_sync_thread+0x0/0x7d0 [osp] <4> [<ffffffff8109abf6>] kthread+0x96/0xa0 <4> [<ffffffff8100c20a>] child_rip+0xa/0x20 <4> [<ffffffff8109ab60>] ? kthread+0x0/0xa0 <4> [<ffffffff8100c200>] ? child_rip+0x0/0x20 <4> <3>LustreError: 6135:0:(llog.c:159:llog_cancel_rec()) echo-OST005d-osc-MDT0000: fail to write header for llog #0x5552:1#00000000: rc = -30 <3>LustreError: 6135:0:(llog_cat.c:538:llog_cat_cancel_records()) echo-OST005d-osc-MDT0000: fail to cancel 1 of 1 llog-records: rc = -30 <3>LustreError: 6135:0:(osp_sync.c:721:osp_sync_process_committed()) echo-OST005d-osc-MDT0000: can't cancel record: -30 <0>Kernel panic - not syncing: LBUG <4>Pid: 6145, comm: osp-syn-98-0 Not tainted 2.6.32-431.23.3.el6_lustre.x86_64 #1 <4>Call Trace: <4> [<ffffffff8152896c>] ? panic+0xa7/0x16f <4> [<ffffffffa03b3eeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs] <4> [<ffffffffa0eff2e3>] ? osp_sync_thread+0x753/0x7d0 [osp] <4> [<ffffffff81528df6>] ? schedule+0x176/0x3b0 <4> [<ffffffffa0efeb90>] ? osp_sync_thread+0x0/0x7d0 [osp] <4> [<ffffffff8109abf6>] ? kthread+0x96/0xa0 <4> [<ffffffff8100c20a>] ? child_rip+0xa/0x20 <4> [<ffffffff8109ab60>] ? kthread+0x0/0xa0 <4> [<ffffffff8100c200>] ? child_rip+0x0/0x20
Attachments
Issue Links
Activity
So it seems like this was eventually resolved (we have not had further issues), but I do have a related question.
If we were to build this filesystem again, what would be the optimal inode size/ratio for performance considering we are likely to have 10+ hard links per file? Or does it not really matter and just ensuring we have more space available would be sufficient?
I tried to create a two-level subdirectory test/test2 and then zeroed out the leaf block of test1 so that there was no entry pointing to test2 and also set the ".." entry of test2 to <2>, but this didn't show anything different. Another test with just changing ".." of the test3 subdirectory to <2> didn't cause the problem.
e2fsck 1.42.13.wc5 (15-Apr-2016) Pass 1: Checking inodes, blocks, and sizes Pass 2: Checking directory structure Directory inode 12, block #0, offset 0: directory corrupted Salvage<y>? yes Missing '.' in directory inode 12. Fix<y>? yes Setting filetype for entry '.' in ??? (12) to 2. Missing '..' in directory inode 12. Fix<y>? yes Setting filetype for entry '..' in ??? (12) to 2. Pass 3: Checking directory connectivity '..' in /test (12) is <The NULL inode> (0), should be / (2). Fix<y>? yes Unconnected directory inode 13 (/test/???) Connect to /lost+found<y>? yes '..' in /test2/test3 (15) is / (2), should be /test2 (14). Fix<y>? yes
I guess it is worthwhile to look into how directories are inserted into the parent directory list for e2fsck_dir_info_get_parent() to find. Something is preventing the 3040644673 inode from being found in the parent directory list.
I've tried to created a /mnt/lustre/dir1/dir2 which is disconnected, and e2fsck reports this
# e2fsck -fvy /dev/sdb
e2fsck 1.42.3.wc3 (15-Aug-2012)
Pass 1: Checking inodes, blocks, and sizes
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Unconnected directory inode 25047 (/???)
Connect to /lost+found? yes
Pass 4: Checking reference counts
Inode 2 ref count is 12, should be 13. Fix? yes
Inode 25047 ref count is 3, should be 2. Fix? yes
Pass 5: Checking group summary information
lustre-MDT0000: ***** FILE SYSTEM WAS MODIFIED *****
246 inodes used (0.25%)
3 non-contiguous files (1.2%)
0 non-contiguous directories (0.0%)
# of inodes with ind/dind/tind blocks: 0/0/0
17038 blocks used (34.08%)
0 bad blocks
1 large file
119 regular files
118 directories
0 character device files
0 block device files
0 fifos
4294967295 links
0 symbolic links (0 fast symbolic links)
0 sockets
--------
236 files
It does not complain anything in the pass2.
The problematic directory inode is 3040644673 as reported by e2fsck and hasn't been fixed after several runs:
debugfs: stat <3040644673> Inode: 3040644673 Type: directory Mode: 0777 Flags: 0x0 Generation: 2336434627 Version: 0x00000012:75b668cd User: 518 Group: 20 Size: 4096 File ACL: 0 Directory ACL: 0 Links: 2 Blockcount: 8 Fragment: Address: 0 Number: 0 Size: 0 ctime: 0x57421268:00000000 -- Sun May 22 13:11:20 2016 atime: 0x57421268:00000000 -- Sun May 22 13:11:20 2016 mtime: 0x56b2143f:00000000 -- Wed Feb 3 06:52:47 2016 crtime: 0x57421268:888eaf54 -- Sun May 22 13:11:20 2016 Size of extra inode fields: 28 Extended attributes stored in inode body: lma = "00 00 00 00 00 00 00 00 b5 83 00 00 02 00 00 00 df a8 00 00 00 00 00 00 " (24) lma: fid=[0x2000083b5:0xa8df:0x0] compat=0 incompat=0 link = "df f1 ea 11 01 00 00 00 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0 0 00 19 00 00 00 02 00 00 83 b5 00 00 a8 bf 00 00 00 00 61 63 6c 6f 63 61 6c " ( 49) BLOCKS: (0):14090 TOTAL: 1
Dumping the directory block shows nothing completely broken, except that the parent entry ".." is inode <2>, which is the ext4 root inode that should never be used by Lustre directories, but shouldn't cause any problems for e2fsck:
debugfs: block_dump 14090 0000 418e 3cb5 0c00 0102 2e00 0000 0200 0000 A.<............. 0020 f40f 0202 2e2e 0000 2537 0000 1a37 0000 ........%7...7.. 0040 2037 0000 2f37 0000 2e37 0000 2637 0000 7../7...7..&7.. 0060 2d37 0000 0f37 0000 2737 0000 1337 0000 -7...7..'7...7.. 0100 1237 0000 1b37 0000 1e37 0000 2c37 0000 .7...7...7..,7.. 0120 3037 0000 0000 0000 1f37 0000 0d37 0000 07.......7...7.. 0140 3137 0000 1837 0000 3437 0000 1037 0000 17...7..47...7.. 0160 2937 0000 3237 0000 3337 0000 1d37 0000 )7..27..37...7.. 0200 1137 0000 3537 0000 2b37 0000 3637 0000 .7..57..+7..67.. 0220 2837 0000 3737 0000 0000 0000 0000 0000 (7..77.......... 0240 0000 0000 0000 0000 0000 0000 0000 0000 ................ *
Even listing the directory shows nothing wrong with it except the ".." directory number:
debugfs: ls <3040644673> 3040644673 (12) . 2 (4084) ..
The code that is triggering is in e2fsck/pass2.c::check_dir_block(), where e2fsck_dir_info_get_parent() fails:
if (e2fsck_dir_info_get_parent(ctx, dirent->inode, &subdir_parent)) { cd->pctx.ino = dirent->inode; fix_problem(ctx, PR_2_NO_DIRINFO, &cd->pctx); goto abort_free_dict; }
after which e2fsck immediately aborts.
I'll need to dig into the population of the dir_info list to see why it is choking on "2" as the parent, since every directory under the root "/" directory also has <2> as the parent. Maybe that is special-cased in the code? Another possibility isn't that the parent directory "2" is the problem, but rather that this directory is not connected anywhere? I'd think that would be handled by adding it to lost+found or similar. It may be possible to debug this by creating a test filesystem that is similarly corrupted (non-root, maybe disconnected directory with <2> as the parent) to see what it is that triggers e2fsck to be unhappy.
There were a couple of patches landed for 2.8.0 that make ldiskfs more robust in the face of similar corruption:
- http://review.whamcloud.com/16679 "
LU-1026ldiskfs: make bitmaps corruption not fatal" - http://review.whamcloud.com/16312 "
LU-7114ldiskfs: corrupted bitmaps handling patches"
The ext2fs_warn_bitmap() function is the source of the message Illegal inode number passed to ext2fs_test_inode_bitmap #0 for in-use inode map, but it turns out that this isn't the reason the e2fsck was aborted since in the first run this message appeared some time before e2fsck was aborted. That is caused by the later error Internal error: couldn't find dir_info for 3040644673, which was one of the inodes repaired in a previous run.
The Internal error message did appear for a different inode the first time, so it does seem possible that e2fsck is still repairing these inodes in each run, but not as well as they should be, causing an abort each run.
Look into e2fsck code, It is failed at:
int ext2fs_test_inode_bitmap_range(ext2fs_inode_bitmap bitmap,
ino_t inode, int num)
{
EXT2_CHECK_MAGIC(bitmap, EXT2_ET_MAGIC_INODE_BITMAP);
if ((inode < bitmap->start) || (inode+num-1 > bitmap->real_end)) {
ext2fs_warn_bitmap(EXT2_ET_BAD_INODE_TEST,
inode, bitmap->description);
return 0;
}
return ext2fs_test_clear_generic_bitmap_range((ext2fs_generic_bitmap)
bitmap, inode, num);
}
So looks like metadata is inconsistent. Maybe will passed after manual fixed.
Looking into this issue, it appears that the MDT filesystem is becoming full because of the use of hard-link trees for backup. This results in each file having a large link xattr that spills into an external block, as well as multiple directories referencing each file.
Inode count: 3079569408 Free inodes: 2166646521 == 912922887 files used Block count: 1539776448 Free blocks: 41729879 == 159GB free, 5992186276 KB used == 5714 GB used, 6721 bytes used/inode
It would normally not be possible to have more than about 4500 bytes used per inode, even with the external xattr block, but the extra directory trees are consuming this space.
A file taken at random has a link count of 10 and an external xattr block (the File ACL block):
debugfs: stat F_006_fx_smokep F_006_fx_smokep: File not found by ext2_lookup debugfs: stat F_006_fx_smokeplumes_0010_comp_v001_01.nk Inode: 2467900774 Type: regular Mode: 0666 Flags: 0x0 Generation: 3837434978 Version: 0x00000014:f756e940 User: 0 Group: 0 Size: 0 File ACL: 1234063101 Directory ACL: 0 Links: 10 Blockcount: 8 Fragment: Address: 0 Number: 0 Size: 0 ctime: 0x57541f8e:00000000 -- Sun Jun 5 05:48:14 2016 atime: 0x571b5195:00000000 -- Sat Apr 23 03:42:29 2016 mtime: 0x539eb883:00000000 -- Mon Jun 16 02:27:31 2014 crtime: 0x571b5195:7f0d72f8 -- Sat Apr 23 03:42:29 2016 Size of extra inode fields: 28 Extended attributes stored in inode body: lma = "00 00 00 00 00 00 00 00 40 66 00 00 02 00 00 00 81 b6 01 00 00 00 00 00 " (24) lma: fid=[0x200006640:0x1b681:0x0] compat=0 incompat=0 lov = "d0 0b d1 0b 01 00 00 00 81 b6 01 00 00 00 00 00 40 66 00 00 02 00 00 00 00 00 10 00 01 00 00 00 6c 7c 0e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0 0 00 56 00 00 00 " (56)
As for the e2fsck problem, I haven't been able to debug it yet because the problem takes several hours to hit. In the meantime, I've fixed the (first) problem that was causing the MDT to be remounted read-only:
Jun 8 00:56:41 emds1 kernel: LDISKFS-fs error (device md0): ldiskfs_mb_check_on disk_bitmap: on-disk bitmap for group 0 corrupted: 57 blocks free in bitmap, 6 in gd Jun 8 00:56:41 emds1 kernel: Jun 8 00:56:41 emds1 kernel: Aborting journal on device md0-8. Jun 8 00:56:41 emds1 kernel: LDISKFS-fs (md0): Remounting filesystem read-only
I manually marked all of the blocks in group 0 used, and changed the group summary to match, as well as recomputed the block group checksum, which is the safest workaround given that I don't know which block(s) are actually in use, or which of those values is correct. It isn't clear if there are more errors like this, but I verified the next few groups had consistent block counts in the bitmap and group descriptors.
There is an e2fsck read-only check running under GDB to hopefully be able to debug the problem, but it will take about 8h to hit the point of the prior corruption.
We can get that in place. We're actually in Vancouver so Pacific hours. I'll set up some SSH and get back to you. Do you have an incoming IP I can restrict this to?
Please mail me on sfw@dneg.com - Thanks.
Daire, if you have a large number of links per file, then increasing the amount of space per inode would improve your space efficiency somewhat. Something like --mkfsoptions="-i 4608" would provide room for one external xattr block per file