[Lustre-discuss] ldiskfs kernel bug in ldiskfs_mb_use_best_found

Aaron Knister aaron.knister at gmail.com
Thu Jun 5 05:42:57 PDT 2008 

Unfortunately the monkeys maintaining this setup (I left the company  
last week) have managed to destroy one of the 13 terabyte arrays...so  
they've got bigger issues right now. Thanks for your help though.

On Jun 5, 2008, at 3:18 AM, Alex Zhuravlev wrote:

> hmm. could you provide me with ldiskfs.ok then?
>
> thanks, Alex
>
> Aaron Knister wrote:
>> I'm not sure how to obtain that. I'm running whatever was distributed
>> with 1.6.4.3 for rhel5-x86_64.
>>
>> On Jun 2, 2008, at 8:08 AM, Alex Zhuravlev wrote:
>>
>>> could you also send me your mballoc.c please?
>>>
>>> thanks, Alex
>>>
>>> Aaron Knister wrote:
>>>> Thanks so much for looking into this. Here's what I got from dmesg.
>>>> Interestingly enough every time it panics the CPU listed is #4...do
>>>> you think that points to a hardware problem? -
>>>> ----------- [cut here ] --------- [please bite here ] ---------
>>>> Kernel BUG at ...build/BUILD/lustre-ldiskfs-3.0.4/ldiskfs/ 
>>>> mballoc.c:1334
>>>> invalid opcode: 0000 [1] SMP
>>>> last sysfs file:
>>>> /devices/ 
>>>> pci0000:00/0000:00:02.0/0000:01:00.0/0000:02:02.0/0000:04:00.1/irq
>>>>
>>>> CPU 4
>>>> Modules linked in: obdfilter(U) fsfilt_ldiskfs(U) ost(U) mgc(U)
>>>> ldiskfs(U) crc16(U) lustre(U) lov(U) lquota(U) mdc(U) ko2iblnd(U)
>>>> ptlrpc(U) obdclass(
>>>> U) lnet(U) lvfs(U) libcfs(U) netconsole(U) autofs4(U) hidp(U)
>>>> rfcomm(U) l2cap(U) bluetooth(U) sunrpc(U) ip6t_REJECT(U)  
>>>> xt_tcpudp(U)
>>>> ip6table_filter(U
>>>> ) ip6_tables(U) x_tables(U) ipv6(U) ib_iser(U) libiscsi(U)
>>>> scsi_transport_iscsi(U) rdma_ucm(U) ib_ucm(U) ib_srp(U) ib_sdp(U)
>>>> rdma_cm(U) ib_cm(U) iw_c
>>>> m(U) ib_addr(U) ib_local_sa(U) ib_ipoib(U) ib_sa(U) ib_uverbs(U)
>>>> ib_umad(U) dm_multipath(U) video(U) sbs(U) backlight(U) i2c_ec(U)
>>>> button(U) battery(
>>>> U) asus_acpi(U) acpi_memhotplug(U) ac(U) parport_pc(U) lp(U)
>>>> parport(U) ib_mthca(U) ib_mad(U) i2c_i801(U) e1000(U) ide_cd(U)
>>>> ib_core(U) shpchp(U) i2c
>>>> _core(U) cdrom(U) sg(U) pcspkr(U) dm_snapshot(U) dm_zero(U)
>>>> dm_mirror(U) dm_mod(U) ata_piix(U) ahci(U) megaraid_sas(U)
>>>> sata_sil(U) libata(U) sd_mod(U
>>>> ) scsi_mod(U) ext3(U) jbd(U) ehci_hcd(U) ohci_hcd(U) uhci_hcd(U)
>>>> Pid: 5717, comm: ll_ost_io_11 Tainted: GF
>>>> 2.6.18-53.1.13.el5_lustre.1.6.4.3smp #1
>>>> RIP: 0010:[<ffffffff8885a01f>]  [<ffffffff8885a01f>]
>>>> :ldiskfs:ldiskfs_mb_use_best_found+0xef/0x520
>>>> RSP: 0018:ffff81040e4dd320  EFLAGS: 00010246
>>>> RAX: 0000000000000000 RBX: ffff81040e4dd3d0 RCX: 000000000000007f
>>>> RDX: ffff810406833000 RSI: ffff8103a8250000 RDI: 0000000000001000
>>>> RBP: 0000000000000800 R08: 0000000000000020 R09: 0000000000000010
>>>> R10: ffff81037d136ff8 R11: 0000000000008000 R12: ffff81040e4dd470
>>>> R13: 0000000000010000 R14: 0000000000000020 R15: 0000000000000800
>>>> FS:  00002aaaaaac0220(0000) GS:ffff81042fc20b40(0000)
>>>> knlGS:0000000000000000
>>>> CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>>>> CR2: 00002aaaae2ad0a0 CR3: 000000041c6d1000 CR4: 00000000000006e0
>>>> Process ll_ost_io_11 (pid: 5717, threadinfo ffff81040e4dc000, task
>>>> ffff81041228a040)
>>>> Stack:  ffff81040e4dd4c0 ffff81040e4dd470 000000000000000b
>>>> 0000000000010000
>>>> 0000000000010000 0000000000000020 ffff81040e4dd4c0 ffffffff8885cd4e
>>>> ffff81038c2b0a38 0000000000000010 ffff81040e4dd4a0 0000000000000000
>>>> Call Trace:
>>>> [<ffffffff8885cd4e>] :ldiskfs:ldiskfs_mb_regular_allocator+0x66e/ 
>>>> 0xd50
>>>> [<ffffffff888443c2>] :ldiskfs:ldiskfs_mark_inode_dirty+0x132/0x160
>>>> [<ffffffff88859664>] :ldiskfs:ldiskfs_mb_initialize_context 
>>>> +0x144/0x160
>>>> [<ffffffff8885e1e6>] :ldiskfs:ldiskfs_mb_new_blocks+0x166/0x280
>>>> [<ffffffff888bf091>]
>>>> :fsfilt_ldiskfs:ldiskfs_ext_new_extent_cb+0x301/0x640
>>>> [<ffffffff8000a63f>] get_page_from_freelist+0x223/0x3cf
>>>> [<ffffffff882390b0>] :ib_mthca:mthca_arbel_post_send+0x5a2/0x5b4
>>>> [<ffffffff88856d27>] :ldiskfs:ldiskfs_ext_walk_space+0x1b7/0x250
>>>> [<ffffffff888bed90>] :fsfilt_ldiskfs:ldiskfs_ext_new_extent_cb 
>>>> +0x0/0x640
>>>> [<ffffffff80054ccc>] mwait_idle+0x0/0x4a
>>>> [<ffffffff888ba9ae>] :fsfilt_ldiskfs:fsfilt_map_nblocks+0xfe/0x150
>>>> [<ffffffff888eee08>] :obdfilter:filter_direct_io+0x478/0xce0
>>>> [<ffffffff888f14de>] :obdfilter:filter_commitrw_write+0x184e/0x2570
>>>> [<ffffffff8005a2ea>] cache_alloc_refill+0x106/0x186
>>>> [<ffffffff8003ce86>] lock_timer_base+0x1b/0x3c
>>>> [<ffffffff8889eb46>] :ost:ost_brw_write+0x21b6/0x28c0
>>>> [<ffffffff80088431>] default_wake_function+0x0/0xe
>>>> [<ffffffff888a283e>] :ost:ost_handle+0x2a8e/0x58d8
>>>> [<ffffffff88603c82>] :obdclass:class_handle2object+0xd2/0x160
>>>> [<ffffffff8869f230>] :ptlrpc:lustre_swab_ptlrpc_body+0x0/0x90
>>>> [<ffffffff8869cde5>] :ptlrpc:lustre_swab_buf+0xc5/0xf0
>>>> [<ffffffff886a4a3b>] :ptlrpc:ptlrpc_server_handle_request+0xb0b/ 
>>>> 0x1270
>>>> [<ffffffff80060f29>] thread_return+0x0/0xeb
>>>> [<ffffffff8006b6c9>] do_gettimeofday+0x50/0x92
>>>> [<ffffffff8855d056>] :libcfs:lcw_update_time+0x16/0x100
>>>> [<ffffffff8003ce86>] lock_timer_base+0x1b/0x3c
>>>> [<ffffffff886a747c>] :ptlrpc:ptlrpc_main+0x7dc/0x950
>>>> [<ffffffff80088431>] default_wake_function+0x0/0xe
>>>> [<ffffffff8005bfb1>] child_rip+0xa/0x11
>>>> [<ffffffff886a6ca0>] :ptlrpc:ptlrpc_main+0x0/0x950
>>>> [<ffffffff8005bfa7>] child_rip+0x0/0x11
>>>> Code: 0f 0b 68 50 5c 86 88 c2 36 05 0f 1f 80 00 00 00 00 48 8b 43
>>>> RIP  [<ffffffff8885a01f>] :ldiskfs:ldiskfs_mb_use_best_found+0xef/ 
>>>> 0x520
>>>> RSP <ffff81040e4dd320>
>>>> <0>Kernel panic - not syncing: Fatal exception
>>>> On Jun 2, 2008, at 3:40 AM, Alex Zhuravlev wrote:
>>>>> what about dmesg output? it's unlikely lustre debug can help  
>>>>> here as
>>>>> the problem
>>>>> seem to be very internal to ldiskfs (mballoc piece of it)
>>>>>
>>>>> thanks, Alex
>>>>>
>>>>> Aaron Knister wrote:
>>>>>> I bumped up debugging, and here's  (below) the last bit of  
>>>>>> debugging
>>>>>> info from lustre that I have on the oss before it went belly  
>>>>>> up. My
>>>>>> system is totally inoperable. Does anybody have any ideas?
>>>>>>
>>>>>> 00010000:00001000:4:1212157576.884909:0:6378:0:(ldlm_resource.c: 
>>>>>> 865:ldlm_resource_add_lock())
>>>>>>
>>>>>> About to add this lock:
>>>>>> 00010000:00001000:4:1212157576.884910:0:6378:0:(ldlm_lock.c: 
>>>>>> 1718:ldlm_lock_dump())
>>>>>>
>>>>>> -- Lock dump: ffff81036e61f1c0/0x1fb135e1e3fd2cc6 (rc: 3) (pos:  
>>>>>> 0) 
>>>>>> (pid:6378)
>>>>>> 00010000:00001000:4:1212157576.884913:0:6378:0:(ldlm_lock.c: 
>>>>>> 1726:ldlm_lock_dump())
>>>>>>
>>>>>> Node: local
>>>>>> 00010000:00001000:4:1212157576.884914:0:6378:0:(ldlm_lock.c: 
>>>>>> 1735:ldlm_lock_dump())
>>>>>>
>>>>>> Resource: ffff8103849211c0 (3129942/0)
>>>>>> 00010000:00001000:4:1212157576.884915:0:6378:0:(ldlm_lock.c: 
>>>>>> 1740:ldlm_lock_dump())
>>>>>>
>>>>>> Req mode: PW, grant mode: PW, rc: 3, read: 0, write: 1 flags:
>>>>>> 0x80004000
>>>>>> 00010000:00001000:4:1212157576.884917:0:6378:0:(ldlm_lock.c: 
>>>>>> 1746:ldlm_lock_dump())
>>>>>>
>>>>>> Extent: 0 -> 18446744073709551615 (req 0-18446744073709551615)
>>>>>> 00010000:00000040:4:1212157576.884920:0:6378:0:(ldlm_lock.c: 
>>>>>> 615:ldlm_lock_decref_internal())
>>>>>>
>>>>>> forcing cancel of local lock
>>>>>> 00010000:00000010:4:1212157576.884922:0:6378:0:(ldlm_lockd.c: 
>>>>>> 1357:ldlm_bl_to_thread())
>>>>>>
>>>>>> kmalloced 'blwi': 120 at ffff81040e90a340 (tot 49135175)
>>>>>> 00002000:00000040:4:1212157576.884925:0:6378:0:(lustre_fsfilt.h: 
>>>>>> 194:fsfilt_start_log())
>>>>>>
>>>>>> started handle ffff8103766dfc78 (0000000000000000)
>>>>>> 00002000:00000040:4:1212157576.884930:0:6378:0:(lustre_fsfilt.h: 
>>>>>> 270:fsfilt_commit())
>>>>>>
>>>>>> committing handle ffff8103766dfc78
>>>>>> 00002000:00000040:4:1212157576.884931:0:6378:0:(lustre_fsfilt.h: 
>>>>>> 194:fsfilt_start_log())
>>>>>>
>>>>>> started handle ffff8103766dfc78 (0000000000000000)
>>>>>> 00000020:00000040:4:1212157576.884957:0:5557:0: 
>>>>>> (lustre_handles.c:121:class_handle_unhash_nolock())
>>>>>>
>>>>>> removing object ffff81036e61f1c0 with handle 0x1fb135e1e3fd2cc6
>>>>>> from hash
>>>>>> 00000100:00000010:4:1212157576.884960:0:5557:0:(client.c: 
>>>>>> 394:ptlrpc_prep_set())
>>>>>>
>>>>>> kmalloced 'set': 104 at ffff8104012d38c0 (tot 49135279)
>>>>>> 00000100:00000010:4:1212157576.884962:0:5557:0:(client.c: 
>>>>>> 457:ptlrpc_set_destroy())
>>>>>>
>>>>>> kfreed 'set': 104 at ffff8104012d38c0 (tot 49135175).
>>>>>> 00010000:00000040:4:1212157576.884964:0:5557:0:(ldlm_resource.c: 
>>>>>> 818:ldlm_resource_putref())
>>>>>>
>>>>>> putref res: ffff8103849211c0 count: 0
>>>>>> 00010000:00000010:4:1212157576.884969:0:5557:0:(ldlm_resource.c: 
>>>>>> 828:ldlm_resource_putref())
>>>>>>
>>>>>> kfreed 'res->lr_lvb_data': 40 at ffff810379ded880 (tot 49135135).
>>>>>> 00010000:00000010:4:1212157576.885000:0:5557:0:(ldlm_resource.c: 
>>>>>> 829:ldlm_resource_putref())
>>>>>>
>>>>>> slab-freed 'res': 224 at ffff8103849211c0 (tot 49135135).
>>>>>> 00010000:00000010:4:1212157576.885002:0:5557:0:(ldlm_lockd.c: 
>>>>>> 1657:ldlm_bl_thread_main())
>>>>>>
>>>>>> kfreed 'blwi': 120 at ffff81040e90a340 (tot 49134791).
>>>>>> 00002000:00000040:4:1212157576.885623:0:6378:0:(lustre_fsfilt.h: 
>>>>>> 270:fsfilt_commit())
>>>>>>
>>>>>> committing handle ffff8103766dfc78
>>>>>> 00002000:00000002:4:1212157576.885625:0:6378:0:(filter.c: 
>>>>>> 148:f_dput())
>>>>>> putting 3129942: ffff8103599cea98, count = 0
>>>>>> 00002000:00080000:4:1212157576.885627:0:6378:0:(filter.c: 
>>>>>> 2689:filter_destroy_precreated())
>>>>>>
>>>>>> crew4-OST0001: after destroy: set last_objids[0] = 3129941
>>>>>> 00002000:00000002:4:1212157576.885630:0:6378:0:(filter.c: 
>>>>>> 607:filter_update_last_objid())
>>>>>>
>>>>>> crew4-OST0001: server last_objid for group 0: 3129941
>>>>>> 00002000:00000010:4:1212157576.912615:0:6485:0:(fsfilt- 
>>>>>> ldiskfs.c:747:fsfilt_ldiskfs_cb_func())
>>>>>>
>>>>>> slab-freed 'fcb': 56 at ffff810371404920 (tot 49134335).
>>>>>> 00010000:00000040:4:1212157576.912669:0:6378:0:(ldlm_lib.c: 
>>>>>> 1556:target_committed_to_req())
>>>>>>
>>>>>> last_committed 17896268, xid 3841
>>>>>> 00000100:00000040:4:1212157576.912674:0:6378:0:(connection.c: 
>>>>>> 191:ptlrpc_connection_addref())
>>>>>>
>>>>>> connection=ffff8103fbe9e2c0 refcount 10 to 172.18.0.10
>>>>>> <http://172.18.0.10>@o2ib
>>>>>> 00000100:00000040:4:1212157576.912678:0:6378:0:(niobuf.c: 
>>>>>> 46:ptl_send_buf())
>>>>>>
>>>>>> conn=ffff8103fbe9e2c0 id 12345-172.18.0.10 at o2ib
>>>>>> 00000400:00000010:4:1212157576.912680:0:6378:0:(lib-lnet.h: 
>>>>>> 247:lnet_md_alloc())
>>>>>>
>>>>>> kmalloced 'md': 136 at ffff81040cb6cb80 (tot 9568949).
>>>>>> 00000400:00000010:4:1212157576.912683:0:6378:0:(lib-lnet.h: 
>>>>>> 295:lnet_msg_alloc())
>>>>>>
>>>>>> kmalloced 'msg': 336 at ffff8104285e1e00 (tot 9569285).
>>>>>> 00000100:00000040:4:1212157576.912693:0:6378:0:(connection.c: 
>>>>>> 150:ptlrpc_put_connection())
>>>>>>
>>>>>> connection=ffff8103fbe9e2c0 refcount 9 to 172.18.0.10
>>>>>> <http://172.18.0.10>@o2ib
>>>>>> 00000100:00000040:4:1212157576.912695:0:6378:0:(service.c: 
>>>>>> 648:ptlrpc_server_handle_request())
>>>>>>
>>>>>> RPC PUTting export ffff8103848e9000 : new rpc_count 0
>>>>>> 00000100:00000040:4:1212157576.912697:0:6378:0:(service.c: 
>>>>>> 648:ptlrpc_server_handle_request())
>>>>>>
>>>>>> PUTting export ffff8103848e9000 : new refcount 4
>>>>>> 00000100:00000040:4:1212157576.912699:0:6378:0:(service.c: 
>>>>>> 652:ptlrpc_server_handle_request())
>>>>>>
>>>>>> PUTting export ffff8103848e9000 : new refcount 3
>>>>>> 00000400:00000010:4:1212157576.912741:0:5351:0:(lib-lnet.h: 
>>>>>> 269:lnet_md_free())
>>>>>>
>>>>>> kfreed 'md': 136 at ffff81040cb6cb80 (tot 9569149).
>>>>>> 00000400:00000010:4:1212157576.912744:0:5351:0:(lib-lnet.h: 
>>>>>> 312:lnet_msg_free())
>>>>>>
>>>>>> kfreed 'msg': 336 at ffff8104285e1e00 (tot 9568813).
>>>>>>
>>>>>>
>>>>>> On Wed, May 28, 2008 at 8:03 PM, Aaron Knister
>>>>>> <aaron.knister at gmail.com
>>>>>> <mailto:aaron.knister at gmail.com>> wrote:
>>>>>>
>>>>>>  Thank you very much for looking into this. I've attached my  
>>>>>> dmesg to
>>>>>>  the bug. i looked at line number 1334 which the panic seems to
>>>>>>  reference. i can't figure out what its doing though
>>>>>>
>>>>>>  On Wed, May 28, 2008 at 4:54 PM, Alex Zhuravlev
>>>>>>  <Alex.Zhuravlev at sun.com <mailto:Alex.Zhuravlev at sun.com>> wrote:
>>>>>>
>>>>>>      Aaron Knister wrote:
>>>>>>
>>>>>>          I'm seeing this bug (14465) under heavy load on my  
>>>>>> OSSes. If
>>>>>>          I reboot the MDS it appears to help...any ideas?  
>>>>>> What's the
>>>>>>          status on this bug?
>>>>>>
>>>>>>
>>>>>>      could you attach your dmesg to the bug? as for the status  
>>>>>> - I'm
>>>>>>      still not
>>>>>>      able to reproduce this, neither I found possible cause,  
>>>>>> sorry.
>>>>>>
>>>>>>      thanks, Alex
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> Lustre-discuss mailing list
>>>>> Lustre-discuss at lists.lustre.org
>>>>> http://lists.lustre.org/mailman/listinfo/lustre-discuss
>>>
>>
>
> _______________________________________________
> Lustre-discuss mailing list
> Lustre-discuss at lists.lustre.org
> http://lists.lustre.org/mailman/listinfo/lustre-discuss

More information about the lustre-discuss mailing list