@@ -436,7 +436,14 @@ void jbd2_journal_commit_transaction(journal_t *journal)
trace_jbd2_commit_locking(journal, commit_transaction);
stats.run.rs_wait = commit_transaction->t_max_wait;
+ stats.run.rs_request_delay = 0;
stats.run.rs_locked = jiffies;
+ if (commit_transaction->t_requested) {
+ stats.run.rs_request_delay =
+ jbd2_time_diff(commit_transaction->t_requested,
+ stats.run.rs_locked);
+ stats.run.rs_locked = commit_transaction->t_requested;
+ }
stats.run.rs_running = jbd2_time_diff(commit_transaction->t_start,
stats.run.rs_locked);
@@ -1117,7 +1124,10 @@ restart_loop:
*/
spin_lock(&journal->j_history_lock);
journal->j_stats.ts_tid++;
+ if (commit_transaction->t_requested)
+ journal->j_stats.ts_requested++;
journal->j_stats.run.rs_wait += stats.run.rs_wait;
+ journal->j_stats.run.rs_request_delay += stats.run.rs_request_delay;
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;
@@ -534,6 +534,7 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
journal->j_commit_request,
journal->j_commit_sequence);
journal->j_running_transaction->t_state = T_REQUESTED;
+ journal->j_running_transaction->t_requested = jiffies;
wake_up(&journal->j_wait_commit);
return 1;
} else if (!tid_geq(journal->j_commit_request, target))
@@ -899,13 +900,18 @@ 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 up to %u blocks\n",
- s->stats->ts_tid,
- s->journal->j_max_transaction_buffers);
+ seq_printf(seq, "%lu transactions (%lu requested), "
+ "each up to %u blocks\n",
+ s->stats->ts_tid, s->stats->ts_requested,
+ 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->run.rs_wait / s->stats->ts_tid));
+ seq_printf(seq, " %ums request delay\n",
+ (s->stats->ts_requested == 0) ? 0 :
+ jiffies_to_msecs(s->stats->run.rs_request_delay /
+ s->stats->ts_requested));
seq_printf(seq, " %ums running transaction\n",
jiffies_to_msecs(s->stats->run.rs_running / s->stats->ts_tid));
seq_printf(seq, " %ums transaction was being locked\n",
@@ -100,6 +100,7 @@ jbd2_get_transaction(journal_t *journal, transaction_t *transaction)
journal->j_running_transaction = transaction;
transaction->t_max_wait = 0;
transaction->t_start = jiffies;
+ transaction->t_requested = 0;
return transaction;
}
@@ -582,6 +582,11 @@ struct transaction_s
unsigned long t_start;
/*
+ * When commit was requested
+ */
+ unsigned long t_requested;
+
+ /*
* Checkpointing stats [j_checkpoint_sem]
*/
struct transaction_chp_stats_s t_chp_stats;
@@ -638,6 +643,7 @@ struct transaction_s
struct transaction_run_stats_s {
unsigned long rs_wait;
+ unsigned long rs_request_delay;
unsigned long rs_running;
unsigned long rs_locked;
unsigned long rs_flushing;
@@ -650,6 +656,7 @@ struct transaction_run_stats_s {
struct transaction_stats_s {
unsigned long ts_tid;
+ unsigned long ts_requested;
struct transaction_run_stats_s run;
};
@@ -142,6 +142,7 @@ TRACE_EVENT(jbd2_run_stats,
__field( dev_t, dev )
__field( unsigned long, tid )
__field( unsigned long, wait )
+ __field( unsigned long, request_delay )
__field( unsigned long, running )
__field( unsigned long, locked )
__field( unsigned long, flushing )
@@ -155,6 +156,7 @@ TRACE_EVENT(jbd2_run_stats,
__entry->dev = dev;
__entry->tid = tid;
__entry->wait = stats->rs_wait;
+ __entry->request_delay = stats->rs_request_delay;
__entry->running = stats->rs_running;
__entry->locked = stats->rs_locked;
__entry->flushing = stats->rs_flushing;
@@ -164,10 +166,12 @@ TRACE_EVENT(jbd2_run_stats,
__entry->blocks_logged = stats->rs_blocks_logged;
),
- TP_printk("dev %d,%d tid %lu wait %u running %u locked %u flushing %u "
- "logging %u handle_count %u blocks %u blocks_logged %u",
+ TP_printk("dev %d,%d tid %lu wait %u request_delay %u running %u "
+ "locked %u flushing %u logging %u handle_count %u "
+ "blocks %u blocks_logged %u",
MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid,
jiffies_to_msecs(__entry->wait),
+ jiffies_to_msecs(__entry->request_delay),
jiffies_to_msecs(__entry->running),
jiffies_to_msecs(__entry->locked),
jiffies_to_msecs(__entry->flushing),
Track the delay between when we first request that the commit begin and when it actually begins, so we can see how much of a gap exists. In theory, this should just be the remaining time scheduling quantuum of the thread which requested the commit (assuming it was not a synchronous operation which triggered the commit request) plus scheduling overhead; however, it's possible that real time processes might get in the way of letting the kjournald thread from executing. In addition, since we now prohibit handles from being newly started or extended once a commit has been requested, calculate the commit running time from when the commit was first requested, and include the request delay as part of the transaction lockdown delay. Signed-off-by: "Theodore Ts'o" <tytso@mit.edu> --- fs/jbd2/commit.c | 10 ++++++++++ fs/jbd2/journal.c | 12 +++++++++--- fs/jbd2/transaction.c | 1 + include/linux/jbd2.h | 7 +++++++ include/trace/events/jbd2.h | 8 ++++++-- 5 files changed, 33 insertions(+), 5 deletions(-)