[PATCH] printk: add option to print cpu id

[Vikram Pandita]

From: Vikram Pandita <vikram....@ti.com>

Introduce config option to enable CPU id reporting for printk() calls.

Its sometimes very useful to have printk also print the CPU Identifier
that executed the call. This has helped to debug various SMP issues on shipping
products.

Known limitation is, if the system gets preempted between function call and
actual printk, the reported cpu-id might not be accurate. But most of the
times its seen to give a good feel of how the N cpu's in the system are
getting loaded.

Signed-off-by: Vikram Pandita <vikram....@ti.com>
Cc: Mike Turquette <mturq...@linaro.org>
Cc: Vimarsh Zutshi <vimarsh...@gmail.com>
---
kernel/printk.c | 20 ++++++++++++++++++++
lib/Kconfig.debug | 13 +++++++++++++
2 files changed, 33 insertions(+)

diff --git a/kernel/printk.c b/kernel/printk.c
index 6a76ab9..50feb82 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -855,6 +855,25 @@ static size_t print_time(u64 ts, char *buf)
(unsigned long)ts, rem_nsec / 1000);
}

+#if defined(CONFIG_PRINTK_CPUID)
+static bool printk_cpuid = 1;
+#else
+static bool printk_cpuid;
+#endif
+module_param_named(cpuid, printk_cpuid, bool, S_IRUGO | S_IWUSR);
+
+static size_t print_cpuid(char *buf)
+{
+
+ if (!printk_cpuid)
+ return 0;
+
+ if (!buf)
+ return 4;
+
+ return sprintf(buf, "[%1d] ", smp_processor_id());
+}
+
static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
{
size_t len = 0;
@@ -874,6 +893,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
}
}

+ len += print_cpuid(buf ? buf + len : NULL);
len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
return len;
}
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 2403a63..139b2b1 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -14,6 +14,19 @@ config PRINTK_TIME
The behavior is also controlled by the kernel command line
parameter printk.time=1. See Documentation/kernel-parameters.txt

+config PRINTK_CPUID
+ bool "Show cpu id information on printks"
+ depends on PRINTK
+ help
+ Selecting this option causes cpu identifier to be added to the
+ output of the syslog() system call and at the console.
+
+ This flag just specifies if the cpu-id should
+ be included.
+
+ The behavior is also controlled by the kernel command line
+ parameter printk.cpuid=1.
+
config DEFAULT_MESSAGE_LOGLEVEL
int "Default message log level (1-7)"
range 1 7
--
1.7.9.5

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

[Kay Sievers]

How is that supposed to be useful?

The prefix is added while exporting data from the kmsg buffer, which
is just the CPU that *reads* the data from the buffer, not the one
that has *written* the data it into it.

Do I miss anything here?

Thanks,
Kay

[Pandita, Vikram]

Kay

I don't think so.
I can see the backtrace of the printk() call looks like follows:

print_cpuid
print_prefix
msg_print_text
console_unlock
vprint_emit
printk

Now this is a synchronous path, where in the buffer is getting filled
with cpuid and timer info from the printk() calling context.
So you should get the right CPU id with the trace - with the exception
that i pointed out earlier for preemption.

>
> Do I miss anything here?

This is my understanding of the printk framework.
At least the print_time and print_cpuid seems to be happening
synchronously wrt printk

[Kay Sievers]

Printk is a store-and-forward-model, and it always was. There is no
guarantee at all, that the data is immediately flushed to the console
by the same CPU, it just happens to be in most cases. It's pretty
common though, that a different task is doing that work when it gets
the console lock, and that is not a matter of preemption, it's normal
and expected operation. The data which CPU has emitted the text is
just not available. It would need to be stored in the records, for
this to work.

Your patch just prints the CPU that writes to the console, not
necessarily the one that has stored the data. I think the second one
is which is what you are looking for, but that is not what the patch
does.

Also dmesg and syslog uses the same logic and would put-out all
entirely wrong CPU information with it, because the original
information is long gone.

[Pandita, Vikram]

Kay

