linux-kernel - Re: [PATCH] printk: Print cpu number along with time

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, 24 Apr 2014 17:23:13 -0400
From:	Jörn Engel <joern@...fs.org>
To:	Greg Kroah-Hartman <gregkh@...uxfoundation.org>
Cc:	Jiri Kosina <jkosina@...e.cz>, Rik van Riel <riel@...hat.com>,
	linux-kernel@...r.kernel.org, peterz@...radead.org,
	akpm@...ux-foundation.org, cxie@...hat.com,
	Jiri Slaby <jslaby@...e.cz>
Subject: Re: [PATCH] printk: Print cpu number along with time

On Thu, 24 April 2014 12:58:21 -0700, Greg Kroah-Hartman wrote:
> > @@ -868,11 +870,20 @@ static size_t print_time(u64 ts, char *buf)
> >  
> >  	rem_nsec = do_div(ts, 1000000000);
> >  
> > +#ifdef CONFIG_PRINTK_CPU
> > +	if (!buf)
> > +		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",
> 
> %02x for a cpu?  What happens on machines with 8k cpus?

You should get something like:
Apr 23 10:34:03 [  228.950926,1a] Call Trace:
Apr 23 10:34:03 [  228.950926,201] Call Trace:
Apr 23 10:34:03 [  228.950928,1a]  [<ffffffff815e0f29>] schedule+0x29/0x70
...

That said, I don't have access to hardware with >256 cpus and haven't
actually tested this.

> And is this really an issue?  Debugging by using printk is fun, but not
> really something that people need to add a cpu number to.  Why not just
> use a tracepoint in your code to get the needed information instead?

Yes, this is an issue.  There have been several instances in my life
when I would have had to guess which function belonged to which
backtrace without this patch.  Good guesses take a long time, bad
guesses are nearly useless and giving up means you cannot debug the
issue.

I don't have a good example at hand, but here is something from a
quick grep for illustration.
Feb 22 19:04:46 [   11.642470,2e] Call Trace:
Feb 22 19:04:46 [   11.642472,16] Call Trace:
Feb 22 19:04:46 [   11.642476,29]  [<ffffffff81115bf8>] pcpu_alloc+0x988/0xa20
Feb 22 19:04:46 [   11.642481,01]  [<ffffffff810992ad>] ?  find_symbol+0x3d/0xb0
Feb 22 19:04:46 [   11.642489,05]  [<ffffffff81115bf8>] pcpu_alloc+0x988/0xa20
Feb 22 19:04:46 [   11.642493,12]  [<ffffffff81115bf8>] pcpu_alloc+0x988/0xa20
Feb 22 19:04:46 [   11.642498,08]  [<ffffffff81115bf8>] pcpu_alloc+0x988/0xa20
Feb 22 19:04:46 [   11.642504,21]  [<ffffffff810992ad>] ?  find_symbol+0x3d/0xb0

And are you seriously suggesting I use a tracepoint for kernel panics? ;)

Jörn

--
There's nothing better for promoting creativity in a medium than
making an audience feel "Hmm  I could do better than that!"
-- Douglas Adams in a slashdot interview
--
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/