Skip to contentSkip to conversation

make jbd2 debug switch per device

RFC PATCH Superseded Chunguang Xu 3 participants 10 messages Jan 22, 2021 – Jan 26, 2021

Subsystems (2)
ext4 file system Journalling layer for block devices (JBD2)

v1 of 3 Superseded Latest is v3 →

lore
Share & tools
lore

Chunguang Xu

author
#0 lore raw

cover make jbd2 debug switch per device

On a multi-disk machine, because jbd2 debugging switch is global, this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

We can enable jbd2 debugging of a device in the following ways:
echo X > /proc/fs/jbd2/sdX/jbd2_debug

But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

Chunguang Xu (4):
jbd2: make jdb2_debug module parameter per device
jbd2: introduce some new log interfaces
jbd2: replace jbd_debug with the new log interface
ext4: replace jbd_debug with the new log interface

 fs/ext4/balloc.c      |   2 +-
 fs/ext4/ext4_jbd2.c   |   3 +-
 fs/ext4/fast_commit.c |  64 ++++++++++++----------
 fs/ext4/indirect.c    |   4 +-
 fs/ext4/inode.c       |   3 +-
 fs/ext4/namei.c       |  10 ++--
 fs/ext4/super.c       |  16 +++---
 fs/jbd2/checkpoint.c  |   6 +--
 fs/jbd2/commit.c      |  36 ++++++-------
 fs/jbd2/journal.c     | 122 +++++++++++++++++++++++++++---------------
 fs/jbd2/recovery.c    |  59 ++++++++++----------
 fs/jbd2/revoke.c      |   8 +--
 fs/jbd2/transaction.c |  35 ++++++------
 include/linux/jbd2.h  |  65 ++++++++++++++++------
 14 files changed, 257 insertions(+), 176 deletions(-)
Signature · 1 line
2.30.0
author
#1 lore raw

RFC PATCH 1/4 jbd2: make jdb2_debug module parameter per device

From: Chunguang Xu <[email protected]>

On a multi-disk machine, because jbd2's debugging switch is global,this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Signed-off-by Chunguang Xu <[email protected]>
---
 fs/jbd2/journal.c     | 63 +++++++++++++++++++++++++++++++++++--------
 fs/jbd2/transaction.c |  2 +-
 include/linux/jbd2.h  |  7 +++++
 3 files changed, 60 insertions(+), 12 deletions(-)
fs/jbd2/journal.c +52 -11
index 2dc944442802..ae147cc713c7 100644
@@ -48,14 +48,6 @@
 #include <linux/uaccess.h>
 #include <asm/page.h>
 
-#ifdef CONFIG_JBD2_DEBUG
-ushort jbd2_journal_enable_debug __read_mostly;
-EXPORT_SYMBOL(jbd2_journal_enable_debug);
-
-module_param_named(jbd2_debug, jbd2_journal_enable_debug, ushort, 0644);
-MODULE_PARM_DESC(jbd2_debug, "Debugging level for jbd2");
-#endif
-
 EXPORT_SYMBOL(jbd2_journal_extend);
 EXPORT_SYMBOL(jbd2_journal_stop);
 EXPORT_SYMBOL(jbd2_journal_lock_updates);

@@ -101,13 +93,13 @@ EXPORT_SYMBOL(jbd2_inode_cache);
 static int jbd2_journal_create_slab(size_t slab_size);
 
 #ifdef CONFIG_JBD2_DEBUG