I did not understand well the complexity of the console layer. Thanks
for enlightenment :-)
Would be nice if you have any suggestion to get this done the right way.

First look i could guess this would do, but need to study further:

@@ -1550,6 +1550,9 @@ asmlinkage int vprintk_emit(int facility, int level,
NULL, 0, recursion_msg, printed_len);
}

+ text_len = print_cpuid(text);
+ text += text_len;
+
/*
* The printf needs to come first; we need the syslog
* prefix which might be passed-in as a parameter.
@@ -1582,6 +1585,13 @@ asmlinkage int vprintk_emit(int facility, int level,
}
}

+ /* Adjust for cpu-id string */
+ if (printk_cpuid) {
+ strncpy(text - 4, textbuf, 4);
+ text -= 4;
+ text_len += 4;
+ }
+
if (level == -1)
level = default_message_loglevel;

[Pandita, Vikram]

Kay

Understand somewhat better now the logging mechanism.
The proposal above does not seem to be correct or complete.

Will post v2 patch, hopefully fixing now.

[Vikram Pandita]

From: Vikram Pandita <vikram....@ti.com>

Introduce config option to enable CPU id reporting for printk() calls.

Example logs with this option enabled look like:
[1] [ 2.328613] usbcore: registered new interface driver libusual
[1] [ 2.335418] usbcore: registered new interface driver usbtest
[1] [ 2.342803] mousedev: PS/2 mouse device common for all mice
[0] [ 2.352600] twl_rtc twl_rtc: Power up reset detected.
[0] [ 2.359191] twl_rtc twl_rtc: Enabling TWL-RTC
[1] [ 2.367797] twl_rtc twl_rtc: rtc core: registered twl_rtc as rtc0
[1] [ 2.375274] i2c /dev entries driver
[1] [ 2.382324] Driver for 1-wire Dallas network protocol.

Its sometimes very useful to have printk also print the CPU Identifier
that executed the call. This has helped to debug various SMP issues on shipping
products.

Known limitation is if the system gets preempted between function call and

actual printk, the reported cpu-id might not be accurate. But most of the
times its seen to give a good feel of how the N cpu's in the system are
getting loaded.

Signed-off-by: Vikram Pandita <vikram....@ti.com>

Cc: Kay Sievers <k...@vrfy.org>

Cc: Mike Turquette <mturq...@linaro.org>
Cc: Vimarsh Zutshi <vimarsh...@gmail.com>
---

v1: initial version - had wrong cpuid logging mechanism
v2: fixed as per review comments from Kay Sievers

kernel/printk.c | 51 +++++++++++++++++++++++++++++++++++++++++----------
lib/Kconfig.debug | 13 +++++++++++++
2 files changed, 54 insertions(+), 10 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 6a76ab9..64f4a1b 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -208,6 +208,7 @@ struct log {
u8 facility; /* syslog facility */
u8 flags:5; /* internal record flags */
u8 level:3; /* syslog level */
+ u8 cpuid; /* cpu invoking the log */
};

/*
@@ -305,7 +306,8 @@ static u32 log_next(u32 idx)
static void log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
const char *dict, u16 dict_len,
- const char *text, u16 text_len)
+ const char *text, u16 text_len,
+ const u8 cpuid)
{
struct log *msg;
u32 size, pad_len;
@@ -356,6 +358,7 @@ static void log_store(int facility, int level,
msg->ts_nsec = local_clock();
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
+ msg->cpuid = cpuid;

/* insert message */
log_next_idx += msg->len;
@@ -855,6 +858,25 @@ static size_t print_time(u64 ts, char *buf)

(unsigned long)ts, rem_nsec / 1000);
}

+#if defined(CONFIG_PRINTK_CPUID)
+static bool printk_cpuid = 1;
+#else
+static bool printk_cpuid;
+#endif
+module_param_named(cpuid, printk_cpuid, bool, S_IRUGO | S_IWUSR);
+

+static size_t print_cpuid(u8 cpuid, char *buf)

