Message ID | 1344013004-32211-1-git-send-email-vikram.pandita@ti.com (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
Vikram Pandita <vikram.pandita@ti.com> writes: > From: Vikram Pandita <vikram.pandita@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
On Fri, Aug 3, 2012 at 10:54 AM, Andi Kleen <andi@firstfloor.org> wrote: > Vikram Pandita <vikram.pandita@ti.com> writes: > >> From: Vikram Pandita <vikram.pandita@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. > > -Andi > > -- > ak@linux.intel.com -- Speaking for myself only -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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. -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Aaro On Fri, Aug 3, 2012 at 1:08 PM, Aaro Koskinen <aaro.koskinen@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. > > A. -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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.koskinen@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 -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 3, 2012 at 2:59 PM, Greg KH <gregkh@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.koskinen@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 k-h -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 03, 2012 at 03:07:39PM -0700, Pandita, Vikram wrote: > On Fri, Aug 3, 2012 at 2:59 PM, Greg KH <gregkh@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.koskinen@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? greg k-h -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 3, 2012 at 3:13 PM, Greg KH <gregkh@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 <gregkh@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.koskinen@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 k-h -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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? greg k-h -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 3, 2012 at 3:36 PM, Greg KH <gregkh@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. > greg k-h -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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. -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 03, 2012 at 03:48:26PM -0700, Pandita, Vikram wrote: > On Fri, Aug 3, 2012 at 3:36 PM, Greg KH <gregkh@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 -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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) { 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