jbd2: Use tracepoints for history file
Theodore Ts'o [Wed, 30 Sep 2009 04:32:06 +0000 (00:32 -0400)]
The /proc/fs/jbd2/<dev>/history was maintained manually; by using
tracepoints, we can get all of the existing functionality of the /proc
file plus extra capabilities thanks to the ftrace infrastructure.  We
save memory as a bonus.

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

fs/jbd2/checkpoint.c
fs/jbd2/commit.c
fs/jbd2/journal.c
include/linux/jbd2.h
include/trace/events/jbd2.h

index 5d70b3e..ca0f5eb 100644 (file)
@@ -643,6 +643,7 @@ out:
 
 int __jbd2_journal_remove_checkpoint(struct journal_head *jh)
 {
+       struct transaction_chp_stats_s *stats;
        transaction_t *transaction;
        journal_t *journal;
        int ret = 0;
@@ -679,6 +680,12 @@ int __jbd2_journal_remove_checkpoint(struct journal_head *jh)
 
        /* OK, that was the last buffer for the transaction: we can now
           safely remove this transaction from the log */
+       stats = &transaction->t_chp_stats;
+       if (stats->cs_chp_time)
+               stats->cs_chp_time = jbd2_time_diff(stats->cs_chp_time,
+                                                   jiffies);
+       trace_jbd2_checkpoint_stats(journal->j_fs_dev->bd_dev,
+                                   transaction->t_tid, stats);
 
        __jbd2_journal_drop_transaction(journal, transaction);
        kfree(transaction);
index 26d991d..d4cfd6d 100644 (file)
@@ -410,10 +410,10 @@ void jbd2_journal_commit_transaction(journal_t *journal)
        if (commit_transaction->t_synchronous_commit)
                write_op = WRITE_SYNC_PLUG;
        trace_jbd2_commit_locking(journal, commit_transaction);
-       stats.u.run.rs_wait = commit_transaction->t_max_wait;
-       stats.u.run.rs_locked = jiffies;
-       stats.u.run.rs_running = jbd2_time_diff(commit_transaction->t_start,
-                                               stats.u.run.rs_locked);
+       stats.run.rs_wait = commit_transaction->t_max_wait;
+       stats.run.rs_locked = jiffies;
+       stats.run.rs_running = jbd2_time_diff(commit_transaction->t_start,
+                                             stats.run.rs_locked);
 
        spin_lock(&commit_transaction->t_handle_lock);
        while (commit_transaction->t_updates) {
@@ -486,9 +486,9 @@ void jbd2_journal_commit_transaction(journal_t *journal)
        jbd2_journal_switch_revoke_table(journal);
 
        trace_jbd2_commit_flushing(journal, commit_transaction);
-       stats.u.run.rs_flushing = jiffies;
-       stats.u.run.rs_locked = jbd2_time_diff(stats.u.run.rs_locked,
-                                              stats.u.run.rs_flushing);
+       stats.run.rs_flushing = jiffies;
+       stats.run.rs_locked = jbd2_time_diff(stats.run.rs_locked,
+                                            stats.run.rs_flushing);
 
        commit_transaction->t_state = T_FLUSH;
        journal->j_committing_transaction = commit_transaction;
@@ -523,11 +523,11 @@ void jbd2_journal_commit_transaction(journal_t *journal)
        spin_unlock(&journal->j_state_lock);
 
        trace_jbd2_commit_logging(journal, commit_transaction);
-       stats.u.run.rs_logging = jiffies;
-       stats.u.run.rs_flushing = jbd2_time_diff(stats.u.run.rs_flushing,
-                                                stats.u.run.rs_logging);
-       stats.u.run.rs_blocks = commit_transaction->t_outstanding_credits;
-       stats.u.run.rs_blocks_logged = 0;
+       stats.run.rs_logging = jiffies;
+       stats.run.rs_flushing = jbd2_time_diff(stats.run.rs_flushing,
+                                              stats.run.rs_logging);
+       stats.run.rs_blocks = commit_transaction->t_outstanding_credits;
+       stats.run.rs_blocks_logged = 0;
 
        J_ASSERT(commit_transaction->t_nr_buffers <=
                 commit_transaction->t_outstanding_credits);
@@ -695,7 +695,7 @@ start_journal_io:
                                submit_bh(write_op, bh);
                        }
                        cond_resched();
-                       stats.u.run.rs_blocks_logged += bufs;
+                       stats.run.rs_blocks_logged += bufs;
 
                        /* Force a new descriptor to be generated next
                            time round the loop. */
@@ -988,33 +988,30 @@ restart_loop:
        J_ASSERT(commit_transaction->t_state == T_COMMIT);
 
        commit_transaction->t_start = jiffies;
-       stats.u.run.rs_logging = jbd2_time_diff(stats.u.run.rs_logging,
-                                               commit_transaction->t_start);
+       stats.run.rs_logging = jbd2_time_diff(stats.run.rs_logging,
+                                             commit_transaction->t_start);
 
        /*
-        * File the transaction for history
+        * File the transaction statistics
         */
-       stats.ts_type = JBD2_STATS_RUN;
        stats.ts_tid = commit_transaction->t_tid;
-       stats.u.run.rs_handle_count = commit_transaction->t_handle_count;
-       spin_lock(&journal->j_history_lock);
-       memcpy(journal->j_history + journal->j_history_cur, &stats,
-                       sizeof(stats));
-       if (++journal->j_history_cur == journal->j_history_max)
-               journal->j_history_cur = 0;
+       stats.run.rs_handle_count = commit_transaction->t_handle_count;
+       trace_jbd2_run_stats(journal->j_fs_dev->bd_dev,
+                            commit_transaction->t_tid, &stats.run);
 
        /*
         * Calculate overall stats
         */
+       spin_lock(&journal->j_history_lock);
        journal->j_stats.ts_tid++;
-       journal->j_stats.u.run.rs_wait += stats.u.run.rs_wait;
-       journal->j_stats.u.run.rs_running += stats.u.run.rs_running;
-       journal->j_stats.u.run.rs_locked += stats.u.run.rs_locked;
-       journal->j_stats.u.run.rs_flushing += stats.u.run.rs_flushing;
-       journal->j_stats.u.run.rs_logging += stats.u.run.rs_logging;
-       journal->j_stats.u.run.rs_handle_count += stats.u.run.rs_handle_count;
-       journal->j_stats.u.run.rs_blocks += stats.u.run.rs_blocks;
-       journal->j_stats.u.run.rs_blocks_logged += stats.u.run.rs_blocks_logged;
+       journal->j_stats.run.rs_wait += stats.run.rs_wait;
+       journal->j_stats.run.rs_running += stats.run.rs_running;
+       journal->j_stats.run.rs_locked += stats.run.rs_locked;
+       journal->j_stats.run.rs_flushing += stats.run.rs_flushing;
+       journal->j_stats.run.rs_logging += stats.run.rs_logging;
+       journal->j_stats.run.rs_handle_count += stats.run.rs_handle_count;
+       journal->j_stats.run.rs_blocks += stats.run.rs_blocks;
+       journal->j_stats.run.rs_blocks_logged += stats.run.rs_blocks_logged;
        spin_unlock(&journal->j_history_lock);
 
        commit_transaction->t_state = T_FINISHED;
index 977a8da..761af77 100644 (file)
@@ -676,153 +676,6 @@ struct jbd2_stats_proc_session {
        int max;
 };
 
-static void *jbd2_history_skip_empty(struct jbd2_stats_proc_session *s,
-                                       struct transaction_stats_s *ts,
-                                       int first)
-{
-       if (ts == s->stats + s->max)
-               ts = s->stats;
-       if (!first && ts == s->stats + s->start)
-               return NULL;
-       while (ts->ts_type == 0) {
-               ts++;
-               if (ts == s->stats + s->max)
-                       ts = s->stats;
-               if (ts == s->stats + s->start)
-                       return NULL;
-       }
-       return ts;
-
-}
-
-static void *jbd2_seq_history_start(struct seq_file *seq, loff_t *pos)
-{
-       struct jbd2_stats_proc_session *s = seq->private;
-       struct transaction_stats_s *ts;
-       int l = *pos;
-
-       if (l == 0)
-               return SEQ_START_TOKEN;
-       ts = jbd2_history_skip_empty(s, s->stats + s->start, 1);
-       if (!ts)
-               return NULL;
-       l--;
-       while (l) {
-               ts = jbd2_history_skip_empty(s, ++ts, 0);
-               if (!ts)
-                       break;
-               l--;
-       }
-       return ts;
-}
-
-static void *jbd2_seq_history_next(struct seq_file *seq, void *v, loff_t *pos)
-{
-       struct jbd2_stats_proc_session *s = seq->private;
-       struct transaction_stats_s *ts = v;
-
-       ++*pos;
-       if (v == SEQ_START_TOKEN)
-               return jbd2_history_skip_empty(s, s->stats + s->start, 1);
-       else
-               return jbd2_history_skip_empty(s, ++ts, 0);
-}
-
-static int jbd2_seq_history_show(struct seq_file *seq, void *v)
-{
-       struct transaction_stats_s *ts = v;
-       if (v == SEQ_START_TOKEN) {
-               seq_printf(seq, "%-4s %-5s %-5s %-5s %-5s %-5s %-5s %-6s %-5s "
-                               "%-5s %-5s %-5s %-5s %-5s\n", "R/C", "tid",
-                               "wait", "run", "lock", "flush", "log", "hndls",
-                               "block", "inlog", "ctime", "write", "drop",
-                               "close");
-               return 0;
-       }
-       if (ts->ts_type == JBD2_STATS_RUN)
-               seq_printf(seq, "%-4s %-5lu %-5u %-5u %-5u %-5u %-5u "
-                               "%-6lu %-5lu %-5lu\n", "R", ts->ts_tid,
-                               jiffies_to_msecs(ts->u.run.rs_wait),
-                               jiffies_to_msecs(ts->u.run.rs_running),
-                               jiffies_to_msecs(ts->u.run.rs_locked),
-                               jiffies_to_msecs(ts->u.run.rs_flushing),
-                               jiffies_to_msecs(ts->u.run.rs_logging),
-                               ts->u.run.rs_handle_count,
-                               ts->u.run.rs_blocks,
-                               ts->u.run.rs_blocks_logged);
-       else if (ts->ts_type == JBD2_STATS_CHECKPOINT)
-               seq_printf(seq, "%-4s %-5lu %48s %-5u %-5lu %-5lu %-5lu\n",
-                               "C", ts->ts_tid, " ",
-                               jiffies_to_msecs(ts->u.chp.cs_chp_time),
-                               ts->u.chp.cs_written, ts->u.chp.cs_dropped,
-                               ts->u.chp.cs_forced_to_close);
-       else
-               J_ASSERT(0);
-       return 0;
-}
-
-static void jbd2_seq_history_stop(struct seq_file *seq, void *v)
-{
-}
-
-static const struct seq_operations jbd2_seq_history_ops = {
-       .start  = jbd2_seq_history_start,
-       .next   = jbd2_seq_history_next,
-       .stop   = jbd2_seq_history_stop,
-       .show   = jbd2_seq_history_show,
-};
-
-static int jbd2_seq_history_open(struct inode *inode, struct file *file)
-{
-       journal_t *journal = PDE(inode)->data;
-       struct jbd2_stats_proc_session *s;
-       int rc, size;
-
-       s = kmalloc(sizeof(*s), GFP_KERNEL);
-       if (s == NULL)
-               return -ENOMEM;
-       size = sizeof(struct transaction_stats_s) * journal->j_history_max;
-       s->stats = kmalloc(size, GFP_KERNEL);
-       if (s->stats == NULL) {
-               kfree(s);
-               return -ENOMEM;
-       }
-       spin_lock(&journal->j_history_lock);
-       memcpy(s->stats, journal->j_history, size);
-       s->max = journal->j_history_max;
-       s->start = journal->j_history_cur % s->max;
-       spin_unlock(&journal->j_history_lock);
-
-       rc = seq_open(file, &jbd2_seq_history_ops);
-       if (rc == 0) {
-               struct seq_file *m = file->private_data;
-               m->private = s;
-       } else {
-               kfree(s->stats);
-               kfree(s);
-       }
-       return rc;
-
-}
-
-static int jbd2_seq_history_release(struct inode *inode, struct file *file)
-{
-       struct seq_file *seq = file->private_data;
-       struct jbd2_stats_proc_session *s = seq->private;
-
-       kfree(s->stats);
-       kfree(s);
-       return seq_release(inode, file);
-}
-
-static struct file_operations jbd2_seq_history_fops = {
-       .owner          = THIS_MODULE,
-       .open           = jbd2_seq_history_open,
-       .read           = seq_read,
-       .llseek         = seq_lseek,
-       .release        = jbd2_seq_history_release,
-};
-
 static void *jbd2_seq_info_start(struct seq_file *seq, loff_t *pos)
 {
        return *pos ? NULL : SEQ_START_TOKEN;
@@ -839,29 +692,29 @@ static int jbd2_seq_info_show(struct seq_file *seq, void *v)
 
        if (v != SEQ_START_TOKEN)
                return 0;
-       seq_printf(seq, "%lu transaction, each upto %u blocks\n",
+       seq_printf(seq, "%lu transaction, each up to %u blocks\n",
                        s->stats->ts_tid,
                        s->journal->j_max_transaction_buffers);
        if (s->stats->ts_tid == 0)
                return 0;
        seq_printf(seq, "average: \n  %ums waiting for transaction\n",
-           jiffies_to_msecs(s->stats->u.run.rs_wait / s->stats->ts_tid));
+           jiffies_to_msecs(s->stats->run.rs_wait / s->stats->ts_tid));
        seq_printf(seq, "  %ums running transaction\n",
-           jiffies_to_msecs(s->stats->u.run.rs_running / s->stats->ts_tid));
+           jiffies_to_msecs(s->stats->run.rs_running / s->stats->ts_tid));
        seq_printf(seq, "  %ums transaction was being locked\n",
-           jiffies_to_msecs(s->stats->u.run.rs_locked / s->stats->ts_tid));
+           jiffies_to_msecs(s->stats->run.rs_locked / s->stats->ts_tid));
        seq_printf(seq, "  %ums flushing data (in ordered mode)\n",
-           jiffies_to_msecs(s->stats->u.run.rs_flushing / s->stats->ts_tid));
+           jiffies_to_msecs(s->stats->run.rs_flushing / s->stats->ts_tid));
        seq_printf(seq, "  %ums logging transaction\n",
-           jiffies_to_msecs(s->stats->u.run.rs_logging / s->stats->ts_tid));
+           jiffies_to_msecs(s->stats->run.rs_logging / s->stats->ts_tid));
        seq_printf(seq, "  %lluus average transaction commit time\n",
                   div_u64(s->journal->j_average_commit_time, 1000));
        seq_printf(seq, "  %lu handles per transaction\n",
-           s->stats->u.run.rs_handle_count / s->stats->ts_tid);
+           s->stats->run.rs_handle_count / s->stats->ts_tid);
        seq_printf(seq, "  %lu blocks per transaction\n",
-           s->stats->u.run.rs_blocks / s->stats->ts_tid);
+           s->stats->run.rs_blocks / s->stats->ts_tid);
        seq_printf(seq, "  %lu logged blocks per transaction\n",
-           s->stats->u.run.rs_blocks_logged / s->stats->ts_tid);
+           s->stats->run.rs_blocks_logged / s->stats->ts_tid);
        return 0;
 }
 