+{
+
+ if (!printk_cpuid)
+ return 0;
+
+ if (!buf)
+ return 4;
+

+ return sprintf(buf, "[%1d] ", cpuid);

+}
+
static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
{
size_t len = 0;

@@ -874,6 +896,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
}
}

+ len += print_cpuid(msg->cpuid, buf ? buf + len : NULL);

len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
return len;
}

@@ -1387,6 +1410,7 @@ static struct cont {
u64 ts_nsec; /* time of first print */
u8 level; /* log level of first message */
u8 facility; /* log level of first message */
+ u8 cpuid; /* cpu invoking the logging request */
enum log_flags flags; /* prefix, newline flags */
bool flushed:1; /* buffer sealed and committed */
} cont;
@@ -1405,7 +1429,8 @@ static void cont_flush(enum log_flags flags)
* line. LOG_NOCONS suppresses a duplicated output.
*/
log_store(cont.facility, cont.level, flags | LOG_NOCONS,
- cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+ cont.ts_nsec, NULL, 0, cont.buf, cont.len,
+ cont.cpuid);
cont.flags = flags;
cont.flushed = true;
} else {
@@ -1414,12 +1439,14 @@ static void cont_flush(enum log_flags flags)
* just submit it to the store and free the buffer.
*/
log_store(cont.facility, cont.level, flags, 0,
- NULL, 0, cont.buf, cont.len);
+ NULL, 0, cont.buf, cont.len,
+ cont.cpuid);
cont.len = 0;
}
}

-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, const char *text, size_t len,
+ const u8 cpuid)
{
if (cont.len && cont.flushed)
return false;
@@ -1442,6 +1469,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)

memcpy(cont.buf + cont.len, text, len);
cont.len += len;
+ cont.cpuid = cpuid;

if (cont.len > (sizeof(cont.buf) * 80) / 100)
cont_flush(LOG_CONT);
@@ -1455,7 +1483,8 @@ static size_t cont_print_text(char *text, size_t size)
size_t len;

if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
- textlen += print_time(cont.ts_nsec, text);
+ textlen += print_cpuid(cont.cpuid, text);
+ textlen += print_time(cont.ts_nsec, text + textlen);
size -= textlen;
}

@@ -1527,7 +1556,7 @@ asmlinkage int vprintk_emit(int facility, int level,
printed_len += strlen(recursion_msg);
/* emit KERN_CRIT message */
log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
- NULL, 0, recursion_msg, printed_len);
+ NULL, 0, recursion_msg, printed_len, this_cpu);
}

/*
@@ -1577,9 +1606,9 @@ asmlinkage int vprintk_emit(int facility, int level,
cont_flush(LOG_NEWLINE);

/* buffer line if possible, otherwise store it right away */
- if (!cont_add(facility, level, text, text_len))
+ if (!cont_add(facility, level, text, text_len, this_cpu))
log_store(facility, level, lflags | LOG_CONT, 0,
- dict, dictlen, text, text_len);
+ dict, dictlen, text, text_len, this_cpu);
} else {
bool stored = false;

@@ -1591,13 +1620,15 @@ asmlinkage int vprintk_emit(int facility, int level,
*/
if (cont.len && cont.owner == current) {
if (!(lflags & LOG_PREFIX))
- stored = cont_add(facility, level, text, text_len);
+ stored = cont_add(facility, level, text, text_len,
+ this_cpu);
cont_flush(LOG_NEWLINE);
}

if (!stored)
log_store(facility, level, lflags, 0,
- dict, dictlen, text, text_len);
+ dict, dictlen, text, text_len,
+ this_cpu);
}
printed_len += text_len;

[Venu Byravarasu]

