From 29e36c9ffb696ed8d73e1aee713d483ec74a9a43 Mon Sep 17 00:00:00 2001 From: Jim Cromie Date: Fri, 27 Apr 2012 14:30:41 -0600 Subject: dynamic_debug: update Documentation/*, Kconfig.debug In dynamic-debug-howto.txt: - add section: Debug Messages at Module Initialization Time - update flags indicators in example outputs to include '=' - make flags descriptions tabular - add item on '_' flag-char - add dyndbg, boot-args examples - rewrap some paragraphs with long lines In Kconfig.debug, note that compiling with -DDEBUG enables all pr_debug()s in that code. In kernel-parameters.txt, add dyndbg and module.dyndbg items, and deprecate ddebug_query. Signed-off-by: Jim Cromie Acked-by: Jason Baron Signed-off-by: Greg Kroah-Hartman --- lib/Kconfig.debug | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) (limited to 'lib/Kconfig.debug') diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index 6777153f18f3..ef8192bc0c33 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -1205,8 +1205,13 @@ config DYNAMIC_DEBUG otherwise be available at runtime. These messages can then be enabled/disabled based on various levels of scope - per source file, function, module, format string, and line number. This mechanism - implicitly enables all pr_debug() and dev_dbg() calls. The impact of - this compile option is a larger kernel text size of about 2%. + implicitly compiles in all pr_debug() and dev_dbg() calls, which + enlarges the kernel text size by about 2%. + + If a source file is compiled with DEBUG flag set, any + pr_debug() calls in it are enabled by default, but can be + disabled at runtime as below. Note that DEBUG flag is + turned on by many CONFIG_*DEBUG* options. Usage: @@ -1223,16 +1228,16 @@ config DYNAMIC_DEBUG lineno : line number of the debug statement module : module that contains the debug statement function : function that contains the debug statement - flags : 'p' means the line is turned 'on' for printing + flags : '=p' means the line is turned 'on' for printing format : the format used for the debug statement From a live system: nullarbor:~ # cat /dynamic_debug/control # filename:lineno [module]function flags format - fs/aio.c:222 [aio]__put_ioctx - "__put_ioctx:\040freeing\040%p\012" - fs/aio.c:248 [aio]ioctx_alloc - "ENOMEM:\040nr_events\040too\040high\012" - fs/aio.c:1770 [aio]sys_io_cancel - "calling\040cancel\012" + fs/aio.c:222 [aio]__put_ioctx =_ "__put_ioctx:\040freeing\040%p\012" + fs/aio.c:248 [aio]ioctx_alloc =_ "ENOMEM:\040nr_events\040too\040high\012" + fs/aio.c:1770 [aio]sys_io_cancel =_ "calling\040cancel\012" Example usage: -- cgit v1.3-14-g43fede From 649e6ee33f73ba1c4f2492c6de9aff2254b540cb Mon Sep 17 00:00:00 2001 From: Kay Sievers Date: Thu, 10 May 2012 04:30:45 +0200 Subject: printk() - restore timestamp printing at console output The output of the timestamps got lost with the conversion of the kmsg buffer to records; restore the old behavior. Document, that CONFIG_PRINTK_TIME now only controls the output of the timestamps in the syslog() system call and on the console, and not the recording of the timestamps. Cc: Joe Perches Cc: Linus Torvalds Cc: Sasha Levin Cc: Ingo Molnar Reported-by: Yinghai Lu Signed-off-by: Kay Sievers Signed-off-by: Greg Kroah-Hartman --- kernel/printk.c | 43 ++++++++++++++++++++++++++----------------- lib/Kconfig.debug | 16 ++++++++++------ 2 files changed, 36 insertions(+), 23 deletions(-) (limited to 'lib/Kconfig.debug') diff --git a/kernel/printk.c b/kernel/printk.c index 301fb0f09fbf..572941d7e5f7 100644 --- a/kernel/printk.c +++ b/kernel/printk.c @@ -786,6 +786,22 @@ static bool printk_time; #endif module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); +static size_t prepend_timestamp(unsigned long long t, char *buf) +{ + unsigned long rem_ns; + + if (!printk_time) + return 0; + + if (!buf) + return 15; + + rem_ns = do_div(t, 1000000000); + + return sprintf(buf, "[%5lu.%06lu] ", + (unsigned long) t, rem_ns / 1000); +} + static int syslog_print_line(u32 idx, char *text, size_t size) { struct log *msg; @@ -800,9 +816,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size) len++; if (msg->level > 99) len++; - - if (printk_time) - len += 15; + len += prepend_timestamp(0, NULL); len += msg->text_len; len++; @@ -810,15 +824,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size) } len = sprintf(text, "<%u>", msg->level); - - if (printk_time) { - unsigned long long t = msg->ts_nsec; - unsigned long rem_ns = do_div(t, 1000000000); - - len += sprintf(text + len, "[%5lu.%06lu] ", - (unsigned long) t, rem_ns / 1000); - } - + len += prepend_timestamp(msg->ts_nsec, text + len); if (len + msg->text_len > size) return -EINVAL; memcpy(text + len, log_text(msg), msg->text_len); @@ -1741,7 +1747,7 @@ again: for (;;) { struct log *msg; static char text[LOG_LINE_MAX]; - size_t len; + size_t len, l; int level; raw_spin_lock_irqsave(&logbuf_lock, flags); @@ -1761,10 +1767,13 @@ again: msg = log_from_idx(console_idx); level = msg->level & 7; - len = msg->text_len; - if (len+1 >= sizeof(text)) - len = sizeof(text)-1; - memcpy(text, log_text(msg), len); + + len = prepend_timestamp(msg->ts_nsec, text); + l = msg->text_len; + if (len + l + 1 >= sizeof(text)) + l = sizeof(text) - len - 1; + memcpy(text + len, log_text(msg), l); + len += l; text[len++] = '\n'; console_idx = log_next(console_idx); diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index ef8192bc0c33..e11934177030 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -3,12 +3,16 @@ config PRINTK_TIME bool "Show timing information on printks" depends on PRINTK help - Selecting this option causes timing information to be - included in printk output. This allows you to measure - the interval between kernel operations, including bootup - operations. This is useful for identifying long delays - in kernel startup. Or add printk.time=1 at boot-time. - See Documentation/kernel-parameters.txt + Selecting this option causes time stamps of the printk() + messages to be added to the output of the syslog() system + call and at the console. + + The timestamp is always recorded internally, and exported + to /dev/kmsg. This flag just specifies if the timestamp should + be included, not that the timestamp is recorded. + + The behavior is also controlled by the kernel command line + parameter printk.time=1. See Documentation/kernel-parameters.txt config DEFAULT_MESSAGE_LOGLEVEL int "Default message log level (1-7)" -- cgit v1.3-14-g43fede