[PATCH 0/5] updates to ftrace framework and mmiotrace

[PATCH 0/5] updates to ftrace framework and mmiotrace

[Pekka Paalanen]

Hello all,

here starts a little patch series that finally makes mmiotrace produce good
trace logs with the ftrace framework. There are some caveats which I note
below. Also, the marker feature (as in inserting user comments into the log)
is still missing.

I believe I should try to make a full patch containing everything of
mmiotrace for review, but it might be tricky and not apply to any public
git tree, as it depends on new features in sched-devel, especially ftrace.
We'll see.

On Sat, 26 Apr 2008 20:33:06 +0300
Pekka Paalanen <pq@iki.fi> wrote:

> On Mon, 21 Apr 2008 17:09:37 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > This patch adds a method for open_pipe and open_read to the pluggins
> > so that they can add a header to the trace pipe call.
> > 
> > Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> 
> In addition to this, I think I need tracer::close method called on
> tracing_release_pipe(). Use case: the reader closes the pipe before
> I have printed all of my header, i.e. walked through all PCI devices,
> so I need to properly destroy trace_iterator::private.

This is still broken. The close method is there, but it is not called,
as far as I can tell.

> I also intend to use trace_iterator::seq for printing my header, so I
> am looking if I can reuse code from tracing_read_pipe(). Looks like I'll
> extract the "return any leftover data" part into a separate function.

This resulted in the function trace_seq_to_user() which comes in the
first patch. Just like the code I refactored, it does not touch filp
or ppos. I trust the original author better than myself in this one :-)

> To check trace_iterator::overrun, I'd like to be able to use
> for_each_tracing_cpu(), but that is local to trace.c.

I'm using for_each_online_cpu() and trace_iterator::overrun for now.
It works, but I think the "events lost" trace log messages come too
late, like I explained earlier. On the other hand, the precise point
in the stream is not important, if one is aiming for a complete trace.

The patches will follow.


Thanks.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

[PATCH 1/5] ftrace: add readpos to struct trace_seq; add trace_seq_to_user()

[Pekka Paalanen]

>From c69153a56ddcdc09a2135a4d9cbf95ab4bdd08a0 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sat, 26 Apr 2008 21:58:39 +0300
Subject: [PATCH] ftrace: add readpos to struct trace_seq; add trace_seq_to_user()

Refactor code from tracing_read_pipe() and create trace_seq_to_user().
Moved trace_seq_reset() call before iter->trace->read() call so that
when all leftover data is returned, trace_seq is reset automatically.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---

Steven,

do you approve this?


 kernel/trace/trace.c |   73 ++++++++++++++++++++++++-------------------------
 kernel/trace/trace.h |    3 ++
 2 files changed, 39 insertions(+), 37 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 04366ae..06c85b3 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -403,6 +403,26 @@ static void
 trace_seq_reset(struct trace_seq *s)
 {
 	s->len = 0;
+	s->readpos = 0;
+}
+
+ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf, size_t cnt)
+{
+	int len;
+	int ret;
+
+	if (s->len <= s->readpos)
+		return -EBUSY;
+
+	len = s->len - s->readpos;
+	if (cnt > len)
+		cnt = len;
+	ret = copy_to_user(ubuf, s->buffer + s->readpos, cnt);
+	if (ret)
+		return -EFAULT;
+
+	s->readpos += len;
+	return cnt;
 }
 
 static void
@@ -2406,46 +2426,32 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 	struct trace_iterator *iter = filp->private_data;
 	struct trace_array_cpu *data;
 	static cpumask_t mask;
-	static int start;
 	unsigned long flags;
 #ifdef CONFIG_FTRACE
 	int ftrace_save;
 #endif
-	int read = 0;
 	int cpu;
-	int len;
-	int ret;
+	ssize_t sret;
 
 	/* return any leftover data */
-	if (iter->seq.len > start) {
-		len = iter->seq.len - start;
-		if (cnt > len)
-			cnt = len;
-		ret = copy_to_user(ubuf, iter->seq.buffer + start, cnt);
-		if (ret)
-			cnt = -EFAULT;
-
-		start += len;
+	sret = trace_seq_to_user(&iter->seq, ubuf, cnt);
+	if (sret != -EBUSY)
+		return sret;
+	sret = 0;
 
-		return cnt;
-	}
+	trace_seq_reset(&iter->seq);
 
 	mutex_lock(&trace_types_lock);
 	if (iter->trace->read) {
-		ret = iter->trace->read(iter, filp, ubuf, cnt, ppos);
-		if (ret) {
-			read = ret;
+		sret = iter->trace->read(iter, filp, ubuf, cnt, ppos);
+		if (sret)
 			goto out;
-		}
 	}
 
