From: Paul Gortmaker Subject: [PATCH 5/6] jbd2: make jbd_debug that won't split printk statements Date: Tue, 11 Jun 2013 18:44:29 -0400 Message-ID: <1370990670-49249-6-git-send-email-paul.gortmaker@windriver.com> References: <1370892723-30860-1-git-send-email-paul.gortmaker@windriver.com> <1370990670-49249-1-git-send-email-paul.gortmaker@windriver.com> Mime-Version: 1.0 Content-Type: text/plain Cc: , , Paul Gortmaker To: "Theodore Ts'o" Return-path: Received: from mail.windriver.com ([147.11.1.11]:32974 "EHLO mail.windriver.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756938Ab3FKWpP (ORCPT ); Tue, 11 Jun 2013 18:45:15 -0400 In-Reply-To: <1370990670-49249-1-git-send-email-paul.gortmaker@windriver.com> Sender: linux-ext4-owner@vger.kernel.org List-ID: Since the jbd_debug() is implemented with two separate printk() calls, it can lead to corrupted and misleading debug output like the following (see lines marked with "*"): [ 290.339362] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes [ 290.339365] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=42103, commit_request=42104 [ 290.339369] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ [* 290.339376] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: [* 290.339379] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: want 42104, j_commit_sequence=42103 [* 290.339382] JBD2: starting commit of transaction 42104 [ 290.339410] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records [ 290.376555] (fs/jbd2/commit.c, 1088): jbd2_journal_commit_transaction: JBD2: commit 42104 complete, head 42079 i.e. the debug output from log_wait_commit and journal_commit_transaction have become interleaved. The output should have been: (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 42104, j_commit_sequence=42103 (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 42104 It is expected that this is not easy to replicate -- I was only able to cause it on preempt-rt kernels, and even then only under heavy I/O load. Reported-by: Paul Gortmaker Suggested-by: "Theodore Ts'o" Signed-off-by: Paul Gortmaker --- fs/jbd2/journal.c | 17 +++++++++++++++++ include/linux/jbd2.h | 14 +++++--------- 2 files changed, 22 insertions(+), 9 deletions(-) diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c index 9545757..6aa196e 100644 --- a/fs/jbd2/journal.c +++ b/fs/jbd2/journal.c @@ -103,6 +103,23 @@ EXPORT_SYMBOL(jbd2_inode_cache); static void __journal_abort_soft (journal_t *journal, int errno); 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, + unsigned int line, const char *fmt, ...) +{ + struct va_format vaf; + va_list args; + + if (level > jbd2_journal_enable_debug) + return; + va_start(args, fmt); + vaf.fmt = fmt; + vaf.va = &args; + printk(KERN_DEBUG "%s: (%s, %u): %pV\n", file, func, line, &vaf); + va_end(args); +} +#endif + /* Checksumming functions */ int jbd2_verify_csum_type(journal_t *j, journal_superblock_t *sb) { diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h index 9986ab8..8d95314 100644 --- a/include/linux/jbd2.h +++ b/include/linux/jbd2.h @@ -56,17 +56,13 @@ */ #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, f, a...) \ - do { \ - if ((n) <= jbd2_journal_enable_debug) { \ - printk (KERN_DEBUG "(%s, %d): %s: ", \ - __FILE__, __LINE__, __func__); \ - printk (f, ## a); \ - } \ - } while (0) +#define jbd_debug(n, fmt, a...) \ + __jbd2_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a) #else -#define jbd_debug(f, a...) /**/ +#define jbd_debug(n, fmt, a...) /**/ #endif extern void *jbd2_alloc(size_t size, gfp_t flags); -- 1.8.1.2