-void __jbd2_debug(int level, const char *file, const char *func,
+void jbd2_log(int level, journal_t *j, const char *file, const char *func,
 		  unsigned int line, const char *fmt, ...)
 {
 	struct va_format vaf;
 	va_list args;
 
-	if (level > jbd2_journal_enable_debug)
+	if (!j || level > j->j_debug_level)
 		return;
 	va_start(args, fmt);
 	vaf.fmt = fmt;

@@ -115,7 +107,7 @@ void __jbd2_debug(int level, const char *file, const char *func,
 	printk(KERN_DEBUG "%s: (%s, %u): %pV", file, func, line, &vaf);
 	va_end(args);
 }
-EXPORT_SYMBOL(__jbd2_debug);
+EXPORT_SYMBOL(jbd2_log);
 #endif
 
 /* Checksumming functions */

@@ -1257,6 +1249,48 @@ static int jbd2_seq_info_release(struct inode *inode, struct file *file)
 	return seq_release(inode, file);
 }
 
+#ifdef CONFIG_JBD2_DEBUG
+static int jbd2_proc_debug_show(struct seq_file *m, void *v)
+{
+	journal_t *j = m->private;
+
+	seq_printf(m, "%d\n", j->j_debug_level);
+	return 0;
+}
+
+static int jbd2_proc_debug_open(struct inode *inode, struct file *file)
+{
+	journal_t *journal = PDE_DATA(inode);
+
+	return single_open(file, jbd2_proc_debug_show, journal);
+}
+
+static ssize_t jbd2_proc_debug_write(struct file *file,
+		const char __user *buffer, size_t count, loff_t *ppos)
+{
+	struct seq_file *seq = file->private_data;
+	journal_t *j = seq->private;
+	char c;
+
+	if (get_user(c, buffer))
+		return -EFAULT;
+
+	if (c < '0' || c > '5')
+		return -EINVAL;
+
+	j->j_debug_level = c - '0';
+	return count;
+}
+
+static const struct proc_ops jbd2_debug_proc_ops = {
+	.proc_open	= jbd2_proc_debug_open,
+	.proc_read	= seq_read,
+	.proc_write	= jbd2_proc_debug_write,
+	.proc_release	= single_release,
+	.proc_lseek	= seq_lseek,
+};
+#endif
+
 static const struct proc_ops jbd2_info_proc_ops = {
 	.proc_open	= jbd2_seq_info_open,
 	.proc_read	= seq_read,

@@ -1272,12 +1306,19 @@ static void jbd2_stats_proc_init(journal_t *journal)
 	if (journal->j_proc_entry) {
 		proc_create_data("info", S_IRUGO, journal->j_proc_entry,
 				 &jbd2_info_proc_ops, journal);
+#ifdef CONFIG_JBD2_DEBUG
+		proc_create_data("jbd2_debug", S_IRUGO, journal->j_proc_entry,
+				 &jbd2_debug_proc_ops, journal);
+#endif
 	}
 }
 
 static void jbd2_stats_proc_exit(journal_t *journal)
 {
 	remove_proc_entry("info", journal->j_proc_entry);
+#ifdef CONFIG_JBD2_DEBUG
+	remove_proc_entry("jbd2_debug", journal->j_proc_entry);
+#endif
 	remove_proc_entry(journal->j_devname, proc_jbd2_stats);
 }
fs/jbd2/transaction.c +1 -1
index 9396666b7314..f25c6ff16165 100644
@@ -150,7 +150,7 @@ static inline void update_t_max_wait(transaction_t *transaction,
 				     unsigned long ts)
 {
 #ifdef CONFIG_JBD2_DEBUG
-	if (jbd2_journal_enable_debug &&
+	if (transaction->t_journal->j_debug_level &&
 	    time_after(transaction->t_start, ts)) {
 		ts = jbd2_time_diff(ts, transaction->t_start);
 		spin_lock(&transaction->t_handle_lock);
include/linux/jbd2.h +7 -0
index 99d3cd051ac3..600a2ea8324a 100644
@@ -1211,6 +1211,13 @@ struct journal_s
 	 */
 	struct transaction_stats_s j_stats;
 
+#ifdef CONFIG_JBD2_DEBUG
+	/**
+	 * @j_debug_level: debugging level for jbd2.
+	 */
+	unsigned int j_debug_level;
+#endif
+
 	/**
 	 * @j_failed_commit: Failed journal commit ID.
 	 */
Signature · 1 line
2.30.0
#2 lore raw

Re: [RFC PATCH 1/4] jbd2: make jdb2_debug module parameter per device

I wonder if we should retain the existing module param as well apart from the new device specific logging switch? If that switch is enabled, we'll get jbd2 logs for all the devices. Given that the old jbd2_debug interface was a module param, I wonder somebody somewhere might have infrastructure on top of that to enable debugging for jbd2? And by removing this interface we may accidentally break them?

Quoted 52 lines · Chunguang Xu

From: Chunguang Xu <[email protected]>

On a multi-disk machine, because jbd2's debugging switch is global,this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Signed-off-by Chunguang Xu <[email protected]>
---
 fs/jbd2/journal.c     | 63 +++++++++++++++++++++++++++++++++++--------
 fs/jbd2/transaction.c |  2 +-
 include/linux/jbd2.h  |  7 +++++
 3 files changed, 60 insertions(+), 12 deletions(-)
fs/jbd2/journal.c +2 -10
index 2dc944442802..ae147cc713c7 100644
@@ -48,14 +48,6 @@
 #include <linux/uaccess.h>
 #include <asm/page.h>
 
-#ifdef CONFIG_JBD2_DEBUG
-ushort jbd2_journal_enable_debug __read_mostly;
-EXPORT_SYMBOL(jbd2_journal_enable_debug);
-
-module_param_named(jbd2_debug, jbd2_journal_enable_debug, ushort, 0644);
-MODULE_PARM_DESC(jbd2_debug, "Debugging level for jbd2");
-#endif
-
 EXPORT_SYMBOL(jbd2_journal_extend);
 EXPORT_SYMBOL(jbd2_journal_stop);
 EXPORT_SYMBOL(jbd2_journal_lock_updates);

@@ -101,13 +93,13 @@ EXPORT_SYMBOL(jbd2_inode_cache);
 static int jbd2_journal_create_slab(size_t slab_size);
 
 #ifdef CONFIG_JBD2_DEBUG
-void __jbd2_debug(int level, const char *file, const char *func,
+void jbd2_log(int level, journal_t *j, const char *file, const char *func,
                  unsigned int line, const char *fmt, ...)
 {
        struct va_format vaf;
        va_list args;
 
-       if (level > jbd2_journal_enable_debug)
+       if (!j || level > j->j_debug_level)
                return;
        va_start(args, fmt);
        vaf.fmt = fmt;

fs/jbd2/journal.c void __jbd2_debug(int level, const char *file, const char *func, · line 107

Quoted 1 line
fs/jbd2/journal.c +0 -0
@@ -115,7 +107,7 @@ void __jbd2_debug(int level, const char *file, const char *func,
        printk(KERN_DEBUG "%s: (%s, %u): %pV", file, func, line, &vaf);

Now that you have journal_t passed to jbd2_log, it would also be good to print the name of the device in this message. I think you can use j->j_devname for that.

Thanks,
Harshad

Quoted 110 lines
fs/jbd2/journal.c +50 -1
        va_end(args);
 }
-EXPORT_SYMBOL(__jbd2_debug);
+EXPORT_SYMBOL(jbd2_log);
 #endif
 
 /* Checksumming functions */

@@ -1257,6 +1249,48 @@ static int jbd2_seq_info_release(struct inode *inode, struct file *file)
        return seq_release(inode, file);
 }
 
+#ifdef CONFIG_JBD2_DEBUG
+static int jbd2_proc_debug_show(struct seq_file *m, void *v)
+{
+       journal_t *j = m->private;
+
+       seq_printf(m, "%d\n", j->j_debug_level);
+       return 0;
+}
+
+static int jbd2_proc_debug_open(struct inode *inode, struct file *file)
+{
+       journal_t *journal = PDE_DATA(inode);
+
+       return single_open(file, jbd2_proc_debug_show, journal);
+}
+
+static ssize_t jbd2_proc_debug_write(struct file *file,
+               const char __user *buffer, size_t count, loff_t *ppos)
+{
+       struct seq_file *seq = file->private_data;
+       journal_t *j = seq->private;
+       char c;
+
+       if (get_user(c, buffer))
+               return -EFAULT;
+
+       if (c < '0' || c > '5')
+               return -EINVAL;
+
+       j->j_debug_level = c - '0';
+       return count;
+}
+
+static const struct proc_ops jbd2_debug_proc_ops = {
+       .proc_open      = jbd2_proc_debug_open,
+       .proc_read      = seq_read,
+       .proc_write     = jbd2_proc_debug_write,
+       .proc_release   = single_release,
+       .proc_lseek     = seq_lseek,
+};
+#endif
+
 static const struct proc_ops jbd2_info_proc_ops = {
        .proc_open      = jbd2_seq_info_open,
        .proc_read      = seq_read,

@@ -1272,12 +1306,19 @@ static void jbd2_stats_proc_init(journal_t *journal)
        if (journal->j_proc_entry) {
                proc_create_data("info", S_IRUGO, journal->j_proc_entry,
                                 &jbd2_info_proc_ops, journal);
+#ifdef CONFIG_JBD2_DEBUG
+               proc_create_data("jbd2_debug", S_IRUGO, journal->j_proc_entry,
+                                &jbd2_debug_proc_ops, journal);
+#endif
        }
 }
 
 static void jbd2_stats_proc_exit(journal_t *journal)
 {
        remove_proc_entry("info", journal->j_proc_entry);
+#ifdef CONFIG_JBD2_DEBUG
+       remove_proc_entry("jbd2_debug", journal->j_proc_entry);
+#endif
        remove_proc_entry(journal->j_devname, proc_jbd2_stats);
 }
fs/jbd2/transaction.c +1 -1
index 9396666b7314..f25c6ff16165 100644
@@ -150,7 +150,7 @@ static inline void update_t_max_wait(transaction_t *transaction,
                                     unsigned long ts)
 {
 #ifdef CONFIG_JBD2_DEBUG
-       if (jbd2_journal_enable_debug &&
+       if (transaction->t_journal->j_debug_level &&
            time_after(transaction->t_start, ts)) {
                ts = jbd2_time_diff(ts, transaction->t_start);
                spin_lock(&transaction->t_handle_lock);
include/linux/jbd2.h +7 -1
index 99d3cd051ac3..600a2ea8324a 100644
@@ -1211,6 +1211,13 @@ struct journal_s
         */
        struct transaction_stats_s j_stats;
 
+#ifdef CONFIG_JBD2_DEBUG
+       /**
+        * @j_debug_level: debugging level for jbd2.
+        */
+       unsigned int j_debug_level;
+#endif
+
        /**
         * @j_failed_commit: Failed journal commit ID.
         */
--

2.30.0

author
#3 lore raw

Re: [RFC PATCH 1/4] jbd2: make jdb2_debug module parameter per device

En...，your idea maybe better, thanks for your time.

harshad shirwadkar wrote on 2021/1/23 3:00:

Quoted 177 lines

I wonder if we should retain the existing module param as well apart from the new device specific logging switch? If that switch is enabled, we'll get jbd2 logs for all the devices. Given that the old jbd2_debug interface was a module param, I wonder somebody somewhere might have infrastructure on top of that to enable debugging for jbd2? And by removing this interface we may accidentally break them?

Quoted 52 lines · Chunguang Xu

From: Chunguang Xu <[email protected]>

On a multi-disk machine, because jbd2's debugging switch is global,this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Signed-off-by Chunguang Xu <[email protected]>
---
 fs/jbd2/journal.c     | 63 +++++++++++++++++++++++++++++++++++--------
 fs/jbd2/transaction.c |  2 +-
 include/linux/jbd2.h  |  7 +++++
 3 files changed, 60 insertions(+), 12 deletions(-)
fs/jbd2/journal.c +2 -10
index 2dc944442802..ae147cc713c7 100644
@@ -48,14 +48,6 @@
 #include <linux/uaccess.h>
 #include <asm/page.h>
 
-#ifdef CONFIG_JBD2_DEBUG
-ushort jbd2_journal_enable_debug __read_mostly;
-EXPORT_SYMBOL(jbd2_journal_enable_debug);
-
-module_param_named(jbd2_debug, jbd2_journal_enable_debug, ushort, 0644);
-MODULE_PARM_DESC(jbd2_debug, "Debugging level for jbd2");
-#endif
-
 EXPORT_SYMBOL(jbd2_journal_extend);
 EXPORT_SYMBOL(jbd2_journal_stop);
 EXPORT_SYMBOL(jbd2_journal_lock_updates);

@@ -101,13 +93,13 @@ EXPORT_SYMBOL(jbd2_inode_cache);
 static int jbd2_journal_create_slab(size_t slab_size);
 
 #ifdef CONFIG_JBD2_DEBUG
-void __jbd2_debug(int level, const char *file, const char *func,
+void jbd2_log(int level, journal_t *j, const char *file, const char *func,
                  unsigned int line, const char *fmt, ...)
 {
        struct va_format vaf;
        va_list args;
 
-       if (level > jbd2_journal_enable_debug)
+       if (!j || level > j->j_debug_level)
                return;
        va_start(args, fmt);
        vaf.fmt = fmt;

fs/jbd2/journal.c void __jbd2_debug(int level, const char *file, const char *func, · line 107

Quoted 1 line
fs/jbd2/journal.c +0 -0
@@ -115,7 +107,7 @@ void __jbd2_debug(int level, const char *file, const char *func,
        printk(KERN_DEBUG "%s: (%s, %u): %pV", file, func, line, &vaf);

Now that you have journal_t passed to jbd2_log, it would also be good to print the name of the device in this message. I think you can use j->j_devname for that.

Thanks,
Harshad

Quoted 110 lines
fs/jbd2/journal.c +50 -1
        va_end(args);
 }
-EXPORT_SYMBOL(__jbd2_debug);
+EXPORT_SYMBOL(jbd2_log);
 #endif
 
 /* Checksumming functions */

@@ -1257,6 +1249,48 @@ static int jbd2_seq_info_release(struct inode *inode, struct file *file)
        return seq_release(inode, file);
 }
 
+#ifdef CONFIG_JBD2_DEBUG
+static int jbd2_proc_debug_show(struct seq_file *m, void *v)
+{
+       journal_t *j = m->private;
+
+       seq_printf(m, "%d\n", j->j_debug_level);
+       return 0;
+}
+
+static int jbd2_proc_debug_open(struct inode *inode, struct file *file)
+{
+       journal_t *journal = PDE_DATA(inode);
+
+       return single_open(file, jbd2_proc_debug_show, journal);
+}
+
+static ssize_t jbd2_proc_debug_write(struct file *file,
+               const char __user *buffer, size_t count, loff_t *ppos)
+{
+       struct seq_file *seq = file->private_data;
+       journal_t *j = seq->private;
+       char c;
+
+       if (get_user(c, buffer))
+               return -EFAULT;
+
+       if (c < '0' || c > '5')
+               return -EINVAL;
+
+       j->j_debug_level = c - '0';
+       return count;
+}
+
+static const struct proc_ops jbd2_debug_proc_ops = {
+       .proc_open      = jbd2_proc_debug_open,
+       .proc_read      = seq_read,
+       .proc_write     = jbd2_proc_debug_write,
+       .proc_release   = single_release,
+       .proc_lseek     = seq_lseek,
+};
+#endif
+
 static const struct proc_ops jbd2_info_proc_ops = {
        .proc_open      = jbd2_seq_info_open,
        .proc_read      = seq_read,

@@ -1272,12 +1306,19 @@ static void jbd2_stats_proc_init(journal_t *journal)
        if (journal->j_proc_entry) {
                proc_create_data("info", S_IRUGO, journal->j_proc_entry,
                                 &jbd2_info_proc_ops, journal);
+#ifdef CONFIG_JBD2_DEBUG
+               proc_create_data("jbd2_debug", S_IRUGO, journal->j_proc_entry,
+                                &jbd2_debug_proc_ops, journal);
+#endif
        }
 }
 
 static void jbd2_stats_proc_exit(journal_t *journal)
 {
        remove_proc_entry("info", journal->j_proc_entry);
+#ifdef CONFIG_JBD2_DEBUG
+       remove_proc_entry("jbd2_debug", journal->j_proc_entry);
+#endif
        remove_proc_entry(journal->j_devname, proc_jbd2_stats);
 }
fs/jbd2/transaction.c +1 -1
index 9396666b7314..f25c6ff16165 100644
@@ -150,7 +150,7 @@ static inline void update_t_max_wait(transaction_t *transaction,
                                     unsigned long ts)
 {
 #ifdef CONFIG_JBD2_DEBUG
-       if (jbd2_journal_enable_debug &&
+       if (transaction->t_journal->j_debug_level &&
            time_after(transaction->t_start, ts)) {
                ts = jbd2_time_diff(ts, transaction->t_start);
                spin_lock(&transaction->t_handle_lock);
include/linux/jbd2.h +7 -1
index 99d3cd051ac3..600a2ea8324a 100644
@@ -1211,6 +1211,13 @@ struct journal_s
         */
        struct transaction_stats_s j_stats;
 
+#ifdef CONFIG_JBD2_DEBUG
+       /**
+        * @j_debug_level: debugging level for jbd2.
+        */
+       unsigned int j_debug_level;
+#endif
+
        /**
         * @j_failed_commit: Failed journal commit ID.
         */
--

2.30.0

author
#4 lore raw

RFC PATCH 2/4 jbd2: introduce some new log interfaces

In reply to Chunguang Xu

From: Chunguang Xu <[email protected]>

Compared to directly using numbers to indicate levels, using abstract error, warn, notice, info, debug to indicate levels may be more convenient for code reading and writing. Similar to other kernel modules, some basic log interfaces are introduced.

Signed-off-by Chunguang Xu <[email protected]>
---
 include/linux/jbd2.h | 58 +++++++++++++++++++++++++++++++-------------
 1 file changed, 41 insertions(+), 17 deletions(-)
include/linux/jbd2.h +41 -17
index 600a2ea8324a..d3d3ed33be30 100644
@@ -47,23 +47,6 @@
  */
 #define JBD2_DEFAULT_MAX_COMMIT_AGE 5
 
-#ifdef CONFIG_JBD2_DEBUG
-/*
- * Define JBD2_EXPENSIVE_CHECKING to enable more expensive internal
- * consistency checks.  By default we don't do this unless
- * CONFIG_JBD2_DEBUG is on.
- */
-#define JBD2_EXPENSIVE_CHECKING
-extern ushort jbd2_journal_enable_debug;
-void __jbd2_debug(int level, const char *file, const char *func,
-		  unsigned int line, const char *fmt, ...);
-
-#define jbd_debug(n, fmt, a...) \
-	__jbd2_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a)
-#else
-#define jbd_debug(n, fmt, a...)    /**/
-#endif
-
 extern void *jbd2_alloc(size_t size, gfp_t flags);
 extern void jbd2_free(void *ptr, size_t size);
 

@@ -104,6 +87,47 @@ typedef struct jbd2_journal_handle handle_t;	/* Atomic operation type */
  * This is an opaque datatype.
  **/
 typedef struct journal_s	journal_t;	/* Journal control structure */
+
+#ifdef CONFIG_JBD2_DEBUG
+/*
+ * Define JBD2_EXPENSIVE_CHECKING to enable more expensive internal
+ * consistency checks.  By default we don't do this unless
+ * CONFIG_JBD2_DEBUG is on.
+ */
+#define JBD2_EXPENSIVE_CHECKING
+void jbd2_log(int level, journal_t *j, const char *file, const char *func,
+		      unsigned int line, const char *fmt, ...);
+
+#define JBD2_ERR	1	/* error conditions */
+#define JBD2_WARN	2	/* warning conditions */
+#define JBD2_NOTICE	3	/* normal but significant condition */
+#define JBD2_INFO	4	/* informational */
+#define JBD2_DEBUG	5	/* debug-level messages */
+
+#define jbd2_err(j, fmt, a...)						\
+	jbd2_log(JBD2_ERR, j, __FILE__, __func__, __LINE__, (fmt), ##a)
+
+#define jbd2_warn(j, fmt, a...)						\
+	jbd2_log(JBD2_WARN, j, __FILE__, __func__, __LINE__, (fmt), ##a)
+
+#define jbd2_notice(j, fmt, a...)					\
+	jbd2_log(JBD2_NOTICE, j, __FILE__, __func__, __LINE__, (fmt), ##a)
+
+#define jbd2_info(j, fmt, a...)						\
+	jbd2_log(JBD2_INFO, j, __FILE__, __func__, __LINE__, (fmt), ##a)
+
+#define jbd2_debug(j, fmt, a...)					\
+	jbd2_log(JBD2_DEBUG, j, __FILE__, __func__, __LINE__, (fmt), ##a)
+
+#else
+
+#define jbd2_err(j, fmt, a...)
+#define jbd2_warn(j, fmt, a...)
+#define jbd2_notice(j, fmt, a...)
+#define jbd2_info(j, fmt, a...)
+#define jbd2_debug(j, fmt, a...)
+
+#endif
 #endif
 
 /*
Signature · 1 line
2.30.0
author
#5 lore raw

RFC PATCH 3/4 jbd2: replace jbd_debug with the new log interface

In reply to Chunguang Xu

From: Chunguang Xu <[email protected]>

In order to support jbd2 per device debugging switch, here we need to replace jbd_debug with a new log interface. But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

Signed-off-by Chunguang Xu <[email protected]>
---
 fs/jbd2/checkpoint.c  |  6 ++---
 fs/jbd2/commit.c      | 36 +++++++++++++-------------
 fs/jbd2/journal.c     | 59 ++++++++++++++++++++-----------------------
 fs/jbd2/recovery.c    | 59 +++++++++++++++++++++++--------------------
 fs/jbd2/revoke.c      |  8 +++---
 fs/jbd2/transaction.c | 33 ++++++++++++------------
 6 files changed, 100 insertions(+), 101 deletions(-)
fs/jbd2/checkpoint.c +3 -3
index 472932b9e6bc..916f0c495805 100644
@@ -211,7 +211,7 @@ int jbd2_log_do_checkpoint(journal_t *journal)
 	tid_t			this_tid;
 	int			result, batch_count = 0;
 
-	jbd_debug(1, "Start checkpoint\n");
+	jbd2_err(journal, "Start checkpoint\n");
 
 	/*
 	 * First thing: if there are any transactions in the log which

@@ -220,7 +220,7 @@ int jbd2_log_do_checkpoint(journal_t *journal)
 	 */
 	result = jbd2_cleanup_journal_tail(journal);
 	trace_jbd2_checkpoint(journal, result);
-	jbd_debug(1, "cleanup_journal_tail returned %d\n", result);
+	jbd2_err(journal, "cleanup_journal_tail returned %d\n", result);
 	if (result <= 0)
 		return result;
 

@@ -676,5 +676,5 @@ void __jbd2_journal_drop_transaction(journal_t *journal, transaction_t *transact
 
 	trace_jbd2_drop_transaction(journal, transaction);
 
-	jbd_debug(1, "Dropping transaction %d, all done\n", transaction->t_tid);
+	jbd2_err(journal, "Dropping transaction %d, all done\n", transaction->t_tid);
 }
fs/jbd2/commit.c +18 -18
index b121d7d434c6..47b7019268ed 100644
@@ -419,7 +419,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 
 	/* Do we need to erase the effects of a prior jbd2_journal_flush? */
 	if (journal->j_flags & JBD2_FLUSHED) {
-		jbd_debug(3, "super block updated\n");
+		jbd2_notice(journal, "super block updated\n");
 		mutex_lock_io(&journal->j_checkpoint_mutex);
 		/*
 		 * We hold j_checkpoint_mutex so tail cannot change under us.

@@ -433,7 +433,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 						REQ_SYNC);
 		mutex_unlock(&journal->j_checkpoint_mutex);
 	} else {
-		jbd_debug(3, "superblock not updated\n");
+		jbd2_notice(journal, "superblock not updated\n");
 	}
 
 	J_ASSERT(journal->j_running_transaction != NULL);

@@ -465,7 +465,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	commit_transaction = journal->j_running_transaction;
 
 	trace_jbd2_start_commit(journal, commit_transaction);
-	jbd_debug(1, "JBD2: starting commit of transaction %d\n",
+	jbd2_err(journal, "JBD2: starting commit of transaction %d\n",
 			commit_transaction->t_tid);
 
 	write_lock(&journal->j_state_lock);

@@ -549,7 +549,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	__jbd2_journal_clean_checkpoint_list(journal, false);
 	spin_unlock(&journal->j_list_lock);
 
-	jbd_debug(3, "JBD2: commit phase 1\n");
+	jbd2_notice(journal, "JBD2: commit phase 1\n");
 
 	/*
 	 * Clear revoked flag to reflect there is no revoked buffers

@@ -582,7 +582,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	wake_up(&journal->j_wait_transaction_locked);
 	write_unlock(&journal->j_state_lock);
 
-	jbd_debug(3, "JBD2: commit phase 2a\n");
+	jbd2_notice(journal, "JBD2: commit phase 2a\n");
 
 	/*
 	 * Now start flushing things to disk, in the order they appear

@@ -595,7 +595,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	blk_start_plug(&plug);
 	jbd2_journal_write_revoke_records(commit_transaction, &log_bufs);
 
-	jbd_debug(3, "JBD2: commit phase 2b\n");
+	jbd2_notice(journal, "JBD2: commit phase 2b\n");
 
 	/*
 	 * Way to go: we have now written out all of the data for a

@@ -651,7 +651,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 		if (!descriptor) {
 			J_ASSERT (bufs == 0);
 
-			jbd_debug(4, "JBD2: get descriptor\n");
+			jbd2_info(journal, "JBD2: get descriptor\n");
 
 			descriptor = jbd2_journal_get_descriptor_buffer(
 							commit_transaction,

@@ -661,9 +661,9 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 				continue;
 			}
 
-			jbd_debug(4, "JBD2: got buffer %llu (%p)\n",
-				(unsigned long long)descriptor->b_blocknr,
-				descriptor->b_data);
+			jbd2_info(journal, "JBD2: got buffer %llu (%p)\n",
+				  (unsigned long long)descriptor->b_blocknr,
+				  descriptor->b_data);
 			tagp = &descriptor->b_data[sizeof(journal_header_t)];
 			space_left = descriptor->b_size -
 						sizeof(journal_header_t);

@@ -746,7 +746,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 		    commit_transaction->t_buffers == NULL ||
 		    space_left < tag_bytes + 16 + csum_size) {
 
-			jbd_debug(4, "JBD2: Submit %d IOs\n", bufs);
+			jbd2_info(journal, "JBD2: Submit %d IOs\n", bufs);
 
 			/* Write an end-of-descriptor marker before
                            submitting the IOs.  "tag" still points to

@@ -848,7 +848,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	   so we incur less scheduling load.
 	*/
 
-	jbd_debug(3, "JBD2: commit phase 3\n");
+	jbd2_notice(journal, "JBD2: commit phase 3\n");
 
 	while (!list_empty(&io_bufs)) {
 		struct buffer_head *bh = list_entry(io_bufs.prev,

@@ -891,7 +891,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 
 	J_ASSERT (commit_transaction->t_shadow_list == NULL);
 
-	jbd_debug(3, "JBD2: commit phase 4\n");
+	jbd2_notice(journal, "JBD2: commit phase 4\n");
 
 	/* Here we wait for the revoke record and descriptor record buffers */
 	while (!list_empty(&log_bufs)) {

@@ -915,7 +915,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	if (err)
 		jbd2_journal_abort(journal, err);
 
-	jbd_debug(3, "JBD2: commit phase 5\n");
+	jbd2_notice(journal, "JBD2: commit phase 5\n");
 	write_lock(&journal->j_state_lock);
 	J_ASSERT(commit_transaction->t_state == T_COMMIT_DFLUSH);
 	commit_transaction->t_state = T_COMMIT_JFLUSH;

@@ -954,7 +954,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
            transaction can be removed from any checkpoint list it was on
            before. */
 
-	jbd_debug(3, "JBD2: commit phase 6\n");
+	jbd2_notice(journal, "JBD2: commit phase 6\n");
 
 	J_ASSERT(list_empty(&commit_transaction->t_inode_list));
 	J_ASSERT(commit_transaction->t_buffers == NULL);

@@ -1131,7 +1131,7 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 
 	/* Done with this transaction! */
 
-	jbd_debug(3, "JBD2: commit phase 7\n");
+	jbd2_notice(journal, "JBD2: commit phase 7\n");
 
 	J_ASSERT(commit_transaction->t_state == T_COMMIT_JFLUSH);
 

@@ -1173,8 +1173,8 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 		journal->j_fc_cleanup_callback(journal, 1);
 
 	trace_jbd2_end_commit(journal, commit_transaction);
-	jbd_debug(1, "JBD2: commit %d complete, head %d\n",
-		  journal->j_commit_sequence, journal->j_tail_sequence);
+	jbd2_err(journal, "JBD2: commit %d complete, head %d\n",
+		 journal->j_commit_sequence, journal->j_tail_sequence);
 
 	write_lock(&journal->j_state_lock);
 	journal->j_flags &= ~JBD2_FULL_COMMIT_ONGOING;
fs/jbd2/journal.c +27 -32

157 lines not on this page · raw message

fs/jbd2/recovery.c +31 -28

143 lines not on this page · raw message

fs/jbd2/revoke.c +4 -4
index fa608788b93d..777ac701a56f 100644
@@ -398,7 +398,7 @@ int jbd2_journal_revoke(handle_t *handle, unsigned long long blocknr,
 	}
 	handle->h_revoke_credits--;
 
-	jbd_debug(2, "insert revoke for block %llu, bh_in=%p\n",blocknr, bh_in);
+	jbd2_warn(journal, "insert revoke for block %llu, bh_in=%p\n", blocknr, bh_in);
 	err = insert_revoke_hash(journal, blocknr,
 				handle->h_transaction->t_tid);
 	BUFFER_TRACE(bh_in, "exit");

@@ -428,7 +428,7 @@ int jbd2_journal_cancel_revoke(handle_t *handle, struct journal_head *jh)
 	int did_revoke = 0;	/* akpm: debug */
 	struct buffer_head *bh = jh2bh(jh);
 
-	jbd_debug(4, "journal_head %p, cancelling revoke\n", jh);
+	jbd2_info(journal, "journal_head %p, cancelling revoke\n", jh);
 
 	/* Is the existing Revoke bit valid?  If so, we trust it, and
 	 * only perform the full cancel if the revoke bit is set.  If

@@ -444,7 +444,7 @@ int jbd2_journal_cancel_revoke(handle_t *handle, struct journal_head *jh)
 	if (need_cancel) {
 		record = find_revoke_record(journal, bh->b_blocknr);
 		if (record) {
-			jbd_debug(4, "cancelled existing revoke on "
+			jbd2_info(journal, "cancelled existing revoke on "
 				  "blocknr %llu\n", (unsigned long long)bh->b_blocknr);
 			spin_lock(&journal->j_revoke_lock);
 			list_del(&record->hash);

@@ -560,7 +560,7 @@ void jbd2_journal_write_revoke_records(transaction_t *transaction,
 	}
 	if (descriptor)
 		flush_descriptor(journal, descriptor, offset);
-	jbd_debug(1, "Wrote %d revoke records\n", count);
+	jbd2_err(journal, "Wrote %d revoke records\n", count);
 }
 
 /*
fs/jbd2/transaction.c +17 -16
index f25c6ff16165..1eb6261c9faa 100644
@@ -362,7 +362,7 @@ static int start_this_handle(journal_t *journal, handle_t *handle,
 			return -ENOMEM;
 	}
 
-	jbd_debug(3, "New handle %p going live.\n", handle);
+	jbd2_notice(journal, "New handle %p going live.\n", handle);
 
 	/*
 	 * We need to hold j_state_lock until t_updates has been incremented,

@@ -436,7 +436,7 @@ static int start_this_handle(journal_t *journal, handle_t *handle,
 	handle->h_start_jiffies = jiffies;
 	atomic_inc(&transaction->t_updates);
 	atomic_inc(&transaction->t_handle_count);
-	jbd_debug(4, "Handle %p given %d credits (total %d, free %lu)\n",
+	jbd2_info(journal, "Handle %p given %d credits (total %d, free %lu)\n",
 		  handle, blocks,
 		  atomic_read(&transaction->t_outstanding_credits),
 		  jbd2_log_space_left(journal));

@@ -657,8 +657,8 @@ int jbd2_journal_extend(handle_t *handle, int nblocks, int revoke_records)
 
 	/* Don't extend a locked-down transaction! */
 	if (transaction->t_state != T_RUNNING) {
-		jbd_debug(3, "denied handle %p %d blocks: "
-			  "transaction not running\n", handle, nblocks);
+		jbd2_notice(journal, "denied handle %p %d blocks: "
+			    "transaction not running\n", handle, nblocks);
 		goto error_out;
 	}
 

@@ -673,8 +673,8 @@ int jbd2_journal_extend(handle_t *handle, int nblocks, int revoke_records)
 				   &transaction->t_outstanding_credits);
 
 	if (wanted > journal->j_max_transaction_buffers) {
-		jbd_debug(3, "denied handle %p %d blocks: "
-			  "transaction too large\n", handle, nblocks);
+		jbd2_notice(journal, "denied handle %p %d blocks: "
+			    "transaction too large\n", handle, nblocks);
 		atomic_sub(nblocks, &transaction->t_outstanding_credits);
 		goto unlock;
 	}

@@ -691,7 +691,7 @@ int jbd2_journal_extend(handle_t *handle, int nblocks, int revoke_records)
 	handle->h_revoke_credits_requested += revoke_records;
 	result = 0;
 
-	jbd_debug(3, "extended handle %p by %d\n", handle, nblocks);
+	jbd2_notice(journal, "extended handle %p by %d\n", handle, nblocks);
 unlock:
 	spin_unlock(&transaction->t_handle_lock);
 error_out:

@@ -781,7 +781,7 @@ int jbd2__journal_restart(handle_t *handle, int nblocks, int revoke_records,
 	 * First unlink the handle from its current transaction, and start the
 	 * commit on that.
 	 */
-	jbd_debug(2, "restarting handle %p\n", handle);
+	jbd2_warn(journal, "restarting handle %p\n", handle);
 	stop_this_handle(handle);
 	handle->h_transaction = NULL;
 

@@ -948,7 +948,7 @@ do_get_write_access(handle_t *handle, struct journal_head *jh,
 
 	journal = transaction->t_journal;
 
-	jbd_debug(5, "journal_head %p, force_copy %d\n", jh, force_copy);
+	jbd2_debug(journal, "journal_head %p, force_copy %d\n", jh, force_copy);
 
 	JBUFFER_TRACE(jh, "entry");
 repeat:

@@ -1240,13 +1240,13 @@ int jbd2_journal_get_create_access(handle_t *handle, struct buffer_head *bh)
 	struct journal_head *jh = jbd2_journal_add_journal_head(bh);
 	int err;
 
-	jbd_debug(5, "journal_head %p\n", jh);
 	err = -EROFS;
 	if (is_handle_aborted(handle))
 		goto out;
 	journal = transaction->t_journal;
 	err = 0;
 
+	jbd2_debug(journal, "journal_head %p\n", jh);
 	JBUFFER_TRACE(jh, "entry");
 	/*
 	 * The buffer may already belong to this transaction due to pre-zeroing

@@ -1465,7 +1465,7 @@ int jbd2_journal_dirty_metadata(handle_t *handle, struct buffer_head *bh)
 	 * of the running transaction.
 	 */
 	jh = bh2jh(bh);
-	jbd_debug(5, "journal_head %p\n", jh);
+	jbd2_debug(transaction->t_journal, "journal_head %p\n", jh);
 	JBUFFER_TRACE(jh, "entry");
 
 	/*

@@ -1787,8 +1787,9 @@ int jbd2_journal_stop(handle_t *handle)
 	pid_t pid;
 
 	if (--handle->h_ref > 0) {
-		jbd_debug(4, "h_ref %d -> %d\n", handle->h_ref + 1,
-						 handle->h_ref);
+		jbd2_info(transaction->t_journal,
+			  "h_ref %d -> %d\n", handle->h_ref + 1,
+			  handle->h_ref);
 		if (is_handle_aborted(handle))
 			return -EIO;
 		return 0;

@@ -1807,7 +1808,7 @@ int jbd2_journal_stop(handle_t *handle)
 	if (is_handle_aborted(handle))
 		err = -EIO;
 
-	jbd_debug(4, "Handle %p going down\n", handle);
+	jbd2_info(journal, "Handle %p going down\n", handle);
 	trace_jbd2_handle_stats(journal->j_fs_dev->bd_dev,
 				tid, handle->h_type, handle->h_line_no,
 				jiffies - handle->h_start_jiffies,

@@ -1885,7 +1886,7 @@ int jbd2_journal_stop(handle_t *handle)
 		 * completes the commit thread, it just doesn't write
 		 * anything to disk. */
 
-		jbd_debug(2, "transaction too old, requesting commit for "
+		jbd2_warn(journal, "transaction too old, requesting commit for "
 					"handle %p\n", handle);
 		/* This is non-blocking */
 		jbd2_log_start_commit(journal, tid);

@@ -2649,7 +2650,7 @@ static int jbd2_journal_file_inode(handle_t *handle, struct jbd2_inode *jinode,
 		return -EROFS;
 	journal = transaction->t_journal;
 
-	jbd_debug(4, "Adding inode %lu, tid:%d\n", jinode->i_vfs_inode->i_ino,
+	jbd2_info(journal, "Adding inode %lu, tid:%d\n", jinode->i_vfs_inode->i_ino,
 			transaction->t_tid);
 
 	spin_lock(&journal->j_list_lock);
Signature · 1 line
2.30.0
author
#6 lore raw

RFC PATCH 4/4 ext4: replace jbd_debug with the new log interface

In reply to Chunguang Xu

From: Chunguang Xu <[email protected]>

In order to support jbd2 per device debugging switch, here we need to replace jbd_debug with a new log interface. But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

Signed-off-by Chunguang Xu <[email protected]>
---
 fs/ext4/balloc.c      |  2 +-
 fs/ext4/ext4_jbd2.c   |  3 +-
 fs/ext4/fast_commit.c | 64 +++++++++++++++++++++++--------------------
 fs/ext4/indirect.c    |  4 +--
 fs/ext4/inode.c       |  3 +-
 fs/ext4/namei.c       | 10 +++----
 fs/ext4/super.c       | 16 ++++++-----
 7 files changed, 56 insertions(+), 46 deletions(-)
fs/ext4/balloc.c +1 -1
index f45f9feebe59..469aec970b36 100644
@@ -645,7 +645,7 @@ int ext4_should_retry_alloc(struct super_block *sb, int *retries)
 	if (EXT4_SB(sb)->s_mb_free_pending == 0)
 		return 0;
 
-	jbd_debug(1, "%s: retrying operation after ENOSPC\n", sb->s_id);
+	jbd2_err(EXT4_SB(sb)->s_journal, "%s: retrying operation after ENOSPC\n", sb->s_id);
 	jbd2_journal_force_commit_nested(EXT4_SB(sb)->s_journal);
 	return 1;
 }
fs/ext4/ext4_jbd2.c +2 -1
index be799040a415..5c1c06662019 100644
@@ -259,7 +259,8 @@ int __ext4_forget(const char *where, unsigned int line, handle_t *handle,
 	trace_ext4_forget(inode, is_metadata, blocknr);
 	BUFFER_TRACE(bh, "enter");
 
-	jbd_debug(4, "forgetting bh %p: is_metadata = %d, mode %o, "
+	jbd2_info(EXT4_SB(inode->i_sb)->s_journal,
+		  "forgetting bh %p: is_metadata = %d, mode %o, "
 		  "data mode %x\n",
 		  bh, is_metadata, inode->i_mode,
 		  test_opt(inode->i_sb, DATA_FLAGS));
fs/ext4/fast_commit.c +35 -29

195 lines not on this page · raw message

fs/ext4/indirect.c +2 -2
index 1223a18c3ff9..f544f0530e14 100644
@@ -458,7 +458,7 @@ static int ext4_splice_branch(handle_t *handle,
 		 * the new i_size.  But that is not done here - it is done in
 		 * generic_commit_write->__mark_inode_dirty->ext4_dirty_inode.
 		 */
-		jbd_debug(5, "splicing indirect only\n");
+		jbd2_debug(EXT4_SB(ar->inode->i_sb)->s_journal, "splicing indirect only\n");
 		BUFFER_TRACE(where->bh, "call ext4_handle_dirty_metadata");
 		err = ext4_handle_dirty_metadata(handle, ar->inode, where->bh);
 		if (err)

@@ -470,7 +470,7 @@ static int ext4_splice_branch(handle_t *handle,
 		err = ext4_mark_inode_dirty(handle, ar->inode);
 		if (unlikely(err))
 			goto err_out;
-		jbd_debug(5, "splicing direct\n");
+		jbd2_debug(EXT4_SB(ar->inode->i_sb)->s_journal, "splicing direct\n");
 	}
 	return err;
fs/ext4/inode.c +2 -1
index c173c8405856..89683b7f1a48 100644
@@ -5212,7 +5212,8 @@ int ext4_write_inode(struct inode *inode, struct writeback_control *wbc)
 
 	if (EXT4_SB(inode->i_sb)->s_journal) {
 		if (ext4_journal_current_handle()) {
-			jbd_debug(1, "called recursively, non-PF_MEMALLOC!\n");
+			jbd2_err(EXT4_SB(inode->i_sb)->s_journal,
+				 "called recursively, non-PF_MEMALLOC!\n");
 			dump_stack();
 			return -EIO;
 		}
fs/ext4/namei.c +5 -5
index cf652ba3e74d..0e8da7f010d1 100644
@@ -3003,8 +3003,8 @@ int ext4_orphan_add(handle_t *handle, struct inode *inode)
 	} else
 		brelse(iloc.bh);
 
-	jbd_debug(4, "superblock will point to %lu\n", inode->i_ino);
-	jbd_debug(4, "orphan inode %lu will point to %d\n",
+	jbd2_info(sbi->s_journal, "superblock will point to %lu\n", inode->i_ino);
+	jbd2_info(sbi->s_journal, "orphan inode %lu will point to %d\n",
 			inode->i_ino, NEXT_ORPHAN(inode));
 out:
 	ext4_std_error(sb, err);

@@ -3039,7 +3039,7 @@ int ext4_orphan_del(handle_t *handle, struct inode *inode)
 	}
 
 	mutex_lock(&sbi->s_orphan_lock);
-	jbd_debug(4, "remove inode %lu from orphan list\n", inode->i_ino);
+	jbd2_info(sbi->s_journal, "remove inode %lu from orphan list\n", inode->i_ino);
 
 	prev = ei->i_orphan.prev;
 	list_del_init(&ei->i_orphan);

@@ -3055,7 +3055,7 @@ int ext4_orphan_del(handle_t *handle, struct inode *inode)
 
 	ino_next = NEXT_ORPHAN(inode);
 	if (prev == &sbi->s_orphan) {
-		jbd_debug(4, "superblock will point to %u\n", ino_next);
+		jbd2_info(sbi->s_journal, "superblock will point to %u\n", ino_next);
 		BUFFER_TRACE(sbi->s_sbh, "get_write_access");
 		err = ext4_journal_get_write_access(handle, sbi->s_sbh);
 		if (err) {

@@ -3073,7 +3073,7 @@ int ext4_orphan_del(handle_t *handle, struct inode *inode)
 		struct inode *i_prev =
 			&list_entry(prev, struct ext4_inode_info, i_orphan)->vfs_inode;
 
-		jbd_debug(4, "orphan inode %lu will point to %u\n",
+		jbd2_info(sbi->s_journal, "orphan inode %lu will point to %u\n",
 			  i_prev->i_ino, ino_next);
 		err = ext4_reserve_inode_write(handle, i_prev, &iloc2);
 		if (err) {
fs/ext4/super.c +9 -7
index 9a6f9875aa34..e4ee88bd698c 100644
@@ -2989,7 +2989,7 @@ static void ext4_orphan_cleanup(struct super_block *sb,
 	int i;
 #endif
 	if (!es->s_last_orphan) {
-		jbd_debug(4, "no orphan inodes to clean up\n");
+		jbd2_info(EXT4_SB(sb)->s_journal, "no orphan inodes to clean up\n");
 		return;
 	}
 

@@ -3013,7 +3013,8 @@ static void ext4_orphan_cleanup(struct super_block *sb,
 				  "clearing orphan list.\n");
 			es->s_last_orphan = 0;
 		}
-		jbd_debug(1, "Skipping orphan recovery on fs with errors.\n");
+		jbd2_err(EXT4_SB(sb)->s_journal,
+			 "Skipping orphan recovery on fs with errors.\n");
 		return;
 	}
 

@@ -3062,7 +3063,8 @@ static void ext4_orphan_cleanup(struct super_block *sb,
 		 * so, skip the rest.
 		 */
 		if (EXT4_SB(sb)->s_mount_state & EXT4_ERROR_FS) {
-			jbd_debug(1, "Skipping orphan recovery on fs with errors.\n");
+			jbd2_err(EXT4_SB(sb)->s_journal,
+				 "Skipping orphan recovery on fs with errors.\n");
 			es->s_last_orphan = 0;
 			break;
 		}

@@ -3080,7 +3082,8 @@ static void ext4_orphan_cleanup(struct super_block *sb,
 				ext4_msg(sb, KERN_DEBUG,
 					"%s: truncating inode %lu to %lld bytes",
 					__func__, inode->i_ino, inode->i_size);
-			jbd_debug(2, "truncating inode %lu to %lld bytes\n",
+			jbd2_warn(EXT4_SB(sb)->s_journal,
+				  "truncating inode %lu to %lld bytes\n",
 				  inode->i_ino, inode->i_size);
 			inode_lock(inode);
 			truncate_inode_pages(inode->i_mapping, inode->i_size);

@@ -3094,7 +3097,8 @@ static void ext4_orphan_cleanup(struct super_block *sb,
 				ext4_msg(sb, KERN_DEBUG,
 					"%s: deleting unreferenced inode %lu",
 					__func__, inode->i_ino);
-			jbd_debug(2, "deleting unreferenced inode %lu\n",
+			jbd2_warn(EXT4_SB(sb)->s_journal,
+				  "deleting unreferenced inode %lu\n",
 				  inode->i_ino);
 			nr_orphans++;
 		}

@@ -5226,8 +5230,6 @@ static struct inode *ext4_get_journal_inode(struct super_block *sb,
 		return NULL;
 	}
 
-	jbd_debug(2, "Journal inode found at %p: %lld bytes\n",
-		  journal_inode, journal_inode->i_size);
 	if (!S_ISREG(journal_inode->i_mode)) {
 		ext4_msg(sb, KERN_ERR, "invalid journal inode");
 		iput(journal_inode);
Signature · 1 line
2.30.0
reviewer
#7 lore raw
In reply to Chunguang Xu
Quoted 6 lines · Chunguang Xu

On a multi-disk machine, because jbd2 debugging switch is global, this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Quoted 7 lines

We can enable jbd2 debugging of a device in the following ways:
echo X > /proc/fs/jbd2/sdX/jbd2_debug

But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

OK, I didn't look at the series yet but I'm wondering: How are you using jbd2 debugging? I mean obviously it isn't meant for production use but rather for debugging JBD2 bugs so I'm kind of wondering in which case too many messages matter.

And if the problem is that there's a problem with distinguishing messages from multiple filesystems, then it would be perhaps more useful to add journal identification to each message similarly as we do it with ext4 messages (likely by using journal->j_dev) - which is very simple to do after your patches 3 and 4.

Honza

Signature · 2 lines
Jan Kara <[email protected]>
SUSE Labs, CR
author
#8 lore raw

Thanks for your reply.

Jan Kara wrote on 2021/1/25 20:41:

Quoted 15 lines · Chunguang Xu
Quoted 6 lines

On a multi-disk machine, because jbd2 debugging switch is global, this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Quoted 7 lines

We can enable jbd2 debugging of a device in the following ways:
echo X > /proc/fs/jbd2/sdX/jbd2_debug

But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

Quoted 4 lines

OK, I didn't look at the series yet but I'm wondering: How are you using jbd2 debugging? I mean obviously it isn't meant for production use but rather for debugging JBD2 bugs so I'm kind of wondering in which case too many messages matter.

We perform stress testing on machines in the test environment, and use scripts to capture journal related logs to analyze problems. There are 12 disks on this machine, and each disk runs different jobs. Our test kernel also adds some additional
function-related logs. If we adjust the log level to a higher level, a large number of logs have nothing to do with the disk to be observed. These logs are generated by system agents or coordinated tasks. This makes the log difficul to analyze.

Quoted 5 lines

And if the problem is that there's a problem with distinguishing messages from multiple filesystems, then it would be perhaps more useful to add journal identification to each message similarly as we do it with ext4 messages (likely by using journal->j_dev) - which is very simple to do after your patches 3 and 4.

Our test kernel did this. Because it broke the log format, I was not sure whether
it would break something, so I didn't bring this part. Even if the device information
is added, when there are more disks and the log level is higher, there will be a lot of irrelevant logs, which makes it necessary to consume a lot of CPU to filter
messages. Therefore, a device-level switch is provided to make everything simpler.

Quoted 3 lines

Honza

author
#9 lore raw
In reply to Jan Kara

Thanks for your reply.

Jan Kara wrote on 2021/1/25 20:41:

Quoted 15 lines · Chunguang Xu
Quoted 6 lines

On a multi-disk machine, because jbd2 debugging switch is global, this confuses the logs of multiple disks. It is not easy to distinguish the logs of each disk and the amount of generated logs is very large. Or a separate debugging switch for each disk would be better, so that you can easily distinguish the logs of a certain disk.

Quoted 7 lines

We can enable jbd2 debugging of a device in the following ways:
echo X > /proc/fs/jbd2/sdX/jbd2_debug

But there is a small disadvantage here. Because the debugging switch is placed in the journal_t object, the log before the object is initialized will be lost. However, usually this will not have much impact on debugging.

Quoted 4 lines

OK, I didn't look at the series yet but I'm wondering: How are you using jbd2 debugging? I mean obviously it isn't meant for production use but rather for debugging JBD2 bugs so I'm kind of wondering in which case too many messages matter.

We perform stress testing on machines in the test environment, and use scripts to capture journal related logs to analyze problems. There are 12 disks on this machine, and each disk runs different jobs. Our test kernel also adds some additional function-related logs. If we adjust the log level to a higher level, a large number of logs have nothing to do with the disk to be observed. These logs are generated by system agents or coordinated tasks. This makes the log difficul to analyze.

Quoted 5 lines

And if the problem is that there's a problem with distinguishing messages from multiple filesystems, then it would be perhaps more useful to add journal identification to each message similarly as we do it with ext4 messages (likely by using journal->j_dev) - which is very simple to do after your patches 3 and 4.

Our test kernel did this. Because it broke the log format, I was not sure whether it would break something, so I didn't bring this part. Even if the device information is added, when there are more disks and the log level is higher, there will be a lot of irrelevant logs, which makes it necessary to consume a lot of CPU to filter messages. Therefore, a device-level switch is provided to make everything simpler.

Quoted 3 lines

Honza