From: Vikram Pandita <[email protected]>
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 <[email protected]>
Cc: Mike Turquette <[email protected]>
Cc: Vimarsh Zutshi <[email protected]>
---
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
On Thu, Aug 2, 2012 at 9:46 PM, Vikram Pandita <[email protected]> wrote:
> From: Vikram Pandita <[email protected]>
>
> 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 <[email protected]>
> Cc: Mike Turquette <[email protected]>
> Cc: Vimarsh Zutshi <[email protected]>
> ---
> 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;
> }
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
Kay
On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <[email protected]> wrote:
>
> On Thu, Aug 2, 2012 at 9:46 PM, Vikram Pandita <[email protected]>
> wrote:
> > From: Vikram Pandita <[email protected]>
> >
> > 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 <[email protected]>
> > Cc: Mike Turquette <[email protected]>
> > Cc: Vimarsh Zutshi <[email protected]>
> > ---
> > 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;
> > }
>
> 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.
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
>
> Thanks,
> Kay
On Fri, Aug 3, 2012 at 1:50 AM, Pandita, Vikram <[email protected]> wrote:
> On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <[email protected]> wrote:
>> 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.
>
> 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
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.
Kay
Kay
On Thu, Aug 2, 2012 at 5:06 PM, Kay Sievers <[email protected]> wrote:
> On Fri, Aug 3, 2012 at 1:50 AM, Pandita, Vikram <[email protected]> wrote:
>> On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <[email protected]> wrote:
>
>>> 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.
>>
>> 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
>
> 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.
>
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;
> 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.
>
> Kay
Kay
On Thu, Aug 2, 2012 at 7:19 PM, Pandita, Vikram <[email protected]> wrote:
> Kay
>
> On Thu, Aug 2, 2012 at 5:06 PM, Kay Sievers <[email protected]> wrote:
>> On Fri, Aug 3, 2012 at 1:50 AM, Pandita, Vikram <[email protected]> wrote:
>>> On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <[email protected]> wrote:
>>
>>>> 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.
>>>
>>> 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
>>
>> 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.
>>
>
> 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;
>
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.
>
>
>> 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.
>>
>> Kay