From: Vikram Pandita <[email protected]>
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 <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: Mike Turquette <[email protected]>
Cc: Vimarsh Zutshi <[email protected]>
---
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;
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
> -----Original Message-----
> From: [email protected] [mailto:linux-kernel-
> [email protected]] On Behalf Of Vikram Pandita
> Sent: Friday, August 03, 2012 2:46 PM
> To: [email protected]; [email protected]
> Cc: [email protected]; Vikram Pandita; Mike Turquette; Vimarsh
> Zutshi
> Subject: [PATCH v2] printk: add option to print cpu id
>
> From: Vikram Pandita <[email protected]>
>
> 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.
>
> -----Original Message-----
> From: [email protected] [mailto:linux-kernel-
> [email protected]] On Behalf Of Venu Byravarasu
> Sent: Friday, August 03, 2012 2:58 PM
> To: Vikram Pandita; [email protected]; [email protected]
> Cc: [email protected]; Mike Turquette; Vimarsh Zutshi
> Subject: RE: [PATCH v2] printk: add option to print cpu id
>
> > -----Original Message-----
> > From: [email protected] [mailto:linux-kernel-
> > [email protected]] On Behalf Of Vikram Pandita
> > Sent: Friday, August 03, 2012 2:46 PM
> > To: [email protected]; [email protected]
> > Cc: [email protected]; Vikram Pandita; Mike Turquette; Vimarsh
> > Zutshi
> > Subject: [PATCH v2] printk: add option to print cpu id
> >
> > From: Vikram Pandita <[email protected]>
> >
> > 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.
>
As having Macro locally in the file of interest would serve the purpose,
Why to change the printk code?
> 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.
> >
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
Venu
On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <[email protected]> wrote:
>
>> -----Original Message-----
>> From: [email protected] [mailto:linux-kernel-
>> [email protected]] On Behalf Of Venu Byravarasu
>> Sent: Friday, August 03, 2012 2:58 PM
>> To: Vikram Pandita; [email protected]; [email protected]
>> Cc: [email protected]; Mike Turquette; Vimarsh Zutshi
>> Subject: RE: [PATCH v2] printk: add option to print cpu id
>>
>> > -----Original Message-----
>> > From: [email protected] [mailto:linux-kernel-
>> > [email protected]] On Behalf Of Vikram Pandita
>> > Sent: Friday, August 03, 2012 2:46 PM
>> > To: [email protected]; [email protected]
>> > Cc: [email protected]; Vikram Pandita; Mike Turquette; Vimarsh
>> > Zutshi
>> > Subject: [PATCH v2] printk: add option to print cpu id
>> >
>> > From: Vikram Pandita <[email protected]>
>> >
>> > 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.
>>
>
> 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?
>
>> 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.
>> >
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
>> the body of a message to [email protected]
>> More majordomo info at http://vger.kernel.org/majordomo-info.html
>> Please read the FAQ at http://www.tux.org/lkml/
On Fri, 3 Aug 2012 02:16:18 -0700, Vikram Pandita <[email protected]> wrote:
> From: Vikram Pandita <[email protected]>
>
> 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 <[email protected]>
> Cc: Kay Sievers <[email protected]>
> Cc: Mike Turquette <[email protected]>
> Cc: Vimarsh Zutshi <[email protected]>
> ---
> 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 */
> };
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.
> /*
> @@ -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;
> +
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
> -----Original Message-----
> From: Pandita, Vikram [mailto:[email protected]]
> Sent: Friday, August 03, 2012 3:07 PM
> To: Venu Byravarasu
> Cc: [email protected]; [email protected]; linux-
> [email protected]; 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 <[email protected]>
> 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.
> Do u imply PRINTK_TIME is not right then?
>
> >
> >> 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.
> >> >
> >> --
> >> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> >> the body of a message to [email protected]
> >> More majordomo info at http://vger.kernel.org/majordomo-info.html
> >> Please read the FAQ at http://www.tux.org/lkml/
On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <[email protected]> wrote:
> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <[email protected]> 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
On Fri, Aug 3, 2012 at 11:43 AM, Nikunj A Dadhania
<[email protected]> wrote:
> On Fri, 3 Aug 2012 02:16:18 -0700, Vikram Pandita <[email protected]> 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
Kay
On Fri, Aug 3, 2012 at 2:48 AM, Kay Sievers <[email protected]> wrote:
> On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <[email protected]> wrote:
>> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <[email protected]> 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?
> I can't tell, if
> everybody wants to pay the storage space for the the CPU-ID feature.
>
> Kay
On Fri, Aug 3, 2012 at 11:56 AM, Pandita, Vikram <[email protected]> wrote:
> On Fri, Aug 3, 2012 at 2:48 AM, Kay Sievers <[email protected]> wrote:
>> On Fri, Aug 3, 2012 at 11:36 AM, Pandita, Vikram <[email protected]> wrote:
>>> On Fri, Aug 3, 2012 at 2:32 AM, Venu Byravarasu <[email protected]> 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. :)
Kay
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.
Borislav/Kay
On Fri, Aug 3, 2012 at 3:42 AM, Borislav Petkov <[email protected]> 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.
>
> 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.
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).
Thanks.
--
Regards/Gruss,
Boris.