jbd2: track request delay statistics
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 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. Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
This commit is contained in:
parent
40ae348762
commit
9fff24aa2c
|
@ -435,7 +435,12 @@ 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_running = jbd2_time_diff(commit_transaction->t_start,
|
||||
stats.run.rs_locked);
|
||||
|
||||
|
@ -1116,7 +1121,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;
|
||||
|
|
|
@ -533,6 +533,7 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
|
|||
jbd_debug(1, "JBD2: requesting commit %d/%d\n",
|
||||
journal->j_commit_request,
|
||||
journal->j_commit_sequence);
|
||||
journal->j_running_transaction->t_requested = jiffies;
|
||||
wake_up(&journal->j_wait_commit);
|
||||
return 1;
|
||||
} else if (!tid_geq(journal->j_commit_request, target))
|
||||
|
@ -898,13 +899,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;
|
||||
}
|
||||
|
|
|
@ -580,6 +580,11 @@ struct transaction_s
|
|||
*/
|
||||
unsigned long t_start;
|
||||
|
||||
/*
|
||||
* When commit was requested
|
||||
*/
|
||||
unsigned long t_requested;
|
||||
|
||||
/*
|
||||
* Checkpointing stats [j_checkpoint_sem]
|
||||
*/
|
||||
|
@ -637,6 +642,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;
|
||||
|
@ -649,6 +655,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),
|
||||
|
|
Loading…
Reference in a new issue