[PATCH tracepoints] nilfs2: add a tracepoint for transaction events

Discussion:

Hitoshi Mitake

2014-09-24 14:18:31 UTC

This patch adds a tracepoint for transaction events of nilfs. With the
tracepoint, these events can be tracked: begin, abort, commit,
trylock, lock, and unlock. Basically, these events have corresponding
functions e.g. begin event corresponds nilfs_transaction_begin(). The
unlock event is an exception. It corresponds to the iteration in
nilfs_transaction_lock().

Only one tracepoint is introcued: nilfs2_transaction_transition. The
above events are distinguished with newly introduced enum. With this
tracepoint, we can analyse a critical section of segment constructoin.

Sample output by tpoint of perf-tools:
cp-4457 [000] ...1 63.266220: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 1, flags = 9 state = BEGIN
cp-4457 [000] ...1 63.266221: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 0, flags = 9 state = COMMIT
cp-4457 [000] ...1 63.266221: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 0, flags = 9 state = COMMIT
segctord-4371 [001] ...1 68.261196: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = TRYLOCK
segctord-4371 [001] ...1 68.261280: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = LOCK
segctord-4371 [001] ...1 68.261877: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 1, flags = 10 state = BEGIN
segctord-4371 [001] ...1 68.262116: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 18 state = COMMIT
segctord-4371 [001] ...1 68.265032: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 18 state = UNLOCK
segctord-4371 [001] ...1 132.376847: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = TRYLOCK

Signed-off-by: Hitoshi Mitake <mitake.hitoshi-***@public.gmane.org>
---
fs/nilfs2/segment.c | 33 ++++++++++++++++++++++++++-
include/trace/events/nilfs2.h | 53 +++++++++++++++++++++++++++++++++++++++++++
2 files changed, 85 insertions(+), 1 deletion(-)

diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
index 0fcf8e7..1dd9330 100644
--- a/fs/nilfs2/segment.c
+++ b/fs/nilfs2/segment.c
@@ -213,11 +213,18 @@ int nilfs_transaction_begin(struct super_block *sb,
{
struct the_nilfs *nilfs;
int ret = nilfs_prepare_segment_lock(ti);
+ struct nilfs_transaction_info *trace_ti;

if (unlikely(ret < 0))
return ret;
- if (ret > 0)
+ if (ret > 0) {
+ trace_ti = current->journal_info;
+
+ trace_nilfs2_transaction_transition(sb, trace_ti,
+ trace_ti->ti_count, trace_ti->ti_flags,
+ TRACE_NILFS2_TRANSACTION_BEGIN);
return 0;
+ }

sb_start_intwrite(sb);

@@ -228,6 +235,11 @@ int nilfs_transaction_begin(struct super_block *sb,
ret = -ENOSPC;
goto failed;
}
+
+ trace_ti = current->journal_info;
+ trace_nilfs2_transaction_transition(sb, trace_ti, trace_ti->ti_count,
+ trace_ti->ti_flags,
+ TRACE_NILFS2_TRANSACTION_BEGIN);
return 0;

failed:
@@ -260,6 +272,8 @@ int nilfs_transaction_commit(struct super_block *sb)
ti->ti_flags |= NILFS_TI_COMMIT;
if (ti->ti_count > 0) {
ti->ti_count--;
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_COMMIT);
return 0;
}
if (nilfs->ns_writer) {
@@ -271,6 +285,9 @@ int nilfs_transaction_commit(struct super_block *sb)
nilfs_segctor_do_flush(sci, 0);
}
up_read(&nilfs->ns_segctor_sem);
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_COMMIT);
+
current->journal_info = ti->ti_save;

if (ti->ti_flags & NILFS_TI_SYNC)
@@ -289,10 +306,15 @@ void nilfs_transaction_abort(struct super_block *sb)
BUG_ON(ti == NULL || ti->ti_magic != NILFS_TI_MAGIC);
if (ti->ti_count > 0) {
ti->ti_count--;
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_ABORT);
return;
}
up_read(&nilfs->ns_segctor_sem);

+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_ABORT);
+
current->journal_info = ti->ti_save;
if (ti->ti_flags & NILFS_TI_DYNAMIC_ALLOC)
kmem_cache_free(nilfs_transaction_cachep, ti);
@@ -339,6 +361,9 @@ static void nilfs_transaction_lock(struct super_block *sb,
current->journal_info = ti;

for (;;) {
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_TRYLOCK);
+
down_write(&nilfs->ns_segctor_sem);
if (!test_bit(NILFS_SC_PRIOR_FLUSH, &sci->sc_flags))
break;
@@ -350,6 +375,9 @@ static void nilfs_transaction_lock(struct super_block *sb,
}
if (gcflag)
ti->ti_flags |= NILFS_TI_GC;
+
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_LOCK);
}

