From 83cd9d23197d0b37c9ae485621f80c8e36ff3a9f Mon Sep 17 00:00:00 2001 From: Xiaoguang Wang Date: Thu, 9 Jan 2020 15:32:32 +0800 Subject: [PATCH 0558/2944] alinux: jbd2: track slow handle which is preventing transaction committing While transaction is going to commit, it first sets its state to be T_LOCKED and waits all outstanding handles to complete, and the committing transaction will always be in locked state so long as it has outstanding handles, also the whole fs will be locked and all later fs modification operations will be stucked in wait_transaction_locked(). It's hard to tell why handles are that slow, so here we add a new staic tracepoint to track such slow handle, and show io wait time and sched wait time, output likes below: fsstress-20347 [024] .... 1570.305454: jbd2_slow_handle_stats: dev 254,17 tid 15853 type 4 line_no 3101 interval 126 sync 0 requested_blocks 24 dirtied_blocks 0 trans_wait 122 space_wait 0 sched_wait 0 io_wait 126 "trans_wait 122" means that this current committing transaction has been locked for 122ms, due to this handle is not completed quickly. From "io_wait 126", we can see that io is the major reason. In this patch, we also add a per fs control file used to determine whether a handle can be considered to be slow. /proc/fs/jbd2/vdb1-8/stall_thresh default value is 100ms, users can set new threshold by echoing new value to this file. Later I also plan to add a proc file fs per fs to record these info. Reviewed-by: Joseph Qi Signed-off-by: Xiaoguang Wang --- fs/jbd2/commit.c | 1 + fs/jbd2/journal.c | 53 +++++++++++++++++++++++++++++++++++++++++++++ fs/jbd2/transaction.c | 31 ++++++++++++++++++++++++++ include/linux/jbd2.h | 15 +++++++++++++ include/trace/events/jbd2.h | 50 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 150 insertions(+) diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c index 24f86ff..bdfba34 100644 --- a/fs/jbd2/commit.c +++ b/fs/jbd2/commit.c @@ -422,6 +422,7 @@ void jbd2_journal_commit_transaction(journal_t *journal) write_lock(&journal->j_state_lock); J_ASSERT(commit_transaction->t_state == T_RUNNING); commit_transaction->t_state = T_LOCKED; + WRITE_ONCE(commit_transaction->t_locked_time, jiffies); trace_jbd2_commit_locking(journal, commit_transaction); stats.run.rs_wait = commit_transaction->t_max_wait; diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c index 9ff4b74..f522bf4 100644 --- a/fs/jbd2/journal.c +++ b/fs/jbd2/journal.c @@ -1299,6 +1299,55 @@ static ssize_t jbd2_seq_force_copy_write(struct file *file, .release = single_release, }; +static int jbd2_seq_stall_thresh_show(struct seq_file *m, void *v) +{ + journal_t *journal = m->private; + + seq_printf(m, "%lu\n", journal->j_stall_thresh); + return 0; +} + +static int jbd2_seq_stall_thresh_open(struct inode *inode, struct file *filp) +{ + journal_t *journal = PDE_DATA(inode); + + return single_open(filp, jbd2_seq_stall_thresh_show, journal); +} + +static ssize_t jbd2_seq_stall_thresh_write(struct file *file, + const char __user *buf, size_t count, loff_t *offset) +{ + struct inode *inode = file_inode(file); + journal_t *journal = PDE_DATA(inode); + char buffer[PROC_NUMBUF]; + unsigned long long stall_thresh; + int err; + + memset(buffer, 0, sizeof(buffer)); + if (count > sizeof(buffer) - 1) + count = sizeof(buffer) - 1; + if (copy_from_user(buffer, buf, count)) { + err = -EFAULT; + goto out; + } + + err = kstrtoull(strstrip(buffer), 0, &stall_thresh); + if (err) + goto out; + WRITE_ONCE(journal->j_stall_thresh, stall_thresh); +out: + return err < 0 ? err : count; +} + +static const struct file_operations jbd2_seq_stall_thresh_fops = { + .owner = THIS_MODULE, + .open = jbd2_seq_stall_thresh_open, + .read = seq_read, + .write = jbd2_seq_stall_thresh_write, + .llseek = seq_lseek, + .release = single_release, +}; + static struct proc_dir_entry *proc_jbd2_stats; static void jbd2_stats_proc_init(journal_t *journal) @@ -1311,6 +1360,8 @@ static void jbd2_stats_proc_init(journal_t *journal) &jbd2_seq_force_copy_fops, journal); proc_create_data("stats", S_IRUGO, journal->j_proc_entry, &jbd2_seq_stats_fops, journal); + proc_create_data("stall_thresh", 0644, journal->j_proc_entry, + &jbd2_seq_stall_thresh_fops, journal); } } @@ -1319,6 +1370,7 @@ static void jbd2_stats_proc_exit(journal_t *journal) remove_proc_entry("info", journal->j_proc_entry); remove_proc_entry("force_copy", journal->j_proc_entry); remove_proc_entry("stats", journal->j_proc_entry); + remove_proc_entry("stall_thresh", journal->j_proc_entry); remove_proc_entry(journal->j_devname, proc_jbd2_stats); } @@ -1361,6 +1413,7 @@ static journal_t *journal_init_common(struct block_device *bdev, journal->j_commit_interval = (HZ * JBD2_DEFAULT_MAX_COMMIT_AGE); journal->j_min_batch_time = 0; journal->j_max_batch_time = 15000; /* 15ms */ + journal->j_stall_thresh = JBD2_DEFAULT_TRANS_STALL_THRESH; atomic_set(&journal->j_reserved_credits, 0); /* The journal is marked for error until we succeed with recovery! */ diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c index cfe3810..9c1a842 100644 --- a/fs/jbd2/transaction.c +++ b/fs/jbd2/transaction.c @@ -402,6 +402,9 @@ static handle_t *new_handle(int nblocks) return NULL; handle->h_buffer_credits = nblocks; handle->h_ref = 1; + handle->h_pre_start_jiffies = jiffies; + handle->h_sched_wait_sum = current->se.statistics.wait_sum; + handle->h_io_wait_sum = current->se.statistics.iowait_sum; return handle; } @@ -1803,6 +1806,34 @@ int jbd2_journal_stop(handle_t *handle) wait_for_commit = 1; } + do { + unsigned long transaction_locked_time, delta; + unsigned long journal_space_wait; + u64 sched_wait, io_wait; + + transaction_locked_time = READ_ONCE(transaction->t_locked_time); + if (!transaction_locked_time) + break; + + delta = jiffies_to_msecs(jiffies - transaction_locked_time); + if (delta < READ_ONCE(journal->j_stall_thresh)) + break; + + journal_space_wait = handle->h_start_jiffies - + handle->h_pre_start_jiffies; + sched_wait = current->se.statistics.wait_sum - + handle->h_sched_wait_sum; + io_wait = current->se.statistics.iowait_sum - + handle->h_io_wait_sum; + trace_jbd2_slow_handle_stats(journal->j_fs_dev->bd_dev, + transaction->t_tid, handle->h_type, handle->h_line_no, + jiffies - handle->h_start_jiffies, handle->h_sync, + handle->h_requested_credits, + handle->h_requested_credits - handle->h_buffer_credits, + delta, jiffies_to_msecs(journal_space_wait), + sched_wait / NSEC_PER_MSEC, io_wait / NSEC_PER_MSEC); + } while (0); + /* * Once we drop t_updates, if it goes to zero the transaction * could start committing on us and eventually disappear. So diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h index 6c5859c..f67ae03 100644 --- a/include/linux/jbd2.h +++ b/include/linux/jbd2.h @@ -519,7 +519,10 @@ struct jbd2_journal_handle unsigned int h_type: 8; unsigned int h_line_no: 16; + unsigned long h_pre_start_jiffies; unsigned long h_start_jiffies; + u64 h_sched_wait_sum; + u64 h_io_wait_sum; unsigned int h_requested_credits; unsigned int saved_alloc_context; @@ -724,6 +727,9 @@ struct transaction_s * structures associated with the transaction */ struct list_head t_private_list; + + /* When this transaction is locked */ + unsigned long t_locked_time; }; struct transaction_run_stats_s { @@ -1150,6 +1156,15 @@ struct journal_s unsigned int j_force_copy; /** + * @j_stall_thresh: when transaction is locked and there are still + * outstanding handles, such handles will prevent transaction + * committing, trace these handles if they have stalled the transaction + * for @j_stall_thresh time, unit is millisecond, default 100ms. + */ +#define JBD2_DEFAULT_TRANS_STALL_THRESH 100 + unsigned long j_stall_thresh; + + /** * @j_failed_commit: Failed journal commit ID. */ unsigned int j_failed_commit; diff --git a/include/trace/events/jbd2.h b/include/trace/events/jbd2.h index 2310b25..6ea10d5 100644 --- a/include/trace/events/jbd2.h +++ b/include/trace/events/jbd2.h @@ -231,6 +231,56 @@ __entry->dirtied_blocks) ); +TRACE_EVENT(jbd2_slow_handle_stats, + TP_PROTO(dev_t dev, unsigned long tid, unsigned int type, + unsigned int line_no, int interval, int sync, + int requested_blocks, int dirtied_blocks, + unsigned long trans_wait, unsigned long space_wait, + u64 sched_wait, u64 io_wait), + + TP_ARGS(dev, tid, type, line_no, interval, sync, + requested_blocks, dirtied_blocks, trans_wait, space_wait, + sched_wait, io_wait), + + TP_STRUCT__entry( + __field( dev_t, dev ) + __field( unsigned long, tid ) + __field( unsigned int, type ) + __field( unsigned int, line_no ) + __field( int, interval ) + __field( int, sync ) + __field( int, requested_blocks) + __field( int, dirtied_blocks ) + __field( unsigned long, trans_wait ) + __field( unsigned long, space_wait ) + __field( u64, sched_wait ) + __field( u64, io_wait ) + ), + + TP_fast_assign( + __entry->dev = dev; + __entry->tid = tid; + __entry->type = type; + __entry->line_no = line_no; + __entry->interval = interval; + __entry->sync = sync; + __entry->requested_blocks = requested_blocks; + __entry->dirtied_blocks = dirtied_blocks; + __entry->trans_wait = trans_wait; + __entry->space_wait = space_wait; + __entry->sched_wait = sched_wait; + __entry->io_wait = io_wait; + ), + + TP_printk("dev %d,%d tid %lu type %u line_no %u interval %d " + "sync %d requested_blocks %d dirtied_blocks %d " + "trans_wait %lu space_wait %lu sched_wait %llu io_wait %llu", + MAJOR(__entry->dev), MINOR(__entry->dev), __entry->tid, + __entry->type, __entry->line_no, __entry->interval, + __entry->sync, __entry->requested_blocks, + __entry->dirtied_blocks, __entry->trans_wait, + __entry->space_wait, __entry->sched_wait, __entry->io_wait) +); TRACE_EVENT(jbd2_run_stats, TP_PROTO(dev_t dev, unsigned long tid, struct transaction_run_stats_s *stats), -- 1.8.3.1