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]

Date:	Thu, 28 May 2009 16:52:39 +0200 (CEST)
From:	Thomas Gleixner <tglx@...utronix.de>
To:	Frederic Weisbecker <fweisbec@...il.com>
cc:	LKML <linux-kernel@...r.kernel.org>,
	Steven Rostedt <rostedt@...dmis.org>
Subject: Re: [PATCH] tracing: annotate emit_log_char() notrace

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 :)

Thanks,

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