jbd2: add tracepoints which provide per-handle statistics

Handles which stay open a long time are problematic when it comes time
to close down a transaction so it can be committed.  These tracepoints
will help us determine which ones are the problematic ones, and to
validate whether changes makes things better or worse.

Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>

diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index 735609e2d63697437d9624836e3c7fc2d348641c..b7e2385c6e92d373ffbfa18e43494535615d968b 100644 (file)
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -30,6 +30,8 @@
 #include <linux/bug.h>
 #include <linux/module.h>
 
+#include <trace/events/jbd2.h>
+
 static void __jbd2_journal_temp_unlink_buffer(struct journal_head *jh);
 static void __jbd2_journal_unfile_buffer(struct journal_head *jh);
 
@@ -307,6 +309,8 @@ repeat:
         */
        update_t_max_wait(transaction, ts);
        handle->h_transaction = transaction;
+       handle->h_requested_credits = nblocks;
+       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 %d)\n",
@@ -353,7 +357,8 @@ static handle_t *new_handle(int nblocks)
  * Return a pointer to a newly allocated handle, or an ERR_PTR() value
  * on failure.
  */
-handle_t *jbd2__journal_start(journal_t *journal, int nblocks, gfp_t gfp_mask)
+handle_t *jbd2__journal_start(journal_t *journal, int nblocks, gfp_t gfp_mask,
+                             unsigned int type, unsigned int line_no)
 {
        handle_t *handle = journal_current_handle();
        int err;
@@ -379,6 +384,11 @@ handle_t *jbd2__journal_start(journal_t *journal, int nblocks, gfp_t gfp_mask)
                current->journal_info = NULL;
                handle = ERR_PTR(err);
        }
+       handle->h_type = type;
+       handle->h_line_no = line_no;
+       trace_jbd2_handle_start(journal->j_fs_dev->bd_dev,
+                               handle->h_transaction->t_tid, type,
+                               line_no, nblocks);
        return handle;
 }
 EXPORT_SYMBOL(jbd2__journal_start);
@@ -386,7 +396,7 @@ EXPORT_SYMBOL(jbd2__journal_start);
 
 handle_t *jbd2_journal_start(journal_t *journal, int nblocks)
 {
-       return jbd2__journal_start(journal, nblocks, GFP_NOFS);
+       return jbd2__journal_start(journal, nblocks, GFP_NOFS, 0, 0);
 }
 EXPORT_SYMBOL(jbd2_journal_start);
 
@@ -448,7 +458,14 @@ int jbd2_journal_extend(handle_t *handle, int nblocks)
                goto unlock;
        }
 
+       trace_jbd2_handle_extend(journal->j_fs_dev->bd_dev,
+                                handle->h_transaction->t_tid,
+                                handle->h_type, handle->h_line_no,
+                                handle->h_buffer_credits,
+                                nblocks);
+
        handle->h_buffer_credits += nblocks;
+       handle->h_requested_credits += nblocks;
        atomic_add(nblocks, &transaction->t_outstanding_credits);
        result = 0;
 
@@ -1377,6 +1394,13 @@ int jbd2_journal_stop(handle_t *handle)
        }
 
        jbd_debug(4, "Handle %p going down\n", handle);
+       trace_jbd2_handle_stats(journal->j_fs_dev->bd_dev,
+                               handle->h_transaction->t_tid,
+                               handle->h_type, handle->h_line_no,
+                               jiffies - handle->h_start_jiffies,
+                               handle->h_sync, handle->h_requested_credits,
+                               (handle->h_requested_credits -
+                                handle->h_buffer_credits));
 
        /*
         * Implement synchronous transaction batching.  If the handle

diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h
index 24db7256a5ff5c3888f340cf13884dda994149e1..fa5fea17b61963ef4c09e6e55a659b4ec81b8625 100644 (file)
--- a/include/linux/jbd2.h
+++ b/include/linux/jbd2.h
@@ -400,6 +400,11 @@ struct jbd2_journal_handle
        unsigned int    h_sync:         1;      /* sync-on-close */
        unsigned int    h_jdata:        1;      /* force data journaling */
        unsigned int    h_aborted:      1;      /* fatal error on handle */
+       unsigned int    h_type:         8;      /* for handle statistics */
+       unsigned int    h_line_no:      16;     /* for handle statistics */
+
+       unsigned long           h_start_jiffies;
+       unsigned int            h_requested_credits;
 
 #ifdef CONFIG_DEBUG_LOCK_ALLOC
        struct lockdep_map      h_lockdep_map;
@@ -1071,7 +1076,8 @@ static inline handle_t *journal_current_handle(void)
  */
 
 extern handle_t *jbd2_journal_start(journal_t *, int nblocks);
