[#LU-601] kernel BUG at fs/jbd2/transaction.c:1030

[LU-601] kernel BUG at fs/jbd2/transaction.c:1030 Created: 17/Aug/11 Updated: 26/Feb/12 Resolved: 26/Feb/12
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	None
Fix Version/s:	Lustre 2.2.0, Lustre 2.1.1

Type:

Bug

Priority:

Minor

Reporter:

Patrick Valentin (Inactive)

Assignee:

Zhenyu Xu

Resolution:

Fixed

Votes:

Labels:

None

Attachments:

trace_chown_1_to_10

Issue Links:

Duplicate
is duplicated by	~~LU-1045~~	kernel BUG at fs/jbd2/transaction.c:1...	Resolved

Severity:

Rank (Obsolete):

4726

Description

Hi,

The following assertion failed with Lustre 2.0.0 was reported by the on site support at CEA customer site:

fs/jbd2/transaction.c:jbd2_journal_dirty_metadata() ,line 1030

J_ASSERT_JH(jh, handle->h_buffer_credits > 0);

This issue has been hit several times on restart of an MDS. On this particular one, the problem is not extremely critical
since after dump+restart, the service continue



------------[ cut here ]------------
kernel BUG at fs/jbd2/transaction.c:1030!
invalid opcode: 0000 [#1] SMP 

PID: 24472  TASK: ffff8808556011c0  CPU: 22  COMMAND: "tgt_recov"
 #0 [ffff88083370a9d0] machine_kexec at ffffffff8102e77b
 #1 [ffff88083370aa30] crash_kexec at ffffffff810a6cd8
 #2 [ffff88083370ab00] oops_end at ffffffff8146aad0
 #3 [ffff88083370ab30] die at ffffffff8101021b
 #4 [ffff88083370ab60] do_trap at ffffffff8146a3a4
 #5 [ffff88083370abc0] do_invalid_op at ffffffff8100dda5
 #6 [ffff88083370ac60] invalid_op at ffffffff8100cf3b
    [exception RIP: jbd2_journal_dirty_metadata+269]
    RIP: ffffffffa00518ed  RSP: ffff88083370ad10  RFLAGS: 00010246
    RAX: ffff881831c8b8c0  RBX: ffff881834107468  RCX: ffff8808512adc90
    RDX: 0000000000000000  RSI: ffff8808512adc90  RDI: 0000000000000000
    RBP: ffff88083370ad30   R8: 2010000000000000   R9: f790d737baaf2402
    R10: 0000000000000001  R11: 0000000000000040  R12: ffff8818343606d8
    R13: ffff8808512adc90  R14: ffff880859b81800  R15: 0000000000002000
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #7 [ffff88083370ad38] __ldiskfs_handle_dirty_metadata at ffffffffa04bb3fb [ldiskfs]
 #8 [ffff88083370ad78] fsfilt_ldiskfs_write_handle at ffffffffa09bede7 [fsfilt_ldiskfs]
 #9 [ffff88083370ae28] fsfilt_ldiskfs_write_record at ffffffffa09bf0fe [fsfilt_ldiskfs]
#10 [ffff88083370aea8] llog_lvfs_write_blob at ffffffffa05a018c [obdclass]
#11 [ffff88083370af58] llog_lvfs_write_rec at ffffffffa05a1732 [obdclass]
#12 [ffff88083370b038] llog_cat_current_log.clone.0 at ffffffffa059e14f [obdclass]
#13 [ffff88083370b118] llog_cat_add_rec at ffffffffa059e86a [obdclass]
#14 [ffff88083370b198] llog_obd_origin_add at ffffffffa05a51a6 [obdclass]
#15 [ffff88083370b1f8] llog_add at ffffffffa05a5381 [obdclass]
#16 [ffff88083370b268] lov_llog_origin_add at ffffffffa089a0cc [lov]
#17 [ffff88083370b318] llog_add at ffffffffa05a5381 [obdclass]
#18 [ffff88083370b388] mds_llog_origin_add at ffffffffa09d46f9 [mds]
#19 [ffff88083370b408] llog_add at ffffffffa05a5381 [obdclass]
#20 [ffff88083370b478] mds_llog_add_unlink at ffffffffa09d4de4 [mds]
#21 [ffff88083370b4f8] mds_log_op_orphan at ffffffffa09d5229 [mds]
#22 [ffff88083370b578] mds_lov_update_objids at ffffffffa09de7ef [mds]
#23 [ffff88083370b638] mdd_lov_objid_update at ffffffffa09f5cb2 [mdd]
#24 [ffff88083370b648] mdd_create_data at ffffffffa0a02c91 [mdd]
#25 [ffff88083370b6e8] cml_create_data at ffffffffa0acf036 [cmm]
#26 [ffff88083370b768] mdt_finish_open at ffffffffa0a6c885 [mdt]
#27 [ffff88083370b838] mdt_reint_open at ffffffffa0a6d119 [mdt]
#28 [ffff88083370b958] mdt_reint_rec at ffffffffa0a5764f [mdt]
#29 [ffff88083370b9a8] mdt_reint_internal at ffffffffa0a4ea04 [mdt]
#30 [ffff88083370ba38] mdt_intent_reint at ffffffffa0a4f085 [mdt]
#31 [ffff88083370bab8] mdt_intent_policy at ffffffffa0a48270 [mdt]
#32 [ffff88083370bb28] ldlm_lock_enqueue at ffffffffa068ea9d [ptlrpc]
#33 [ffff88083370bbc8] ldlm_handle_enqueue0 at ffffffffa06b64d1 [ptlrpc]
#34 [ffff88083370bc68] mdt_enqueue at ffffffffa0a47dea [mdt]
#35 [ffff88083370bc98] mdt_handle_common at ffffffffa0a439f5 [mdt]
#36 [ffff88083370bd18] mdt_recovery_handle at ffffffffa0a44a68 [mdt]
#37 [ffff88083370bd68] handle_recovery_req at ffffffffa0699512 [ptlrpc]
#38 [ffff88083370bde8] target_recovery_thread at ffffffffa0699b36 [ptlrpc]
#39 [ffff88083370bf48] kernel_thread at ffffffff8100d1aa


Something similar is sometime hit just after the MDS end the recovery, during orphan cleanup. In such case the MDS fall
repetitively after each lustre restart and, as a workaround, we had to mount the volume in ldiskfs mode and remove the
PENDING subdirectory.

Is block reservation done in fsfilt_ldiskfs_write_record for the jbd2 transaction is too small ?

Comments

Comment by Peter Jones [ 18/Aug/11 ]

Bobijam

Could you please look into this one?

Thanks

Peter

Comment by Zhenyu Xu [ 19/Aug/11 ]

fsfilt_ldiskfs_write_record()

        /* Determine how many transaction credits are needed */
        blocksize = 1 << inode->i_blkbits;
        block_count = (*offs & (blocksize - 1)) + bufsize;
        block_count = (block_count + blocksize - 1) >> inode->i_blkbits;

        handle = ldiskfs_journal_start(inode,
                               block_count * FSFILT_DATA_TRANS_BLOCKS(inode->i_sb) + 2);

bzzz, is it occasionally possible that the transaction credit calculation not enough for unlink record writing?

please ignore the question

Comment by Zhenyu Xu [ 22/Aug/11 ]

This happens in mdd_create_data() and it only preserve transaction credit for object create

mdd_txn_param_build(env, mdd, MDD_TXN_CREATE_DATA_OP);

which does not count in the possible unlinking lost precreated object logs credits.

Comment by Zhenyu Xu [ 24/Aug/11 ]

patch tracking at http://review.whamcloud.com/1276

Comment by Patrick Valentin (Inactive) [ 15/Sep/11 ]

I attached the trace file (traces.tar.gz) but it seems it doesn't work. So I upload a copy on your ftp site, under uploads/LU-L687.

Comment by Patrick Valentin (Inactive) [ 15/Sep/11 ]

Ooops, ignore my previous comment! Sorry, it was for ~~LU-687~~.

Comment by Patrick Valentin (Inactive) [ 16/Sep/11 ]

The following patch, at http://review.whamcloud.com/1276, was installed at CEA site on tuesday september the 6th.
This morning, they experienced a MDS pseudo-hang situation as described in ~~LU-685~~, and they had to reboot the MDS.
During the restart, they had again a linux kernel crash, due to the following ASSERT:

fs/jbd2/transaction.c:1030
    jbd2_journal_dirty_metadata()
        J_ASSERT_JH(jh, handle->h_buffer_credits > 0);

Comment by Zhenyu Xu [ 16/Sep/11 ]

Is the crash dump stack the same as that of the original dump stack posted in the description?

Comment by Patrick Valentin (Inactive) [ 16/Sep/11 ]

Yes, the stack is the same. Here under is a copy.
If you are interrested to have the dump, I can ask to have an upload.
It's on another cluster at CEA site, and on this one we are allowed
to get a copy of the dumps.

PID: 9687   TASK: ffff88185b8216c0  CPU: 9   COMMAND: "tgt_recov"
 #0 [ffff881831588f40] machine_kexec at ffffffff8102e77b
 #1 [ffff881831588fa0] crash_kexec at ffffffff810a6cd8
 #2 [ffff881831589070] oops_end at ffffffff8146aad0
 #3 [ffff8818315890a0] die at ffffffff8101021b
 #4 [ffff8818315890d0] do_trap at ffffffff8146a3a4
 #5 [ffff881831589130] do_invalid_op at ffffffff8100dda5
 #6 [ffff8818315891d0] invalid_op at ffffffff8100cf3b
    [exception RIP: jbd2_journal_dirty_metadata+269]
    RIP: ffffffffa08b08ed  RSP: ffff881831589280  RFLAGS: 00010246
    RAX: ffff8820452b7680  RBX: ffff88104db7c1c8  RCX: ffff8808127194d8
    RDX: 0000000000000000  RSI: ffff8808127194d8  RDI: 0000000000000000
    RBP: ffff8818315892a0   R8: b010000000000000   R9: f7cf906fc45d3602
    R10: 0000000000000001  R11: 00000000000000c0  R12: ffff8808127ed908
    R13: ffff8808127194d8  R14: ffff881055678800  R15: 0000000000002000
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #7 [ffff8818315892a8] __ldiskfs_handle_dirty_metadata at ffffffffa08cb3fb
 #8 [ffff8818315892e8] fsfilt_ldiskfs_write_handle at ffffffffa055cde7
 #9 [ffff881831589398] fsfilt_ldiskfs_write_record at ffffffffa055d0fe
#10 [ffff881831589418] llog_lvfs_write_blob at ffffffffa04a218c
#11 [ffff8818315894c8] llog_lvfs_write_rec at ffffffffa04a39fa
#12 [ffff8818315895a8] llog_cat_add_rec at ffffffffa04a0905
#13 [ffff881831589628] llog_obd_origin_add at ffffffffa04a71a6
#14 [ffff881831589688] llog_add at ffffffffa04a7381
#15 [ffff8818315896f8] lov_llog_origin_add at ffffffffa079c0cc
#16 [ffff8818315897a8] llog_add at ffffffffa04a7381
#17 [ffff881831589818] mds_llog_origin_add at ffffffffa0572d29
#18 [ffff881831589898] llog_add at ffffffffa04a7381
#19 [ffff881831589908] mds_llog_add_unlink at ffffffffa0573414
#20 [ffff881831589988] mds_log_op_unlink at ffffffffa0573b26
#21 [ffff881831589a18] mdd_unlink_log at ffffffffa094bc1e
#22 [ffff881831589a78] mdd_lov_destroy at ffffffffa094e5d0
#23 [ffff881831589b38] __mdd_orphan_cleanup at ffffffffa0955c8c
#24 [ffff881831589c18] mdd_recovery_complete at ffffffffa0967be8
#25 [ffff881831589c98] cmm_recovery_complete at ffffffffa09dc17a
#26 [ffff881831589ce8] mdt_postrecov at ffffffffa098278e
#27 [ffff881831589d48] mdt_obd_postrecov at ffffffffa0985ca7
#28 [ffff881831589de8] target_recovery_thread at ffffffffa059c0e8
#29 [ffff881831589f48] kernel_thread at ffffffff8100d1aa

Comment by Zhenyu Xu [ 16/Sep/11 ]

orphan_object_destroy() also does not preserve enough journal credit, it calls orphan_object_kill()->mdd_lov_destroy() which need another llog write credit.

Comment by Peter Jones [ 22/Sep/11 ]

http://review.whamcloud.com/#change,1276

Comment by Patrick Valentin (Inactive) [ 13/Oct/11 ]

Hi,

We have delivered an EFIX containing ~~LU-601~~ patch set 7 to our CEA customer last tuestay (october 4), and yesterday they experienced twice the same same crash, during Lustre recovery. Here is the stack and an extract of the syslog recorded by on line support. This stack is quite close to the initial one posted in this Jira ticket, and is exactly the same than other traces recorded by support team before this efix was installed.

BTW, we had to add the following lines to the original patch set 7, because we have already integrated ~~LU-81~~, which adds a call to mdd_txn_param_build():

--- a/lustre/mdd/mdd_device.c
+++ b/lustre/mdd/mdd_device.c
@@ -1393,7 +1393,7 @@ static int mdd_changelog_user_purge_cb(s
 
                 /* XXX This is a workaround for the deadlock of changelog
                  * adding vs. changelog cancelling. LU-81. */
-                mdd_txn_param_build(mcud->mcud_env, mdd, MDD_TXN_UNLINK_OP);
+                mdd_txn_param_build(mcud->mcud_env, mdd, MDD_TXN_UNLINK_OP, 1);
                 trans_h = mdd_trans_start(mcud->mcud_env, mdd);
                 if (IS_ERR(trans_h)) {
                         CERROR("fsfilt_start_log failed: %ld\n",

traces provided by support team:

crash&gt; bt
PID: 13511  TASK: ffff88085b462440  CPU: 30  COMMAND: &quot;tgt_recov&quot;
 #0 [ffff88082ec22e50] machine_kexec at ffffffff8102e77b
 #1 [ffff88082ec22eb0] crash_kexec at ffffffff810a6cd8
 #2 [ffff88082ec22f80] oops_end at ffffffff8146aad0
 #3 [ffff88082ec22fb0] die at ffffffff8101021b
 #4 [ffff88082ec22fe0] do_trap at ffffffff8146a3a4
 #5 [ffff88082ec23040] do_invalid_op at ffffffff8100dda5
 #6 [ffff88082ec230e0] invalid_op at ffffffff8100cf3b
    [exception RIP: jbd2_journal_dirty_metadata+269]
    RIP: ffffffffa00518ed  RSP: ffff88082ec23190  RFLAGS: 00010246
    RAX: ffff881830d86ac0  RBX: ffff881841975438  RCX: ffff8818419dfe98
    RDX: 0000000000000000  RSI: ffff8818419dfe98  RDI: 0000000000000000
    RBP: ffff88082ec231b0   R8: 3010000000000000   R9: e7a06811cf77a602
    R10: 0000000000000000  R11: 00000000000001ad  R12: ffff8818419dd438
    R13: ffff8818419dfe98  R14: ffff88185a75c800  R15: ffff8818419de558
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #7 [ffff88082ec231b8] __ldiskfs_handle_dirty_metadata at ffffffffa09433fb
 #8 [ffff88082ec231f8] ldiskfs_getblk at ffffffffa095150d
 #9 [ffff88082ec232b8] ldiskfs_bread at ffffffffa09515b8
#10 [ffff88082ec232e8] fsfilt_ldiskfs_write_handle at ffffffffa09f0e47
#11 [ffff88082ec23398] fsfilt_ldiskfs_write_record at ffffffffa09f10fe
#12 [ffff88082ec23418] llog_lvfs_write_blob at ffffffffa053318c
#13 [ffff88082ec234c8] llog_lvfs_write_rec at ffffffffa05349fa
#14 [ffff88082ec235a8] llog_cat_add_rec at ffffffffa0531905
#15 [ffff88082ec23628] llog_obd_origin_add at ffffffffa05381a6
#16 [ffff88082ec23688] llog_add at ffffffffa0538381
#17 [ffff88082ec236f8] lov_llog_origin_add at ffffffffa082d0cc
#18 [ffff88082ec237a8] llog_add at ffffffffa0538381
#19 [ffff88082ec23818] mds_llog_origin_add at ffffffffa05f1d29
#20 [ffff88082ec23898] llog_add at ffffffffa0538381
#21 [ffff88082ec23908] mds_llog_add_unlink at ffffffffa05f2414
#22 [ffff88082ec23988] mds_log_op_unlink at ffffffffa05f2b26
#23 [ffff88082ec23a18] mdd_unlink_log at ffffffffa0a0cc1e
#24 [ffff88082ec23a78] mdd_lov_destroy at ffffffffa0a0f5d0
#25 [ffff88082ec23b38] __mdd_orphan_cleanup at ffffffffa0a16c8c
#26 [ffff88082ec23c18] mdd_recovery_complete at ffffffffa0a28c08
#27 [ffff88082ec23c98] cmm_recovery_complete at ffffffffa073a17a
#28 [ffff88082ec23ce8] mdt_postrecov at ffffffffa0a4378e
#29 [ffff88082ec23d48] mdt_obd_postrecov at ffffffffa0a46ca7
#30 [ffff88082ec23de8] target_recovery_thread at ffffffffa062d0e8
#31 [ffff88082ec23f48] kernel_thread at ffffffff8100d1aa
crash&gt; log | tail -100
LustreError: 13540:0:(mdt_handler.c:2796:mdt_recovery()) operation 400 on unconnected MDS from 12345-10.100.62.53@o2ib2
LustreError: 13551:0:(mdt_handler.c:2796:mdt_recovery()) operation 400 on unconnected MDS from 12345-10.100.62.52@o2ib2
LustreError: 13568:0:(ldlm_lib.c:2123:target_send_reply_msg()) @@@ processing error (-19)  req@ffff88083f8c1400
x1382292200733537/t0(0) o38-&gt;&lt;?&gt;@&lt;?&gt;:0/0 lens 368/0 e 0 to 0 dl 1318420955 ref 1
fl Interpret:/ffffffff/ffffffff rc -19/-1
LustreError: 13568:0:(ldlm_lib.c:2123:target_send_reply_msg()) Skipped 63 previous similar messages
LustreError: 137-5: UUID 'work1-MDT0000_UUID' is not available  for connect (no target)
LustreError: Skipped 215 previous similar messages
Lustre: 13009:0:(ldlm_lib.c:866:target_handle_connect()) MGS: connection from
8226fbc1-0138-e464-46e9-4106014c8d32@10.100.60.97@o2ib2 t0 exp (null) cur 1318420879 last 0
Lustre: 13009:0:(ldlm_lib.c:866:target_handle_connect()) Skipped 583 previous similar messages
Lustre: 13009:0:(sec.c:1428:sptlrpc_import_sec_adapt()) import MGS-&gt; netid 50000: select flavor null
Lustre: 13009:0:(sec.c:1428:sptlrpc_import_sec_adapt()) Skipped 647 previous similar messages
LustreError: 12579:0:(lib-move.c:2633:LNetGet()) error sending GET to 12345-172.24.110.198@o2ib: -113
LustreError: 12579:0:(lib-move.c:2633:LNetGet()) Skipped 1 previous similar message
LustreError: 13512:0:(ldlm_lib.c:2123:target_send_reply_msg()) @@@ processing error (-19)  req@ffff88081fe70400
x1382292245433402/t0(0) o38-&gt;&lt;?&gt;@&lt;?&gt;:0/0 lens 368/0 e 0 to 0 dl 1318420988 ref 1
fl Interpret:/ffffffff/ffffffff rc -19/-1
LustreError: 13512:0:(ldlm_lib.c:2123:target_send_reply_msg()) Skipped 341 previous similar messages
LustreError: 137-5: UUID 'work1-MDT0000_UUID' is not available  for connect (no target)
LustreError: Skipped 326 previous similar messages
Lustre: 13528:0:(ldlm_lib.c:2023:target_queue_recovery_request()) Next recovery transno: 42949908740, current: 42949908740,
replaying: 0
Lustre: 13532:0:(ldlm_lib.c:2023:target_queue_recovery_request()) Next recovery transno: 42949908373, current: 42949908373,
replaying: 0
LustreError: 12579:0:(lib-move.c:2633:LNetGet()) error sending GET to 12345-172.24.110.198@o2ib: -113
LustreError: 12579:0:(lib-move.c:2633:LNetGet()) Skipped 1 previous similar message
Lustre: 13536:0:(ldlm_lib.c:2023:target_queue_recovery_request()) Next recovery transno: 42949908374, current: 42949908374,
replaying: 1
Lustre: store1-MDT0000: sending delayed replies to recovered clients
Lustre: 13511:0:(mds_lov.c:1014:mds_notify()) MDS mdd_obd-store1-MDT0000-0: in recovery, not resetting orphans
on store1-OST0000_UUID
Lustre: 13511:0:(mds_lov.c:1014:mds_notify()) Skipped 62 previous similar messages
Lustre: 13511:0:(mdd_orphans.c:360:orph_key_test_and_del()) Found orphan! Delete it
------------[ cut here ]------------
kernel BUG at fs/jbd2/transaction.c:1030!
Lustre: MDS mdd_obd-store1-MDT0000-0: store1-OST001e_UUID now active, resetting orphans
invalid opcode: 0000 [#1] SMP 
last sysfs file: /sys/devices/pci0000:80/0000:80:07.0/0000:86:00.1/host14/rport-14:0-0/target14:0:0/14:0:0:5/timeout
CPU 30 
Modules linked in: cmm(U) osd_ldiskfs(U) mdt(U) mdd(U) mds(U) fsfilt_ldiskfs(U) mgs(U) mgc(U) ldiskfs(U) lustre(U) lov(U)
osc(U) mdc(U) lquota(U) fid(U) fld(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) ipmi_devintf
Lustre: MDS mdd_obd-store1-MDT0000-0: store1-OST002e_UUID now active, resetting orphans
Lustre: Skipped 40 previous similar messages
 ipmi_si ipmi_msghandler nfs lockd fscache nfs_acl auth_rpcgss sunrpc acpi_cpufreq freq_table rdma_ucm(U) ib_sdp(U)
rdma_cm(U) iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U) mlx4_ib(U) mlx4_core(U) ib_mthca(U)
ib_mad(U) ib_core(U) dm_round_robin dm_multipath usbhid hid i2c_i801 i2c_core iTCO_wdt iTCO_vendor_support ehci_hcd
uhci_hcd ioatdma lpfc scsi_transport_fc scsi_tgt sg igb dca ext4 jbd2 sd_mod crc_t10dif ahci megaraid_sas dm_mod [last
unloaded: microcode]

Modules linked in: cmm(U) osd_ldiskfs(U) mdt(U) mdd(U) mds(U) fsfilt_ldiskfs(U) mgs(U) mgc(U) ldiskfs(U) lustre(U) lov(U)
osc(U) mdc(U) lquota(U) fid(U) fld(U) ko2iblnd(U) ptlrpc(U) obdclass(U) lnet(U) lvfs(U) libcfs(U) ipmi_devintf ipmi_si
ipmi_msghandler nfs lockd fscache nfs_acl auth_rpcgss sunrpc acpi_cpufreq freq_table rdma_ucm(U) ib_sdp(U) rdma_cm(U)
iw_cm(U) ib_addr(U) ib_ipoib(U) ib_cm(U) ib_sa(U) ipv6 ib_uverbs(U) ib_umad(U) mlx4_ib(U) mlx4_core(U) ib_mthca(U) ib_mad(U)
ib_core(U) dm_round_robin dm_multipath usbhid hid i2c_i801 i2c_core iTCO_wdt iTCO_vendor_support ehci_hcd uhci_hcd ioatdma
lpfc scsi_transport_fc scsi_tgt sg igb dca ext4 jbd2 sd_mod crc_t10dif ahci megaraid_sas dm_mod [last unloaded:
microcode]
Pid: 13511, comm: tgt_recov Not tainted 2.6.32-71.24.1.el6.Bull.23.x86_64 #1 bullx super-node
RIP: 0010:[&lt;ffffffffa00518ed&gt;]  [&lt;ffffffffa00518ed&gt;] jbd2_journal_dirty_metadata+0x10d/0x150
[jbd2]
RSP: 0018:ffff88082ec23190  EFLAGS: 00010246
RAX: ffff881830d86ac0 RBX: ffff881841975438 RCX: ffff8818419dfe98
RDX: 0000000000000000 RSI: ffff8818419dfe98 RDI: 0000000000000000
RBP: ffff88082ec231b0 R08: 3010000000000000 R09: e7a06811cf77a602
R10: 0000000000000000 R11: 00000000000001ad R12: ffff8818419dd438
R13: ffff8818419dfe98 R14: ffff88185a75c800 R15: ffff8818419de558
FS:  00007fc535a01700(0000) GS:ffff88109c7c0000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007f9cfa3a6000 CR3: 0000000001001000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process tgt_recov (pid: 13511, threadinfo ffff88082ec22000, task ffff88085b462440)
Stack:
 ffff881841975438 ffffffffa097e37f ffff8818419dfe98 ffff8818419de558
&lt;0&gt; ffff88082ec231f0 ffffffffa09433fb ffff88082ec231e0 ffffffff8107f36f
&lt;0&gt; ffff881841975438 0000000000000000 ffff88082ec2335c ffff8818419dfe98
Call Trace:
 [&lt;ffffffffa09433fb&gt;] __ldiskfs_handle_dirty_metadata+0x7b/0x100 [ldiskfs]
 [&lt;ffffffff8107f36f&gt;] ? wake_up_bit+0x2f/0x40
 [&lt;ffffffffa095150d&gt;] ldiskfs_getblk+0x15d/0x1f0 [ldiskfs]
 [&lt;ffffffffa09515b8&gt;] ldiskfs_bread+0x18/0x80 [ldiskfs]
 [&lt;ffffffffa09f0e47&gt;] fsfilt_ldiskfs_write_handle+0x147/0x340 [fsfilt_ldiskfs]
 [&lt;ffffffffa09f10fe&gt;] fsfilt_ldiskfs_write_record+0xbe/0x1a0 [fsfilt_ldiskfs]
 [&lt;ffffffffa04b9a03&gt;] ? cfs_alloc+0x63/0x90 [libcfs]
 [&lt;ffffffffa053318c&gt;] llog_lvfs_write_blob+0x2bc/0x460 [obdclass]
 [&lt;ffffffffa052e758&gt;] ? llog_init_handle+0xa18/0xa70 [obdclass]
 [&lt;ffffffff8106666b&gt;] ? round_jiffies_up+0x1b/0x20
 [&lt;ffffffffa05349fa&gt;] llog_lvfs_write_rec+0x40a/0xf00 [obdclass]
 [&lt;ffffffffa0531905&gt;] llog_cat_add_rec+0xf5/0x840 [obdclass]
 [&lt;ffffffffa05381a6&gt;] llog_obd_origin_add+0x56/0x190 [obdclass]
 [&lt;ffffffff8110c431&gt;] ? __alloc_pages_nodemask+0x111/0x850
 [&lt;ffffffffa0538381&gt;] llog_add+0xa1/0x3c0 [obdclass]
 [&lt;ffffffffa0538e64&gt;] ? __llog_ctxt_put+0x34/0x220 [obdclass]
 [&lt;ffffffff8114159a&gt;] ? kmem_getpages+0xba/0x170
 [&lt;ffffffffa082d0cc&gt;] lov_llog_origin_add+0xcc/0x640 [lov]
 [&lt;ffffffffa0538381&gt;] llog_add+0xa1/0x3c0 [obdclass]
 [&lt;ffffffffa05f1d29&gt;] mds_llog_origin_add+0xb9/0x320 [mds]
 [&lt;ffffffffa0538381&gt;] llog_add+0xa1/0x3c0 [obdclass]
 [&lt;ffffffffa05f2414&gt;] mds_llog_add_unlink+0x164/0x540 [mds]
 [&lt;ffffffffa05f2b26&gt;] mds_log_op_unlink+0x196/0x9a0 [mds]
 [&lt;ffffffffa072503b&gt;] ? osd_xattr_get+0xfb/0x170 [osd_ldiskfs]
 [&lt;ffffffffa0a0cc1e&gt;] mdd_unlink_log+0x4e/0x100 [mdd]
 [&lt;ffffffffa0a0f5d0&gt;] mdd_lov_destroy+0x130/0xf70 [mdd]
 [&lt;ffffffffa0725142&gt;] ? osd_attr_get+0x92/0x140 [osd_ldiskfs]
 [&lt;ffffffffa0a0180d&gt;] ? mdd_la_get+0xad/0xb0 [mdd]
 [&lt;ffffffffa0a16c8c&gt;] __mdd_orphan_cleanup+0x95c/0xae0 [mdd]
 [&lt;ffffffffa0841db1&gt;] ? lov_notify+0xde1/0x15e0 [lov]
 [&lt;ffffffffa0a28c08&gt;] mdd_recovery_complete+0x168/0x570 [mdd]
 [&lt;ffffffffa073cd19&gt;] ? cmm_key_init+0x59/0x190 [cmm]
 [&lt;ffffffffa073a17a&gt;] cmm_recovery_complete+0x3a/0x100 [cmm]
 [&lt;ffffffffa05773ab&gt;] ? lu_context_init+0xab/0x240 [obdclass]
 [&lt;ffffffffa0a4378e&gt;] mdt_postrecov+0x4e/0x130 [mdt]
 [&lt;ffffffffa0a46ca7&gt;] mdt_obd_postrecov+0xd7/0x100 [mdt]
 [&lt;ffffffffa0a50a10&gt;] ? mdt_recovery_handle+0x0/0x160 [mdt]
 [&lt;ffffffffa062d0e8&gt;] target_recovery_thread+0x938/0xf10 [ptlrpc]
 [&lt;ffffffff8100d1aa&gt;] child_rip+0xa/0x20
 [&lt;ffffffffa062c7b0&gt;] ? target_recovery_thread+0x0/0xf10 [ptlrpc]
 [&lt;ffffffff8100d1a0&gt;] ? child_rip+0x0/0x20
Code: c6 9c 03 00 00 4c 89 f7 e8 c1 80 41 e1 48 8b 33 ba 01 00 00 00 4c 89 e7 e8 91 eb ff ff 4c 89 f0 66 ff 00 66 66
90 e9 73 ff ff ff &lt;0f&gt; 0b eb fe 0f 0b eb fe 0f 0b 66 0f 1f 84 00 00 00 00 00 eb f5
RIP  [&lt;ffffffffa00518ed&gt;] jbd2_journal_dirty_metadata+0x10d/0x150 [jbd2]
 RSP &lt;ffff88082ec23190&gt;
crash&gt;

Comment by Zhenyu Xu [ 13/Oct/11 ]

It looks I underestimate the llog number mdd_lov_destroy() needs, it requires "stripe_count" of llog records instead of 1.

update patch set 8.

Comment by Patrick Valentin (Inactive) [ 20/Oct/11 ]

By the beginning of september, we delevered to our CEA customer an Efix containing the patch proposed for ~~LU-81~~ ticket, which is till in open state.
This patch contains the following line in "mdd_changelog_user_purge_cb()" routine in "lustre/mdd/mdd_device.c file":

mdd_txn_param_build(mcud->mcud_env, mdd, MDD_TXN_UNLINK_OP);

In the patch proposed for ~~LU-601~~ ticket, "mdd_txn_param_build()" routine has now an additional "int changelog_cnt" parameter.
We can also see in "orphan_object_destroy()" routine in "lustre/mdd/mdd_orphans.c" file that this patch adds a call to "mdd_log_txn_param_build()" with MDD_TXN_UNLINK_OP operation.

As we have to produce a new EFIX for CEA containing both ~~LU-81~~ and ~~LU-601~~, we have the following question about the call to "mdd_txn_param_build()" in "mdd_changelog_user_purge_cb()":
1) Do we have to keep this call to "mdd_txn_param_build()", and which value should we pass for "int changelog_cnt" parameter ?
2) Or do we have to replace it by a call to "mdd_log_txn_param_build()", and in this case which value do we have to pass for "md_object", "md_attr" and "changelog_cnt" parameters?

TIA
Patrick

Comment by Zhenyu Xu [ 20/Oct/11 ]

I've consult with ~~LU-81~~ patch author, it does not involve writing log record for LOV, so it can be kept as mdd_txn_param_build() with 0 as its changelog_cnt.

According to the review of patch set 10, a new patch set will be posted soon.

Comment by Patrick Valentin (Inactive) [ 20/Oct/11 ]

Hi,
Thanks a lot for the information.
I'm waiting for the next patch set to be reviewed before integrating it. The CEA EFIX must be available on november the 7th.

Thanks and regards,
Patrick

Comment by Bruno Faccini (Inactive) [ 27/Oct/11 ]

Very bad news from TGCC site, we now suffer (twice today until now !) the same problem no longer during orphan recovery but under normal operations with the following stack trace :
===================================================================================
PID: 8018 TASK: ffff881826c2af60 CPU: 1 COMMAND: "mdt_40"
#0 [ffff881826c30d80] machine_kexec at ffffffff8102e77b
#1 [ffff881826c30de0] crash_kexec at ffffffff810a6cd8
#2 [ffff881826c30eb0] oops_end at ffffffff8146aad0
#3 [ffff881826c30ee0] die at ffffffff8101021b
#4 [ffff881826c30f10] do_trap at ffffffff8146a3a4
#5 [ffff881826c30f70] do_invalid_op at ffffffff8100dda5
#6 [ffff881826c31010] invalid_op at ffffffff8100cf3b
[exception RIP: jbd2_journal_dirty_metadata+269]
RIP: ffffffffa04228ed RSP: ffff881826c310c0 RFLAGS: 00010246
RAX: ffff8810418ac280 RBX: ffff88103e6af7f8 RCX: ffff8817f06c0610
RDX: 0000000000000000 RSI: ffff8817f06c0610 RDI: 0000000000000000
RBP: ffff881826c310e0 R8: 2010000000000000 R9: e7f199f60af98402
R10: 0000000000000001 R11: 0000000000001970 R12: ffff880ffcdcad68
R13: ffff8817f06c0610 R14: ffff881058b77800 R15: 0000000000002000
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#7 [ffff881826c310e8] __ldiskfs_handle_dirty_metadata at ffffffffa043d3fb
#8 [ffff881826c31128] fsfilt_ldiskfs_write_handle at ffffffffa095fde7
#9 [ffff881826c311d8] fsfilt_ldiskfs_write_record at ffffffffa09600fe
#10 [ffff881826c31258] llog_lvfs_write_blob at ffffffffa054118c
#11 [ffff881826c31308] llog_lvfs_write_rec at ffffffffa05429fa
#12 [ffff881826c313e8] llog_cat_add_rec at ffffffffa053f905
#13 [ffff881826c31468] llog_obd_origin_add at ffffffffa05461a6
#14 [ffff881826c314c8] llog_add at ffffffffa0546381
#15 [ffff881826c31538] lov_llog_origin_add at ffffffffa083b0cc
#16 [ffff881826c315e8] llog_add at ffffffffa0546381
#17 [ffff881826c31658] mds_llog_origin_add at ffffffffa0975d29
#18 [ffff881826c316d8] llog_add at ffffffffa0546381
#19 [ffff881826c31748] mdd_log_op_setattr at ffffffffa099c80a
#20 [ffff881826c317e8] mdd_setattr_log at ffffffffa099d480
#21 [ffff881826c31858] mdd_attr_set at ffffffffa0993e07
#22 [ffff881826c31968] cml_attr_set at ffffffffa0a6f7af
#23 [ffff881826c319c8] mdt_attr_set at ffffffffa09fc6c4
#24 [ffff881826c31a58] mdt_reint_setattr at ffffffffa09fce1e
#25 [ffff881826c31ae8] mdt_reint_rec at ffffffffa09f864f
#26 [ffff881826c31b38] mdt_reint_internal at ffffffffa09efa04
#27 [ffff881826c31bc8] mdt_reint at ffffffffa09efd6c
#28 [ffff881826c31c18] mdt_handle_common at ffffffffa09e49f5
#29 [ffff881826c31c98] mdt_regular_handle at ffffffffa09e5a05
#30 [ffff881826c31ca8] ptlrpc_server_handle_request at ffffffffa06825f1
#31 [ffff881826c31de8] ptlrpc_main at ffffffffa0683992
#32 [ffff881826c31f48] kernel_thread at ffffffff8100d1aa
===================================================================================

seems that this new occurence/scenario occurs during a "chmod -R" command.

So we may trigger a new case of wrong block computation for chmod/setattr related Changelog/llog transaction ??...

Comment by Zhenyu Xu [ 27/Oct/11 ]

yes, another transaction credit miscalculation case. will update patch.

Comment by jacques-charles lafoucriere [ 02/Nov/11 ]

It seems very difficult to compute a safe size for all cases (recovery, replay, .....)
Is it possible to oversize this size or to have a dynamic way to set it so in case of bad number we can keep the system up and running ?