@@ -931,8 +784,6 @@ static void jbd2_stats_proc_init(journal_t *journal)
 {
        journal->j_proc_entry = proc_mkdir(journal->j_devname, proc_jbd2_stats);
        if (journal->j_proc_entry) {
-               proc_create_data("history", S_IRUGO, journal->j_proc_entry,
-                                &jbd2_seq_history_fops, journal);
                proc_create_data("info", S_IRUGO, journal->j_proc_entry,
                                 &jbd2_seq_info_fops, journal);
        }
@@ -941,27 +792,9 @@ static void jbd2_stats_proc_init(journal_t *journal)
 static void jbd2_stats_proc_exit(journal_t *journal)
 {
        remove_proc_entry("info", journal->j_proc_entry);
-       remove_proc_entry("history", journal->j_proc_entry);
        remove_proc_entry(journal->j_devname, proc_jbd2_stats);
 }
 
-static void journal_init_stats(journal_t *journal)
-{
-       int size;
-
-       if (!proc_jbd2_stats)
-               return;
-
-       journal->j_history_max = 100;
-       size = sizeof(struct transaction_stats_s) * journal->j_history_max;
-       journal->j_history = kzalloc(size, GFP_KERNEL);
-       if (!journal->j_history) {
-               journal->j_history_max = 0;
-               return;
-       }
-       spin_lock_init(&journal->j_history_lock);
-}
-
 /*
  * Management for journal control blocks: functions to create and
  * destroy journal_t structures, and to initialise and read existing
@@ -1006,7 +839,7 @@ static journal_t * journal_init_common (void)
                goto fail;
        }
 
-       journal_init_stats(journal);
+       spin_lock_init(&journal->j_history_lock);
 
        return journal;
 fail:
index 52695d3..f1011f7 100644 (file)
@@ -464,9 +464,9 @@ struct handle_s
  */
 struct transaction_chp_stats_s {
        unsigned long           cs_chp_time;
-       unsigned long           cs_forced_to_close;
-       unsigned long           cs_written;
-       unsigned long           cs_dropped;
+       __u32                   cs_forced_to_close;
+       __u32                   cs_written;
+       __u32                   cs_dropped;
 };
 
 /* The transaction_t type is the guts of the journaling mechanism.  It
@@ -668,23 +668,16 @@ struct transaction_run_stats_s {
        unsigned long           rs_flushing;
        unsigned long           rs_logging;
 
-       unsigned long           rs_handle_count;
-       unsigned long           rs_blocks;
-       unsigned long           rs_blocks_logged;
+       __u32                   rs_handle_count;
+       __u32                   rs_blocks;
+       __u32                   rs_blocks_logged;
 };
 
 struct transaction_stats_s {
-       int                     ts_type;
        unsigned long           ts_tid;
-       union {
-               struct transaction_run_stats_s run;
-               struct transaction_chp_stats_s chp;
-       } u;
+       struct transaction_run_stats_s run;
 };
 
-#define JBD2_STATS_RUN         1
-#define JBD2_STATS_CHECKPOINT  2
-
 static inline unsigned long
 jbd2_time_diff(unsigned long start, unsigned long end)
 {
@@ -988,12 +981,6 @@ struct journal_s
        /*
         * Journal statistics
         */
-       struct transaction_stats_s *j_history;
-       int                     j_history_max;
-       int                     j_history_cur;
-       /*
-        * Protect the transactions statistics history
-        */
        spinlock_t              j_history_lock;
        struct proc_dir_entry   *j_proc_entry;
        struct transaction_stats_s j_stats;
index b851f0b..3c60b75 100644 (file)
@@ -7,6 +7,9 @@
 #include <linux/jbd2.h>
 #include <linux/tracepoint.h>
 
+struct transaction_chp_stats_s;
+struct transaction_run_stats_s;
+
 TRACE_EVENT(jbd2_checkpoint,
 
        TP_PROTO(journal_t *journal, int result),
@@ -162,6 +165,81 @@ TRACE_EVENT(jbd2_submit_inode_data,
                  jbd2_dev_to_name(__entry->dev), (unsigned long) __entry->ino)
 );
 
+TRACE_EVENT(jbd2_run_stats,
+       TP_PROTO(dev_t dev, unsigned long tid,
+                struct transaction_run_stats_s *stats),
+
+       TP_ARGS(dev, tid, stats),
+
+       TP_STRUCT__entry(
+               __field(                dev_t,  dev             )
+               __field(        unsigned long,  tid             )
+               __field(        unsigned long,  wait            )
+               __field(        unsigned long,  running         )
+               __field(        unsigned long,  locked          )
+               __field(        unsigned long,  flushing        )
+               __field(        unsigned long,  logging         )
+               __field(                __u32,  handle_count    )
+               __field(                __u32,  blocks          )
+               __field(                __u32,  blocks_logged   )
+       ),
+
+       TP_fast_assign(
+               __entry->dev            = dev;
+               __entry->tid            = tid;
+               __entry->wait           = stats->rs_wait;
+               __entry->running        = stats->rs_running;
+               __entry->locked         = stats->rs_locked;
+               __entry->flushing       = stats->rs_flushing;
+               __entry->logging        = stats->rs_logging;
+               __entry->handle_count   = stats->rs_handle_count;
+               __entry->blocks         = stats->rs_blocks;
+               __entry->blocks_logged  = stats->rs_blocks_logged;
+       ),
+
+       TP_printk("dev %s tid %lu wait %u running %u locked %u flushing %u "
+                 "logging %u handle_count %u blocks %u blocks_logged %u",
+                 jbd2_dev_to_name(__entry->dev), __entry->tid,
+                 jiffies_to_msecs(__entry->wait),
+                 jiffies_to_msecs(__entry->running),
+                 jiffies_to_msecs(__entry->locked),
+                 jiffies_to_msecs(__entry->flushing),
+                 jiffies_to_msecs(__entry->logging),
+                 __entry->handle_count, __entry->blocks,
+                 __entry->blocks_logged)
+);
+
+TRACE_EVENT(jbd2_checkpoint_stats,
+       TP_PROTO(dev_t dev, unsigned long tid,
+                struct transaction_chp_stats_s *stats),
+
+       TP_ARGS(dev, tid, stats),
+
+       TP_STRUCT__entry(
+               __field(                dev_t,  dev             )
+               __field(        unsigned long,  tid             )
+               __field(        unsigned long,  chp_time        )
+               __field(                __u32,  forced_to_close )
+               __field(                __u32,  written         )
+               __field(                __u32,  dropped         )
+       ),
+
+       TP_fast_assign(
+               __entry->dev            = dev;
+               __entry->tid            = tid;
+               __entry->chp_time       = stats->cs_chp_time;
+               __entry->forced_to_close= stats->cs_forced_to_close;
+               __entry->written        = stats->cs_written;
+               __entry->dropped        = stats->cs_dropped;
+       ),
+
+       TP_printk("dev %s tid %lu chp_time %u forced_to_close %u "
+                 "written %u dropped %u",
+                 jbd2_dev_to_name(__entry->dev), __entry->tid,
+                 jiffies_to_msecs(__entry->chp_time),
+                 __entry->forced_to_close, __entry->written, __entry->dropped)
+);
+
 #endif /* _TRACE_JBD2_H */
 
 /* This part must be outside protection */