-	trace_seq_reset(&iter->seq);
-	start = 0;
-
 	while (trace_empty(iter)) {
 
 		if ((filp->f_flags & O_NONBLOCK)) {
-			read = -EAGAIN;
+			sret = -EAGAIN;
 			goto out;
 		}
 
@@ -2471,7 +2477,7 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 		iter->tr->waiter = NULL;
 
 		if (signal_pending(current)) {
-			read = -EINTR;
+			sret = -EINTR;
 			goto out;
 		}
 
@@ -2541,6 +2547,7 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 	}
 
 	while (find_next_entry_inc(iter) != NULL) {
+		int ret;
 		int len = iter->seq.len;
 
 		ret = print_trace_line(iter);
@@ -2571,24 +2578,16 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 	local_irq_restore(flags);
 
 	/* Now copy what we have to the user */
-	read = iter->seq.len;
-	if (read > cnt)
-		read = cnt;
-
-	ret = copy_to_user(ubuf, iter->seq.buffer, read);
-
-	if (read < iter->seq.len)
-		start = read;
-	else
+	sret = trace_seq_to_user(&iter->seq, ubuf, cnt);
+	if (iter->seq.readpos >= iter->seq.len)
 		trace_seq_reset(&iter->seq);
-
-	if (ret)
-		read = -EFAULT;
+	if (sret == -EBUSY)
+		sret = 0;
 
 out:
 	mutex_unlock(&trace_types_lock);
 
-	return read;
+	return sret;
 }
 
 static ssize_t
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index a151c87..3e15c23 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -160,6 +160,7 @@ struct tracer {
 struct trace_seq {
 	unsigned char		buffer[PAGE_SIZE];
 	unsigned int		len;
+	unsigned int		readpos;
 };
 
 /*
@@ -303,6 +304,8 @@ extern int trace_selftest_startup_sysprof(struct tracer *trace,
 
 extern void *head_page(struct trace_array_cpu *data);
 extern int trace_seq_printf(struct trace_seq *s, const char *fmt, ...);
+extern ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf,
+				 size_t cnt);
 extern long ns2usecs(cycle_t nsec);
 
 extern unsigned long trace_flags;
-- 
1.5.3.7

[PATCH 2/5] mmiotrace: print header using the read hook.

[Pekka Paalanen]

>From edf8d48e6bea0202536f3221bc4098f88278645f Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sat, 26 Apr 2008 23:05:23 +0300
Subject: [PATCH] mmiotrace: print header using the read hook.

Now the header is printed only for `trace_pipe' file.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace_mmiotrace.c |   60 +++++++++++++++++++++++++++++++++++----
 1 files changed, 53 insertions(+), 7 deletions(-)

diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 79be4a1..6d2edbd 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -12,6 +12,10 @@
 
 #include "trace.h"
 
+struct header_iter {
+	struct pci_dev *dev;
+};
+
 static struct trace_array *mmio_trace_array;
 
 static void mmio_reset_data(struct trace_array *tr)
@@ -89,17 +93,57 @@ static int mmio_print_pcidev(struct trace_seq *s, const struct pci_dev *dev)
 	return ret;
 }
 
-/* XXX: This is not called for trace_pipe file! */
-static void mmio_print_header(struct trace_iterator *iter)
+static void destroy_header_iter(struct header_iter *hiter)
+{
+	if (!hiter)
+		return;
+	pci_dev_put(hiter->dev);
+	kfree(hiter);
+}
+
+static void mmio_pipe_open(struct trace_iterator *iter)
 {
+	struct header_iter *hiter;
 	struct trace_seq *s = &iter->seq;
-	struct pci_dev *dev = NULL;
 
 	trace_seq_printf(s, "VERSION 20070824\n");
 
-	for_each_pci_dev(dev)
-		mmio_print_pcidev(s, dev);
-	/* XXX: return value? What if header is very long? */
+	hiter = kzalloc(sizeof(*hiter), GFP_KERNEL);
+	if (!hiter)
+		return;
+
+	hiter->dev = pci_get_device(PCI_ANY_ID, PCI_ANY_ID, NULL);
+	iter->private = hiter;
+}
+
+/* XXX: This is not called when the pipe is closed! */
+static void mmio_close(struct trace_iterator *iter)
+{
+	struct header_iter *hiter = iter->private;
+	destroy_header_iter(hiter);
+	iter->private = NULL;
+}
+
+static ssize_t mmio_read(struct trace_iterator *iter, struct file *filp,
+				char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+	ssize_t ret;
+	struct header_iter *hiter = iter->private;
+	struct trace_seq *s = &iter->seq;
+
+	if (!hiter)
+		return 0;
+
+	mmio_print_pcidev(s, hiter->dev);
+	hiter->dev = pci_get_device(PCI_ANY_ID, PCI_ANY_ID, hiter->dev);
+
+	if (!hiter->dev) {
+		destroy_header_iter(hiter);
+		iter->private = NULL;
+	}
+
+	ret = trace_seq_to_user(s, ubuf, cnt);
+	return (ret == -EBUSY) ? 0 : ret;
 }
 
 static int mmio_print_rw(struct trace_iterator *iter)
@@ -190,7 +234,9 @@ static struct tracer mmio_tracer __read_mostly =
 	.name		= "mmiotrace",
 	.init		= mmio_trace_init,
 	.reset		= mmio_trace_reset,
-	.open		= mmio_print_header,
+	.pipe_open	= mmio_pipe_open,
+	.close		= mmio_close,
+	.read		= mmio_read,
 	.ctrl_update	= mmio_trace_ctrl_update,
 	.print_line	= mmio_print_line,
 };
