Re: Tracing to console

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 15 Jun 2018 21:01:53 +0000
Bart Van Assche <Bart.VanAssche@wdc.com> wrote:

> Hello Steven,

Sorry about the 6 month old reply. I just noticed this email buried in
my INBOX (I triage my INBOX to find emails like this that got missed).
And yes I missed your reply as well :-/


> 
> If I run the following commands as root:
> 
> cd /sys/kernel/debug/tracing
> grep pm_ available_events > set_event
> echo function >current_tracer
> grep scsi_ available_filter_functions | while read a b; do echo $a; done >set_ftrace_filter
> echo 1 >events/printk/enable
> echo 1 >tracing_on
> echo 1 >/proc/sys/kernel/tracepoint_printk

Just for some closure. The tracepoint_printk is a special command that
only gets enabled if you pass "tp_printk" on the kernel command line.

> echo - - - >/sys/class/scsi_host/host0/scan
> 
> then the following appears on the console:
> 
> console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ ... ]
> 
> I assume that the repeated "console: " prefix is a bug and also that the same
> line repeats over and over again is also a bug? I ran into this with commit
> 017b3f8a10ca ("scsi: snic: fix a couple of spelling mistakes: "COMPLETE"").
>

The above behavior is actually expected and not a bug. It's a "Doctor
it hurts me when I do this" issue. Don't do that ;-)

The tracepoint_printk is for cases where the system crashes before you
ever get to a command prompt, and you want to see trace events that you
can enable from the kernel command line. What you did above was like
running "ls -lR / > /dev/mem" in old kernels. It's doomed to fail.

You just told the kernel that you want all trace events to go over
printk, and you also told the kernel, you want all printk to become a
trace event. Thus you created a recursive loop. You're lucky it didn't
crash.

I hope this explains things for you.

Again, sorry that it took 6 months to reply. I believe June was a busy
time for me (vacation and work travel).

-- Steve