| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Tue, 16 Dec 2008 17:18:33 +0100
From: "Frédéric Weisbecker" <fweisbec@...il.com>
To: "Arnaldo Carvalho de Melo" <acme@...hat.com>,
"Frédéric Weisbecker" <fweisbec@...il.com>,
"Steven Rostedt" <rostedt@...dmis.org>,
"Ingo Molnar" <mingo@...e.hu>,
"Jens Axboe" <jens.axboe@...cle.com>,
"Linux Kernel" <linux-kernel@...r.kernel.org>
Subject: Re: trace_seq_printf/.print_line question
2008/12/16 Arnaldo Carvalho de Melo <acme@...hat.com>:
> Jens, just a FYI about this stuff, not yet ready for reviewing.
>
> Hi Frédéric, Steven,
>
> Have you guys ever get into this kind of situation?
>
> [root@...a linux-2.6-tip]# cat /sys/kernel/debug/tracing/trace | tail
> kjournald-480 [000] 593.219805: C W 2149459 + 8 [0]
> <idle>-0 [000] 593.219849: A WS 2149467 + 8 <- (8,2) 44952
> kjournald-480 [000] 607.210959: Q WS 2149467 + 8
> kjournald-480 [000] 607.210960: G WS 2149467 + 8
> kjournald-480 [000] 607.210963: P N
> kjournald-480 [000] 607.210964: I W 2149467 + 8
> kjournald-480 [000] 607.210965: D W 2149467 + 8
> kjournald-480 [000] 607.210967: U N 1
> kjournald-480 [000] 607.210971: C W 2149467 + 8 [0]
> <idle>-0 [000] 607.211049: [root@...a linux-2.6-tip]#
>
> [root@...a linux-2.6-tip]# head /sys/kernel/debug/tracing/trace
> # tracer: blk
> #
> # TASK-PID CPU# TIMESTAMP FUNCTION
> # | | | | |
> A W 2147707 + 8 <- (8,2) 43192
> kjournald-480 [000] 254.428659: Q W 2147707 + 8
> kjournald-480 [000] 254.428661: G W 2147707 + 8
> kjournald-480 [000] 254.428663: I W 100410211 + 8
> pdflush-261 [000] 147.328259: P N
> kjournald-480 [000] 254.428664: I W 2147707 + 8
> [root@...a linux-2.6-tip]#
Actually, if you implement a print_line callback for your tracer,
you're not supposed to see the
task-pid, cpu number and time printed before your traces. You should
only see what you print with your tracer.
task-pid/cpu/timespamp are only printed by the default printing
functions in trace.c, ie: used by
the function tracer, the stack tracer, the sched tracer... or when a
tracer's print_line
returns TRACE_TYPE_UNHANDLED.
And that's what is happening with your tracer.
If you look at the following:
> +static enum print_line_t blk_tracer_print_line(struct trace_iterator *iter)
> +{
> + struct trace_seq *s = &iter->seq;
> + struct trace_entry *entry = iter->ent;
> +
> + switch (entry->type) {
> + case TRACE_BLOCK: {
> + int ret, act;
> + struct blk_io_entry *t;
> +
> + trace_assign_type(t, entry);
> + act = what_action(t);
> +
> + switch (act) {
> + case __BLK_TA_ISSUE:
> + ret = blk_log_generic(s, t, "D");
> + break;
> + case __BLK_TA_INSERT:
> + ret = blk_log_generic(s, t, "I");
> + break;
> + case __BLK_TA_QUEUE:
> + ret = blk_log_generic(s, t, "Q");
> + break;
> + case __BLK_TA_BOUNCE:
> + ret = blk_log_generic(s, t, "B");
> + break;
> + case __BLK_TA_BACKMERGE:
> + ret = blk_log_generic(s, t, "M");
> + break;
> + case __BLK_TA_FRONTMERGE:
> + ret = blk_log_generic(s, t, "F");
> + break;
> + case __BLK_TA_GETRQ:
> + ret = blk_log_generic(s, t, "G");
> + break;
> + case __BLK_TA_SLEEPRQ:
> + ret = blk_log_generic(s, t, "S");
> + break;
> + case __BLK_TA_REQUEUE:
> + ret = blk_log_with_error(s, t, "R");
> + break;
> + case __BLK_TA_COMPLETE:
> + ret = blk_log_with_error(s, t, "C");
> + break;
> + case __BLK_TA_PLUG:
> + ret = blk_log_action(s, t, "P");
> + break;
> + case __BLK_TA_UNPLUG_IO:
> + ret = blk_log_unplug(s, t, "U");
> + break;
> + case __BLK_TA_UNPLUG_TIMER:
> + ret = blk_log_unplug(s, t, "UT");
> + break;
> + case __BLK_TA_REMAP:
> + ret = blk_log_remap(s, t);
> + break;
> + case __BLK_TA_SPLIT:
> + ret = blk_log_split(s, t, "X");
> + break;
> + default:
> + ret = trace_seq_printf(s, "Bad pc action %x\n", act);
> + break;
> + }
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> + }
> + default:
> + return TRACE_TYPE_UNHANDLED;
> + }
> +
> + return TRACE_TYPE_HANDLED;
> +}
You are always returning TRACE_TYPE_UNHANDLED because you missed a
break statement at the
end of your TRACE_BLOCK case :-)
So you are printing your trace, and then the default printing
functions on trace.c, assuming you haven't
handled it, will print task/cpu/timestamp for a function trace or a
stack trace or whatever...
Hence the weird output :-)
--
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