> -----Original Message-----
> From: linux-ker...@vger.kernel.org [mailto:linux-kernel-
> ow...@vger.kernel.org] On Behalf Of Vikram Pandita
> Sent: Friday, August 03, 2012 2:46 PM
> To: gre...@linuxfoundation.org; k...@vrfy.org
> Cc: linux-...@vger.kernel.org; Vikram Pandita; Mike Turquette; Vimarsh
> Zutshi
> Subject: [PATCH v2] printk: add option to print cpu id
>
> From: Vikram Pandita <vikram....@ti.com>
>
> Introduce config option to enable CPU id reporting for printk() calls.
>
> Example logs with this option enabled look like:
> [1] [ 2.328613] usbcore: registered new interface driver libusual
> [1] [ 2.335418] usbcore: registered new interface driver usbtest
> [1] [ 2.342803] mousedev: PS/2 mouse device common for all mice
> [0] [ 2.352600] twl_rtc twl_rtc: Power up reset detected.
> [0] [ 2.359191] twl_rtc twl_rtc: Enabling TWL-RTC
> [1] [ 2.367797] twl_rtc twl_rtc: rtc core: registered twl_rtc as rtc0
> [1] [ 2.375274] i2c /dev entries driver
> [1] [ 2.382324] Driver for 1-wire Dallas network protocol.
>
> Its sometimes very useful to have printk also print the CPU Identifier
> that executed the call. This has helped to debug various SMP issues on
> shipping
> products.

Is it not better to have macros which will have wrapper to printk with required
debug info added? E.g. cpu# in your case.
If by default we add cupid, is it not over head in each message getting
printed with printk?

>
> Known limitation is if the system gets preempted between function call and
> actual printk, the reported cpu-id might not be accurate. But most of the
> times its seen to give a good feel of how the N cpu's in the system are
> getting loaded.
>

[Venu Byravarasu]

As having Macro locally in the file of interest would serve the purpose,
Why to change the printk code?

[Pandita, Vikram]

Venu

As stated, the logic followed is exactly similar to well proven and
approved way to handle printk time stamp: CONFIG_PRINTK_TIME
Its an overhead on the system that enables the config option:
CONFIG_PRINTK_CPUID
Otherwise the system remains as is.

To gain insight on SMP system logging behavior, the price to pay is
the extra 4 chars per printk line,
just like printk-time adds 15 chars to each line. Both options can be
disabled as desired.

So i am not sure what kind of option you are proposing?
Do u imply PRINTK_TIME is not right then?

[Nikunj A Dadhania]

That would be sufficient for only 256 cpus. Is that what you intend?

There are systems which will have much higher numbers than this limit.

Firstly, why this magic number?
Secondly, if buf is NULL, why should you increment?