static void nilfs_transaction_unlock(struct super_block *sb)
@@ -364,6 +392,9 @@ static void nilfs_transaction_unlock(struct super_block *sb)
current->journal_info = ti->ti_save;
if (!list_empty(&ti->ti_garbage))
nilfs_dispose_list(nilfs, &ti->ti_garbage, 0);
+
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_UNLOCK);
}

static void *nilfs_segctor_map_segsum_entry(struct nilfs_sc_info *sci,
diff --git a/include/trace/events/nilfs2.h b/include/trace/events/nilfs2.h
index 285d5f3..2f4ee06 100644
--- a/include/trace/events/nilfs2.h
+++ b/include/trace/events/nilfs2.h
@@ -42,6 +42,59 @@ TRACE_EVENT(nilfs2_collection_stage_transition,
show_collection_stage(__entry->stage))
);

+#ifndef TRACE_HEADER_MULTI_READ
+enum nilfs2_transaction_transition_state {
+ TRACE_NILFS2_TRANSACTION_BEGIN,
+ TRACE_NILFS2_TRANSACTION_COMMIT,
+ TRACE_NILFS2_TRANSACTION_ABORT,
+ TRACE_NILFS2_TRANSACTION_TRYLOCK,
+ TRACE_NILFS2_TRANSACTION_LOCK,
+ TRACE_NILFS2_TRANSACTION_UNLOCK,
+};
+#endif
+
+#define show_transaction_state(type) \
+ __print_symbolic(type, \
+ { TRACE_NILFS2_TRANSACTION_BEGIN, "BEGIN" }, \
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, \
+ { TRACE_NILFS2_TRANSACTION_ABORT, "ABORT" }, \
+ { TRACE_NILFS2_TRANSACTION_TRYLOCK, "TRYLOCK" }, \
+ { TRACE_NILFS2_TRANSACTION_LOCK, "LOCK" }, \
+ { TRACE_NILFS2_TRANSACTION_UNLOCK, "UNLOCK" })
+
+TRACE_EVENT(nilfs2_transaction_transition,
+ TP_PROTO(struct super_block *sb,
+ struct nilfs_transaction_info *ti,
+ int count,
+ unsigned int flags,
+ enum nilfs2_transaction_transition_state state),
+
+ TP_ARGS(sb, ti, count, flags, state),
+
+ TP_STRUCT__entry(
+ __field(void *, sb)
+ __field(void *, ti)
+ __field(int, count)
+ __field(unsigned int, flags)
+ __field(int, state)
+ ),
+
+ TP_fast_assign(
+ __entry->sb = sb;
+ __entry->ti = ti;
+ __entry->count = count;
+ __entry->flags = flags;
+ __entry->state = state;
+ ),
+
+ TP_printk("sb = %p, ti = %p, count = %d, flags = %x state = %s",
+ __entry->sb,
+ __entry->ti,
+ __entry->count,
+ __entry->flags,
+ show_transaction_state(__entry->state))
+);
+
#endif /* _TRACE_NILFS2_H */

/* This part must be outside protection */

--
1.9.1

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Ryusuke Konishi

2014-09-24 15:22:06 UTC

Permalink

