Re: [PATCH v3] printk: add option to print cpu id

12 messages, 6 authors, 2012-08-06 · open the first message on its own page

Re: [PATCH v3] printk: add option to print cpu id

From: Andi Kleen <hidden>
Date: 2012-08-03 17:54:36

Vikram Pandita [off-list ref] writes:
From: Vikram Pandita <redacted>

Introduce config option to enable CPU id reporting for printk() calls.
What's wrong with using trace_printk for this? That's much faster
anyways. Generally printk is so slow that it's typically useless for
instrumenting races.

And really: Wasting 1/3 of the 80 character line is too much.

-Andi

-- 
ak at linux.intel.com -- Speaking for myself only

Re: [PATCH v3] printk: add option to print cpu id

From: Pandita, Vikram <hidden>
Date: 2012-08-03 18:26:01

On Fri, Aug 3, 2012 at 10:54 AM, Andi Kleen [off-list ref] wrote:
Vikram Pandita [off-list ref] writes:
quoted
From: Vikram Pandita <redacted>

Introduce config option to enable CPU id reporting for printk() calls.
What's wrong with using trace_printk for this?
trace_printk works only when you know the _exact_ path in code that
you want to profile.
When you have no idea of a random lockup, then it would be kind of
touch and time consuming
to put trace prints all around the code.
That's much faster
anyways. Generally printk is so slow that it's typically useless for
instrumenting races.
As stated in another thread, its found useful to debug some specific cases:
Check thread: http://marc.info/?l=linux-omap&m=134401269106619&w=2
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
Just like you _WASTE_ 15 chars when you enable existing: CONFIG_PRINTK_TIME

For general usecase, recommendation would be to keep these options disabled.
Working on shipping products, i find almost all shipping with
CONFIG_PRINTK_TIME enabled, so there must be some value.
Same would hold for the use case being debugged for CPUID enabling.
-Andi

--
ak at linux.intel.com -- Speaking for myself only

Re: [PATCH v3] printk: add option to print cpu id

From: Aaro Koskinen <aaro.koskinen@iki.fi>
Date: 2012-08-03 20:17:31

Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?

A.

Re: [PATCH v3] printk: add option to print cpu id

From: Pandita, Vikram <hidden>
Date: 2012-08-03 21:24:45

Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen [off-list ref] wrote:
Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?
Good point.
Looks there is a variable 'nr_cpu_ids' that could be used as well.

If there is general consensus that the patch can help the arm
community, and others in general,
this optimization should be easy to implement - saving few chars space
in each line of console output.

For now i will stick to this v3 version of path, unless you think otherwise.
A.

Re: [PATCH v3] printk: add option to print cpu id

From: Greg KH <gregkh@linuxfoundation.org>
Date: 2012-08-03 22:00:03

On Fri, Aug 03, 2012 at 02:24:20PM -0700, Pandita, Vikram wrote:
Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen [off-list ref] wrote:
quoted
Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?
Good point.
Looks there is a variable 'nr_cpu_ids' that could be used as well.

If there is general consensus that the patch can help the arm
community, and others in general,
this optimization should be easy to implement - saving few chars space
in each line of console output.

For now i will stick to this v3 version of path, unless you think otherwise.
I don't think is is something that anyone needs, and if you do, as
pointed out, you can use the trace function to make it happen.

Adding features are not "free", someone has to maintain them and all of
the other work involved with it.  So don't just think that because it is
hidden behind a config option, that it doesn't affect people.

greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Pandita, Vikram <hidden>
Date: 2012-08-03 22:08:05

On Fri, Aug 3, 2012 at 2:59 PM, Greg KH [off-list ref] wrote:
On Fri, Aug 03, 2012 at 02:24:20PM -0700, Pandita, Vikram wrote:
quoted
Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen [off-list ref] wrote:
quoted
Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?
Good point.
Looks there is a variable 'nr_cpu_ids' that could be used as well.

If there is general consensus that the patch can help the arm
community, and others in general,
this optimization should be easy to implement - saving few chars space
in each line of console output.

For now i will stick to this v3 version of path, unless you think otherwise.
I don't think is is something that anyone needs, and if you do, as
pointed out, you can use the trace function to make it happen.
This was something that got used internally and helped at times.
This attempt to give back to community, but i understand the rationale to go
with larger consensus.