-- 
1.5.3.7

[PATCH 3/5] mmiotrace: print overrun counts

[Pekka Paalanen]

>From d5c3a38d48e223bcf192f48a8b202fdffa616390 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 27 Apr 2008 00:00:33 +0300
Subject: [PATCH] mmiotrace: print overrun counts

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace_mmiotrace.c |   25 +++++++++++++++++++++++++
 1 files changed, 25 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 6d2edbd..d0f649a 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -17,11 +17,13 @@ struct header_iter {
 };
 
 static struct trace_array *mmio_trace_array;
+static bool overrun_detected;
 
 static void mmio_reset_data(struct trace_array *tr)
 {
 	int cpu;
 
+	overrun_detected = false;
 	tr->time_start = ftrace_now(tr->cpu);
 
 	for_each_online_cpu(cpu)
@@ -124,12 +126,34 @@ static void mmio_close(struct trace_iterator *iter)
 	iter->private = NULL;
 }
 
+static unsigned long count_overruns(struct trace_iterator *iter)
+{
+	int cpu;
+	unsigned long cnt = 0;
+	for_each_online_cpu(cpu) {
+		cnt += iter->overrun[cpu];
+		iter->overrun[cpu] = 0;
+	}
+	return cnt;
+}
+
 static ssize_t mmio_read(struct trace_iterator *iter, struct file *filp,
 				char __user *ubuf, size_t cnt, loff_t *ppos)
 {
 	ssize_t ret;
 	struct header_iter *hiter = iter->private;
 	struct trace_seq *s = &iter->seq;
+	unsigned long n;
+
+	n = count_overruns(iter);
+	if (n) {
+		/* XXX: This is later than where events were lost. */
+		trace_seq_printf(s, "MARK 0.000000 Lost %lu events.\n", n);
+		if (!overrun_detected)
+			pr_warning("mmiotrace has lost events.\n");
+		overrun_detected = true;
+		goto print_out;
+	}
 
 	if (!hiter)
 		return 0;
@@ -142,6 +166,7 @@ static ssize_t mmio_read(struct trace_iterator *iter, struct file *filp,
 		iter->private = NULL;
 	}
 
+print_out:
 	ret = trace_seq_to_user(s, ubuf, cnt);
 	return (ret == -EBUSY) ? 0 : ret;
 }
-- 
1.5.3.7

[PATCH 4/5] mmiotrace: Do not print bogus pid for maps either

[Pekka Paalanen]