Post by Hitoshi Mitake
This patch adds a tracepoint for transaction events of nilfs. With the
tracepoint, these events can be tracked: begin, abort, commit,
trylock, lock, and unlock. Basically, these events have corresponding
functions e.g. begin event corresponds nilfs_transaction_begin(). The
unlock event is an exception. It corresponds to the iteration in
nilfs_transaction_lock().
Only one tracepoint is introcued: nilfs2_transaction_transition. The
above events are distinguished with newly introduced enum. With this
tracepoint, we can analyse a critical section of segment constructoin.
cp-4457 [000] ...1 63.266220: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 1, flags = 9 state = BEGIN
cp-4457 [000] ...1 63.266221: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 0, flags = 9 state = COMMIT
cp-4457 [000] ...1 63.266221: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800bf5ccc58, count = 0, flags = 9 state = COMMIT
segctord-4371 [001] ...1 68.261196: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = TRYLOCK
segctord-4371 [001] ...1 68.261280: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = LOCK
segctord-4371 [001] ...1 68.261877: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 1, flags = 10 state = BEGIN
segctord-4371 [001] ...1 68.262116: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 18 state = COMMIT
segctord-4371 [001] ...1 68.265032: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 18 state = UNLOCK
segctord-4371 [001] ...1 132.376847: nilfs2_transaction_transition: sb = ffff8802112b8800, ti = ffff8800b889bdf8, count = 0, flags = 10 state = TRYLOCK
---
fs/nilfs2/segment.c | 33 ++++++++++++++++++++++++++-
include/trace/events/nilfs2.h | 53 +++++++++++++++++++++++++++++++++++++++++++
2 files changed, 85 insertions(+), 1 deletion(-)
diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
index 0fcf8e7..1dd9330 100644
--- a/fs/nilfs2/segment.c
+++ b/fs/nilfs2/segment.c
@@ -213,11 +213,18 @@ int nilfs_transaction_begin(struct super_block *sb,
{
struct the_nilfs *nilfs;
int ret = nilfs_prepare_segment_lock(ti);
+ struct nilfs_transaction_info *trace_ti;
if (unlikely(ret < 0))
return ret;
- if (ret > 0)
+ if (ret > 0) {
+ trace_ti = current->journal_info;
+
+ trace_nilfs2_transaction_transition(sb, trace_ti,
+ trace_ti->ti_count, trace_ti->ti_flags,
+ TRACE_NILFS2_TRANSACTION_BEGIN);
return 0;
+ }
sb_start_intwrite(sb);
@@ -228,6 +235,11 @@ int nilfs_transaction_begin(struct super_block *sb,
ret = -ENOSPC;
goto failed;
}
+
+ trace_ti = current->journal_info;
+ trace_nilfs2_transaction_transition(sb, trace_ti, trace_ti->ti_count,
+ trace_ti->ti_flags,
+ TRACE_NILFS2_TRANSACTION_BEGIN);
return 0;
@@ -260,6 +272,8 @@ int nilfs_transaction_commit(struct super_block *sb)
ti->ti_flags |= NILFS_TI_COMMIT;
if (ti->ti_count > 0) {
ti->ti_count--;
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_COMMIT);
return 0;
}
if (nilfs->ns_writer) {
@@ -271,6 +285,9 @@ int nilfs_transaction_commit(struct super_block *sb)
nilfs_segctor_do_flush(sci, 0);
}
up_read(&nilfs->ns_segctor_sem);
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_COMMIT);
+
current->journal_info = ti->ti_save;
if (ti->ti_flags & NILFS_TI_SYNC)
@@ -289,10 +306,15 @@ void nilfs_transaction_abort(struct super_block *sb)
BUG_ON(ti == NULL || ti->ti_magic != NILFS_TI_MAGIC);
if (ti->ti_count > 0) {
ti->ti_count--;
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_ABORT);
return;
}
up_read(&nilfs->ns_segctor_sem);
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_ABORT);
+
current->journal_info = ti->ti_save;
if (ti->ti_flags & NILFS_TI_DYNAMIC_ALLOC)
kmem_cache_free(nilfs_transaction_cachep, ti);
@@ -339,6 +361,9 @@ static void nilfs_transaction_lock(struct super_block *sb,
current->journal_info = ti;
for (;;) {
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_TRYLOCK);
+
down_write(&nilfs->ns_segctor_sem);
if (!test_bit(NILFS_SC_PRIOR_FLUSH, &sci->sc_flags))
break;
@@ -350,6 +375,9 @@ static void nilfs_transaction_lock(struct super_block *sb,
}
if (gcflag)
ti->ti_flags |= NILFS_TI_GC;
+
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_LOCK);
}
static void nilfs_transaction_unlock(struct super_block *sb)
@@ -364,6 +392,9 @@ static void nilfs_transaction_unlock(struct super_block *sb)
current->journal_info = ti->ti_save;
if (!list_empty(&ti->ti_garbage))
nilfs_dispose_list(nilfs, &ti->ti_garbage, 0);
+
+ trace_nilfs2_transaction_transition(sb, ti, ti->ti_count,
+ ti->ti_flags, TRACE_NILFS2_TRANSACTION_UNLOCK);
}
static void *nilfs_segctor_map_segsum_entry(struct nilfs_sc_info *sci,
diff --git a/include/trace/events/nilfs2.h b/include/trace/events/nilfs2.h
index 285d5f3..2f4ee06 100644
--- a/include/trace/events/nilfs2.h
+++ b/include/trace/events/nilfs2.h
@@ -42,6 +42,59 @@ TRACE_EVENT(nilfs2_collection_stage_transition,
show_collection_stage(__entry->stage))
);
+#ifndef TRACE_HEADER_MULTI_READ
+enum nilfs2_transaction_transition_state {
+ TRACE_NILFS2_TRANSACTION_BEGIN,
+ TRACE_NILFS2_TRANSACTION_COMMIT,
+ TRACE_NILFS2_TRANSACTION_ABORT,
+ TRACE_NILFS2_TRANSACTION_TRYLOCK,
+ TRACE_NILFS2_TRANSACTION_LOCK,
+ TRACE_NILFS2_TRANSACTION_UNLOCK,
+};
+#endif
+
+#define show_transaction_state(type) \
+ __print_symbolic(type, \
+ { TRACE_NILFS2_TRANSACTION_BEGIN, "BEGIN" }, \
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, \
+ { TRACE_NILFS2_TRANSACTION_ABORT, "ABORT" }, \
+ { TRACE_NILFS2_TRANSACTION_TRYLOCK, "TRYLOCK" }, \
+ { TRACE_NILFS2_TRANSACTION_LOCK, "LOCK" }, \
+ { TRACE_NILFS2_TRANSACTION_UNLOCK, "UNLOCK" })
+
+TRACE_EVENT(nilfs2_transaction_transition,
+ TP_PROTO(struct super_block *sb,
+ struct nilfs_transaction_info *ti,
+ int count,
+ unsigned int flags,
+ enum nilfs2_transaction_transition_state state),
+
+ TP_ARGS(sb, ti, count, flags, state),
+
+ TP_STRUCT__entry(
+ __field(void *, sb)
+ __field(void *, ti)
+ __field(int, count)
+ __field(unsigned int, flags)
+ __field(int, state)
+ ),
+
+ TP_fast_assign(
+ __entry->sb = sb;
+ __entry->ti = ti;
+ __entry->count = count;
+ __entry->flags = flags;
+ __entry->state = state;
+ ),
+
+ TP_printk("sb = %p, ti = %p, count = %d, flags = %x state = %s",
+ __entry->sb,
+ __entry->ti,
+ __entry->count,
+ __entry->flags,
+ show_transaction_state(__entry->state))
+);
+
#endif /* _TRACE_NILFS2_H */
/* This part must be outside protection */
--
1.9.1

