login
Search
The documentation of mmiotrace describes an unimplemented feature which allows the user
to write any comments on his trace by writing on a tracing/marker file.
Here is an implementation of this idea.
It applies on last version of tip tree.
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
kernel/trace/trace.c | 264 ++++++++++++++++++++++++++++++++++++--------------
kernel/trace/trace.h | 5 +
2 files changed, 198 insertions(+), 71 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 1801900..ee06849 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -955,6 +955,121 @@ __trace_special(void *__tr, void *__data,
trace_wake_up();
}
+/* Add a message provided by the user (TRACE_MARK) or by __ftrace_printk */
+
+void trace_print(char *buf, int len, struct trace_entry *tmp_ent,
+ struct trace_array *tr, struct trace_array_cpu *data,
+ unsigned long flags)
+{
+ struct trace_entry *entry;
+ int write, written = 0;
+
+ __raw_spin_lock(&data->lock);
+ entry = tracing_get_trace_entry(tr, data);
+ tracing_generic_entry_update(entry, flags);
+ entry->type = tmp_ent->type;
+
+ if (entry->type == TRACE_PRINT)
+ entry->field.print.ip = tmp_ent->field.print.ip;
+
+ write = min(len, (int)(TRACE_PRINT_BUF_SIZE-1));
+ memcpy(&entry->field.print.buf, buf, write);
+ entry->field.print.buf[write] = 0;
+
+ written = write;
+
+ if (written != len)
+ entry->field.flags |= TRACE_FLAG_CONT;
+
+ while (written != len) {
+ entry = tracing_get_trace_entry(tr, data);
+
+ entry->type = TRACE_CONT;
+ write = min(len - written, (int)(TRACE_CONT_BUF_SIZE-1));
+ memcpy(&entry->cont.buf, buf+written, write);
+ entry->cont.buf[write] = 0;
+ written += write;
+ }
+ __raw_spin_unlock(&data->lock);
+}
+
+/* Add a message provided by the user towards the tracing_mark file */
+int tracing_mark(char *buf, int size)
+{
+ struct trace_array *tr = &global_trace;
+ struct trace_array_cpu *data;
+ struct trace_entry ...hmm ... have you looked at the (recently implemented) ftrace_printk() facility? Ingo --
Yes but I didn't want to use ftrace_printk() because it needs the "ip" parameter. User messages doesn't need this. But I reuse a part of the code of ftrace_printk and I splitted ftrace_printk() in two parts for this purpose: __ftrace_printk() and trace_print(). I also reused the print_entry but with a new TRACE_MARK type to make the difference when it is time to send the entry to the pipe because user messages don't use ip. --
Feel free to make TRACE_CONT work for you. I coupled it a little more than I wanted to with the ftrace print. If you can find a nice way to make TRACE_CONT a bit more generic, then feel free. -- Steve --
Thanks. But TRACE_CONT is not a problem. It is generic enough to contain parts of a TRACE_MARK message and that's why I use it in my patch. --
Do you think I should modify something or use a way to make it better? (Added Pekka Paalanen in Cc since it concerns an idea from his mmiotrace's documentation)... --
Nice to hear from you, Frédéric! I have some comments in the following. On Wed, 27 Aug 2008 10:59:33 +0100 IMHO we could just make ftrace_printk() work for all tracers. I doubt there will be need to be able to record nil bytes. The idea of a marker And that is the kind of check that makes current ftrace_printk() unusable. I think this restriction should be lifted and allow it to work on all tracers. I would also like to be able to have e.g. mmiotrace_marker(), which would have the same signature as ftrace_printk(), but is a no-op if mmiotrace is not active. So, we could have an __ftrace_vprintk() to make writing such wrappers easy. And the wrappers could be #ifdef'd away, if the corresponding tracer is not built. I recall somewhere mentioning, that one shouldn't leave ftrace_printk's lying around in "final" code, so I'm not sure how people feel about this wrapping idea, especially when e.g. mmiotrace is hoped to be built-in by default. OTOH, I don't think in-tree drivers and stuff want to use them, so they would be mostly offered for out-of-tree modules (reverse-engineering) and developers (debugging). That makes me wonder ..so that tracers may override it at will. Mmiotrace needs to replace newlines and nil characters, before printing it in its own style, i.e. prefixed with a tag and a timestamp, which are specified in the mmiotrace I think TRACE_MARK and TRACE_PRINT are equivalent, so we could stick Thanks for adding me, I've been brewing my own version of this stuff, but didn't yet solve the __ftrace_printk-is-unusable issue yet. I have the mmiotrace specific parts written for TRACE_PRINT, so we haven't really overlapped each other's work yet. Ingo recently told me it would be good to have a generic debugfs file for adding markers to any tracer log, and this is basically what you did. I didn't try the patch yet, or read it too carefully, but I should. Unfortunately I'm away the next weekend, so I hope to continue working on it the weekend after ...
we can certainly include and test Frédéric's patch in tip/tracing/ftrace - i'll wait for v2 as i guess he will implement the modifications suggested by you? Ingo --
Ok I will send a new patch on the next days... --
Hello Pekka, I like your idea of a ftrace_vprintk wrapper. But actually I'm questioning about the fact that the tracing api itself is not generic enough. At this time, a tracer has to put a function inside the tracing api when it wants to add an entry into the list. See __trace_mmiotrace_rw() for example. Just imagine if one wants to implement a tracer by using a simple module. The way seems to be simple at the beginning: you define your struct tracer, implement your functions and register your tracer. But the simple, single function that will add your entries has to be put in tracing api. It's quite impossible without changing the trace.c file and so impossible without recompiling your kernel. And if I make my own tracer and want to implement my handler for the marker messages, I will have to put my foo_trace_printk in trace.c and add it on the wrapper. IMHO the choice of a wrapper is good but it should dynamically dispatch the message on a handler proposed by the tracer. I think about a new function pointer which could be called "mark" on the struct tracer. And (always IMHO) I think that functions like __trace_mmiotrace_rw() shouldn't be located on trace.c but implemented on the appropriate tracer (in this example: trace_mmiotrace.c). And for this purpose, functions like tracing_generic_entry_update() (or even more higher level function of entry adding) should be symbol's exported. With such a new environment, building personal and quick tracers by using modules may be more appreciated if one has not to touch the Yes I think such a function should really be exported. For example using mmiotrace on a module and beeing able to signal the fact that we are entering the "foo" function seems to me very useful. It's Perhaps the idea of an appropriate "mark" handler for each tracer No problem. Thanks! --
On Thu, 28 Aug 2008 11:04:36 +0100 I think making it more modular would be nice, but I'm not really working Yes, but the atmosphere is that if there are no users in-tree, the feature gets kicked, out-of-tree users or no. That's the reason mmiotrace went in-tree in the first place. So, to get that stuff exported, we might need in-tree users, I believe. Thanks. -- Pekka Paalanen http://www.iki.fi/pq/ --
Perhaps it should be more discussed because it is an unsual case... Ok so just a question before I start a new patch to correct the marker's file. What is the best way to implement tracers's printk handlers? Do you think that these functions must be implemented in trace.c or is it more relevant to dispatch the message to a function provided by the current tracer in its struct tracer operations? If such handler is not implemented, we just defaults the formatting like ftrace_printk does. Thanks... --
On Thu, 4 Sep 2008 18:20:09 +0200 Your last message had an idea I didn't think before (or I misunderstood you), that there could be an optional callback for inserting markers into the ring buffer. My first thought was to have the usual entry handler (print_line callback) to format marker text when it is taken For the output formatting case, I'd prefer the print_line callback, it's just one more case for an entry type in there. Notice the difference between writing to ring buffer and reading to user. The trick is, when does mmiotrace sanitize the marker text, when it comes from user space, the debugfs file. Either a) have another callback for inserting messages into the ring buffer b) have a customisable trace_seq_print_cont() I think I'd favour b). When I tried to use trace_seq_print_cont(), I found it difficult to control the printing of \n at the end of message. So I would implement my own routine to handle also what trace_seq_print_cont() does, filtering the text while copying it to struct trace_seq. I'm not sure where this function should live. It could be useful to all tracers, that want "one line per marker entry" style output, so it could live in trace.c. So my suggestion is to put the marker text unfiltered into the ring buffer, and filter it (if required) during read to user (print_line). Cheers, pq -- Pekka Paalanen http://www.iki.fi/pq/ --
For logdev (my pet project from way back, and the latest ftrace is based on), I had a CUSTOM type. The API allowed to register a callback to a type, and it would associate that type to some number (descriptor) and pass that number back to you. Then you could use this number to write to the buffer using the CUSTOM type and registered number. On output, when a CUSTOM type is detected, it would read the custom.id (the number) and search for any registered callbacks to handle the entry. This probably would not be too difficult to implement. Especially since it is already implemented in logdev. (see http://rostedt.homelinux.com/logdev/) -- Steve --
Why not. It is a way for a tracer to handle output for any type of entries. But will this feature really be used for other special types than TRACE_PRINT? I'm not sure... If it is not the case, the Pekka's solution seems to me far more simple. But actually I don't know the needs of others tracers... --
On Sat, 6 Sep 2008 13:39:55 +0200 I never thought TRACE_PRINT would need anything more. At least I'm happy with the concept of TRACE_PRINT, it just needs some adjustments in the API to be nice to use. True, I might some day want to add yet another entry type for mmiotrace, but I'm not planning that for now, and I could just add it like they are in the current framework. But the benefit of the CUSTOM type would be to allow modularized and out-of-tree tracers. And then, why keep the current predefined types, why not make everything a CUSTOM type? Just define a block size in the ring buffer and use TRACE_CONT to handle payload larger than the block. Anyway, personally I'm satisfied with the current state of the framework and I can only talk for mmiotrace. Cheers, pq -- Pekka Paalanen http://www.iki.fi/pq/ --
Hi Steven and others,
first a minor bug: it seems the units of /debug/tracing/trace_entries
is different for read and write. This is confusing for the users, since
I can't say "if you have problems, double it". If I read from it
something like 16422, then write back 16422, next I read 214. I can't
recall the exact numbers, but the difference really is two orders of
magnitude. I have 1 GB RAM in this box, so that shouldn't be an issue.
My other problem is with trace_pipe. It is again making 'cat' quit too
early. The condition triggered is
if (!tracer_enabled && iter->pos) {
in tracing_read_pipe(), and it is followed by triggering
/* stop when tracing is finished */
if (trace_empty(iter)) {
and then sret=0, so read returns 0 and 'cat' exits.
Now, I am trying my mmiotrace marker patches, but as far as I can tell,
nothing I modified is the reason for this. I didn't yet explicitly test
for it, though. I'll send these patches after I hear from Frederic.
The cat-quit problem is not a constant state. After boot, I could play
with my markers and testmmiotrace without cat quitting. Then something
happens, and cat starts the quitting behaviour, and won't get to normal
by disabling and enabling mmiotrace.
I have a couple of wild guesses of what might be related:
- ring buffer wrap-around
- ring buffer overflow (at first try I hit these, the second try
after putting debug-pr_info's in place I don't hit this)
- ring buffer resize (after playing with trace_entries, cat-quit
problem was present, though it might have been present before)
After viewing the git history, I have some more guesses, mainly
related to setting tracer_enabled to 0.
- commit 2b1bce1787700768cbc87c8509851c6f49d252dc
I don't see where tracer_enabled would be set to 1, when
mmiotrace is enabled. It used to default to 1 and mmiotrace was happy.
- __tracing_open() sets it to 0 (not called for the pipe)
- tracing_release() sets it to 1
- tracing_ctrl_write() toggles it
- tracing_read_pipe() ...You write to it the same number that you read from and it returned something different?? That is indeed a bug, since it should definitely detect that. Is this linux-tip? I'll have to play with it to make sure nothing broke it recently. No, tracer_enabled is something that is internal to the tracer infrastructure. if you read from either tracing/trace or tracing/latency_trace it will disable the tracer while you dump. But you should not be doing that. The trace_pipe should not disable that either. -- Steve --
On Mon, 15 Sep 2008 17:14:34 -0400 (EDT) Yes, it returned a very different number. This is Ingo's tip/master, sorry for not being explicit. Checked-out on Sunday. Echoing the following numbers to trace_entries triggers it: 200, 64, 640, 16422, 16422, 16422, 164220... so the ridiculously small number 64 does something bad. After 640, I read back something less than 200. Each following write increases that number by 46. 16422 is the default before writing anything. That is even stranger than I thought. :-o Ok, so the problem is probably the commit I mentioned. It makes the no_tracer tracer to set tracer_enabled to 0, and I can't find where it would be set to 1 for mmiotrace. And this interferes with tracing_read_pipe(), making it quit when iter->pos is non-zero. See no_trace_init() in trace.c. According to this, the cat-quit occurs when the buffer gets empty after first data, but this isn't totally in agreement with what I recall from my experiments. And it does happen also on other times than injecting markers. So either it is wrong to check tracer_enabled in tracing_read_pipe(), or no_trace_init() should not touch it. Steven, what do you think? -- Pekka Paalanen http://www.iki.fi/pq/ --
Indeed that could be the problem. None_tracer is chosen as the default tracer when the tracer engine loads. But actually no_trace_init is not called at this time. But if you set another tracer and reset current_tracer to none, you will call no_trace_init. Since tracer_enabled is not reset to 1 with other tracer's init functions, the problem occurs when you choose one more time another tracer. I think that mmiotrace receives a smaller flow of entries (depends on the debugged module) whereas sched_switch or function's tracer, as an example, are continuously fed and never enter the "while (trace_empty(iter))" block. That's why I only see this bug in mmiotrace. Perhaps it would be a good idea to reenable tracer_enabled on tracing_set_trace_write() just before calling the init callback of the tracer chosen. --
On Wed, 17 Sep 2008 14:41:29 +0200 Mmiotrace does see times, when there are a small number of events That's a third option, yes. Steven, what is the correct fix? Frederic, thank you very much for testing this! -- Pekka Paalanen http://www.iki.fi/pq/ --
From da74191de5e5a3c0adee0604757d19b2faf8ec79 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sat, 23 Aug 2008 14:32:22 +0300
Subject: [PATCH] x86 mmiotrace: fix a rare memory leak.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
arch/x86/mm/mmio-mod.c | 4 +++-
1 files changed, 3 insertions(+), 1 deletions(-)
diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 635b50e..754bd1e 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -307,8 +307,10 @@ static void ioremap_trace_core(resource_size_t offset, unsigned long size,
map.map_id = trace->id;
spin_lock_irq(&trace_lock);
- if (!is_enabled())
+ if (!is_enabled()) {
+ kfree(trace);
goto not_enabled;
+ }
mmio_trace_mapping(&map);
list_add_tail(&trace->list, &trace_list);
--
1.5.6.4
--
From 743cab2763d3e8d9f4d3b82a02fcdc5ad8a13c04 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 16:53:05 +0300
Subject: [PATCH] ftrace: move mmiotrace functions out of trace.c.
Moves the mmiotrace specific functions from trace.c to
trace_mmiotrace.c. Functions trace_wake_up(), tracing_get_trace_entry(),
and tracing_generic_entry_update() are therefore made available outside
trace.c.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
kernel/trace/trace.c | 46 +--------------------------------------
kernel/trace/trace.h | 15 +++++-------
kernel/trace/trace_mmiotrace.c | 42 ++++++++++++++++++++++++++++++++++++
3 files changed, 50 insertions(+), 53 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 7e6cb4f..d372bc5 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -785,7 +785,7 @@ trace_next_page(struct trace_array_cpu *data, void *addr)
return page_address(page);
}
-static inline struct trace_entry *
+struct trace_entry *
tracing_get_trace_entry(struct trace_array *tr, struct trace_array_cpu *data)
{
unsigned long idx, idx_next;
@@ -821,7 +821,7 @@ tracing_get_trace_entry(struct trace_array *tr, struct trace_array_cpu *data)
return entry;
}
-static inline void
+void
tracing_generic_entry_update(struct trace_entry *entry, unsigned long flags)
{
struct task_struct *tsk = current;
@@ -865,48 +865,6 @@ ftrace(struct trace_array *tr, struct trace_array_cpu *data,
trace_function(tr, data, ip, parent_ip, flags);
}
-#ifdef CONFIG_MMIOTRACE
-void __trace_mmiotrace_rw(struct trace_array *tr, struct trace_array_cpu *data,
- struct mmiotrace_rw *rw)
-{
- struct trace_entry *entry;
- unsigned long irq_flags;
-
- raw_local_irq_save(irq_flags);
- __raw_spin_lock(&data->lock);
-
- entry = tracing_get_trace_entry(tr, data);
- tracing_generic_entry_update(entry, 0);
- entry->type = TRACE_MMIO_RW;
- entry->field.mmiorw = ...From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 17:27:05 +0300
Subject: [PATCH] ftrace: add trace_vprintk()
trace_vprintk() for easier implementation of tracer specific *_printk
functions. Add check check for no_tracer, and implement
__ftrace_printk() as a wrapper.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
kernel/trace/trace.c | 24 ++++++++++++++++++------
kernel/trace/trace.h | 1 +
2 files changed, 19 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index d372bc5..406de9c 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3054,7 +3054,7 @@ static __init void tracer_init_debugfs(void)
(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
#define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
-int __ftrace_printk(unsigned long ip, const char *fmt, ...)
+int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
{
static DEFINE_SPINLOCK(trace_buf_lock);
static char trace_buf[TRACE_BUF_SIZE];
@@ -3064,10 +3064,9 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
struct trace_entry *entry;
unsigned long flags;
long disabled;
- va_list ap;
int cpu, len = 0, write, written = 0;
- if (!(trace_flags & TRACE_ITER_PRINTK) || !tr->ctrl || tracing_disabled)
+ if (current_trace == &no_tracer || !tr->ctrl || tracing_disabled)
return 0;
local_irq_save(flags);
@@ -3079,9 +3078,7 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
goto out;
spin_lock(&trace_buf_lock);
- va_start(ap, fmt);
- len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, ap);
- va_end(ap);
+ len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
len = min(len, TRACE_BUF_SIZE-1);
trace_buf[len] = 0;
@@ -3120,6 +3117,21 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
return len;
}
+EXPORT_SYMBOL_GPL(trace_vprintk);
+
+int __ftrace_printk(unsigned long ip, ...Nice! Acked-by: Steven Rostedt <rostedt@goodmis.org> -- Steve --
nice - i've picked up Pekka's patches into tip/tracing/ftrace: f2e1ec3: ftrace: inject markers via trace_marker file 574a7a7: mmiotrace: remove left-over marker cruft fb87810: mmiotrace: handle TRACE_PRINT entries eaa4f4e: x86 mmiotrace: implement mmiotrace_printk() d77a3b8: ftrace: add trace_vprintk() 809fff6: ftrace: move mmiotrace functions out of trace.c bc94fff: x86 mmiotrace: fix a rare memory leak and added your ack to all of them. Thanks, Ingo --
From ca4db25e22b79fd77f4a7c6bb812e605379840a0 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 18:37:46 +0300
Subject: [PATCH] x86 mmiotrace: implement mmiotrace_printk().
Offer mmiotrace users a function to inject markers from inside the kernel.
This depends on the trace_vprintk() patch.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
arch/x86/mm/mmio-mod.c | 19 ++++++++++++++++++-
arch/x86/mm/testmmiotrace.c | 4 ++++
include/linux/mmiotrace.h | 17 +++++++++++++++--
kernel/trace/trace_mmiotrace.c | 5 +++++
4 files changed, 42 insertions(+), 3 deletions(-)
diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 754bd1e..5e2e2e7 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -75,7 +75,7 @@ static LIST_HEAD(trace_list); /* struct remap_trace */
* and trace_lock.
* - Routines depending on is_enabled() must take trace_lock.
* - trace_list users must hold trace_lock.
- * - is_enabled() guarantees that mmio_trace_record is allowed.
+ * - is_enabled() guarantees that mmio_trace_{rw,mapping} are allowed.
* - pre/post callbacks assume the effect of is_enabled() being true.
*/
@@ -379,6 +379,23 @@ void mmiotrace_iounmap(volatile void __iomem *addr)
iounmap_trace_core(addr);
}
+int mmiotrace_printk(const char *fmt, ...)
+{
+ int ret = 0;
+ va_list args;
+ unsigned long flags;
+ va_start(args, fmt);
+
+ spin_lock_irqsave(&trace_lock, flags);
+ if (is_enabled())
+ ret = mmio_trace_printk(fmt, args);
+ spin_unlock_irqrestore(&trace_lock, flags);
+
+ va_end(args);
+ return ret;
+}
+EXPORT_SYMBOL(mmiotrace_printk);
+
static void clear_trace_list(void)
{
struct remap_trace *trace;
diff --git a/arch/x86/mm/testmmiotrace.c b/arch/x86/mm/testmmiotrace.c
index d877c5b..ab50a8d 100644
--- a/arch/x86/mm/testmmiotrace.c
+++ b/arch/x86/mm/testmmiotrace.c
@@ -3,6 +3,7 @@
*/
#include <linux/module.h>
#include <linux/io.h>
+#include ...From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 17 Aug 2008 18:15:13 +0300
Subject: [PATCH] mmiotrace: handle TRACE_PRINT entries.
Also make trace_seq_print_cont() non-static, and add a newline if the
seq buffer can't hold all data.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
kernel/trace/trace.c | 31 +++++++++++--------------------
kernel/trace/trace.h | 19 +++++++++++++++++++
kernel/trace/trace_mmiotrace.c | 23 +++++++++++++++++++++++
3 files changed, 53 insertions(+), 20 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 406de9c..7e7154f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -200,23 +200,6 @@ unsigned long nsecs_to_usecs(unsigned long nsecs)
}
/*
- * trace_flag_type is an enumeration that holds different
- * states when a trace occurs. These are:
- * IRQS_OFF - interrupts were disabled
- * NEED_RESCED - reschedule is requested
- * HARDIRQ - inside an interrupt handler
- * SOFTIRQ - inside a softirq handler
- * CONT - multiple entries hold the trace item
- */
-enum trace_flag_type {
- TRACE_FLAG_IRQS_OFF = 0x01,
- TRACE_FLAG_NEED_RESCHED = 0x02,
- TRACE_FLAG_HARDIRQ = 0x04,
- TRACE_FLAG_SOFTIRQ = 0x08,
- TRACE_FLAG_CONT = 0x10,
-};
-
-/*
* TRACE_ITER_SYM_MASK masks the options in trace_flags that
* control the output of kernel symbols.
*/
@@ -1517,12 +1500,16 @@ lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs,
static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
-static void
-trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
+/*
+ * The message is supposed to contain an ending newline.
+ * If the printing stops prematurely, try to add a newline of our own.
+ */
+void trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
{
struct trace_array *tr = iter->tr;
struct trace_array_cpu *data = ...On Tue, 16 Sep 2008 16:11:20 -0400 (EDT)
Good question. It seems to be used a lot. :-)
commit 6e21828743247270d09a86756a0c11702500dbfb
Author: Richard Knutsson <ricknu-0@student.ltu.se>
Date: Sat Sep 30 23:27:11 2006 -0700
[PATCH] Generic boolean
This patch defines:
* a generic boolean-type, named 'bool'
* aliases to 0 and 1, named 'false' and 'true'
Removing colliding definitions of 'bool', 'false' and 'true'.
Signed-off-by: Richard Knutsson <ricknu-0@student.ltu.se>
Signed-off-by: Andrew Morton <akpm@osdl.org>
Signed-off-by: Linus Torvalds <torvalds@osdl.org>
--
Pekka Paalanen
http://www.iki.fi/pq/
--
From abd3cadc69143804cf4b0cf1d6fcadda5daad903 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 20:50:55 +0300
Subject: [PATCH] mmiotrace: remove left-over marker cruft.
Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
arch/x86/mm/mmio-mod.c | 64 ---------------------------------------------
include/linux/mmiotrace.h | 3 +-
2 files changed, 1 insertions(+), 66 deletions(-)
diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 5e2e2e7..2c4baa8 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -56,13 +56,6 @@ struct remap_trace {
static DEFINE_PER_CPU(struct trap_reason, pf_reason);
static DEFINE_PER_CPU(struct mmiotrace_rw, cpu_trace);
-#if 0 /* XXX: no way gather this info anymore */
-/* Access to this is not per-cpu. */
-static DEFINE_PER_CPU(atomic_t, dropped);
-#endif
-
-static struct dentry *marker_file;
-
static DEFINE_MUTEX(mmiotrace_mutex);
static DEFINE_SPINLOCK(trace_lock);
static atomic_t mmiotrace_enabled;
@@ -97,44 +90,6 @@ static bool is_enabled(void)
return atomic_read(&mmiotrace_enabled);
}
-#if 0 /* XXX: needs rewrite */
-/*
- * Write callback for the debugfs entry:
- * Read a marker and write it to the mmio trace log
- */
-static ssize_t write_marker(struct file *file, const char __user *buffer,
- size_t count, loff_t *ppos)
-{
- char *event = NULL;
- struct mm_io_header *headp;
- ssize_t len = (count > 65535) ? 65535 : count;
-
- event = kzalloc(sizeof(*headp) + len, GFP_KERNEL);
- if (!event)
- return -ENOMEM;
-
- headp = (struct mm_io_header *)event;
- headp->type = MMIO_MAGIC | (MMIO_MARKER << MMIO_OPCODE_SHIFT);
- headp->data_len = len;
-
- if (copy_from_user(event + sizeof(*headp), buffer, len)) {
- kfree(event);
- return -EFAULT;
- }
-
- spin_lock_irq(&trace_lock);
-#if 0 /* XXX: convert this to use tracing */
- if (is_enabled())
- relay_write(chan, event, sizeof(*headp) + len);
- else
-#endif
- len = ...From 9be308e4ea3af69cebb29930757d6457f762866d Mon Sep 17 00:00:00 2001 From: Pekka Paalanen <pq@iki.fi> Date: Sun, 14 Sep 2008 22:34:35 +0300 Subject: [PATCH] ftrace: inject markers via trace_marker file. MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Allow a user to inject a marker (TRACE_PRINT entry) into the trace ring buffer. The related file operations are derived from code by Frédéric Weisbecker <fweisbec@gmail.com>. Signed-off-by: Pekka Paalanen <pq@iki.fi> --- Documentation/tracers/mmiotrace.txt | 5 +- kernel/trace/trace.c | 76 ++++++++++++++++++++++++++++++++-- kernel/trace/trace.h | 4 ++ 3 files changed, 77 insertions(+), 8 deletions(-) diff --git a/Documentation/tracers/mmiotrace.txt b/Documentation/tracers/mmiotrace.txt index a4afb56..5bbbe20 100644 --- a/Documentation/tracers/mmiotrace.txt +++ b/Documentation/tracers/mmiotrace.txt @@ -36,7 +36,7 @@ $ mount -t debugfs debugfs /debug $ echo mmiotrace > /debug/tracing/current_tracer $ cat /debug/tracing/trace_pipe > mydump.txt & Start X or whatever. -$ echo "X is up" > /debug/tracing/marker +$ echo "X is up" > /debug/tracing/trace_marker $ echo none > /debug/tracing/current_tracer Check for lost events. @@ -59,9 +59,8 @@ The 'cat' process should stay running (sleeping) in the background. Load the driver you want to trace and use it. Mmiotrace will only catch MMIO accesses to areas that are ioremapped while mmiotrace is active. -[Unimplemented feature:] During tracing you can place comments (markers) into the trace by -$ echo "X is up" > /debug/tracing/marker +$ echo "X is up" > /debug/tracing/trace_marker This makes it easier to see which part of the (huge) trace corresponds to which action. It is recommended to place descriptive markers about what you do. diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 7e7154f..eee1fd9 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ ...
As I said to you, I met the same bug of this early quit of the pipe. But I should give here more details. This bug occurs with -tip (a version pulled 2 days ago so trace.c didn't change). I never saw it with other tracers than mmiotrace. I had no problem with sched_switch or function tracer. It happened when I was writing the tracer marker. So I'm not sure if the origin is here. If I'm not wrong it happened whithout adding mark messages too. Can you tell me if your pipe quits when you add a mark or if this bug occurs on other cases too? I will try to reproduce the bug this evening. --
Steven,
is there a logic behind trace_seq_print_cont() printing the terminating
newline only, when there actually is no TRACE_CONT entry?
Hmm, wait a minute, I don't understand how this thing works at all.
Let's take for instance print_lat_fmt() which is the first user of
trace_seq_print_cont(). Now, print_lat_fmt() does
struct trace_entry *entry = iter->ent;
and uses 'entry'. Let's assume it is of type TRACE_PRINT. It does
case TRACE_PRINT:
seq_print_ip_sym(s, field->print.ip, sym_flags);
trace_seq_printf(s, ": %s", field->print.buf);
if (field->flags & TRACE_FLAG_CONT)
trace_seq_print_cont(s, iter);
break;
Ok, it prints the beginning of the message, and if there should be
continuation blocks, it calls trace_seq_print_cont(), defined as
follows:
static void
trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
{
struct trace_array *tr = iter->tr;
struct trace_array_cpu *data = tr->data[iter->cpu];
struct trace_entry *ent;
ent = trace_entry_idx(tr, data, iter, iter->cpu);
if (!ent || ent->type != TRACE_CONT) {
trace_seq_putc(s, '\n');
return;
}
do {
trace_seq_printf(s, "%s", ent->cont.buf);
__trace_iterator_increment(iter, iter->cpu);
ent = trace_entry_idx(tr, data, iter, iter->cpu);
} while (ent && ent->type == TRACE_CONT);
}
Here it uses trace_entry_idx() to get 'ent'. What's the difference to
iter->ent? I don't understand how trace_entry_idx() works, but looking
at how it is used, it must return the pointer to the *next* entry in
the ring buffer. So I don't understand the name of the function, and I
don't see a call to __trace_iterator_increment(), which is confusing.
If contrary to the assumption, 'ent' is not a continuation, it prints
the terminating newline. This is an exceptional case, as the original
entry was marked as having continuation entries.
The normal case then is to execute the do-while, until it hits a
non-continuation entry. Here it does *not* print the terminating ...Actually, that case is more of an anomaly than the correct. It means that somehow the print statement wanted to continue, but did not. This means that the print statement probably did not finish the line, and that we should do a newline to make sure the next entry starts on a iter->ent is the start of the entry to print. It is not necessarily Because we do a merge sort of the entries in each CPU buffer, after we get the next entry to print, we increment that iteration buffer. This means that trace_entry_idx() will return the next entry field after we got the iter->ent. This is also why we use iter->ent instead of iter->ent is the entry to be used in the "show" function. When we found that entry, we incremented the buffer to get it ready for the next merge sort. When we get to show, iter->ent is the entry to print, and if we use iter_entry_idx() that will point to the next entry in that buffer that will be used next time. I also did this to make it easier for the latency Right, this is somehow an entry was flagged as continue, but it did not. It is probably a bug in the code, and instead of writing a strange format, where the next entry continued on the same line, I chose to let the Correct. The reason is that the ftrace_printk() call should have contained its own new line. I could also add a check (and probably will) to see if Just did ;-) Hope it helps, -- Steve --
On Sun, 7 Sep 2008 13:29:40 -0400 (EDT) Yes, I forgot the per-cpu buffers. When merging you want the first one wrt. timestamp, and when continuing you want the next on that cpu's My first idea was to filter out all newlines from messages, making a message a single line, and then force a newline, but now I realize that would be an exception to the printk convention. Maybe I should just start a new line in the output, when I get a newline :-) Although that probably means my version of trace_seq_print_cont() must live in trace.c, which IMHO is over-crowded already. But then there's a small chance the whole output of a single TRACE_PRINT entry might not fit into one trace_seq ever, since each line in mmiotrace has a prologue. Oh well, can't win always, I'll just drop what doesn't fit into output. Hmm, it already does that, doesn't it, if the output does not fit into Oh yes, thank you very much :-) btw. How do you feel about moving the #ifdef CONFIG_MMIOTRACE functions from trace.c to trace_mmiotrace.c and unstatifying all the functions they need? Seems some of them are inline, and the spinlock stuff just looks so... raw :-) -- Pekka Paalanen http://www.iki.fi/pq/ --