At least the patch is out there in public for anyone to make use of.
Adding features are not "free", someone has to maintain them and all of
the other work involved with it.  So don't just think that because it is
hidden behind a config option, that it doesn't affect people.
At least the v3 patch is a complete working implementation wrt
kernel/printk.c file
as it exists on linus tree master today.

Understand long term this does have maintenance overhead just like
printk_time does.
greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Greg KH <gregkh@linuxfoundation.org>
Date: 2012-08-03 22:13:34

On Fri, Aug 03, 2012 at 03:07:39PM -0700, Pandita, Vikram wrote:
On Fri, Aug 3, 2012 at 2:59 PM, Greg KH [off-list ref] wrote:
quoted
On Fri, Aug 03, 2012 at 02:24:20PM -0700, Pandita, Vikram wrote:
quoted
Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen [off-list ref] wrote:
quoted
Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?
Good point.
Looks there is a variable 'nr_cpu_ids' that could be used as well.

If there is general consensus that the patch can help the arm
community, and others in general,
this optimization should be easy to implement - saving few chars space
in each line of console output.

For now i will stick to this v3 version of path, unless you think otherwise.
I don't think is is something that anyone needs, and if you do, as
pointed out, you can use the trace function to make it happen.
This was something that got used internally and helped at times.
Could you have used the trace point instead?

greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Pandita, Vikram <hidden>
Date: 2012-08-03 22:25:43

On Fri, Aug 3, 2012 at 3:13 PM, Greg KH [off-list ref] wrote:
On Fri, Aug 03, 2012 at 03:07:39PM -0700, Pandita, Vikram wrote:
quoted
On Fri, Aug 3, 2012 at 2:59 PM, Greg KH [off-list ref] wrote:
quoted
On Fri, Aug 03, 2012 at 02:24:20PM -0700, Pandita, Vikram wrote:
quoted
Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen [off-list ref] wrote:
quoted
Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
quoted
quoted
And really: Wasting 1/3 of the 80 character line is too much.
You _WASTE_ 4 chars only if you are interested in this info by
enabling: CONFIG_PRINTK_CPUID
I guess you waste 4 + 3 chars? You could optimize the length by checking
CONFIG_NR_CPUS?
Good point.
Looks there is a variable 'nr_cpu_ids' that could be used as well.

If there is general consensus that the patch can help the arm
community, and others in general,
this optimization should be easy to implement - saving few chars space
in each line of console output.

For now i will stick to this v3 version of path, unless you think otherwise.
I don't think is is something that anyone needs, and if you do, as
pointed out, you can use the trace function to make it happen.
This was something that got used internally and helped at times.
Could you have used the trace point instead?
As i understood the trace_prink(), one would need to modify existing
printk -> trace_printk. Is my understanding correct?

Most of the times the problem exhibits as a random hang, without having a clue
which code to modify. That time one generic defconfig global switch is
your first tool.

Other issue i found, using this patch, that on multi-core ARM systems,
almost 99% of times, IRQ's are handled by CPU0,
even if CPU0 was really busy and other CPU's were free. I am yet to
understand a good reason why.

this patch also helped in other areas as mentioned in the thread
http://marc.info/?l=linux-omap&m=134401269106619&w=2

Not sure how easy its to use trace_printk for such issues, i found
having one defconfig option was much easier
to get going. Correct me if i have not understood trace_printk well enough.

greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Greg KH <gregkh@linuxfoundation.org>
Date: 2012-08-03 22:36:29

On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
quoted
quoted
This was something that got used internally and helped at times.
Could you have used the trace point instead?
As i understood the trace_prink(), one would need to modify existing
printk -> trace_printk. Is my understanding correct?
No, you should just be able to watch the tracepoint, right?
Most of the times the problem exhibits as a random hang, without having a clue
which code to modify. That time one generic defconfig global switch is
your first tool.

Other issue i found, using this patch, that on multi-core ARM systems,
almost 99% of times, IRQ's are handled by CPU0,
even if CPU0 was really busy and other CPU's were free. I am yet to
understand a good reason why.
Can't you see that from /proc/interrupts today?
this patch also helped in other areas as mentioned in the thread
http://marc.info/?l=linux-omap&m=134401269106619&w=2
I still don't understand how adding the cpu number to printk enabled you
to find any problem like this.  Can't you just add the cpu number to the
printk messages you care about for your specific hardware?

greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Pandita, Vikram <hidden>
Date: 2012-08-03 22:48:50

On Fri, Aug 3, 2012 at 3:36 PM, Greg KH [off-list ref] wrote:
On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
quoted
quoted
quoted
This was something that got used internally and helped at times.
Could you have used the trace point instead?
As i understood the trace_prink(), one would need to modify existing
printk -> trace_printk. Is my understanding correct?
No, you should just be able to watch the tracepoint, right?
yes.
Assumption being you know _EXACTLY_ what code piece to watch for.
Which may not be the case all times.
quoted
Most of the times the problem exhibits as a random hang, without having a clue
which code to modify. That time one generic defconfig global switch is
your first tool.

Other issue i found, using this patch, that on multi-core ARM systems,
almost 99% of times, IRQ's are handled by CPU0,
even if CPU0 was really busy and other CPU's were free. I am yet to
understand a good reason why.
Can't you see that from /proc/interrupts today?
You are right that was the next step i did and that shows the problem as well.
The point i was trying to make, with printk showing cpu-id, there are
problems in system that could get highlighted,
given printk almost always runs with linux kernel.
quoted
this patch also helped in other areas as mentioned in the thread
http://marc.info/?l=linux-omap&m=134401269106619&w=2
I still don't understand how adding the cpu number to printk enabled you
to find any problem like this.  Can't you just add the cpu number to the
printk messages you care about for your specific hardware?
The assumption here is that a developer knows well enough, which code
to modify for logging.
I my experience, that is not true most of the times. A global
defconfig switch is much easier to enable.

Eg: when i have some timing related issue, first thing i go for is to
enable PRINTK_TIME, without even
having to think about the erring code. Then time-stamps lead to bad code.

That is the same though process behind the cpu-id in printk.

greg k-h

Re: [PATCH v3] printk: add option to print cpu id

From: Russell King - ARM Linux <hidden>
Date: 2012-08-04 08:52:06

On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
Other issue i found, using this patch, that on multi-core ARM systems,
almost 99% of times, IRQ's are handled by CPU0,
even if CPU0 was really busy and other CPU's were free. I am yet to
understand a good reason why.
That is because you're probably not running irqbalanced on your platforms.

Firstly, the hardware does no IRQ balancing itself - you have to manually
route IRQs to CPUs in the hardware, and if you ask for an IRQ to be
delivered to several CPUs, all CPUs will get it each time it fires (unlike
x86 IOAPIC which picks a CPU to route the IRQ to.)

The ARM kernel does no IRQ balancing itself across CPUs, because when I
tried to implement it, every algorithm I tried gave completely sub-optimal
results, and irqbalanced existed to do the job in userspace.  So as there
is a userspace solution which works, there was no point to doing this in
the kernel.

Please use the irqbalance daemon to spread IRQs across your CPUs.

Re: [PATCH v3] printk: add option to print cpu id

From: Steven Rostedt <rostedt@goodmis.org>
Date: 2012-08-06 13:39:24

On Fri, Aug 03, 2012 at 03:48:26PM -0700, Pandita, Vikram wrote:
On Fri, Aug 3, 2012 at 3:36 PM, Greg KH [off-list ref] wrote:
quoted
On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
quoted
quoted
quoted
This was something that got used internally and helped at times.
Could you have used the trace point instead?
As i understood the trace_prink(), one would need to modify existing
printk -> trace_printk. Is my understanding correct?
No, you should just be able to watch the tracepoint, right?
yes.
Assumption being you know _EXACTLY_ what code piece to watch for.
Which may not be the case all times.
But it traces all printks.

 # echo 1 > /sys/kernel/debug/tracing/events/printk/console/enable
 # mount /home/rostedt
 # cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-2707  [002] d..1    97.079458: console: [   95.816945] NFS: Registering the id_resolver key type

        modprobe-2707  [002] d..1    97.084534: console: [   95.822038] Key type id_resolver registered

If you wanted this from boot up, you can just add to the kernel command line:

  trace_event=console

-- Steve
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help