2010-02-07 21:05:33

by Bernhard Schiffner

Subject: [mmiotrace] Make timestamps as printk() does.

Hallo,

this little patch makes a simple "sort -m" on output gotten from dmesg and
mmiotrace possible.
It's a real help at least for me.

Bernhard
(CC me please, I'am not on this list.)

------------
Make mmiotrace timestamps compareable to printk().

diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 0acd834..32c21f7 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -146,7 +146,7 @@ static ssize_t mmio_read(struct trace_iterator *iter,
struct file *filp,
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);
+ trace_seq_printf(s, "[ 0.000000] MARK Lost %lu events.\n",
n);
if (!overrun_detected)
pr_warning("mmiotrace has lost events.\n");
overrun_detected = true;
@@ -186,21 +186,21 @@ static enum print_line_t mmio_print_rw(struct
trace_iterator *iter)
switch (rw->opcode) {
case MMIO_READ:
ret = trace_seq_printf(s,
- "R %d %u.%06lu %d 0x%llx 0x%lx 0x%lx %d\n",
- rw->width, secs, usec_rem, rw->map_id,
+ "[%5lu.%06lu] R %d %d 0x%llx 0x%lx 0x%lx %d\n",
+ secs, usec_rem, rw->width, rw->map_id,
(unsigned long long)rw->phys,
rw->value, rw->pc, 0);
break;
case MMIO_WRITE:
ret = trace_seq_printf(s,
- "W %d %u.%06lu %d 0x%llx 0x%lx 0x%lx %d\n",
- rw->width, secs, usec_rem, rw->map_id,
+ "[%5lu.%06lu] W %d %d 0x%llx 0x%lx 0x%lx %d\n",
+ secs, usec_rem, rw->width, rw->map_id,
(unsigned long long)rw->phys,
rw->value, rw->pc, 0);
break;
case MMIO_UNKNOWN_OP:
ret = trace_seq_printf(s,
- "UNKNOWN %u.%06lu %d 0x%llx %02lx,%02lx,"
+ "[%5lu.%06lu] UNKNOWN %d 0x%llx %02lx,%02lx,"
"%02lx 0x%lx %d\n",
secs, usec_rem, rw->map_id,
(unsigned long long)rw->phys,
@@ -233,14 +233,14 @@ static enum print_line_t mmio_print_map(struct
trace_iterator *iter)
switch (m->opcode) {
case MMIO_PROBE:
ret = trace_seq_printf(s,
- "MAP %u.%06lu %d 0x%llx 0x%lx 0x%lx 0x%lx %d\n",
+ "[%5lu.%06lu] MAP %d 0x%llx 0x%lx 0x%lx 0x%lx %d\n",
secs, usec_rem, m->map_id,
(unsigned long long)m->phys, m->virt, m->len,
0UL, 0);
break;
case MMIO_UNPROBE:
ret = trace_seq_printf(s,
- "UNMAP %u.%06lu %d 0x%lx %d\n",
+ "[%5lu.%06lu] UNMAP %d 0x%lx %d\n",
secs, usec_rem, m->map_id, 0UL, 0);
break;
default:
@@ -264,7 +264,7 @@ static enum print_line_t mmio_print_mark(struct
trace_iterator *iter)
int ret;

/* The trailing newline must be in the message. */
- ret = trace_seq_printf(s, "MARK %u.%06lu %s", secs, usec_rem, msg);
+ ret = trace_seq_printf(s, "[%5lu.%06lu] MARK %s", secs, usec_rem,
msg);
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;

2010-02-12 22:33:57

by Larry Finger

Subject: Re: [mmiotrace] Make timestamps as printk() does.

On 02/07/2010 03:05 PM, Bernhard Schiffner wrote:
> Hallo,
>
> this little patch makes a simple "sort -m" on output gotten from dmesg and
> mmiotrace possible.
> It's a real help at least for me.
>
> Bernhard
> (CC me please, I'am not on this list.)

NACK. This sort of transformation is best left to local tools.

Larry

2010-02-12 23:11:37

by Tim Bird

Subject: Re: [mmiotrace] Make timestamps as printk() does.

On 02/12/2010 02:33 PM, Larry Finger wrote:
> On 02/07/2010 03:05 PM, Bernhard Schiffner wrote:
>> Hallo,
>>
>> this little patch makes a simple "sort -m" on output gotten from dmesg and
>> mmiotrace possible.
>> It's a real help at least for me.
>>
>> Bernhard
>> (CC me please, I'am not on this list.)
>
> NACK. This sort of transformation is best left to local tools.

The tools can be much easier to maintain and use,
if there's consistency in the output format from
the kernel. There are already tools which read and
process the printk timestamp format (with time in
[sec.usec] format at the beginning of the line).
One is scripts/show-delta.

-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================