linux-kernel - Re: [PATCH] tracing: annotate emit_log

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

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <alpine.DEB.2.00.0905281057490.905@gandalf.stny.rr.com>
Date:	Thu, 28 May 2009 11:04:06 -0400 (EDT)
From:	Steven Rostedt <rostedt@...dmis.org>
To:	Thomas Gleixner <tglx@...utronix.de>
cc:	Frederic Weisbecker <fweisbec@...il.com>,
	LKML <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH] tracing: annotate emit_log_char() notrace

On Thu, 28 May 2009, Thomas Gleixner wrote:

> On Thu, 28 May 2009, Frederic Weisbecker wrote:
> > On Wed, May 27, 2009 at 05:00:44PM +0200, Thomas Gleixner wrote:
> > > printk calls emit_log_char() in a loop which is cluttering the trace
> > > buffer. Make it notrace.
> > > 
> > > Signed-off-by: Thomas Gleixner <tglx@...utronix.de>
> > > ---
> > 
> > 
> > Does it produce that much annoying traces?
> > I mean, printk() are usually rare events.
> > 
> > Do you have a particular debugging workflow that makes this
> > function invasive in the trace?
> > 
> > May be it's because you are debugging using ftrace and other
> > debugging options that use a lot of printk()
> > In such case, it would indeed be good to apply this patch.
> 
> I noticed when I chased a boot up problem, half of the trace was full
> of
> 
>    0.540550: emit_log_char <-vprintk
>    0.540550: emit_log_char <-vprintk
>    ...
> 
> though there is another annoyance in the same code path:
> 
>    0.540557: vgacon_set_cursor_size <-vgacon_cursor
>    0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
>    0.540558: __rcu_read_unlock <-__atomic_notifier_call_chain
>    0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
>    ...
> 
> It's actually the same number of times as we have emit_log_char()
> there. __atomic_notifier_call_chain() itself is marked notrace but the
> rcu calls inside are not. :(
> 
> IIRC the same happens with a serial console, but that can be worse as
> you busy wait during the character output.
> 
> It'd be nice if we could inherit the notrace from the caller :)
> 

I'd hate to make rcu_read_*lock be a notrace. I've done some debugging 
with wanting to know where the rcu locks were taken.

I'm sure there's lots of functions that people will want to add notrace 
for. Really, the notrace on a function should only be there to prevent 
crashes (functions used by the tracer or early boot up code for some 
archs).

That said, there are times when you want to avoid tracing things on early 
boot up. Thus, if someone adds to the kernel command line 
"ftrace=function" you have no way to filter out these functions you don't 
care about.

What if I add a "ftrace_notrace=<function list>" kernel command line, that 
has <function list> be a comma separated list of functions you want to go 
into the "set_ftrace_notrace" on boot up? Would that satisfy you. Then you 
can keep adding to the list dynamically every boot. And keep it there in a 
grub file.

This will also keep people from constantly asking for notrace annotations 
just because they are annoyed by the functions that always fill up their 
logs.

-- Steve

--
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/