jbd2: jbd2 stats through procfs

The patch below updates the jbd stats patch to 2.6.20/jbd2.
The initial patch was posted by Alex Tomas in December 2005
(http://marc.info/?l=linux-ext4&m=113538565128617&w=2).
It provides statistics via procfs such as transaction lifetime and size.

Sometimes, investigating performance problems, i find useful to have
stats from jbd about transaction's lifetime, size, etc. here is a
patch for review and inclusion probably.

for example, stats after creation of 3M files in htree directory:

[root@bob ~]# cat /proc/fs/jbd/sda/history
R/C  tid   wait  run   lock  flush log   hndls  block inlog ctime write drop  close
R    261   8260  2720  0     0     750   9892   8170  8187
C    259                                                    750   0     4885  1
R    262   20    2200  10    0     770   9836   8170  8187
R    263   30    2200  10    0     3070  9812   8170  8187
R    264   0     5000  10    0     1340  0      0     0
C    261                                                    8240  3212  4957  0
R    265   8260  1470  0     0     4640  9854   8170  8187
R    266   0     5000  10    0     1460  0      0     0
C    262                                                    8210  2989  4868  0
R    267   8230  1490  10    0     4440  9875   8171  8188
R    268   0     5000  10    0     1260  0      0     0
C    263                                                    7710  2937  4908  0
R    269   7730  1470  10    0     3330  9841   8170  8187
R    270   0     5000  10    0     830   0      0     0
C    265                                                    8140  3234  4898  0
C    267                                                    720   0     4849  1
R    271   8630  2740  20    0     740   9819   8170  8187
C    269                                                    800   0     4214  1
R    272   40    2170  10    0     830   9716   8170  8187
R    273   40    2280  0     0     3530  9799   8170  8187
R    274   0     5000  10    0     990   0      0     0


where,

R     - line for transaction's life from T_RUNNING to T_FINISHED
C     - line for transaction's checkpointing
tid   - transaction's id
wait  - for how long we were waiting for new transaction to start
         (the longest period journal_start() took in this transaction)
run   - real transaction's lifetime (from T_RUNNING to T_LOCKED
lock  - how long we were waiting for all handles to close
         (time the transaction was in T_LOCKED)
flush - how long it took to flush all data (data=ordered)
log   - how long it took to write the transaction to the log
hndls - how many handles got to the transaction
block - how many blocks got to the transaction
inlog - how many blocks are written to the log (block + descriptors)
ctime - how long it took to checkpoint the transaction
write - how many blocks have been written during checkpointing
drop  - how many blocks have been dropped during checkpointing
close - how many running transactions have been closed to checkpoint this one

all times are in msec.


[root@bob ~]# cat /proc/fs/jbd/sda/info
280 transaction, each upto 8192 blocks
average:
  1633ms waiting for transaction
  3616ms running transaction
  5ms transaction was being locked
  1ms flushing data (in ordered mode)
  1799ms logging transaction
  11781 handles per transaction
  5629 blocks per transaction
  5641 logged blocks per transaction

Signed-off-by: Johann Lombardi <johann.lombardi@bull.net>
Signed-off-by: Mariusz Kozlowski <m.kozlowski@tuxland.pl>
Signed-off-by: Mingming Cao <cmm@us.ibm.com>
Signed-off-by: Eric Sandeen <sandeen@redhat.com>

1 files changed, 49 insertions, 0 deletions

diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index 39b5cee3dd8a..8749a86f4175 100644
--- a/fs/jbd2/commit.c
+++ b/fs/jbd2/commit.c
@@ -20,6 +20,7 @@
 #include <linux/slab.h>
 #include <linux/mm.h>
 #include <linux/pagemap.h>
+#include <linux/jiffies.h>
 
 /*
  * Default IO end handler for temporary BJ_IO buffer_heads.
@@ -290,6 +291,7 @@ static inline void write_tag_block(int tag_bytes, journal_block_tag_t *tag,
  */
 void jbd2_journal_commit_transaction(journal_t *journal)
 {
+        struct transaction_stats_s stats;
         transaction_t *commit_transaction;
         struct journal_head *jh, *new_jh, *descriptor;
         struct buffer_head **wbuf = journal->j_wbuf;
@@ -337,6 +339,11 @@ void jbd2_journal_commit_transaction(journal_t *journal)
         spin_lock(&journal->j_state_lock);
         commit_transaction->t_state = T_LOCKED;
 
+        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);
+
         spin_lock(&commit_transaction->t_handle_lock);
         while (commit_transaction->t_updates) {
                 DEFINE_WAIT(wait);
@@ -407,6 +414,10 @@ void jbd2_journal_commit_transaction(journal_t *journal)
          */
         jbd2_journal_switch_revoke_table(journal);
 
+        stats.u.run.rs_flushing = jiffies;
+        stats.u.run.rs_locked = jbd2_time_diff(stats.u.run.rs_locked,
+                                               stats.u.run.rs_flushing);
+
         commit_transaction->t_state = T_FLUSH;
         journal->j_committing_transaction = commit_transaction;
         journal->j_running_transaction = NULL;
@@ -498,6 +509,12 @@ void jbd2_journal_commit_transaction(journal_t *journal)
          */
         commit_transaction->t_state = T_COMMIT;
 
+        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;
+
         descriptor = NULL;
         bufs = 0;
         while (commit_transaction->t_buffers) {
@@ -646,6 +663,7 @@ start_journal_io:
                                 submit_bh(WRITE, bh);
                         }
                         cond_resched();
+                        stats.u.run.rs_blocks_logged += bufs;
 
                         /* Force a new descriptor to be generated next
                            time round the loop. */
@@ -816,6 +834,7 @@ restart_loop:
                 cp_transaction = jh->b_cp_transaction;
                 if (cp_transaction) {
                         JBUFFER_TRACE(jh, "remove from old cp transaction");
+                        cp_transaction->t_chp_stats.cs_dropped++;
                         __jbd2_journal_remove_checkpoint(jh);
                 }
 
@@ -890,6 +909,36 @@ 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);
+
+        /*
+         * File the transaction for history
+         */
+        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;
+
+        /*
+         * Calculate overall stats
+         */
+        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;
+        spin_unlock(&journal->j_history_lock);
+
         commit_transaction->t_state = T_FINISHED;
         J_ASSERT(commit_transaction == journal->j_committing_transaction);
         journal->j_commit_sequence = commit_transaction->t_tid;