-extern handle_t *jbd2__journal_start(journal_t *, int nblocks, gfp_t gfp_mask);
+extern handle_t *jbd2__journal_start(journal_t *, int nblocks, gfp_t gfp_mask,
+                                    unsigned int type, unsigned int line_no);
 extern int      jbd2_journal_restart(handle_t *, int nblocks);
 extern int      jbd2__journal_restart(handle_t *, int nblocks, gfp_t gfp_mask);
 extern int      jbd2_journal_extend (handle_t *, int nblocks);

diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h
index 5419f57beb1f4e3b7465f111e40f1e6c0fe77c18..070df49e4a1df18aa6ddc0cb1e8b87b0b62c4130 100644 (file)
--- a/include/trace/events/jbd2.h
+++ b/include/trace/events/jbd2.h
@@ -132,6 +132,104 @@ TRACE_EVENT(jbd2_submit_inode_data,
                  (unsigned long) __entry->ino)
 );
 
+TRACE_EVENT(jbd2_handle_start,
+       TP_PROTO(dev_t dev, unsigned long tid, unsigned int type,
+                unsigned int line_no, int requested_blocks),
+
+       TP_ARGS(dev, tid, type, line_no, requested_blocks),
+
+       TP_STRUCT__entry(
+               __field(                dev_t,  dev             )
+               __field(        unsigned long,  tid             )
+               __field(         unsigned int,  type            )
+               __field(         unsigned int,  line_no         )
+               __field(                  int,  requested_blocks)
+       ),
+
+       TP_fast_assign(
+               __entry->dev              = dev;
+               __entry->tid              = tid;
+               __entry->type             = type;
+               __entry->line_no          = line_no;
+               __entry->requested_blocks = requested_blocks;
+       ),
+
+       TP_printk("dev %d,%d tid %lu type %u line_no %u "
+                 "requested_blocks %d",
+                 MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
+                 __entry->type, __entry->line_no, __entry->requested_blocks)
+);
+
+TRACE_EVENT(jbd2_handle_extend,
+       TP_PROTO(dev_t dev, unsigned long tid, unsigned int type,
+                unsigned int line_no, int buffer_credits,
+                int requested_blocks),
+
+       TP_ARGS(dev, tid, type, line_no, buffer_credits, requested_blocks),
+
+       TP_STRUCT__entry(
+               __field(                dev_t,  dev             )
+               __field(        unsigned long,  tid             )
+               __field(         unsigned int,  type            )
+               __field(         unsigned int,  line_no         )
+               __field(                  int,  buffer_credits  )
+               __field(                  int,  requested_blocks)
+       ),
+
+       TP_fast_assign(
+               __entry->dev              = dev;
+               __entry->tid              = tid;
+               __entry->type             = type;
+               __entry->line_no          = line_no;
+               __entry->buffer_credits   = buffer_credits;
+               __entry->requested_blocks = requested_blocks;
+       ),
+
+       TP_printk("dev %d,%d tid %lu type %u line_no %u "
+                 "buffer_credits %d requested_blocks %d",
+                 MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
+                 __entry->type, __entry->line_no, __entry->buffer_credits,
+                 __entry->requested_blocks)
+);
+
+TRACE_EVENT(jbd2_handle_stats,
+       TP_PROTO(dev_t dev, unsigned long tid, unsigned int type,
+                unsigned int line_no, int interval, int sync,
+                int requested_blocks, int dirtied_blocks),
+
+       TP_ARGS(dev, tid, type, line_no, interval, sync,
+               requested_blocks, dirtied_blocks),
+
+       TP_STRUCT__entry(
+               __field(                dev_t,  dev             )
+               __field(        unsigned long,  tid             )
+               __field(         unsigned int,  type            )
+               __field(         unsigned int,  line_no         )
+               __field(                  int,  interval        )
+               __field(                  int,  sync            )
+               __field(                  int,  requested_blocks)
+               __field(                  int,  dirtied_blocks  )
+       ),
+
+       TP_fast_assign(
+               __entry->dev              = dev;
+               __entry->tid              = tid;
+               __entry->type             = type;
+               __entry->line_no          = line_no;
+               __entry->interval         = interval;
+               __entry->sync             = sync;
+               __entry->requested_blocks = requested_blocks;
+               __entry->dirtied_blocks   = dirtied_blocks;
+       ),
+
+       TP_printk("dev %d,%d tid %lu type %u line_no %u interval %d "
+                 "sync %d requested_blocks %d dirtied_blocks %d",
+                 MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
+                 __entry->type, __entry->line_no, __entry->interval,
+                 __entry->sync, __entry->requested_blocks,
+                 __entry->dirtied_blocks)
+);
+
 TRACE_EVENT(jbd2_run_stats,
        TP_PROTO(dev_t dev, unsigned long tid,
                 struct transaction_run_stats_s *stats),