[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <1239877127.3344.24.camel@localhost.localdomain>
Date: Thu, 16 Apr 2009 11:18:47 +0100
From: Steven Whitehouse <swhiteho@...hat.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: LKML <linux-kernel@...r.kernel.org>, cluster-devel@...hat.com,
Ingo Molnar <mingo@...e.hu>
Subject: Re: GFS2: Tracing support for review
Hi,
On Wed, 2009-04-15 at 12:12 -0400, Steven Rostedt wrote:
> Hi Steven,
>
>
[some comments cut]
> If you look at the latest "tip" code, I have an code in
> examples/trace_events/ that does it better. If found that using the
> -I$(PWD)/path and then defining TRACE_INCLUDE_PATH to "." worked well.
>
> But the way you did it is just fine as well.
>
> >
> > Also there seemed to be a symbol which was not exported, which I've added
> > to the patch below.
>
> Ah, that is because I developed without the perf counters in my branch.
> Could you send that as a separate patch. It should not be tied to
> the rest of your code. Your code can depend on it, but that is something
> that we want to apply right away.
>
Looks like Ingo got there first :-)
> > diff --git a/fs/gfs2/trace_gfs2.h b/fs/gfs2/trace_gfs2.h
> > new file mode 100644
> > index 0000000..73850fd
> > --- /dev/null
> > +++ b/fs/gfs2/trace_gfs2.h
> > @@ -0,0 +1,395 @@
> > +#if !defined(_TRACE_GFS2_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_GFS2_H
> > +
> > +#include <linux/tracepoint.h>
> > +
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM gfs2
> > +#define TRACE_INCLUDE_FILE trace_gfs2
>
> Nice, you figured that part out. I was afraid the double use of
> TRACE_SYSTEM and TRACE_INCLUDE_FILE might confuse people.
>
Yes, that didn't seem too tricky.
> > +
> > +#include <linux/fs.h>
> > +#include <linux/buffer_head.h>
> > +#include <linux/dlmconstants.h>
> > +#include <linux/gfs2_ondisk.h>
> > +#include "incore.h"
> > +#include "glock.h"
> > +
> > +/* Section 1 - Locking
> > + *
> > + * Objectives:
> > + * Latency: Remote demote request to state change
> > + * Latency: Local lock request to state change
> > + * Latency: State change to lock grant
> > + * Correctness: Ordering of local lock state vs. I/O requests
> > + * Correctness: Responses to remote demote requests
> > + */
> > +
> > +/* General glock state change (DLM lock request completes) */
> > +TRACE_EVENT(gfs2_glock_state_change,
> > +
> > + TP_PROTO(const struct gfs2_glock *gl, unsigned int new_state),
> > +
> > + TP_ARGS(gl, new_state),
> > +
> > + TP_STRUCT__entry(
> > + __field( u64, glnum )
> > + __field( u32, gltype )
> > + __field( dev_t, dev )
> > + __field( u8, cur_state )
> > + __field( u8, new_state )
> > + __field( u8, dmt_state )
> > + __field( u8, tgt_state )
> > + __array( char, comm, TASK_COMM_LEN )
> > + __field( pid_t, pid )
> > + ),
> > +
> > + TP_fast_assign(
> > + __entry->glnum = gl->gl_name.ln_number;
> > + __entry->gltype = gl->gl_name.ln_type;
> > + __entry->dev = gl->gl_sbd->sd_vfs->s_dev;
> > + __entry->cur_state = glock_trace_state(gl->gl_state);
> > + __entry->new_state = glock_trace_state(new_state);
> > + __entry->tgt_state = glock_trace_state(gl->gl_target);
> > + __entry->dmt_state = DLM_LOCK_IV;
> > + if (test_bit(GLF_DEMOTE, &gl->gl_flags) ||
> > + test_bit(GLF_PENDING_DEMOTE, &gl->gl_flags))
> > + __entry->dmt_state = glock_trace_state(gl->gl_demote_state);
> > + memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
>
> I wonder if I should add a comm field. The tracing should cache the last
> comm, but that has issues too. All ftrace records say the current pid, so
> the below code pid saving is not needed. And (when it works) the pid comms
> are cached on schedule switches when tracing is enabled. only 100 or so
> comms are cached, and if tracing is on for a long time, you may miss some.
>
> That is how you see the <...> in the traces.
>
> But the pid here is definitely duplicate.
>
>
Ok, I've removed the pid now, but I see traces like:
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<...>-2889 [000] 1211.283008: gfs2_glock_state_change: 253:0 glock
2:33119 state NL => EX tgt:EX dmt:-- task:glock_workqueue
<...>-2889 [000] 1211.283201: gfs2_promote: 253:0 glock 2:33119 pro
mote first task:glock_workqueue
<...>-2941 [000] 1211.283217: gfs2_demote_rq: 253:0 glock 2:33119 d
emote EX to NL task:gfs2_quotad
<...>-2941 [000] 1211.283218: gfs2_glock_queue: 253:0 glock 2:33119
dequeue task:gfs2_quotad
<...>-2889 [000] 1211.283274: gfs2_glock_state_change: 253:0 glock
2:33119 state EX => NL tgt:NL dmt:NL task:glock_workqueue
<...>-2889 [000] 1214.527032: gfs2_glock_state_change: 253:0 glock
2:21 state NL => PR tgt:PR dmt:-- task:glock_workqueue
So I think from what you are telling me, the <...> should be the comm,
but I don't see that here. I think it would be a useful feature to have.
Also I should say that tracing wasn't on for a long time in this case,
and I never get anything other than <...> in the task field. This is on
the latest -tip tree with my patch applied and no other changes.
Many thanks for the review - if I can confirm whether or not I should
keep the comm field, then I can send a revised version of the patch
which I think should be ready for submission to the tracing tree at that
point,
Steve.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists