Commit bf699327 authored by Theodore Ts'o's avatar Theodore Ts'o
Browse files

jbd2: Use tracepoints for history file 



The /proc/fs/jbd2/<dev>/history was maintained manually; by using
tracepoints, we can get all of the existing functionality of the /proc
file plus extra capabilities thanks to the ftrace infrastructure.  We
save memory as a bonus.

Signed-off-by: default avatar"Theodore Ts'o" <tytso@mit.edu>
parent 296c355c

fs/jbd2/checkpoint.c

+7 −0
Original line number Diff line number Diff line
@@ -643,6 +643,7 @@ out: 


int __jbd2_journal_remove_checkpoint(struct journal_head *jh)

{

	struct transaction_chp_stats_s *stats;

	transaction_t *transaction;

	journal_t *journal;

	int ret = 0;
@@ -679,6 +680,12 @@ int __jbd2_journal_remove_checkpoint(struct journal_head *jh) 


	/* OK, that was the last buffer for the transaction: we can now

	   safely remove this transaction from the log */

	stats = &transaction->t_chp_stats;

	if (stats->cs_chp_time)

		stats->cs_chp_time = jbd2_time_diff(stats->cs_chp_time,

						    jiffies);

	trace_jbd2_checkpoint_stats(journal->j_fs_dev->bd_dev,

				    transaction->t_tid, stats);



	__jbd2_journal_drop_transaction(journal, transaction);

	kfree(transaction);

fs/jbd2/commit.c

+28 −31
Original line number Diff line number Diff line
@@ -410,10 +410,10 @@ void jbd2_journal_commit_transaction(journal_t *journal) 
	if (commit_transaction->t_synchronous_commit)

		write_op = WRITE_SYNC_PLUG;

	trace_jbd2_commit_locking(journal, commit_transaction);

	stats.u.run.rs_wait = commit_transaction->t_max_wait;

	stats.u.run.rs_locked = jiffies;

	stats.u.run.rs_running = jbd2_time_diff(commit_transaction->t_start,

						stats.u.run.rs_locked);

	stats.run.rs_wait = commit_transaction->t_max_wait;

	stats.run.rs_locked = jiffies;

	stats.run.rs_running = jbd2_time_diff(commit_transaction->t_start,

					      stats.run.rs_locked);



	spin_lock(&commit_transaction->t_handle_lock);

	while (commit_transaction->t_updates) {
@@ -486,9 +486,9 @@ void jbd2_journal_commit_transaction(journal_t *journal) 
	jbd2_journal_switch_revoke_table(journal);



	trace_jbd2_commit_flushing(journal, commit_transaction);

	stats.u.run.rs_flushing = jiffies;

	stats.u.run.rs_locked = jbd2_time_diff(stats.u.run.rs_locked,

					       stats.u.run.rs_flushing);

	stats.run.rs_flushing = jiffies;

	stats.run.rs_locked = jbd2_time_diff(stats.run.rs_locked,

					     stats.run.rs_flushing);



	commit_transaction->t_state = T_FLUSH;

	journal->j_committing_transaction = commit_transaction;
@@ -523,11 +523,11 @@ void jbd2_journal_commit_transaction(journal_t *journal) 
	spin_unlock(&journal->j_state_lock);



	trace_jbd2_commit_logging(journal, commit_transaction);

	stats.u.run.rs_logging = jiffies;

	stats.u.run.rs_flushing = jbd2_time_diff(stats.u.run.rs_flushing,

						 stats.u.run.rs_logging);

	stats.u.run.rs_blocks = commit_transaction->t_outstanding_credits;

	stats.u.run.rs_blocks_logged = 0;

	stats.run.rs_logging = jiffies;

	stats.run.rs_flushing = jbd2_time_diff(stats.run.rs_flushing,

					       stats.run.rs_logging);

	stats.run.rs_blocks = commit_transaction->t_outstanding_credits;

	stats.run.rs_blocks_logged = 0;



	J_ASSERT(commit_transaction->t_nr_buffers <=

		 commit_transaction->t_outstanding_credits);
@@ -695,7 +695,7 @@ start_journal_io: 
				submit_bh(write_op, bh);

			}

			cond_resched();

			stats.u.run.rs_blocks_logged += bufs;

			stats.run.rs_blocks_logged += bufs;



			/* Force a new descriptor to be generated next

                           time round the loop. */
@@ -988,33 +988,30 @@ restart_loop: 
	J_ASSERT(commit_transaction->t_state == T_COMMIT);



	commit_transaction->t_start = jiffies;

	stats.u.run.rs_logging = jbd2_time_diff(stats.u.run.rs_logging,

	stats.run.rs_logging = jbd2_time_diff(stats.run.rs_logging,

					      commit_transaction->t_start);



	/*

	 * File the transaction for history

	 * File the transaction statistics

	 */

	stats.ts_type = JBD2_STATS_RUN;

	stats.ts_tid = commit_transaction->t_tid;

	stats.u.run.rs_handle_count = commit_transaction->t_handle_count;

	spin_lock(&journal->j_history_lock);

	memcpy(journal->j_history + journal->j_history_cur, &stats,

			sizeof(stats));

	if (++journal->j_history_cur == journal->j_history_max)

		journal->j_history_cur = 0;

	stats.run.rs_handle_count = commit_transaction->t_handle_count;

	trace_jbd2_run_stats(journal->j_fs_dev->bd_dev,

			     commit_transaction->t_tid, &stats.run);



	/*

	 * Calculate overall stats

	 */

	spin_lock(&journal->j_history_lock);

	journal->j_stats.ts_tid++;

	journal->j_stats.u.run.rs_wait += stats.u.run.rs_wait;

	journal->j_stats.u.run.rs_running += stats.u.run.rs_running;

	journal->j_stats.u.run.rs_locked += stats.u.run.rs_locked;

	journal->j_stats.u.run.rs_flushing += stats.u.run.rs_flushing;

	journal->j_stats.u.run.rs_logging += stats.u.run.rs_logging;

	journal->j_stats.u.run.rs_handle_count += stats.u.run.rs_handle_count;

	journal->j_stats.u.run.rs_blocks += stats.u.run.rs_blocks;

	journal->j_stats.u.run.rs_blocks_logged += stats.u.run.rs_blocks_logged;

	journal->j_stats.run.rs_wait += stats.run.rs_wait;

	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;

	journal->j_stats.run.rs_logging += stats.run.rs_logging;

	journal->j_stats.run.rs_handle_count += stats.run.rs_handle_count;

	journal->j_stats.run.rs_blocks += stats.run.rs_blocks;

	journal->j_stats.run.rs_blocks_logged += stats.run.rs_blocks_logged;

	spin_unlock(&journal->j_history_lock);



	commit_transaction->t_state = T_FINISHED;

fs/jbd2/journal.c

+10 −177
Original line number Diff line number Diff line
@@ -676,153 +676,6 @@ struct jbd2_stats_proc_session { 
	int max;

};



static void *jbd2_history_skip_empty(struct jbd2_stats_proc_session *s,

					struct transaction_stats_s *ts,

					int first)

{

	if (ts == s->stats + s->max)

		ts = s->stats;

	if (!first && ts == s->stats + s->start)

		return NULL;

	while (ts->ts_type == 0) {

		ts++;

		if (ts == s->stats + s->max)

			ts = s->stats;

		if (ts == s->stats + s->start)

			return NULL;

	}

	return ts;



}



static void *jbd2_seq_history_start(struct seq_file *seq, loff_t *pos)

{

	struct jbd2_stats_proc_session *s = seq->private;

	struct transaction_stats_s *ts;

	int l = *pos;



	if (l == 0)

		return SEQ_START_TOKEN;

	ts = jbd2_history_skip_empty(s, s->stats + s->start, 1);

	if (!ts)

		return NULL;

	l--;

	while (l) {

		ts = jbd2_history_skip_empty(s, ++ts, 0);

		if (!ts)

			break;

		l--;

	}

	return ts;

}



static void *jbd2_seq_history_next(struct seq_file *seq, void *v, loff_t *pos)

{

	struct jbd2_stats_proc_session *s = seq->private;

	struct transaction_stats_s *ts = v;



	++*pos;

	if (v == SEQ_START_TOKEN)

		return jbd2_history_skip_empty(s, s->stats + s->start, 1);

	else

		return jbd2_history_skip_empty(s, ++ts, 0);

}



static int jbd2_seq_history_show(struct seq_file *seq, void *v)

{

	struct transaction_stats_s *ts = v;

	if (v == SEQ_START_TOKEN) {

		seq_printf(seq, "%-4s %-5s %-5s %-5s %-5s %-5s %-5s %-6s %-5s "

				"%-5s %-5s %-5s %-5s %-5s\n", "R/C", "tid",

				"wait", "run", "lock", "flush", "log", "hndls",

				"block", "inlog", "ctime", "write", "drop",

				"close");

		return 0;

	}

	if (ts->ts_type == JBD2_STATS_RUN)

		seq_printf(seq, "%-4s %-5lu %-5u %-5u %-5u %-5u %-5u "

				"%-6lu %-5lu %-5lu\n", "R", ts->ts_tid,

				jiffies_to_msecs(ts->u.run.rs_wait),

				jiffies_to_msecs(ts->u.run.rs_running),

				jiffies_to_msecs(ts->u.run.rs_locked),

				jiffies_to_msecs(ts->u.run.rs_flushing),

				jiffies_to_msecs(ts->u.run.rs_logging),

				ts->u.run.rs_handle_count,

				ts->u.run.rs_blocks,

				ts->u.run.rs_blocks_logged);

	else if (ts->ts_type == JBD2_STATS_CHECKPOINT)

		seq_printf(seq, "%-4s %-5lu %48s %-5u %-5lu %-5lu %-5lu\n",

				"C", ts->ts_tid, " ",

				jiffies_to_msecs(ts->u.chp.cs_chp_time),

				ts->u.chp.cs_written, ts->u.chp.cs_dropped,

				ts->u.chp.cs_forced_to_close);

	else

		J_ASSERT(0);

	return 0;

}



static void jbd2_seq_history_stop(struct seq_file *seq, void *v)

{

}



static const struct seq_operations jbd2_seq_history_ops = {

	.start  = jbd2_seq_history_start,

	.next   = jbd2_seq_history_next,

	.stop   = jbd2_seq_history_stop,

	.show   = jbd2_seq_history_show,

};



static int jbd2_seq_history_open(struct inode *inode, struct file *file)

{

	journal_t *journal = PDE(inode)->data;

	struct jbd2_stats_proc_session *s;

	int rc, size;



	s = kmalloc(sizeof(*s), GFP_KERNEL);

	if (s == NULL)

		return -ENOMEM;

	size = sizeof(struct transaction_stats_s) * journal->j_history_max;

	s->stats = kmalloc(size, GFP_KERNEL);

	if (s->stats == NULL) {

		kfree(s);

		return -ENOMEM;

	}

	spin_lock(&journal->j_history_lock);

	memcpy(s->stats, journal->j_history, size);

	s->max = journal->j_history_max;

	s->start = journal->j_history_cur % s->max;

	spin_unlock(&journal->j_history_lock);



	rc = seq_open(file, &jbd2_seq_history_ops);

	if (rc == 0) {

		struct seq_file *m = file->private_data;

		m->private = s;

	} else {

		kfree(s->stats);

		kfree(s);

	}

	return rc;



}



static int jbd2_seq_history_release(struct inode *inode, struct file *file)

{

	struct seq_file *seq = file->private_data;

	struct jbd2_stats_proc_session *s = seq->private;



	kfree(s->stats);

	kfree(s);

	return seq_release(inode, file);

}



static struct file_operations jbd2_seq_history_fops = {

	.owner		= THIS_MODULE,

	.open           = jbd2_seq_history_open,

	.read           = seq_read,

	.llseek         = seq_lseek,

	.release        = jbd2_seq_history_release,

};



static void *jbd2_seq_info_start(struct seq_file *seq, loff_t *pos)

{

	return *pos ? NULL : SEQ_START_TOKEN;
@@ -845,23 +698,23 @@ static int jbd2_seq_info_show(struct seq_file *seq, void *v) 
	if (s->stats->ts_tid == 0)

		return 0;

	seq_printf(seq, "average: \n  %ums waiting for transaction\n",

	    jiffies_to_msecs(s->stats->u.run.rs_wait / s->stats->ts_tid));

	    jiffies_to_msecs(s->stats->run.rs_wait / s->stats->ts_tid));

	seq_printf(seq, "  %ums running transaction\n",

	    jiffies_to_msecs(s->stats->u.run.rs_running / s->stats->ts_tid));

	    jiffies_to_msecs(s->stats->run.rs_running / s->stats->ts_tid));

	seq_printf(seq, "  %ums transaction was being locked\n",

	    jiffies_to_msecs(s->stats->u.run.rs_locked / s->stats->ts_tid));

	    jiffies_to_msecs(s->stats->run.rs_locked / s->stats->ts_tid));

	seq_printf(seq, "  %ums flushing data (in ordered mode)\n",

	    jiffies_to_msecs(s->stats->u.run.rs_flushing / s->stats->ts_tid));

	    jiffies_to_msecs(s->stats->run.rs_flushing / s->stats->ts_tid));

	seq_printf(seq, "  %ums logging transaction\n",

	    jiffies_to_msecs(s->stats->u.run.rs_logging / s->stats->ts_tid));

	    jiffies_to_msecs(s->stats->run.rs_logging / s->stats->ts_tid));

	seq_printf(seq, "  %lluus average transaction commit time\n",

		   div_u64(s->journal->j_average_commit_time, 1000));

	seq_printf(seq, "  %lu handles per transaction\n",

	    s->stats->u.run.rs_handle_count / s->stats->ts_tid);

	    s->stats->run.rs_handle_count / s->stats->ts_tid);

	seq_printf(seq, "  %lu blocks per transaction\n",

	    s->stats->u.run.rs_blocks / s->stats->ts_tid);

	    s->stats->run.rs_blocks / s->stats->ts_tid);

	seq_printf(seq, "  %lu logged blocks per transaction\n",

	    s->stats->u.run.rs_blocks_logged / s->stats->ts_tid);

	    s->stats->run.rs_blocks_logged / s->stats->ts_tid);

	return 0;

}
@@ -931,8 +784,6 @@ static void jbd2_stats_proc_init(journal_t *journal) 
{

	journal->j_proc_entry = proc_mkdir(journal->j_devname, proc_jbd2_stats);

	if (journal->j_proc_entry) {

		proc_create_data("history", S_IRUGO, journal->j_proc_entry,

				 &jbd2_seq_history_fops, journal);

		proc_create_data("info", S_IRUGO, journal->j_proc_entry,

				 &jbd2_seq_info_fops, journal);

	}
@@ -941,27 +792,9 @@ static void jbd2_stats_proc_init(journal_t *journal) 
static void jbd2_stats_proc_exit(journal_t *journal)

{

	remove_proc_entry("info", journal->j_proc_entry);

	remove_proc_entry("history", journal->j_proc_entry);

	remove_proc_entry(journal->j_devname, proc_jbd2_stats);

}



static void journal_init_stats(journal_t *journal)

{

	int size;



	if (!proc_jbd2_stats)

		return;



	journal->j_history_max = 100;

	size = sizeof(struct transaction_stats_s) * journal->j_history_max;

	journal->j_history = kzalloc(size, GFP_KERNEL);

	if (!journal->j_history) {

		journal->j_history_max = 0;

		return;

	}

	spin_lock_init(&journal->j_history_lock);

}



/*

 * Management for journal control blocks: functions to create and

 * destroy journal_t structures, and to initialise and read existing
@@ -1006,7 +839,7 @@ static journal_t * journal_init_common (void) 
		goto fail;

	}



	journal_init_stats(journal);

	spin_lock_init(&journal->j_history_lock);



	return journal;

fail:

include/linux/jbd2.h

+7 −20
Original line number Diff line number Diff line
@@ -464,9 +464,9 @@ struct handle_s 
 */

struct transaction_chp_stats_s {

	unsigned long		cs_chp_time;

	unsigned long		cs_forced_to_close;

	unsigned long		cs_written;

	unsigned long		cs_dropped;

	__u32			cs_forced_to_close;

	__u32			cs_written;

	__u32			cs_dropped;

};



/* The transaction_t type is the guts of the journaling mechanism.  It
@@ -668,23 +668,16 @@ struct transaction_run_stats_s { 
	unsigned long		rs_flushing;

	unsigned long		rs_logging;



	unsigned long		rs_handle_count;

	unsigned long		rs_blocks;

	unsigned long		rs_blocks_logged;

	__u32			rs_handle_count;

	__u32			rs_blocks;

	__u32			rs_blocks_logged;

};



struct transaction_stats_s {

	int 			ts_type;

	unsigned long		ts_tid;

	union {

	struct transaction_run_stats_s run;

		struct transaction_chp_stats_s chp;

	} u;

};



#define JBD2_STATS_RUN		1

#define JBD2_STATS_CHECKPOINT	2



static inline unsigned long

jbd2_time_diff(unsigned long start, unsigned long end)

{
@@ -988,12 +981,6 @@ struct journal_s 
	/*

	 * Journal statistics

	 */

	struct transaction_stats_s *j_history;

	int			j_history_max;

	int			j_history_cur;

	/*

	 * Protect the transactions statistics history

	 */

	spinlock_t		j_history_lock;

	struct proc_dir_entry	*j_proc_entry;

	struct transaction_stats_s j_stats;

include/trace/events/jbd2.h

+78 −0
Original line number Diff line number Diff line
@@ -7,6 +7,9 @@ 
#include <linux/jbd2.h>

#include <linux/tracepoint.h>



struct transaction_chp_stats_s;

struct transaction_run_stats_s;



TRACE_EVENT(jbd2_checkpoint,



	TP_PROTO(journal_t *journal, int result),
@@ -162,6 +165,81 @@ TRACE_EVENT(jbd2_submit_inode_data, 
		  jbd2_dev_to_name(__entry->dev), (unsigned long) __entry->ino)

);



TRACE_EVENT(jbd2_run_stats,

	TP_PROTO(dev_t dev, unsigned long tid,

		 struct transaction_run_stats_s *stats),



	TP_ARGS(dev, tid, stats),



	TP_STRUCT__entry(

		__field(		dev_t,	dev		)

		__field(	unsigned long,	tid		)

		__field(	unsigned long,	wait		)

		__field(	unsigned long,	running		)

		__field(	unsigned long,	locked		)

		__field(	unsigned long,	flushing	)

		__field(	unsigned long,	logging		)

		__field(		__u32,	handle_count	)

		__field(		__u32,	blocks		)

		__field(		__u32,	blocks_logged	)

	),



	TP_fast_assign(

		__entry->dev		= dev;

		__entry->tid		= tid;

		__entry->wait		= stats->rs_wait;

		__entry->running	= stats->rs_running;

		__entry->locked		= stats->rs_locked;

		__entry->flushing	= stats->rs_flushing;

		__entry->logging	= stats->rs_logging;

		__entry->handle_count	= stats->rs_handle_count;

		__entry->blocks		= stats->rs_blocks;

		__entry->blocks_logged	= stats->rs_blocks_logged;

	),



	TP_printk("dev %s tid %lu wait %u running %u locked %u flushing %u "

		  "logging %u handle_count %u blocks %u blocks_logged %u",

		  jbd2_dev_to_name(__entry->dev), __entry->tid,

		  jiffies_to_msecs(__entry->wait),

		  jiffies_to_msecs(__entry->running),

		  jiffies_to_msecs(__entry->locked),

		  jiffies_to_msecs(__entry->flushing),

		  jiffies_to_msecs(__entry->logging),

		  __entry->handle_count, __entry->blocks,

		  __entry->blocks_logged)

);



TRACE_EVENT(jbd2_checkpoint_stats,

	TP_PROTO(dev_t dev, unsigned long tid,

		 struct transaction_chp_stats_s *stats),



	TP_ARGS(dev, tid, stats),



	TP_STRUCT__entry(

		__field(		dev_t,	dev		)

		__field(	unsigned long,	tid		)

		__field(	unsigned long,	chp_time	)

		__field(		__u32,	forced_to_close	)

		__field(		__u32,	written		)

		__field(		__u32,	dropped		)

	),



	TP_fast_assign(

		__entry->dev		= dev;

		__entry->tid		= tid;

		__entry->chp_time	= stats->cs_chp_time;

		__entry->forced_to_close= stats->cs_forced_to_close;

		__entry->written	= stats->cs_written;

		__entry->dropped	= stats->cs_dropped;

	),



	TP_printk("dev %s tid %lu chp_time %u forced_to_close %u "

		  "written %u dropped %u",

		  jbd2_dev_to_name(__entry->dev), __entry->tid,

		  jiffies_to_msecs(__entry->chp_time),

		  __entry->forced_to_close, __entry->written, __entry->dropped)

);



#endif /* _TRACE_JBD2_H */



/* This part must be outside protection */

CRA Git | Maintained and supported by SUSTech CRA and CCSE