| Message ID | 1375383668-8072-5-git-send-email-paul.gortmaker@windriver.com |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
On Thu, 2013-08-01 at 15:01 -0400, Paul Gortmaker wrote: > Backport of jbd2 commit 169f1a2a87aae44034da4b9f81be1683d33de6d0 > ("jbd2: use a single printk for jbd_debug()") Hey Paul. > diff --git a/include/linux/jbd.h b/include/linux/jbd.h [] > @@ -56,16 +56,13 @@ > #define JBD_EXPENSIVE_CHECKING > extern ushort journal_enable_debug; > > -#define jbd_debug(n, f, a...) \ > - do { \ > - if ((n) <= journal_enable_debug) { \ > - printk (KERN_DEBUG "(%s, %d): %s: ", \ > - __FILE__, __LINE__, __func__); \ > - printk (f, ## a); \ > - } \ > - } while (0) > +void __jbd_debug(int level, const char *file, const char *func, > + unsigned int line, const char *fmt, ... > + > +#define jbd_debug(n, fmt, a...) \ > + __jbd_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a) > #else > -#define jbd_debug(f, a...) /**/ > +#define jbd_debug(n, fmt, a...) /**/ > #endif It might have been (and may still be) simpler/better to use a single macro like: #define jbd_dbg(n, fmt, ...) \ do { \ if ((n) < journal_enable_debug) \ pr_debug(fmt, ##__VA_ARGS__); \ } while (0) and then use dynamic_debug to add the __func__, and __LINE__ when desired. echo -n 'module jbd +pfl' <dynamic_debug>/control -- To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu 01-08-13 15:01:08, Paul Gortmaker wrote: > Backport of jbd2 commit 169f1a2a87aae44034da4b9f81be1683d33de6d0 > ("jbd2: use a single printk for jbd_debug()") > > Quoting the original: > -------------- > 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. > -------------- Thanks. I've merged the patch to my tree. Honza > > Signed-off-by: Paul Gortmaker <paul.gortmaker@windriver.com> > --- > fs/jbd/journal.c | 18 ++++++++++++++++++ > include/linux/jbd.h | 15 ++++++--------- > 2 files changed, 24 insertions(+), 9 deletions(-) > > diff --git a/fs/jbd/journal.c b/fs/jbd/journal.c > index 166263d..f45f0a3 100644 > --- a/fs/jbd/journal.c > +++ b/fs/jbd/journal.c > @@ -97,6 +97,24 @@ static int journal_convert_superblock_v1(journal_t *, journal_superblock_t *); > static void __journal_abort_soft (journal_t *journal, int errno); > static const char *journal_dev_name(journal_t *journal, char *buffer); > > +#ifdef CONFIG_JBD_DEBUG > +void __jbd_debug(int level, const char *file, const char *func, > + unsigned int line, const char *fmt, ...) > +{ > + struct va_format vaf; > + va_list args; > + > + if (level > jbd_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); > +} > +EXPORT_SYMBOL(__jbd_debug); > +#endif > + > /* > * Helper function used to manage commit timeouts > */ > diff --git a/include/linux/jbd.h b/include/linux/jbd.h > index e45b430..d6d3ae0 100644 > --- a/include/linux/jbd.h > +++ b/include/linux/jbd.h > @@ -56,16 +56,13 @@ > #define JBD_EXPENSIVE_CHECKING > extern ushort journal_enable_debug; > > -#define jbd_debug(n, f, a...) \ > - do { \ > - if ((n) <= journal_enable_debug) { \ > - printk (KERN_DEBUG "(%s, %d): %s: ", \ > - __FILE__, __LINE__, __func__); \ > - printk (f, ## a); \ > - } \ > - } while (0) > +void __jbd_debug(int level, const char *file, const char *func, > + unsigned int line, const char *fmt, ...); > + > +#define jbd_debug(n, fmt, a...) \ > + __jbd_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a) > #else > -#define jbd_debug(f, a...) /**/ > +#define jbd_debug(n, fmt, a...) /**/ > #endif > > static inline void *jbd_alloc(size_t size, gfp_t flags) > -- > 1.8.1.2 >
On Thu 01-08-13 12:21:05, Joe Perches wrote: > On Thu, 2013-08-01 at 15:01 -0400, Paul Gortmaker wrote: > > Backport of jbd2 commit 169f1a2a87aae44034da4b9f81be1683d33de6d0 > > ("jbd2: use a single printk for jbd_debug()") > > Hey Paul. > > > diff --git a/include/linux/jbd.h b/include/linux/jbd.h > [] > > @@ -56,16 +56,13 @@ > > #define JBD_EXPENSIVE_CHECKING > > extern ushort journal_enable_debug; > > > > -#define jbd_debug(n, f, a...) \ > > - do { \ > > - if ((n) <= journal_enable_debug) { \ > > - printk (KERN_DEBUG "(%s, %d): %s: ", \ > > - __FILE__, __LINE__, __func__); \ > > - printk (f, ## a); \ > > - } \ > > - } while (0) > > +void __jbd_debug(int level, const char *file, const char *func, > > + unsigned int line, const char *fmt, ... > > + > > +#define jbd_debug(n, fmt, a...) \ > > + __jbd_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a) > > #else > > -#define jbd_debug(f, a...) /**/ > > +#define jbd_debug(n, fmt, a...) /**/ > > #endif > > It might have been (and may still be) simpler/better > to use a single macro like: > > #define jbd_dbg(n, fmt, ...) \ > do { \ > if ((n) < journal_enable_debug) \ > pr_debug(fmt, ##__VA_ARGS__); \ > } while (0) > > and then use dynamic_debug to add the __func__, > and __LINE__ when desired. > > echo -n 'module jbd +pfl' <dynamic_debug>/control Umm, I like the Paul's way better. Sure we have to jump into __jbd_debug() even if we won't write any message because debug level is low but OTOH jbd_debug() is non-empty only when JBD_EXPENSIVE_CHECKING is enabled. So there the extra call is fine. Honza
diff --git a/fs/jbd/journal.c b/fs/jbd/journal.c index 166263d..f45f0a3 100644 --- a/fs/jbd/journal.c +++ b/fs/jbd/journal.c @@ -97,6 +97,24 @@ static int journal_convert_superblock_v1(journal_t *, journal_superblock_t *); static void __journal_abort_soft (journal_t *journal, int errno); static const char *journal_dev_name(journal_t *journal, char *buffer); +#ifdef CONFIG_JBD_DEBUG +void __jbd_debug(int level, const char *file, const char *func, + unsigned int line, const char *fmt, ...) +{ + struct va_format vaf; + va_list args; + + if (level > jbd_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); +} +EXPORT_SYMBOL(__jbd_debug); +#endif + /* * Helper function used to manage commit timeouts */ diff --git a/include/linux/jbd.h b/include/linux/jbd.h index e45b430..d6d3ae0 100644 --- a/include/linux/jbd.h +++ b/include/linux/jbd.h @@ -56,16 +56,13 @@ #define JBD_EXPENSIVE_CHECKING extern ushort journal_enable_debug; -#define jbd_debug(n, f, a...) \ - do { \ - if ((n) <= journal_enable_debug) { \ - printk (KERN_DEBUG "(%s, %d): %s: ", \ - __FILE__, __LINE__, __func__); \ - printk (f, ## a); \ - } \ - } while (0) +void __jbd_debug(int level, const char *file, const char *func, + unsigned int line, const char *fmt, ...); + +#define jbd_debug(n, fmt, a...) \ + __jbd_debug((n), __FILE__, __func__, __LINE__, (fmt), ##a) #else -#define jbd_debug(f, a...) /**/ +#define jbd_debug(n, fmt, a...) /**/ #endif static inline void *jbd_alloc(size_t size, gfp_t flags)
Backport of jbd2 commit 169f1a2a87aae44034da4b9f81be1683d33de6d0 ("jbd2: use a single printk for jbd_debug()") Quoting the original: -------------- 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. -------------- Signed-off-by: Paul Gortmaker <paul.gortmaker@windriver.com> --- fs/jbd/journal.c | 18 ++++++++++++++++++ include/linux/jbd.h | 15 ++++++--------- 2 files changed, 24 insertions(+), 9 deletions(-)