Tracing to console

Tracing to console

[Bart Van Assche]

Hello Steven,

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
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"").

Thanks,

Bart.

Re: Tracing to console

[Bart Van Assche]

Hello Steven and Ingo,

Did I report this observation to the right people?

Thank you,

Bart.

On 06/15/18 14:01, Bart Van Assche wrote:
> Hello Steven,
> 
> 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
> 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"").

Re: Tracing to console

[Steven Rostedt]

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