> + return sprintf(buf, "[%1d] ", cpuid);
> +}
> +
> static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
> {
> size_t len = 0;

Regards
Nikunj

[Venu Byravarasu]

> -----Original Message-----
> From: Pandita, Vikram [mailto:vikram....@ti.com]
> Sent: Friday, August 03, 2012 3:07 PM
> To: Venu Byravarasu
> Cc: gre...@linuxfoundation.org; k...@vrfy.org; linux-
> ker...@vger.kernel.org; Mike Turquette; Vimarsh Zutshi
> Subject: Re: [PATCH v2] printk: add option to print cpu id
>
> Venu
>
> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <vbyra...@nvidia.com>
> wrote:
>
> To gain insight on SMP system logging behavior, the price to pay is
> the extra 4 chars per printk line,
> just like printk-time adds 15 chars to each line. Both options can be
> disabled as desired.
>
> So i am not sure what kind of option you are proposing?

May be I'm not correct, but IMO having local file level macros to
add wrappers on top of printk would serve this purpose.

Anyways its individual choice.

[Kay Sievers]

On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <vikram....@ti.com> wrote:
> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <vbyra...@nvidia.com> wrote:

>> As having Macro locally in the file of interest would serve the purpose,
>> Why to change the printk code?
>
> As stated, the logic followed is exactly similar to well proven and
> approved way to handle printk time stamp: CONFIG_PRINTK_TIME
> Its an overhead on the system that enables the config option:
> CONFIG_PRINTK_CPUID
> Otherwise the system remains as is.
>
> To gain insight on SMP system logging behavior, the price to pay is
> the extra 4 chars per printk line,
> just like printk-time adds 15 chars to each line. Both options can be
> disabled as desired.
>
> So i am not sure what kind of option you are proposing?
> Do u imply PRINTK_TIME is not right then?

It's 8 bytes per message for storing the timestamp in the records.
There is never 15 bytes storage space needed, the prefix is
constructed on-the-fly only while exporting the data.

The CPU-ID would need at least two additional bytes (2^16 CPUS) in
every record, unless it's a compile-time option. I can't tell, if
everybody wants to pay the storage space for the the CPU-ID feature.

Kay

[Kay Sievers]

On Fri, Aug 3, 2012 at 11:43 AM, Nikunj A Dadhania
<nik...@linux.vnet.ibm.com> wrote:
> On Fri, 3 Aug 2012 02:16:18 -0700, Vikram Pandita <vikram....@ti.com> wrote:

>> +static size_t print_cpuid(u8 cpuid, char *buf)
>> +{
>> +
>> + if (!printk_cpuid)
>> + return 0;
>> +
>> + if (!buf)
>> + return 4;
>> +

> Firstly, why this magic number?
> Secondly, if buf is NULL, why should you increment?

The !buffer logic is used when we only calculate the size of the
output buffer, but do not print to it. It's just an optimization. And
yes, the number returned should match the number of chars that would
have been printed, so this does not look right.

Kay

[Pandita, Vikram]

Kay

On Fri, Aug 3, 2012 at 2:48 AM, Kay Sievers <k...@vrfy.org> wrote:
> On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <vikram....@ti.com> wrote:
>> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <vbyra...@nvidia.com> wrote:
>
>>> As having Macro locally in the file of interest would serve the purpose,
>>> Why to change the printk code?
>>
>> As stated, the logic followed is exactly similar to well proven and
>> approved way to handle printk time stamp: CONFIG_PRINTK_TIME
>> Its an overhead on the system that enables the config option:
>> CONFIG_PRINTK_CPUID
>> Otherwise the system remains as is.
>>
>> To gain insight on SMP system logging behavior, the price to pay is
>> the extra 4 chars per printk line,
>> just like printk-time adds 15 chars to each line. Both options can be
>> disabled as desired.
>>
>> So i am not sure what kind of option you are proposing?
>> Do u imply PRINTK_TIME is not right then?
>
> It's 8 bytes per message for storing the timestamp in the records.
> There is never 15 bytes storage space needed, the prefix is
> constructed on-the-fly only while exporting the data.

When i was referring to 15 chars, its coming from here:
Its the space reserved in each line of output. Corresponding space for
cpuid is 4 chars: "[x] ":

static size_t print_time(u64 ts, char *buf)

{
unsigned long rem_nsec;

if (!printk_time)
return 0;

if (!buf)
>>>> return 15;

>
> The CPU-ID would need at least two additional bytes (2^16 CPUS) in
> every record, unless it's a compile-time option.

are u proposing:
a) to make cpuid a u16?
b) to put cpuid in struct cont and struct log - under the #ifdef macro?

[Kay Sievers]

On Fri, Aug 3, 2012 at 11:56 AM, Pandita, Vikram <vikram....@ti.com> wrote:
> On Fri, Aug 3, 2012 at 2:48 AM, Kay Sievers <k...@vrfy.org> wrote:
>> On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <vikram....@ti.com> wrote:
>>> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <vbyra...@nvidia.com> wrote:
>>
>>>> As having Macro locally in the file of interest would serve the purpose,
>>>> Why to change the printk code?
>>>
>>> As stated, the logic followed is exactly similar to well proven and
>>> approved way to handle printk time stamp: CONFIG_PRINTK_TIME
>>> Its an overhead on the system that enables the config option:
>>> CONFIG_PRINTK_CPUID
>>> Otherwise the system remains as is.
>>>
>>> To gain insight on SMP system logging behavior, the price to pay is
>>> the extra 4 chars per printk line,
>>> just like printk-time adds 15 chars to each line. Both options can be
>>> disabled as desired.
>>>
>>> So i am not sure what kind of option you are proposing?
>>> Do u imply PRINTK_TIME is not right then?
>>
>> It's 8 bytes per message for storing the timestamp in the records.
>> There is never 15 bytes storage space needed, the prefix is
>> constructed on-the-fly only while exporting the data.
>
> When i was referring to 15 chars, its coming from here:
> Its the space reserved in each line of output. Corresponding space for
> cpuid is 4 chars: "[x] ":

Just saying, that's just the length of the printed line to the console
or syslog, there is no reservation or space used for that internally.

>> The CPU-ID would need at least two additional bytes (2^16 CPUS) in
>> every record, unless it's a compile-time option.
>
> are u proposing:
> a) to make cpuid a u16?

