LU-8081 osd-ldiskfs: improve transaction debug message

Print the actual credit limits that were exceeded when complaining
on the console about problems with transaction credit accounting.

Ensure all transaction credit messages include the device name.

Signed-off-by: Andreas Dilger <andreas.dilger@intel.com>
Change-Id: I17125bb39ecaf699a722ac77bf29060cde3ebbe5
Reviewed-on: http://review.whamcloud.com/19865
Reviewed-by: Fan Yong <fan.yong@intel.com>
Tested-by: Jenkins
Tested-by: Maloo <hpdd-maloo@intel.com>
Reviewed-by: Alex Zhuravlev <alexey.zhuravlev@intel.com>
Reviewed-by: Oleg Drokin <oleg.drokin@intel.com>

diff --git a/lustre/osd-ldiskfs/osd_handler.c b/lustre/osd-ldiskfs/osd_handler.c
index fc4f980..4af9a09 100644 (file)
--- a/lustre/osd-ldiskfs/osd_handler.c
+++ b/lustre/osd-ldiskfs/osd_handler.c
@@ -1681,6 +1681,8 @@ static int osd_trans_start(const struct lu_env *env, struct dt_device *d,
                    time_after(jiffies, last_printed +
                               msecs_to_jiffies(60 * MSEC_PER_SEC)) &&
                    osd_transaction_size(dev) > 512) {
                    time_after(jiffies, last_printed +
                               msecs_to_jiffies(60 * MSEC_PER_SEC)) &&
                    osd_transaction_size(dev) > 512) {

+                       CWARN("%s: credits %u > trans_max %u\n", osd_name(dev),
+                             oh->ot_credits, osd_transaction_size(dev));

                        osd_trans_dump_creds(env, th);
                        libcfs_debug_dumpstack(NULL);
                        last_credits = oh->ot_credits;
                        osd_trans_dump_creds(env, th);
                        libcfs_debug_dumpstack(NULL);
                        last_credits = oh->ot_credits;

diff --git a/lustre/osd-ldiskfs/osd_internal.h b/lustre/osd-ldiskfs/osd_internal.h
index 3f685a7..9b9870d 100644 (file)
--- a/lustre/osd-ldiskfs/osd_internal.h
+++ b/lustre/osd-ldiskfs/osd_internal.h
@@ -930,7 +930,7 @@ static inline struct seq_server_site *osd_seq_site(struct osd_device *osd)
 
 static inline char *osd_name(struct osd_device *osd)
 {
 
 static inline char *osd_name(struct osd_device *osd)
 {

-       return osd->od_dt_dev.dd_lu_dev.ld_obd->obd_name;
+       return osd->od_svname;

 }
 
 static inline bool osd_is_ea_inode(struct inode *inode)
 }
 
 static inline bool osd_is_ea_inode(struct inode *inode)


@@ -1041,8 +1041,9 @@ static inline void osd_trans_exec_op(const struct lu_env *env,
                if (unlikely(ldiskfs_track_declares_assert))
                        LASSERT(op < OSD_OT_MAX);
                else {
                if (unlikely(ldiskfs_track_declares_assert))
                        LASSERT(op < OSD_OT_MAX);
                else {

-                       CWARN("%s: Invalid operation index %d\n",
-                             osd_name(osd_dt_dev(oh->ot_super.th_dev)), op);
+                       CWARN("%s: opcode %u: invalid value >= %u\n",
+                             osd_name(osd_dt_dev(oh->ot_super.th_dev)),
+                             op, OSD_OT_MAX);

                        libcfs_debug_dumpstack(NULL);
                        return;
                }
                        libcfs_debug_dumpstack(NULL);
                        return;
                }


@@ -1066,11 +1067,10 @@ static inline void osd_trans_exec_op(const struct lu_env *env,
                if (op == OSD_OT_REF_ADD &&
                    oti->oti_declare_ops_cred[OSD_OT_DESTROY] > 0)
                        goto proceed;
                if (op == OSD_OT_REF_ADD &&
                    oti->oti_declare_ops_cred[OSD_OT_DESTROY] > 0)
                        goto proceed;

+               CWARN("%s: opcode %u: credits = 0, rollback = %u\n",
+                     osd_name(osd_dt_dev(oh->ot_super.th_dev)), op, rb);

                osd_trans_dump_creds(env, th);
                osd_trans_dump_creds(env, th);

-               CERROR("%s: op = %d, rb = %d\n",
-                      osd_name(osd_dt_dev(oh->ot_super.th_dev)), op, rb);
-               if (unlikely(ldiskfs_track_declares_assert))
-                       LBUG();
+               LASSERT(!ldiskfs_track_declares_assert);

        }
 
 proceed:
        }
 
 proceed:


@@ -1078,18 +1078,17 @@ proceed:
        oti->oti_credits_before = oh->ot_handle->h_buffer_credits;
        left = oti->oti_declare_ops_cred[op] - oti->oti_declare_ops_used[op];
        if (unlikely(oti->oti_credits_before < left)) {
        oti->oti_credits_before = oh->ot_handle->h_buffer_credits;
        left = oti->oti_declare_ops_cred[op] - oti->oti_declare_ops_used[op];
        if (unlikely(oti->oti_credits_before < left)) {

+               CWARN("%s: opcode %u: before %u < left %u, rollback = %u\n",
+                     osd_name(osd_dt_dev(oh->ot_super.th_dev)), op,
+                     oti->oti_credits_before, left, rb);

                osd_trans_dump_creds(env, th);
                osd_trans_dump_creds(env, th);

-               CERROR("%s: op = %d, rb = %d\n",
-                      osd_name(osd_dt_dev(oh->ot_super.th_dev)), op, rb);

                /* on a very small fs (testing?) it's possible that
                 * the transaction can't fit 1/4 of journal, so we
                 * just request less credits (see osd_trans_start()).
                 * ignore the same case here */
                rb = osd_transaction_size(osd_dt_dev(th->th_dev));
                /* on a very small fs (testing?) it's possible that
                 * the transaction can't fit 1/4 of journal, so we
                 * just request less credits (see osd_trans_start()).
                 * ignore the same case here */
                rb = osd_transaction_size(osd_dt_dev(th->th_dev));

-               if (unlikely(oh->ot_credits < rb)) {
-                       if (unlikely(ldiskfs_track_declares_assert))
-                               LBUG();
-               }
+               if (unlikely(oh->ot_credits < rb))
+                       LASSERT(!ldiskfs_track_declares_assert);

        }
 }
 
        }
 }
 


@@ -1135,8 +1134,9 @@ static inline void osd_trans_exec_check(const struct lu_env *env,
                oti->oti_declare_ops_used[OSD_OT_QUOTA] += over;
                oti->oti_declare_ops_used[op] -= over;
        } else {
                oti->oti_declare_ops_used[OSD_OT_QUOTA] += over;
                oti->oti_declare_ops_used[op] -= over;
        } else {

-               CWARN("op %d: used %u, used now %u, reserved %u\n",
-                     op, oti->oti_declare_ops_used[op], used,
+               CWARN("%s: opcode %d: used %u, used now %u, reserved %u\n",
+                     osd_name(osd_dt_dev(oh->ot_super.th_dev)), op,
+                     oti->oti_declare_ops_used[op], used,

                      oti->oti_declare_ops_cred[op]);
                osd_trans_dump_creds(env, th);
                if (unlikely(ldiskfs_track_declares_assert))
                      oti->oti_declare_ops_cred[op]);
                osd_trans_dump_creds(env, th);
                if (unlikely(ldiskfs_track_declares_assert))