checkpatch.pl reported many warnings:

$ scripts/checkpatch.pl ~/patch/recv/tracepoints-2.patch
WARNING: please, no spaces at the start of a line
#204: FILE: include/trace/events/nilfs2.h:57:
+ __print_symbolic(type,^I^I^I^I^I\$

WARNING: please, no spaces at the start of a line
#205: FILE: include/trace/events/nilfs2.h:58:
+ { TRACE_NILFS2_TRANSACTION_BEGIN, "BEGIN" },^I^I\$

WARNING: please, no space before tabs
#206: FILE: include/trace/events/nilfs2.h:59:
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, ^I\$

WARNING: please, no spaces at the start of a line
#206: FILE: include/trace/events/nilfs2.h:59:
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, ^I\$

WARNING: please, no spaces at the start of a line
#207: FILE: include/trace/events/nilfs2.h:60:
+ { TRACE_NILFS2_TRANSACTION_ABORT, "ABORT" },^I^I\$

WARNING: please, no spaces at the start of a line
#208: FILE: include/trace/events/nilfs2.h:61:
+ { TRACE_NILFS2_TRANSACTION_TRYLOCK, "TRYLOCK" },^I\$

WARNING: please, no spaces at the start of a line
#209: FILE: include/trace/events/nilfs2.h:62:
+ { TRACE_NILFS2_TRANSACTION_LOCK, "LOCK" },^I^I\$

WARNING: please, no spaces at the start of a line
#210: FILE: include/trace/events/nilfs2.h:63:
+ { TRACE_NILFS2_TRANSACTION_UNLOCK, "UNLOCK" })$

total: 0 errors, 8 warnings, 148 lines checked

Could you make sure if they are false positives or not ?

Regards,
Ryusuke Konishi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hitoshi Mitake

2014-09-25 13:20:13 UTC

Permalink

On Thu, Sep 25, 2014 at 12:22 AM, Ryusuke Konishi

Post by Ryusuke Konishi

$ scripts/checkpatch.pl ~/patch/recv/tracepoints-2.patch
WARNING: please, no spaces at the start of a line
+ __print_symbolic(type,^I^I^I^I^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_BEGIN, "BEGIN" },^I^I\$
WARNING: please, no space before tabs
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, ^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_COMMIT, "COMMIT" }, ^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_ABORT, "ABORT" },^I^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_TRYLOCK, "TRYLOCK" },^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_LOCK, "LOCK" },^I^I\$
WARNING: please, no spaces at the start of a line
+ { TRACE_NILFS2_TRANSACTION_UNLOCK, "UNLOCK" })$
total: 0 errors, 8 warnings, 148 lines checked
Could you make sure if they are false positives or not ?

Sorry for that. It is my mistake. I'll send v2 later.

Thanks,
Hitoshi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html