That would be needed, I guess. We easily have server systems with more
than 255 CPUs. It will only be a matter of time, that the number of
CPUs will increase for everybody, I guess.

> b) to put cpuid in struct cont and struct log - under the #ifdef macro?

As said, I really can't tell how generally useful it is, and if people
think that it should be there unconditionally, should not be there at
all, or as a compile time option. Others might have an opinion on
that.

I personally never missed the CPU-ID in the logs. I personally would
find the PID/task ID more interesting, and even that I never really
missed. :)

[Borislav Petkov]

On Fri, Aug 03, 2012 at 12:09:15PM +0200, Kay Sievers wrote:
> That would be needed, I guess. We easily have server systems with more
> than 255 CPUs. It will only be a matter of time, that the number of
> CPUs will increase for everybody, I guess.

Actually, AFAICR, we already have SGI machines booting Linux on 4K cpus. Now.

> > b) to put cpuid in struct cont and struct log - under the #ifdef macro?
>
> As said, I really can't tell how generally useful it is, and if people
> think that it should be there unconditionally, should not be there at
> all, or as a compile time option. Others might have an opinion on
> that.
>
> I personally never missed the CPU-ID in the logs. I personally would
> find the PID/task ID more interesting, and even that I never really
> missed. :)

And even then you can add debugging code to dump the stuff you need.

And I have to agree with Kai here, having the cpu number in dmesg is
not something I'd wish for - printk timestampts OTOH has at least some
usecases.

Thanks.

--
Regards/Gruss,
Boris.

[Pandita, Vikram]

Borislav/Kay

On Fri, Aug 3, 2012 at 3:42 AM, Borislav Petkov <b...@alien8.de> wrote:
>
> On Fri, Aug 03, 2012 at 12:09:15PM +0200, Kay Sievers wrote:
> > That would be needed, I guess. We easily have server systems with more
> > than 255 CPUs. It will only be a matter of time, that the number of
> > CPUs will increase for everybody, I guess.
>
> Actually, AFAICR, we already have SGI machines booting Linux on 4K cpus.
> Now.
>
> > > b) to put cpuid in struct cont and struct log - under the #ifdef
> > > macro?
> >
> > As said, I really can't tell how generally useful it is, and if people
> > think that it should be there unconditionally, should not be there at
> > all, or as a compile time option. Others might have an opinion on
> > that.
> >
> > I personally never missed the CPU-ID in the logs. I personally would
> > find the PID/task ID more interesting, and even that I never really
> > missed. :)

I mostly work with ARM Soc - specifically on OMAP.
SMP multi core systems in ARM-v7 world started to show up only few
years back - unlike x86 world.

ARM systems are a bit unique when it comes to security( read trust
zone ), and handling of FIQ's.
Most of the ARM cortex-A series SoC's out there have some kind of
affinity to CPU0 being the master.
One use case has been, it has helped to know with this printk logging,
if such constraints are honored.

Sometimes, tracking of some lockup cases between cpu's because of bad
code has also been helpful with this logging support.
For now i will post v3 of the patch and add arm-list and linux-omap
list, and there might be users there can benefit.

[Vikram Pandita]

From: Vikram Pandita <vikram....@ti.com>

Introduce config option to enable CPU id reporting for printk() calls.

Example logs with this option enabled look like:

