From patchwork Sat Feb 9 21:53:41 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Theodore Ts'o X-Patchwork-Id: 219458 Return-Path: X-Original-To: patchwork-incoming@ozlabs.org Delivered-To: patchwork-incoming@ozlabs.org Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by ozlabs.org (Postfix) with ESMTP id A2D8B2C0091 for ; Sun, 10 Feb 2013 08:54:07 +1100 (EST) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1760853Ab3BIVyG (ORCPT ); Sat, 9 Feb 2013 16:54:06 -0500 Received: from li9-11.members.linode.com ([67.18.176.11]:47622 "EHLO imap.thunk.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1760852Ab3BIVx7 (ORCPT ); Sat, 9 Feb 2013 16:53:59 -0500 Received: from root (helo=closure.thunk.org) by imap.thunk.org with local-esmtp (Exim 4.80) (envelope-from ) id 1U4IMr-0001ZG-Nw; Sat, 09 Feb 2013 21:53:53 +0000 Received: by closure.thunk.org (Postfix, from userid 15806) id 3B4372E93E9; Sat, 9 Feb 2013 16:53:52 -0500 (EST) From: Theodore Ts'o To: Ext4 Developers List Cc: Theodore Ts'o Subject: [PATCH 01/12] jbd2: track request delay statistics Date: Sat, 9 Feb 2013 16:53:41 -0500 Message-Id: <1360446832-12724-2-git-send-email-tytso@mit.edu> X-Mailer: git-send-email 1.7.12.rc0.22.gcdd159b In-Reply-To: <1360446832-12724-1-git-send-email-tytso@mit.edu> References: <1360446832-12724-1-git-send-email-tytso@mit.edu> X-SA-Exim-Connect-IP: X-SA-Exim-Mail-From: tytso@thunk.org X-SA-Exim-Scanned: No (on imap.thunk.org); SAEximRunCond expanded to false Sender: linux-ext4-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-ext4@vger.kernel.org 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" --- fs/jbd2/commit.c | 8 ++++++++ fs/jbd2/journal.c | 12 +++++++++--- fs/jbd2/transaction.c | 1 + include/linux/jbd2.h | 7 +++++++ include/trace/events/jbd2.h | 8 ++++++-- 5 files changed, 31 insertions(+), 5 deletions(-) diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c index 3091d42..750c701 100644 --- a/fs/jbd2/commit.c +++ b/fs/jbd2/commit.c @@ -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; diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c index 1a80e31..4ba2e81 100644 --- a/fs/jbd2/journal.c +++ b/fs/jbd2/journal.c @@ -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", diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c index df9f297..735609e 100644 --- a/fs/jbd2/transaction.c +++ b/fs/jbd2/transaction.c @@ -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; } diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h index e30b663..e0aafc4 100644 --- a/include/linux/jbd2.h +++ b/include/linux/jbd2.h @@ -581,6 +581,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; @@ -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; }; diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h index 127993d..5419f57 100644 --- a/include/trace/events/jbd2.h +++ b/include/trace/events/jbd2.h @@ -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),