>From 05689fa9f93c23153a696d18b1bb71286bd2b3d8 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 27 Apr 2008 21:13:52 +0300
Subject: [PATCH] mmiotrace: Do not print bogus pid for maps either

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace_mmiotrace.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index d0f649a..3c1dacd 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -225,12 +225,12 @@ static int mmio_print_map(struct trace_iterator *iter)
 		ret = trace_seq_printf(s,
 			"MAP %lu.%06lu %d 0x%lx 0x%lx 0x%lx 0x%lx %d\n",
 			secs, usec_rem, m->map_id, m->phys, m->virt, m->len,
-			0UL, entry->pid);
+			0UL, 0);
 		break;
 	case MMIO_UNPROBE:
 		ret = trace_seq_printf(s,
 			"UNMAP %lu.%06lu %d 0x%lx %d\n",
-			secs, usec_rem, m->map_id, 0UL, entry->pid);
+			secs, usec_rem, m->map_id, 0UL, 0);
 		break;
 	default:
 		ret = trace_seq_printf(s, "map what?\n");
-- 
1.5.3.7

[PATCH 5/5] doc: update mmiotrace doc to current status

[Pekka Paalanen]

>From bfcf6727d3cf8f5411f1927cf7d490428656ec13 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 27 Apr 2008 21:15:37 +0300
Subject: [PATCH] doc: update mmiotrace doc to current status

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 Documentation/tracers/mmiotrace.txt |   27 +++++++++++++++++++--------
 1 files changed, 19 insertions(+), 8 deletions(-)

diff --git a/Documentation/tracers/mmiotrace.txt b/Documentation/tracers/mmiotrace.txt
index 84246f7..a4afb56 100644
--- a/Documentation/tracers/mmiotrace.txt
+++ b/Documentation/tracers/mmiotrace.txt
@@ -25,7 +25,8 @@ Mmiotrace feature is compiled in by the CONFIG_MMIOTRACE option. Tracing is
 disabled by default, so it is safe to have this set to yes. SMP systems are
 supported, but tracing is unreliable and may miss events if more than one CPU
 is on-line, therefore mmiotrace takes all but one CPU off-line during run-time
-activation [not implemented].
+activation. You can re-enable CPUs by hand, but you have been warned, there
+is no way to automatically detect if you are losing events due to CPUs racing.
 
 
 Usage Quick Reference
@@ -37,7 +38,7 @@ $ cat /debug/tracing/trace_pipe > mydump.txt &
 Start X or whatever.
 $ echo "X is up" > /debug/tracing/marker
 $ echo none > /debug/tracing/current_tracer
-Check kernel log.
+Check for lost events.
 
 
 Usage
@@ -67,12 +68,22 @@ do.
 
 Shut down mmiotrace (requires root privileges):
 $ echo none > /debug/tracing/current_tracer
-The 'cat' process exits. If it does not, kill it by 'fg' and pressing ctrl+c.
-
-[This feature is not implemented yet!]
-Check your kernel log. If there are messages about mmiotrace losing events,
-this is due to buffer overrun, and the trace is incomplete. You should enlarge
-the buffers and try again. [How?]
+The 'cat' process exits. If it does not, kill it by issuing 'fg' command and
+pressing ctrl+c.
+
+Check that mmiotrace did not lose events due to a buffer filling up. Either
+$ grep -i lost mydump.txt
+which tells you exactly how many events were lost, or use
+$ dmesg
+to view your kernel log and look for "mmiotrace has lost events" warning. If
+events were lost, the trace is incomplete. You should enlarge the buffers and
+try again. Buffers are enlarged by first seeing how large the current buffers
+are:
+$ cat /debug/tracing/trace_entries
+gives you a number. Approximately double this number and write it back, for
+instance:
+$ echo 128000 > /debug/tracing/trace_entries
+Then start again from the top.
 
 If you are doing a trace for a driver project, e.g. Nouveau, you should also
 do the following before sending your results:
-- 
1.5.3.7

Re: [PATCH 0/5] updates to ftrace framework and mmiotrace

[Steven Rostedt]

On Sun, 27 Apr 2008, Pekka Paalanen wrote:
>
> This resulted in the function trace_seq_to_user() which comes in the
> first patch. Just like the code I refactored, it does not touch filp
> or ppos. I trust the original author better than myself in this one :-)

If you are talking about me as the original author, then I wouldn't trust
me on ppos ;-).  I believe I screwed that part up. I'm about to go write
some patches for the read functions now.

-- Steve

Re: [PATCH 0/5] updates to ftrace framework and mmiotrace

[Ingo Molnar]

* Pekka Paalanen <pq@iki.fi> wrote:

> Hello all,
> 
> here starts a little patch series that finally makes mmiotrace produce 
> good trace logs with the ftrace framework. There are some caveats 
> which I note below. Also, the marker feature (as in inserting user 
> comments into the log) is still missing.

thanks Pekka, applied.

	Ingo