[ 0] [ 0.063232] Mount-cache hash table entries: 512
[ 0] [ 0.068054] CPU: Testing write buffer coherency: ok
[ 0] [ 0.068939] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0] [ 0.069305] Setting up static identity map for 0x8046dc90 - 0x8046dd00
[ 0] [ 0.069366] L310 cache controller enabled
[ 0] [ 0.069396] l2x0: 16 ways, CACHE_ID 0x410000c7, AUX_CTRL 0x7e470000
[ 1] [ 0.073211] CPU1: Booted secondary processor
[ 1] [ 0.100463] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 1] [ 0.100555] CPU1: Unknown IPI message 0x0
[ 0] [ 0.101348] Brought up 2 CPUs

Its sometimes very useful to have printk also print the CPU Identifier
that executed the call. This has helped to debug various SMP issues on shipping
products.

Known limitation is if the system gets preempted between function call and
actual printk, the reported cpu-id might not be accurate. But most of the
times its seen to give a good feel of how the N cpu's in the system are
getting loaded.

Signed-off-by: Vikram Pandita <vikram....@ti.com>
Cc: Kay Sievers <k...@vrfy.org>
Cc: Mike Turquette <mturq...@linaro.org>
Cc: Vimarsh Zutshi <vimarsh...@gmail.com>

Signed-off-by: Vikram Pandita <vikram....@ti.com>

---
v1: initial version - had wrong cpuid logging mechanism
v2: fixed as per review comments from Kay Sievers

v3: allow cpuid to be u16 to support multi-core systems with 1000+ cores

kernel/printk.c | 51 +++++++++++++++++++++++++++++++++++++++++----------
lib/Kconfig.debug | 13 +++++++++++++
2 files changed, 54 insertions(+), 10 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c

index 6a76ab9..90d49b2 100644

--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -208,6 +208,7 @@ struct log {
u8 facility; /* syslog facility */
u8 flags:5; /* internal record flags */
u8 level:3; /* syslog level */

+ u16 cpuid; /* cpu invoking the log */
};

/*
@@ -305,7 +306,8 @@ static u32 log_next(u32 idx)
static void log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
const char *dict, u16 dict_len,
- const char *text, u16 text_len)
+ const char *text, u16 text_len,

+ const u16 cpuid)

{
struct log *msg;
u32 size, pad_len;
@@ -356,6 +358,7 @@ static void log_store(int facility, int level,
msg->ts_nsec = local_clock();
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
+ msg->cpuid = cpuid;

/* insert message */
log_next_idx += msg->len;
@@ -855,6 +858,25 @@ static size_t print_time(u64 ts, char *buf)
(unsigned long)ts, rem_nsec / 1000);
}

+#if defined(CONFIG_PRINTK_CPUID)
+static bool printk_cpuid = 1;
+#else
+static bool printk_cpuid;
+#endif
+module_param_named(cpuid, printk_cpuid, bool, S_IRUGO | S_IWUSR);
+

+static size_t print_cpuid(u16 cpuid, char *buf)

+{
+
+ if (!printk_cpuid)
+ return 0;
+
+ if (!buf)

+ return 7;
+
+ return sprintf(buf, "[%4d] ", cpuid);

+}
+
static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
{
size_t len = 0;

@@ -874,6 +896,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
}
}

+ len += print_cpuid(msg->cpuid, buf ? buf + len : NULL);
len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
return len;
}
@@ -1387,6 +1410,7 @@ static struct cont {
u64 ts_nsec; /* time of first print */
u8 level; /* log level of first message */
u8 facility; /* log level of first message */

+ u16 cpuid; /* cpu invoking the logging request */

enum log_flags flags; /* prefix, newline flags */
bool flushed:1; /* buffer sealed and committed */
} cont;
@@ -1405,7 +1429,8 @@ static void cont_flush(enum log_flags flags)
* line. LOG_NOCONS suppresses a duplicated output.
*/
log_store(cont.facility, cont.level, flags | LOG_NOCONS,
- cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+ cont.ts_nsec, NULL, 0, cont.buf, cont.len,
+ cont.cpuid);
cont.flags = flags;
cont.flushed = true;
} else {
@@ -1414,12 +1439,14 @@ static void cont_flush(enum log_flags flags)
* just submit it to the store and free the buffer.
*/
log_store(cont.facility, cont.level, flags, 0,
- NULL, 0, cont.buf, cont.len);
+ NULL, 0, cont.buf, cont.len,
+ cont.cpuid);
cont.len = 0;
}
}

