From: Jan Kara <jack@suse.cz>
To: Theodore Ts'o <tytso@mit.edu>
Cc: Ext4 Developers List <linux-ext4@vger.kernel.org>
Subject: Re: [PATCH 01/12] jbd2: track request delay statistics
Date: Mon, 11 Feb 2013 16:57:46 +0100 [thread overview]
Message-ID: <20130211155746.GG5318@quack.suse.cz> (raw)
In-Reply-To: <1360446832-12724-2-git-send-email-tytso@mit.edu>
On Sat 09-02-13 16:53:41, Ted Tso wrote:
> 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.
Looks good. I just wonder whether jiffies really have enough precision to
get you meaningful numbers. Did you try that?
Honza
>
> Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
> ---
> 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),
> --
> 1.7.12.rc0.22.gcdd159b
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
next prev parent reply other threads:[~2013-02-11 15:57 UTC|newest]
Thread overview: 34+ messages / expand[flat|nested] mbox.gz Atom feed top
2013-02-09 21:53 [PATCH 00/12] jbd2 optimization and bug fixes Theodore Ts'o
2013-02-09 21:53 ` [PATCH 01/12] jbd2: track request delay statistics Theodore Ts'o
2013-02-11 15:57 ` Jan Kara [this message]
2013-02-09 21:53 ` [PATCH 02/12] jbd2: revert "jbd2: add COW fields to struct jbd2_journal_handle" Theodore Ts'o
2013-02-11 15:58 ` Jan Kara
2013-02-09 21:53 ` [PATCH 03/12] jbd2: add tracepoints which provide per-handle statistics Theodore Ts'o
2013-02-09 21:53 ` [PATCH 04/12] ext4: move the jbd2 wrapper functions out of super.c Theodore Ts'o
2013-02-09 21:53 ` [PATCH 05/12] ext4: pass context information to jbd2__journal_start() Theodore Ts'o
2013-02-11 16:16 ` Jan Kara
2013-02-11 18:13 ` Theodore Ts'o
2013-02-11 19:58 ` Jan Kara
2013-02-11 20:14 ` Theodore Ts'o
2013-02-09 21:53 ` [PATCH 06/12] ext4: grab page before starting transaction handle in write_begin() Theodore Ts'o
2013-02-11 16:35 ` Jan Kara
2013-02-09 21:53 ` [PATCH 07/12] ext4: start handle at the last possible moment in ext4_unlink() Theodore Ts'o
2013-02-11 16:21 ` Jan Kara
2013-02-09 21:53 ` [PATCH 08/12] ext4: start handle at the last possible moment in ext4_rmdir() Theodore Ts'o
2013-02-11 16:22 ` Jan Kara
2013-02-09 21:53 ` [PATCH 09/12] ext4: fix the number of credits needed for ext4_ext_migrate() Theodore Ts'o
2013-02-11 16:26 ` Jan Kara
2013-02-09 21:53 ` [PATCH 10/12] ext4: fix the number of credits needed for ext4_unlink() and ext4_rmdir() Theodore Ts'o
2013-02-11 16:28 ` Jan Kara
2013-02-11 18:30 ` Theodore Ts'o
2013-02-11 19:30 ` Jan Kara
2013-02-09 21:53 ` [PATCH 11/12] ext4: fix the number of credits needed for acl ops with inline data Theodore Ts'o
2013-02-10 13:42 ` Tao Ma
2013-02-10 18:15 ` Shentino
2013-02-10 19:43 ` Theodore Ts'o
2013-02-11 16:16 ` Andreas Dilger
2013-02-11 16:30 ` Jan Kara
2013-02-09 21:53 ` [PATCH 12/12] ext4: start handle at the last possible moment when creating inodes Theodore Ts'o
2013-02-11 1:47 ` Theodore Ts'o
2013-02-11 16:00 ` Andreas Dilger
2013-02-11 15:52 ` [PATCH 00/12] jbd2 optimization and bug fixes Jan Kara
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20130211155746.GG5318@quack.suse.cz \
--to=jack@suse.cz \
--cc=linux-ext4@vger.kernel.org \
--cc=tytso@mit.edu \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).