-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, const char *text, size_t len,

+ const u16 cpuid)

[Andi Kleen]

Vikram Pandita <vikram....@ti.com> writes:

> From: Vikram Pandita <vikram....@ti.com>
>
> 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

--
a...@linux.intel.com -- Speaking for myself only

[Pandita, Vikram]

On Fri, Aug 3, 2012 at 10:54 AM, Andi Kleen <an...@firstfloor.org> wrote:
> Vikram Pandita <vikram....@ti.com> writes:
>
>> From: Vikram Pandita <vikram....@ti.com>
>>
>> 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.

[Aaro Koskinen]

Hi,

On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
> > 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.

[Pandita, Vikram]

Aaro

On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen <aaro.k...@iki.fi> wrote:
> Hi,
>
> On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
>> > 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.

[Greg KH]

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 <aaro.k...@iki.fi> wrote:
> > Hi,
> >
> > On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
> >> > 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

[Pandita, Vikram]

On Fri, Aug 3, 2012 at 2:59 PM, Greg KH <gre...@linuxfoundation.org> wrote:
> 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 <aaro.k...@iki.fi> wrote:
>> > Hi,
>> >
>> > On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
>> >> > 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 KH]

On Fri, Aug 03, 2012 at 03:07:39PM -0700, Pandita, Vikram wrote:
> On Fri, Aug 3, 2012 at 2:59 PM, Greg KH <gre...@linuxfoundation.org> wrote:
> > 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 <aaro.k...@iki.fi> wrote:
> >> > Hi,
> >> >
> >> > On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
> >> >> > 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?

[Pandita, Vikram]

On Fri, Aug 3, 2012 at 3:13 PM, Greg KH <gre...@linuxfoundation.org> wrote:
> On Fri, Aug 03, 2012 at 03:07:39PM -0700, Pandita, Vikram wrote:
>> On Fri, Aug 3, 2012 at 2:59 PM, Greg KH <gre...@linuxfoundation.org> wrote:
>> > 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 <aaro.k...@iki.fi> wrote:
>> >> > Hi,
>> >> >
>> >> > On Fri, Aug 03, 2012 at 11:25:37AM -0700, Pandita, Vikram wrote:
>> >> >> > 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 KH]

On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
> >> 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?

[Pandita, Vikram]

On Fri, Aug 3, 2012 at 3:36 PM, Greg KH <gre...@linuxfoundation.org> wrote:
> On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
>> >> 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.

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

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

[Borislav Petkov]

On Fri, Aug 03, 2012 at 09:46:15AM -0700, Pandita, Vikram wrote:
> I mostly work with ARM Soc - specifically on OMAP. SMP multi core
> systems in ARM-v7 world started to show up only few years back -
> unlike x86 world.

This is exactly the thing: other SMP vendors have made it so far without
emitting which core is doing what in dmesg.

> ARM systems are a bit unique when it comes to security( read trust
> zone ), and handling of FIQ's. Most of the ARM cortex-A series SoC's
> out there have some kind of affinity to CPU0 being the master. One use
> case has been, it has helped to know with this printk logging, if such
> constraints are honored.
>
> Sometimes, tracking of some lockup cases between cpu's because of bad
> code has also been helpful with this logging support. For now i will
> post v3 of the patch and add arm-list and linux-omap list, and there
> might be users there can benefit.

Right, so if arm people need this thing, why not make it arm-only? I
still fail to see the need for this (... at all, actually).

[Russell King - ARM Linux]

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.

[Steven Rostedt]

On Fri, Aug 03, 2012 at 03:48:26PM -0700, Pandita, Vikram wrote:
> On Fri, Aug 3, 2012 at 3:36 PM, Greg KH <gre...@linuxfoundation.org> wrote:
> > On Fri, Aug 03, 2012 at 03:25:17PM -0700, Pandita, Vikram wrote:
> >> >> 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