* [PATCHSET] printk: implement printk_header() and merging printk, take #3
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Hello, all.
This is the third take of implement-printk_header-and-mprintk
patchset.
Changes from the last take[L] are...
* Now header is printed on every line of a multiline message. If the
header ends with ':' followed by spaces. The colon is replaced with
space from the second line.
* s/mprintk/mprintk_flush/ and s/mprintk_add/mprintk/ as suggested.
* mprintk_init_alloc() and mprintk_free() added to ease malloc'd
buffer handling. No need to specify buffer size. Sizing is left to
mprintk.
This patchset aims to make printing multiline messages and assembling
message piece-by-piece easier.
In a nutshell, printk_header() lets you do the following atomically
(against other messages).
code:
printk(KERN_INFO "ata1.00: ", "line0\nline1\nline2\n");
output:
<6>ata1.00: line0
<6>ata1.00 line1
<6>ata1.00 line2
And mprintk the following.
code:
DEFINE_MPRINTK(mp, 2 * 80);
mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
mprintk_push(&mp, "ATA %d", 7);
mprintk_push(&mp, ", %u sectors\n", 1024);
mprintk(&mp, "everything seems dandy\n");
output:
<6>ata1.00: ATA 7, 1024 sectors
<6>ata1.00 everything seems dandy
For more info, please read Documentation/printk.txt which is created
by the fourth patch.
This patchset is on top of
linux-2.6#master (96b5a46e2a72dc1829370c87053e0cd558d58bc0)
+ printk-fix-possible-printk-buffer-overrun [1]
+ printk-implement-printk_buf-overflow-warning [2]
and contains the following patches.
0001-printk-keep-log-level-on-multiline-messages.patch
0002-printk-implement-v-printk_header.patch
0003-printk-implement-merging-printk.patch
0004-printk-add-Documentation-printk.txt.patch
0005-libata-make-libata-use-printk_header-and-mprintk.patch
Documentation/00-INDEX | 2
Documentation/printk.txt | 724 ++++++++++++++++++++++++++++++++++++++++++++
drivers/ata/libata-core.c | 204 +++++++-----
drivers/ata/libata-eh.c | 182 +++++------
drivers/ata/libata-pmp.c | 5
drivers/ata/libata-scsi.c | 6
drivers/ata/sata_inic162x.c | 2
drivers/ata/sata_nv.c | 4
include/linux/kernel.h | 85 +++++
include/linux/libata.h | 35 +-
kernel/printk.c | 435 ++++++++++++++++++++++++--
11 files changed, 1453 insertions(+), 231 deletions(-)
If this gets acked, I think it's best to push it through libata-dev as
libata is the first user.
Thanks.
--
tejun
[L] http://thread.gmane.org/gmane.linux.ide/27317
[1] http://article.gmane.org/gmane.linux.kernel/639018
[2] http://article.gmane.org/gmane.linux.kernel/639029
^ permalink raw reply [flat|nested] 24+ messages in thread
* [PATCH 1/5] printk: keep log level on multiline messages
2008-02-13 9:09 ` Tejun Heo
@ 2008-02-13 9:09 ` Tejun Heo
-1 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
When printing multiline messages, printk() resets log level to
default_message_loglevel after the first line. This changes log level
unexpectedly when printing multiline messages.
For example, libata error messages are printed like the following.
<3>ata8.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40 tag 0 ncq 512 in
<4> res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
This patch makes printk use the log level of the last line if the
current line doesn't specify log level explicitly.
While at it, separate out is_loglevel() test. This will be used by
later changes.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
kernel/printk.c | 50 +++++++++++++++++++++++---------------------------
1 files changed, 23 insertions(+), 27 deletions(-)
diff --git a/kernel/printk.c b/kernel/printk.c
index 419cd47..2317ec8 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -614,6 +614,11 @@ asmlinkage int printk(const char *fmt, ...)
return r;
}
+static int is_loglevel(const char *p)
+{
+ return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
+}
+
asmlinkage int vprintk(const char *fmt, va_list args)
{
/* cpu currently holding logbuf_lock */
@@ -625,10 +630,11 @@ asmlinkage int vprintk(const char *fmt, va_list args)
static int log_level_unknown = 1;
static char printk_buf[PRINTK_BUF_LEN + sizeof(overflow_tag) - 1];
+ int last_lv = default_message_loglevel;
unsigned long flags;
int printed_len = 0;
int this_cpu;
- char *p;
+ const char *p;
boot_delay_msec();
@@ -682,47 +688,37 @@ asmlinkage int vprintk(const char *fmt, va_list args)
for (p = printk_buf; *p; p++) {
if (log_level_unknown) {
/* log_level_unknown signals the start of a new line */
+ int lv = last_lv;
+
+ if (is_loglevel(p)) {
+ lv = p[1] - '0';
+ p += 3;
+ printed_len -= 3;
+ }
+
+ emit_log_char('<');
+ emit_log_char(lv + '0');
+ emit_log_char('>');
+ printed_len += 3;
+
if (printk_time) {
- int loglev_char;
char tbuf[50], *tp;
unsigned tlen;
unsigned long long t;
unsigned long nanosec_rem;
- /*
- * force the log level token to be
- * before the time output.
- */
- if (p[0] == '<' && p[1] >='0' &&
- p[1] <= '7' && p[2] == '>') {
- loglev_char = p[1];
- p += 3;
- printed_len -= 3;
- } else {
- loglev_char = default_message_loglevel
- + '0';
- }
t = cpu_clock(printk_cpu);
nanosec_rem = do_div(t, 1000000000);
- tlen = sprintf(tbuf,
- "<%c>[%5lu.%06lu] ",
- loglev_char,
+ tlen = sprintf(tbuf, "[%5lu.%06lu] ",
(unsigned long)t,
nanosec_rem/1000);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
- } else {
- if (p[0] != '<' || p[1] < '0' ||
- p[1] > '7' || p[2] != '>') {
- emit_log_char('<');
- emit_log_char(default_message_loglevel
- + '0');
- emit_log_char('>');
- printed_len += 3;
- }
}
+
+ last_lv = lv;
log_level_unknown = 0;
if (!*p)
break;
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread* [PATCH 1/5] printk: keep log level on multiline messages
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
When printing multiline messages, printk() resets log level to
default_message_loglevel after the first line. This changes log level
unexpectedly when printing multiline messages.
For example, libata error messages are printed like the following.
<3>ata8.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40 tag 0 ncq 512 in
<4> res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
This patch makes printk use the log level of the last line if the
current line doesn't specify log level explicitly.
While at it, separate out is_loglevel() test. This will be used by
later changes.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
kernel/printk.c | 50 +++++++++++++++++++++++---------------------------
1 files changed, 23 insertions(+), 27 deletions(-)
diff --git a/kernel/printk.c b/kernel/printk.c
index 419cd47..2317ec8 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -614,6 +614,11 @@ asmlinkage int printk(const char *fmt, ...)
return r;
}
+static int is_loglevel(const char *p)
+{
+ return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
+}
+
asmlinkage int vprintk(const char *fmt, va_list args)
{
/* cpu currently holding logbuf_lock */
@@ -625,10 +630,11 @@ asmlinkage int vprintk(const char *fmt, va_list args)
static int log_level_unknown = 1;
static char printk_buf[PRINTK_BUF_LEN + sizeof(overflow_tag) - 1];
+ int last_lv = default_message_loglevel;
unsigned long flags;
int printed_len = 0;
int this_cpu;
- char *p;
+ const char *p;
boot_delay_msec();
@@ -682,47 +688,37 @@ asmlinkage int vprintk(const char *fmt, va_list args)
for (p = printk_buf; *p; p++) {
if (log_level_unknown) {
/* log_level_unknown signals the start of a new line */
+ int lv = last_lv;
+
+ if (is_loglevel(p)) {
+ lv = p[1] - '0';
+ p += 3;
+ printed_len -= 3;
+ }
+
+ emit_log_char('<');
+ emit_log_char(lv + '0');
+ emit_log_char('>');
+ printed_len += 3;
+
if (printk_time) {
- int loglev_char;
char tbuf[50], *tp;
unsigned tlen;
unsigned long long t;
unsigned long nanosec_rem;
- /*
- * force the log level token to be
- * before the time output.
- */
- if (p[0] == '<' && p[1] >='0' &&
- p[1] <= '7' && p[2] == '>') {
- loglev_char = p[1];
- p += 3;
- printed_len -= 3;
- } else {
- loglev_char = default_message_loglevel
- + '0';
- }
t = cpu_clock(printk_cpu);
nanosec_rem = do_div(t, 1000000000);
- tlen = sprintf(tbuf,
- "<%c>[%5lu.%06lu] ",
- loglev_char,
+ tlen = sprintf(tbuf, "[%5lu.%06lu] ",
(unsigned long)t,
nanosec_rem/1000);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
- } else {
- if (p[0] != '<' || p[1] < '0' ||
- p[1] > '7' || p[2] != '>') {
- emit_log_char('<');
- emit_log_char(default_message_loglevel
- + '0');
- emit_log_char('>');
- printed_len += 3;
- }
}
+
+ last_lv = lv;
log_level_unknown = 0;
if (!*p)
break;
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread
* [PATCH 2/5] printk: implement [v]printk_header()
2008-02-13 9:09 ` Tejun Heo
@ 2008-02-13 9:09 ` Tejun Heo
-1 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Implement [v]printk_header() which takes @header argument and
automatically prints header in front of or indents multiline messages.
For example, if @header is "<7>ata1.00: " and the formatted message is
"<6>line0\nline1\n", the following gets written to the console.
<6>ata1.00: line0
<6>ata1.00 line1
As seen above if header ends with ':' followed by any number of
spaces, the colon is replaced with space from the second line. This
helps to distinguish where a multiline message begins when messages of
similar pattern repeats, for example...
ata8.00: cmd 60/80:20:e1:71:02/00:00:00:00:00/40 tag 4 ncq 65536 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
ata8.00: cmd 60/0e:28:d0:71:02/00:00:00:00:00/40 tag 5 ncq 7168 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
ata8.00: cmd 60/7f:38:61:72:02/00:00:00:00:00/40 tag 7 ncq 65024 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
include/linux/kernel.h | 12 ++++++
kernel/printk.c | 95 +++++++++++++++++++++++++++++++++++++++++++++---
2 files changed, 102 insertions(+), 5 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 2df44e7..d885208 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -177,6 +177,10 @@ struct pid;
extern struct pid *session_of_pgrp(struct pid *pgrp);
#ifdef CONFIG_PRINTK
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+asmlinkage int printk_header(const char *header, const char * fmt, ...)
+ __attribute__ ((format (printf, 2, 3))) __cold;
asmlinkage int vprintk(const char *fmt, va_list args)
__attribute__ ((format (printf, 1, 0)));
asmlinkage int printk(const char * fmt, ...)
@@ -192,6 +196,14 @@ extern int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
unsigned int interval_msec);
#else
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+{ return 0; }
+static inline int printk_header(const char *header, const char *s, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int __cold printk_header(const char *header, const char *s, ...)
+{ return 0; }
static inline int vprintk(const char *s, va_list args)
__attribute__ ((format (printf, 1, 0)));
static inline int vprintk(const char *s, va_list args) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 2317ec8..2283a75 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -608,18 +608,75 @@ asmlinkage int printk(const char *fmt, ...)
int r;
va_start(args, fmt);
- r = vprintk(fmt, args);
+ r = vprintk_header(NULL, fmt, args);
va_end(args);
return r;
}
+EXPORT_SYMBOL(printk);
+
+asmlinkage int vprintk(const char *fmt, va_list args)
+{
+ return vprintk_header(NULL, fmt, args);
+}
+EXPORT_SYMBOL(vprintk);
+
+/**
+ * printk_header - print a kernel message with header
+ * @header: header string
+ * @fmt: format string
+ *
+ * This is printk() with a twist. @header points to string which will
+ * be used as message header. If @header is NULL, this function is
+ * identical to printk().
+ *
+ * @header may contain loglevel in front of it. Each new line
+ * including the first one in the message formatted from @fmt can also
+ * have loglevel. When both exist, the latter is used. In multiline
+ * messages, log level is inherited from the previous line if not
+ * explicitly specified.
+ *
+ * @header is printed when a new line starts. If @header ends with
+ * ':' followed by spaces, the colon is replaced with space from the
+ * second line.
+ *
+ * For example, if @header is "<7>ata1.00: " and the formatted message
+ * is "<6>line0\nline1\n<4>line2\nline3\n", the following gets written to
+ * the console.
+ *
+ * <6>ata1.00: line0
+ * <6>ata1.00 line1
+ * <4>ata1.00 line2
+ * <4>ata1.00 line3
+ */
+asmlinkage int printk_header(const char *header, const char *fmt, ...)
+{
+ va_list args;
+ int r;
+
+ va_start(args, fmt);
+ r = vprintk_header(header, fmt, args);
+ va_end(args);
+
+ return r;
+}
+EXPORT_SYMBOL(printk_header);
static int is_loglevel(const char *p)
{
return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
}
-asmlinkage int vprintk(const char *fmt, va_list args)
+/**
+ * vprintk_header - a variant of printk_header() which takes va_list argument
+ * @header: header string
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to printk_header() except that it takes
+ * va_list @args instead of variable argument list.
+ */
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
{
/* cpu currently holding logbuf_lock */
static volatile unsigned int printk_cpu = UINT_MAX;
@@ -632,7 +689,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
int last_lv = default_message_loglevel;
unsigned long flags;
- int printed_len = 0;
+ const char *header_colon = NULL;
+ int printed_len = 0, printed_header = 0;
int this_cpu;
const char *p;
@@ -670,6 +728,20 @@ asmlinkage int vprintk(const char *fmt, va_list args)
strcpy(printk_buf, printk_recursion_bug_msg);
printed_len = sizeof(printk_recursion_bug_msg);
}
+
+ /* Parse header log level */
+ if (header) {
+ size_t len = strlen(header);
+
+ if (is_loglevel(header)) {
+ last_lv = header[1] - '0';
+ header += 3;
+ }
+
+ if (len >= 2 && !strcmp(header + len - 2, ": "))
+ header_colon = header + len - 2;
+ }
+
/* Emit the output into the temporary buffer */
printed_len += vsnprintf(printk_buf + printed_len,
PRINTK_BUF_LEN - printed_len, fmt, args);
@@ -718,6 +790,20 @@ asmlinkage int vprintk(const char *fmt, va_list args)
printed_len += tlen;
}
+ if (header) {
+ const char *h = header;
+
+ while (*h) {
+ if (!printed_header || h != header_colon)
+ emit_log_char(*h);
+ else
+ emit_log_char(' ');
+ h++;
+ printed_len++;
+ }
+ printed_header = 1;
+ }
+
last_lv = lv;
log_level_unknown = 0;
if (!*p)
@@ -769,8 +855,7 @@ out_restore_irqs:
preempt_enable();
return printed_len;
}
-EXPORT_SYMBOL(printk);
-EXPORT_SYMBOL(vprintk);
+EXPORT_SYMBOL(vprintk_header);
#else
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread* [PATCH 2/5] printk: implement [v]printk_header()
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Implement [v]printk_header() which takes @header argument and
automatically prints header in front of or indents multiline messages.
For example, if @header is "<7>ata1.00: " and the formatted message is
"<6>line0\nline1\n", the following gets written to the console.
<6>ata1.00: line0
<6>ata1.00 line1
As seen above if header ends with ':' followed by any number of
spaces, the colon is replaced with space from the second line. This
helps to distinguish where a multiline message begins when messages of
similar pattern repeats, for example...
ata8.00: cmd 60/80:20:e1:71:02/00:00:00:00:00/40 tag 4 ncq 65536 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
ata8.00: cmd 60/0e:28:d0:71:02/00:00:00:00:00/40 tag 5 ncq 7168 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
ata8.00: cmd 60/7f:38:61:72:02/00:00:00:00:00/40 tag 7 ncq 65024 in
ata8.00 res 40/00:34:de:71:02/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
ata8.00 status: { DRDY }
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
include/linux/kernel.h | 12 ++++++
kernel/printk.c | 95 +++++++++++++++++++++++++++++++++++++++++++++---
2 files changed, 102 insertions(+), 5 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 2df44e7..d885208 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -177,6 +177,10 @@ struct pid;
extern struct pid *session_of_pgrp(struct pid *pgrp);
#ifdef CONFIG_PRINTK
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+asmlinkage int printk_header(const char *header, const char * fmt, ...)
+ __attribute__ ((format (printf, 2, 3))) __cold;
asmlinkage int vprintk(const char *fmt, va_list args)
__attribute__ ((format (printf, 1, 0)));
asmlinkage int printk(const char * fmt, ...)
@@ -192,6 +196,14 @@ extern int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
unsigned int interval_msec);
#else
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vprintk_header(const char *header, const char *s, va_list args)
+{ return 0; }
+static inline int printk_header(const char *header, const char *s, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int __cold printk_header(const char *header, const char *s, ...)
+{ return 0; }
static inline int vprintk(const char *s, va_list args)
__attribute__ ((format (printf, 1, 0)));
static inline int vprintk(const char *s, va_list args) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 2317ec8..2283a75 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -608,18 +608,75 @@ asmlinkage int printk(const char *fmt, ...)
int r;
va_start(args, fmt);
- r = vprintk(fmt, args);
+ r = vprintk_header(NULL, fmt, args);
va_end(args);
return r;
}
+EXPORT_SYMBOL(printk);
+
+asmlinkage int vprintk(const char *fmt, va_list args)
+{
+ return vprintk_header(NULL, fmt, args);
+}
+EXPORT_SYMBOL(vprintk);
+
+/**
+ * printk_header - print a kernel message with header
+ * @header: header string
+ * @fmt: format string
+ *
+ * This is printk() with a twist. @header points to string which will
+ * be used as message header. If @header is NULL, this function is
+ * identical to printk().
+ *
+ * @header may contain loglevel in front of it. Each new line
+ * including the first one in the message formatted from @fmt can also
+ * have loglevel. When both exist, the latter is used. In multiline
+ * messages, log level is inherited from the previous line if not
+ * explicitly specified.
+ *
+ * @header is printed when a new line starts. If @header ends with
+ * ':' followed by spaces, the colon is replaced with space from the
+ * second line.
+ *
+ * For example, if @header is "<7>ata1.00: " and the formatted message
+ * is "<6>line0\nline1\n<4>line2\nline3\n", the following gets written to
+ * the console.
+ *
+ * <6>ata1.00: line0
+ * <6>ata1.00 line1
+ * <4>ata1.00 line2
+ * <4>ata1.00 line3
+ */
+asmlinkage int printk_header(const char *header, const char *fmt, ...)
+{
+ va_list args;
+ int r;
+
+ va_start(args, fmt);
+ r = vprintk_header(header, fmt, args);
+ va_end(args);
+
+ return r;
+}
+EXPORT_SYMBOL(printk_header);
static int is_loglevel(const char *p)
{
return p[0] == '<' && p[1] >= '0' && p[1] <= '7' && p[2] == '>';
}
-asmlinkage int vprintk(const char *fmt, va_list args)
+/**
+ * vprintk_header - a variant of printk_header() which takes va_list argument
+ * @header: header string
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to printk_header() except that it takes
+ * va_list @args instead of variable argument list.
+ */
+asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
{
/* cpu currently holding logbuf_lock */
static volatile unsigned int printk_cpu = UINT_MAX;
@@ -632,7 +689,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
int last_lv = default_message_loglevel;
unsigned long flags;
- int printed_len = 0;
+ const char *header_colon = NULL;
+ int printed_len = 0, printed_header = 0;
int this_cpu;
const char *p;
@@ -670,6 +728,20 @@ asmlinkage int vprintk(const char *fmt, va_list args)
strcpy(printk_buf, printk_recursion_bug_msg);
printed_len = sizeof(printk_recursion_bug_msg);
}
+
+ /* Parse header log level */
+ if (header) {
+ size_t len = strlen(header);
+
+ if (is_loglevel(header)) {
+ last_lv = header[1] - '0';
+ header += 3;
+ }
+
+ if (len >= 2 && !strcmp(header + len - 2, ": "))
+ header_colon = header + len - 2;
+ }
+
/* Emit the output into the temporary buffer */
printed_len += vsnprintf(printk_buf + printed_len,
PRINTK_BUF_LEN - printed_len, fmt, args);
@@ -718,6 +790,20 @@ asmlinkage int vprintk(const char *fmt, va_list args)
printed_len += tlen;
}
+ if (header) {
+ const char *h = header;
+
+ while (*h) {
+ if (!printed_header || h != header_colon)
+ emit_log_char(*h);
+ else
+ emit_log_char(' ');
+ h++;
+ printed_len++;
+ }
+ printed_header = 1;
+ }
+
last_lv = lv;
log_level_unknown = 0;
if (!*p)
@@ -769,8 +855,7 @@ out_restore_irqs:
preempt_enable();
return printed_len;
}
-EXPORT_SYMBOL(printk);
-EXPORT_SYMBOL(vprintk);
+EXPORT_SYMBOL(vprintk_header);
#else
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread
* [PATCH 3/5] printk: implement merging printk
2008-02-13 9:09 ` Tejun Heo
@ 2008-02-13 9:09 ` Tejun Heo
-1 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
There often are times printk messages need to be assembled piece by
piece and it's usually done using one of the following methods.
* Calling printk() on partial message segments. This used to be quite
common but has a problem - the message can break up if someone else
prints something in the middle.
* Prepping a temp buffer and build message piece-by-piece using
snprintf(). This is the most generic solution but corner case
handling can be tedious and on overflow messages can be lost and
such overflows would go unnoticed if overflow detection isn't
properly done.
* Collect all the partial data and perform printk() once with all the
parameters. This is often combined with the second. This usually
works but printing messages can become non-trivial programming
problem and can get quite tedious if the message format varies
depending on data.
None of the above is quite satisfactory. This patch implement merging
printk - mprintk to deal with this problem. It's basically a helper
to construct message piece-by-piece into the specified buffer. The
caller still has to care about buffer size and how the buffer is
allocated but mprintk makes it easier.
* DEFINE_MPRINTK() macro makes it easy to define a mprintk instance
with on-stack buffer. Malloc'd buffer can also be used.
* Message is never lost. On buffer overflow, all queued and to be
queued messages are printed followed by warning message and stack
dump. The warning message and stack dump are printed only once per
mprintk instance. The caller also doesn't have to handle buffer
malloc failure. If buffer is initialized to NULL, mprintk simply
bypasses the messages to printk().
* Has good support for multiline messages. A mprintk instance can
have header associated with it and the header can have log level.
Header log level is used if a partial message doesn't specify log
level explicitly. When log level is specified explicitly in a
partial message, the log level is applied to the partial message
only.
A simple example.
DEFINE_MPRINTK(mp, 2 * 80);
mprintk_set_header(&mp, KERN_DEBUG "ata%u.%2u: ", 1, 0);
mprintk_push(&mp, "ATA %d", 7);
mprintk_push(&mp, ", %u sectors\n", 1024);
mprintk(&mp, "everything seems dandy\n");
Which will be printed like the following as a single message.
<7>ata1.00: ATA 7, 1024 sectors
<7>ata1.00 everything seems dandy
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
include/linux/kernel.h | 73 ++++++++++++
kernel/printk.c | 300 +++++++++++++++++++++++++++++++++++++++++++++++-
2 files changed, 370 insertions(+), 3 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index d885208..a9cbda8 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -177,6 +177,27 @@ struct pid;
extern struct pid *session_of_pgrp(struct pid *pgrp);
#ifdef CONFIG_PRINTK
+struct mprintk {
+ char *buf;
+ char *body;
+ char *cur;
+ char *end;
+ unsigned int flags;
+};
+
+#define MPRINTK_INITIALIZER(_buf, _size) \
+ { \
+ .buf = _buf, \
+ .body = _buf, \
+ .cur = _buf, \
+ .end = _buf + _size, \
+ .flags = 0 \
+ }
+
+#define DEFINE_MPRINTK(name, size) \
+ char __##name##_buf[size]; \
+ struct mprintk name = MPRINTK_INITIALIZER(__##name##_buf, size)
+
asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
__attribute__ ((format (printf, 2, 0)));
asmlinkage int printk_header(const char *header, const char * fmt, ...)
@@ -185,6 +206,26 @@ asmlinkage int vprintk(const char *fmt, va_list args)
__attribute__ ((format (printf, 1, 0)));
asmlinkage int printk(const char * fmt, ...)
__attribute__ ((format (printf, 1, 2))) __cold;
+
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size)
+{
+ *mp = (struct mprintk)MPRINTK_INITIALIZER(buf, size);
+}
+extern void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp);
+extern void mprintk_free(struct mprintk *mp);
+extern int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int mprintk(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+extern int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+extern int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+
extern int log_buf_get_len(void);
extern int log_buf_read(int idx);
extern int log_buf_copy(char *dest, int idx, int len);
@@ -196,6 +237,11 @@ extern int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
unsigned int interval_msec);
#else
+struct mprintk { };
+#define MPRINTK_INITIALIZER(_buf, _size) { }
+#define DEFINE_MPRINTK(name, size) \
+ struct mprintk name = __MPRINTK_INITIALIZER(NULL, size)
+
static inline int vprintk_header(const char *header, const char *s, va_list args)
__attribute__ ((format (printf, 2, 0)));
static inline int vprintk_header(const char *header, const char *s, va_list args)
@@ -210,6 +256,33 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
static inline int printk(const char *s, ...)
__attribute__ ((format (printf, 1, 2)));
static inline int __cold printk(const char *s, ...) { return 0; }
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size) { }
+static inline void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp) { }
+static inline void mprintk_free(struct mprintk *mp) { }
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
static inline int log_buf_get_len(void) { return 0; }
static inline int log_buf_read(int idx) { return 0; }
static inline int log_buf_copy(char *dest, int idx, int len) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 2283a75..0b552b9 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -32,6 +32,7 @@
#include <linux/security.h>
#include <linux/bootmem.h>
#include <linux/syscalls.h>
+#include <linux/ctype.h>
#include <asm/uaccess.h>
@@ -52,6 +53,12 @@ void __attribute__((weak)) early_printk(const char *fmt, ...)
#define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */
#define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */
+/* mprintk flags */
+#define MPRINTK_BUF_ALLOC (1 << 0)
+#define MPRINTK_HAS_HEADER_LOGLV (1 << 1)
+#define MPRINTK_OVERFLOWED (1 << 2)
+#define MPRINTK_LOGLV_OVERRIDDEN (1 << 3)
+
DECLARE_WAIT_QUEUE_HEAD(log_wait);
int console_printk[4] = {
@@ -731,15 +738,18 @@ asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
/* Parse header log level */
if (header) {
- size_t len = strlen(header);
+ const char *p;
if (is_loglevel(header)) {
last_lv = header[1] - '0';
header += 3;
}
- if (len >= 2 && !strcmp(header + len - 2, ": "))
- header_colon = header + len - 2;
+ p = header + strlen(header) - 1;
+ while (p > header && isspace(*p))
+ p--;
+ if (p > header && *p == ':')
+ header_colon = p;
}
/* Emit the output into the temporary buffer */
@@ -857,6 +867,290 @@ out_restore_irqs:
}
EXPORT_SYMBOL(vprintk_header);
+static bool mp_no_buffer(struct mprintk *mp)
+{
+ return unlikely(!mp->buf || mp->buf == mp->end);
+}
+
+static char *mp_header(struct mprintk *mp)
+{
+ if (mp->body != mp->buf)
+ return mp->buf;
+ return NULL;
+}
+
+static void mp_flush(struct mprintk *mp)
+{
+ printk_header(mp_header(mp), "%s", mp->body);
+ mp->cur = mp->body;
+ mp->cur[0] = '\0';
+ mp->flags &= ~MPRINTK_LOGLV_OVERRIDDEN;
+}
+
+/**
+ * mprintk_init_alloc - allocate buffer and initialize mprintk instance
+ * @mp: mprintk instance to initialize
+ * @gfp: allocation flags
+ *
+ * This function initializes @mp such that buffer is automatically
+ * allocated with @gfp flags.
+ */
+void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp)
+{
+ /*
+ * This can be implemented as dynamically growing buffer but
+ * printk truncates messages at PRINTK_BUF_LEN. Allocating
+ * PRINTK_BUF_LEN bytes upfront is good enough for now.
+ */
+ mprintk_init(mp, kmalloc(PRINTK_BUF_LEN, gfp), PRINTK_BUF_LEN);
+ mp->flags |= MPRINTK_BUF_ALLOC;
+}
+EXPORT_SYMBOL(mprintk_init_alloc);
+
+/**
+ * mprintk_free - free mprintk buffer
+ * @mp: mprintk instance to free buffer for
+ *
+ * If @mp was initialized using mprintk_init_alloc(), free mp->buf;
+ * otherwise, noop.
+ */
+void mprintk_free(struct mprintk *mp)
+{
+ if (mp->flags & MPRINTK_BUF_ALLOC) {
+ kfree(mp->buf);
+ mp->buf = NULL;
+ }
+}
+EXPORT_SYMBOL(mprintk_free);
+
+/**
+ * vmprintk - format and add message chunk to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{
+ char *start = mp->cur;
+ size_t size = mp->end - start;
+ int new_line = mp->cur == mp->body || mp->cur[-1] == '\n';
+ int printed = 0;
+ int ret;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ /*
+ * Prepend header log level if the previous chunk has
+ * overridden the log level (implies header log level exists)
+ * && the current chunk starts a new line and doesn't have
+ * explicit log level.
+ */
+ if ((mp->flags & MPRINTK_LOGLV_OVERRIDDEN) && new_line) {
+ char tbuf[4];
+ va_list args_copy;
+
+ va_copy(args_copy, args);
+ vsnprintf(tbuf, sizeof(tbuf), fmt, args_copy);
+ va_end(args_copy);
+
+ if (!is_loglevel(tbuf)) {
+ ret = snprintf(start, size, "<%c>", mp_header(mp)[1]);
+ printed += ret;
+ if (ret >= size)
+ goto overflow;
+ start += ret;
+ size -= ret;
+ mp->flags &= ~MPRINTK_LOGLV_OVERRIDDEN;
+ }
+ }
+
+ ret = vsnprintf(start, size, fmt, args);
+ printed += ret;
+ if (ret >= size)
+ goto overflow;
+
+ if ((mp->flags & MPRINTK_HAS_HEADER_LOGLV) &&
+ new_line && is_loglevel(start))
+ mp->flags |= MPRINTK_LOGLV_OVERRIDDEN;
+
+ mp->cur += printed;
+
+ return printed;
+
+ overflow:
+ mp->cur[0] = '\0';
+ mp_flush(mp);
+ printed = vprintk_header(mp_header(mp), fmt, args);
+
+ if (!(mp->flags & MPRINTK_OVERFLOWED)) {
+ printk("\n" KERN_ERR
+ "mprintk buffer overflow, please file a bug report\n");
+ dump_stack();
+ mp->flags |= MPRINTK_OVERFLOWED;
+ }
+
+ return printed;
+}
+EXPORT_SYMBOL(vmprintk);
+
+/**
+ * vmprintk_set_header - format and set header to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_set_header() except that it
+ * takes va_list @args intead of argument list.
+ */
+int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{
+ const char *reason;
+ int ret;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ if (mp_header(mp) || mp->cur != mp->body) {
+ reason = "dirty mprintk instance";
+ goto err;
+ }
+ if (mp->body + 1 == mp->end) {
+ reason = "buffer too short (1 byte)";
+ goto err;
+ }
+
+ /* reserve one byte for separator */
+ mp->end--;
+ ret = vmprintk(mp, fmt, args);
+ mp->end++;
+
+ if (mp->cur != mp->body) {
+ mp->body = ++mp->cur;
+ if (is_loglevel(mp_header(mp)))
+ mp->flags |= MPRINTK_HAS_HEADER_LOGLV;
+ }
+
+ return ret;
+
+ err:
+ printk(KERN_WARNING "vmprintk_set_header() failed: %s\n", reason);
+ dump_stack();
+ return 0;
+}
+EXPORT_SYMBOL(vmprintk_set_header);
+
+/**
+ * vmprintk_flush - format and add message chunk to mprintk instance and flush
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_flush() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+{
+ int ret = 0;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ if (fmt)
+ ret = vmprintk(mp, fmt, args);
+ mp_flush(mp);
+
+ return ret;
+}
+EXPORT_SYMBOL(vmprintk_flush);
+
+/**
+ * mprintk - format and add message chunk to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * This function formats @fmt and the following list of arguments and
+ * append the result to @mp. If @mp has header with log level and
+ * @fmt is multiline, this function takes care of restoring header log
+ * level if the previous message contained log level overrided and
+ * this message doesn't.
+ *
+ * If the buffer pointed to by @mp is too short to contain the added
+ * message, @mp is flushed, the message to add is printed directly and
+ * warning message with stack dump is printed. If buffer is NULL, the
+ * formatted message is printed directly. Message is never lost. The
+ * warning message and the stack dump are printed only once for each
+ * @mp instance.
+ *
+ * For example, if @mp header is set to "<7>ata1.00: " and the first
+ * message is "line0\n", second "<4>line1\nline2\n" and the third
+ * "line3\n", the following is the end result.
+ *
+ * <7>ata1.00: line0
+ * <4>ata1.00: line1 (different log level, header is printed again)
+ * <4> line2
+ * <7> line3
+ */
+int mprintk(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk);
+
+/**
+ * mprintk_set_header - set header of merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * Set header of @mp to the string formatted according to @fmt and
+ * arguments.
+ */
+int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk_set_header(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk_set_header);
+
+/**
+ * mprintk_flush - format and add a message to mprintk instance and flush it
+ * @mp: mprintk instance to use
+ * @fmt: format string (can be NULL)
+ *
+ * Add message formatted according to @fmt and arguments to @mp and
+ * flush it. If @fmt is NULL, only the latter operation occurs. NULL
+ * @fmt is allowed to avoid zero length formatting string warning from
+ * compiler.
+ */
+int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk_flush(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk_flush);
+
#else
asmlinkage long sys_syslog(int type, char __user *buf, int len)
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread* [PATCH 3/5] printk: implement merging printk
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
There often are times printk messages need to be assembled piece by
piece and it's usually done using one of the following methods.
* Calling printk() on partial message segments. This used to be quite
common but has a problem - the message can break up if someone else
prints something in the middle.
* Prepping a temp buffer and build message piece-by-piece using
snprintf(). This is the most generic solution but corner case
handling can be tedious and on overflow messages can be lost and
such overflows would go unnoticed if overflow detection isn't
properly done.
* Collect all the partial data and perform printk() once with all the
parameters. This is often combined with the second. This usually
works but printing messages can become non-trivial programming
problem and can get quite tedious if the message format varies
depending on data.
None of the above is quite satisfactory. This patch implement merging
printk - mprintk to deal with this problem. It's basically a helper
to construct message piece-by-piece into the specified buffer. The
caller still has to care about buffer size and how the buffer is
allocated but mprintk makes it easier.
* DEFINE_MPRINTK() macro makes it easy to define a mprintk instance
with on-stack buffer. Malloc'd buffer can also be used.
* Message is never lost. On buffer overflow, all queued and to be
queued messages are printed followed by warning message and stack
dump. The warning message and stack dump are printed only once per
mprintk instance. The caller also doesn't have to handle buffer
malloc failure. If buffer is initialized to NULL, mprintk simply
bypasses the messages to printk().
* Has good support for multiline messages. A mprintk instance can
have header associated with it and the header can have log level.
Header log level is used if a partial message doesn't specify log
level explicitly. When log level is specified explicitly in a
partial message, the log level is applied to the partial message
only.
A simple example.
DEFINE_MPRINTK(mp, 2 * 80);
mprintk_set_header(&mp, KERN_DEBUG "ata%u.%2u: ", 1, 0);
mprintk_push(&mp, "ATA %d", 7);
mprintk_push(&mp, ", %u sectors\n", 1024);
mprintk(&mp, "everything seems dandy\n");
Which will be printed like the following as a single message.
<7>ata1.00: ATA 7, 1024 sectors
<7>ata1.00 everything seems dandy
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
include/linux/kernel.h | 73 ++++++++++++
kernel/printk.c | 300 +++++++++++++++++++++++++++++++++++++++++++++++-
2 files changed, 370 insertions(+), 3 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index d885208..a9cbda8 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -177,6 +177,27 @@ struct pid;
extern struct pid *session_of_pgrp(struct pid *pgrp);
#ifdef CONFIG_PRINTK
+struct mprintk {
+ char *buf;
+ char *body;
+ char *cur;
+ char *end;
+ unsigned int flags;
+};
+
+#define MPRINTK_INITIALIZER(_buf, _size) \
+ { \
+ .buf = _buf, \
+ .body = _buf, \
+ .cur = _buf, \
+ .end = _buf + _size, \
+ .flags = 0 \
+ }
+
+#define DEFINE_MPRINTK(name, size) \
+ char __##name##_buf[size]; \
+ struct mprintk name = MPRINTK_INITIALIZER(__##name##_buf, size)
+
asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
__attribute__ ((format (printf, 2, 0)));
asmlinkage int printk_header(const char *header, const char * fmt, ...)
@@ -185,6 +206,26 @@ asmlinkage int vprintk(const char *fmt, va_list args)
__attribute__ ((format (printf, 1, 0)));
asmlinkage int printk(const char * fmt, ...)
__attribute__ ((format (printf, 1, 2))) __cold;
+
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size)
+{
+ *mp = (struct mprintk)MPRINTK_INITIALIZER(buf, size);
+}
+extern void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp);
+extern void mprintk_free(struct mprintk *mp);
+extern int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+extern int mprintk(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+extern int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+extern int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+
extern int log_buf_get_len(void);
extern int log_buf_read(int idx);
extern int log_buf_copy(char *dest, int idx, int len);
@@ -196,6 +237,11 @@ extern int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
unsigned int interval_msec);
#else
+struct mprintk { };
+#define MPRINTK_INITIALIZER(_buf, _size) { }
+#define DEFINE_MPRINTK(name, size) \
+ struct mprintk name = __MPRINTK_INITIALIZER(NULL, size)
+
static inline int vprintk_header(const char *header, const char *s, va_list args)
__attribute__ ((format (printf, 2, 0)));
static inline int vprintk_header(const char *header, const char *s, va_list args)
@@ -210,6 +256,33 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
static inline int printk(const char *s, ...)
__attribute__ ((format (printf, 1, 2)));
static inline int __cold printk(const char *s, ...) { return 0; }
+static inline void mprintk_init(struct mprintk *mp, char *buf, size_t size) { }
+static inline void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp) { }
+static inline void mprintk_free(struct mprintk *mp) { }
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+ __attribute__ ((format (printf, 2, 0)));
+static inline int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+{ return 0; }
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
+static inline int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+static inline int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+{ return 0; }
static inline int log_buf_get_len(void) { return 0; }
static inline int log_buf_read(int idx) { return 0; }
static inline int log_buf_copy(char *dest, int idx, int len) { return 0; }
diff --git a/kernel/printk.c b/kernel/printk.c
index 2283a75..0b552b9 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -32,6 +32,7 @@
#include <linux/security.h>
#include <linux/bootmem.h>
#include <linux/syscalls.h>
+#include <linux/ctype.h>
#include <asm/uaccess.h>
@@ -52,6 +53,12 @@ void __attribute__((weak)) early_printk(const char *fmt, ...)
#define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */
#define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */
+/* mprintk flags */
+#define MPRINTK_BUF_ALLOC (1 << 0)
+#define MPRINTK_HAS_HEADER_LOGLV (1 << 1)
+#define MPRINTK_OVERFLOWED (1 << 2)
+#define MPRINTK_LOGLV_OVERRIDDEN (1 << 3)
+
DECLARE_WAIT_QUEUE_HEAD(log_wait);
int console_printk[4] = {
@@ -731,15 +738,18 @@ asmlinkage int vprintk_header(const char *header, const char *fmt, va_list args)
/* Parse header log level */
if (header) {
- size_t len = strlen(header);
+ const char *p;
if (is_loglevel(header)) {
last_lv = header[1] - '0';
header += 3;
}
- if (len >= 2 && !strcmp(header + len - 2, ": "))
- header_colon = header + len - 2;
+ p = header + strlen(header) - 1;
+ while (p > header && isspace(*p))
+ p--;
+ if (p > header && *p == ':')
+ header_colon = p;
}
/* Emit the output into the temporary buffer */
@@ -857,6 +867,290 @@ out_restore_irqs:
}
EXPORT_SYMBOL(vprintk_header);
+static bool mp_no_buffer(struct mprintk *mp)
+{
+ return unlikely(!mp->buf || mp->buf == mp->end);
+}
+
+static char *mp_header(struct mprintk *mp)
+{
+ if (mp->body != mp->buf)
+ return mp->buf;
+ return NULL;
+}
+
+static void mp_flush(struct mprintk *mp)
+{
+ printk_header(mp_header(mp), "%s", mp->body);
+ mp->cur = mp->body;
+ mp->cur[0] = '\0';
+ mp->flags &= ~MPRINTK_LOGLV_OVERRIDDEN;
+}
+
+/**
+ * mprintk_init_alloc - allocate buffer and initialize mprintk instance
+ * @mp: mprintk instance to initialize
+ * @gfp: allocation flags
+ *
+ * This function initializes @mp such that buffer is automatically
+ * allocated with @gfp flags.
+ */
+void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp)
+{
+ /*
+ * This can be implemented as dynamically growing buffer but
+ * printk truncates messages at PRINTK_BUF_LEN. Allocating
+ * PRINTK_BUF_LEN bytes upfront is good enough for now.
+ */
+ mprintk_init(mp, kmalloc(PRINTK_BUF_LEN, gfp), PRINTK_BUF_LEN);
+ mp->flags |= MPRINTK_BUF_ALLOC;
+}
+EXPORT_SYMBOL(mprintk_init_alloc);
+
+/**
+ * mprintk_free - free mprintk buffer
+ * @mp: mprintk instance to free buffer for
+ *
+ * If @mp was initialized using mprintk_init_alloc(), free mp->buf;
+ * otherwise, noop.
+ */
+void mprintk_free(struct mprintk *mp)
+{
+ if (mp->flags & MPRINTK_BUF_ALLOC) {
+ kfree(mp->buf);
+ mp->buf = NULL;
+ }
+}
+EXPORT_SYMBOL(mprintk_free);
+
+/**
+ * vmprintk - format and add message chunk to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+{
+ char *start = mp->cur;
+ size_t size = mp->end - start;
+ int new_line = mp->cur == mp->body || mp->cur[-1] == '\n';
+ int printed = 0;
+ int ret;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ /*
+ * Prepend header log level if the previous chunk has
+ * overridden the log level (implies header log level exists)
+ * && the current chunk starts a new line and doesn't have
+ * explicit log level.
+ */
+ if ((mp->flags & MPRINTK_LOGLV_OVERRIDDEN) && new_line) {
+ char tbuf[4];
+ va_list args_copy;
+
+ va_copy(args_copy, args);
+ vsnprintf(tbuf, sizeof(tbuf), fmt, args_copy);
+ va_end(args_copy);
+
+ if (!is_loglevel(tbuf)) {
+ ret = snprintf(start, size, "<%c>", mp_header(mp)[1]);
+ printed += ret;
+ if (ret >= size)
+ goto overflow;
+ start += ret;
+ size -= ret;
+ mp->flags &= ~MPRINTK_LOGLV_OVERRIDDEN;
+ }
+ }
+
+ ret = vsnprintf(start, size, fmt, args);
+ printed += ret;
+ if (ret >= size)
+ goto overflow;
+
+ if ((mp->flags & MPRINTK_HAS_HEADER_LOGLV) &&
+ new_line && is_loglevel(start))
+ mp->flags |= MPRINTK_LOGLV_OVERRIDDEN;
+
+ mp->cur += printed;
+
+ return printed;
+
+ overflow:
+ mp->cur[0] = '\0';
+ mp_flush(mp);
+ printed = vprintk_header(mp_header(mp), fmt, args);
+
+ if (!(mp->flags & MPRINTK_OVERFLOWED)) {
+ printk("\n" KERN_ERR
+ "mprintk buffer overflow, please file a bug report\n");
+ dump_stack();
+ mp->flags |= MPRINTK_OVERFLOWED;
+ }
+
+ return printed;
+}
+EXPORT_SYMBOL(vmprintk);
+
+/**
+ * vmprintk_set_header - format and set header to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_set_header() except that it
+ * takes va_list @args intead of argument list.
+ */
+int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+{
+ const char *reason;
+ int ret;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ if (mp_header(mp) || mp->cur != mp->body) {
+ reason = "dirty mprintk instance";
+ goto err;
+ }
+ if (mp->body + 1 == mp->end) {
+ reason = "buffer too short (1 byte)";
+ goto err;
+ }
+
+ /* reserve one byte for separator */
+ mp->end--;
+ ret = vmprintk(mp, fmt, args);
+ mp->end++;
+
+ if (mp->cur != mp->body) {
+ mp->body = ++mp->cur;
+ if (is_loglevel(mp_header(mp)))
+ mp->flags |= MPRINTK_HAS_HEADER_LOGLV;
+ }
+
+ return ret;
+
+ err:
+ printk(KERN_WARNING "vmprintk_set_header() failed: %s\n", reason);
+ dump_stack();
+ return 0;
+}
+EXPORT_SYMBOL(vmprintk_set_header);
+
+/**
+ * vmprintk_flush - format and add message chunk to mprintk instance and flush
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ * @args: va_list to format @fmt
+ *
+ * This function is identical to mprintk_flush() except that it takes
+ * va_list @args intead of argument list.
+ */
+int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+{
+ int ret = 0;
+
+ if (mp_no_buffer(mp))
+ return vprintk(fmt, args);
+
+ if (fmt)
+ ret = vmprintk(mp, fmt, args);
+ mp_flush(mp);
+
+ return ret;
+}
+EXPORT_SYMBOL(vmprintk_flush);
+
+/**
+ * mprintk - format and add message chunk to mprintk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * This function formats @fmt and the following list of arguments and
+ * append the result to @mp. If @mp has header with log level and
+ * @fmt is multiline, this function takes care of restoring header log
+ * level if the previous message contained log level overrided and
+ * this message doesn't.
+ *
+ * If the buffer pointed to by @mp is too short to contain the added
+ * message, @mp is flushed, the message to add is printed directly and
+ * warning message with stack dump is printed. If buffer is NULL, the
+ * formatted message is printed directly. Message is never lost. The
+ * warning message and the stack dump are printed only once for each
+ * @mp instance.
+ *
+ * For example, if @mp header is set to "<7>ata1.00: " and the first
+ * message is "line0\n", second "<4>line1\nline2\n" and the third
+ * "line3\n", the following is the end result.
+ *
+ * <7>ata1.00: line0
+ * <4>ata1.00: line1 (different log level, header is printed again)
+ * <4> line2
+ * <7> line3
+ */
+int mprintk(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk);
+
+/**
+ * mprintk_set_header - set header of merging printk instance
+ * @mp: mprintk instance to use
+ * @fmt: format string
+ *
+ * Set header of @mp to the string formatted according to @fmt and
+ * arguments.
+ */
+int mprintk_set_header(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk_set_header(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk_set_header);
+
+/**
+ * mprintk_flush - format and add a message to mprintk instance and flush it
+ * @mp: mprintk instance to use
+ * @fmt: format string (can be NULL)
+ *
+ * Add message formatted according to @fmt and arguments to @mp and
+ * flush it. If @fmt is NULL, only the latter operation occurs. NULL
+ * @fmt is allowed to avoid zero length formatting string warning from
+ * compiler.
+ */
+int mprintk_flush(struct mprintk *mp, const char *fmt, ...)
+{
+ va_list args;
+ int ret;
+
+ va_start(args, fmt);
+ ret = vmprintk_flush(mp, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+EXPORT_SYMBOL(mprintk_flush);
+
#else
asmlinkage long sys_syslog(int type, char __user *buf, int len)
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread
* [PATCH 4/5] printk: add Documentation/printk.txt
2008-02-13 9:09 ` Tejun Heo
@ 2008-02-13 9:09 ` Tejun Heo
-1 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Add Documentation/printk.txt which explains printk, mprintk and their
friends.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
Documentation/00-INDEX | 2 +
Documentation/printk.txt | 724 ++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 726 insertions(+), 0 deletions(-)
create mode 100644 Documentation/printk.txt
diff --git a/Documentation/00-INDEX b/Documentation/00-INDEX
index 8d55670..e4c2862 100644
--- a/Documentation/00-INDEX
+++ b/Documentation/00-INDEX
@@ -313,6 +313,8 @@ powerpc/
- directory with info on using Linux with the PowerPC.
preempt-locking.txt
- info on locking under a preemptive kernel.
+printk.txt
+ - info on printk and mprintk.
prio_tree.txt
- info on radix-priority-search-tree use for indexing vmas.
ramdisk.txt
diff --git a/Documentation/printk.txt b/Documentation/printk.txt
new file mode 100644
index 0000000..e510a81
--- /dev/null
+++ b/Documentation/printk.txt
@@ -0,0 +1,724 @@
+printk and mprintk
+==================
+Tejun Heo <teheo@suse.de>, January 18 2008
+
+This document describes printk and mprintk.
+
+TABLE OF CONTENTS
+
+[1] printk
+ [1-1] What is printk and how does it operate?
+ [1-2] Log level
+ [1-2-1] What is log level and how do I use it?
+ [1-2-2] How the log level is treated by kernel and logging tools.
+ [1-3] Timestamps
+ [1-4] Multiline messages and printk_header
+ [1-5] printk's friends
+
+[2] mprintk - the merging printk
+ [2-1] What is mprintk?
+ [2-2] How do I use mprintk?
+ [2-2-1] Initialization
+ [2-2-2] Assembling and printing
+ [2-2-3] Error handling
+ [2-3] Some guidelines
+ [2-4] mprintk's friends
+
+[3] How libata uses printk_header and mprintk
+
+
+[1] printk
+
+[1-1] What is printk and how does it operate?
+
+ int printk(const char *fmt, ...)
+
+printk is the equivalent of print for perl scripts, echo for shell
+scripts and much more closely printf(3) for userland C programs. It
+takes the same arguments as printf(3), formats the string the same way
+and spits the result out. printk is the kernel's primary way to emit
+human-readable messages.
+
+printf(3) prints formatted messages to the default destination -
+standard output. printk also has default destination or rather
+destinations. Messages printed out via printk are stored in a message
+buffer which can be retrieved either by syslog(2) system call or
+reading /proc/kmsg and then printed to one or more registered
+consoles.
+
+The ring buffer is the asynchronous way to access the messages.
+dmesg(1) dumps its content, klogd reads the messages and logs the
+result via syslog facility. The ring buffer is of fixed size which
+can be configured by the 'log_buf_len' kernel parameter. If a new
+message is printed and the ring buffer is full, it wraps around and
+writes over the old messages.
+
+On the other hand, the consoles behave mostly synchronously{1}. The
+most common console device is the virtual console (your graphics
+adapter and monitor). While the machine is booting, if you disable or
+escape from the pretty graphical boot screen, you'll see lots of
+kernel messages scrolling by before the userland starts to run. All
+those messages are from printk and your monitor is serving as a
+console device. Other examples of console devices include serial
+console{2} and netconsole{3}.
+
+The synchronous operation of console devices can be very expensive
+depending on which console devices are attached. For example,
+transferring 160 characters over 9600 baud rate serial line consumes
+around 18.75 milliseconds and the CPU won't be doing anything else
+other than pushing the bytes out.
+
+Accesses to the log buffer are synchronized and messages from separate
+printk invocations never get intermixed; however, there is no
+guarantee that two consecutive calls to printk will show up
+consecutively. printk calls from other threads can be printed
+inbetween.
+
+ Thread A Thread B
+
+ printk("hello "); printk("The answer is ");
+ printk("world!\n"); printk("42\n");
+
+The output can be
+
+ hello The answer is world!
+ 42
+
+or any other combination - 6 of them, so you shouldn't construct
+messages piece-by-piece by calling printk on substrings. You should
+build the complete message first and print it by calling printk once.
+As constructing a message from pieces can be a non-trival task, there
+is a helper mechanism called mprintk. It will be explained later.
+
+
+[1-2] Log level
+
+[1-2-1] What is log level and how do I use it?
+
+Another difference from printf(3) is that printk performs a bit of
+post-processing on the printed messages. Each line printed via printk
+has a log level which is priority or urgency of the message. Eight
+log levels are defined and have the following meanings.
+
+ KERN_EMERG : system is unusable
+ KERN_ALERT : action must be taken immediately
+ KERN_CRIT : critical conditions
+ KERN_ERR : error conditions
+ KERN_WARNING : warning conditions
+ KERN_NOTICE : normal but significant condition
+ KERN_INFO : informational
+ KERN_DEBUG : debug-level message
+
+If you search for the above constants in include/linux/kernel.h,
+you'll see that they are defined as string constants "<N>" where N is
+0 for EMERG and increments for each upto 7 for DEBUG. There's nothing
+magical about it. Lines which start with "<N>" has the priority of N.
+Because C's preprocessor merges string constants, simply putting the
+macro in front of a message suffices.
+
+ printk(KERN_WARNING "I'm a whiny kernel.\n");
+ printk("%sAm I too whiny?\n", KERN_WARNING);
+ printk("<%d>You don't think I'm too whiny, do you?\n", 4);
+
+Will output.
+
+ <4>I'm a whiny kernel.
+ <4>Am I too whiny?
+ <4>You don't think I'm too whiny, do you?
+
+But what happens when you don't specify log level? In such cases,
+printk automatically assigns the default log level which is
+KERN_WARNING by default but can be overridden using sysctl{4}, so
+
+ printk("Please tell me I don't whine too much\n");
+
+is mostly equivalent to
+
+ printk(KERN_WARNING "Please tell me I don't whine too much\n");
+
+Noticed 'mostly'? The output will be different if the message doesn't
+start a new line. Please recall that log level is per-line and thus
+log level string doesn't have any meaning when it's not at the start
+of a line.
+
+ printk(KERN_NOTICE "Why don't you notice me? ");
+ printk(KERN_EMERGE "Do I have to say louder?\n");
+
+The above will result in the following string.
+
+ <5>Why don't you notice me? <0>Do I have to say louder
+
+And printk will treat it as a NOTICE message whose content is
+
+ Why don't you notice me? <0>Do I have to say louder
+
+Putting log level in the middle of string doesn't do anything to the
+log level. It just gets printed verbatim. This is another reason to
+avoid constructing messages piece-by-piece by calling printk multiple
+times. Let's go back to the hello world example and add log levels
+there.
+
+ Thread A Thread B
+
+ printk(KERN_ERR "hello "); printk(KERN_INFO "The answer is ");
+ printk("world!\n"); printk("42\n");
+
+The end result can be
+
+ <3>hello <6>The answer is 42
+ <4>world
+
+The first line is ERR message with weird "<6>" in it and the second
+line is WARNING message where the log level is automatically assigned
+by printk.
+
+Another thing to note about log level handling is that printk
+maintains log level in a multiline message.
+
+ printk(KERN_INFO "whine0\nwhine1\n" KERN_ERR "whine2\nwhine3\n");
+
+Becomes
+
+ <6>whine0
+ <6>whine1
+ <3>whine2
+ <3>whine3
+
+
+[1-2-2] How the log level is treated by kernel and logging tools.
+
+You probably have never noticed the log level markup in the dmesg(1)
+output, /var/log/messages or kernel messages printed on your monitor.
+This is because log level is treated specially. When message buffer
+is accessed via syslog(2) or /proc/kmsg, the log level is printed
+verbatim but the reading program - often klogd(8) or dmesg(1) -
+recognizes the log levels, strips them and routes or treats the
+messages accordingly. You can read the raw messages with the log
+level by stopping klogd(8) and executing "cat /proc/kmsg".
+
+For console devices, printk itself performs similar function. The log
+level is stripped before being submitted to console drivers and
+messages are filtered according to the console log level such that low
+priority messages don't clutter consoles. Console log level can be
+adjusted using either syslog(2) system call or kernel.printk sysctl
+node{4}.
+
+
+[1-3] Timestamps
+
+Another post-processing performed by printk is prepending timestamp.
+When enabled, the kernel's conception of time since boot or resume is
+added between the log level and the actual message. The following is
+excerpt from libata probing messages.
+
+ <6>[ 114.971205] ata8: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
+ <6>[ 114.989200] ata8.00: HPA detected: current 156299375, native 156301488
+ <6>[ 115.007362] ata8.00: ATA-7: WDC WD800JD-00MSA1, 10.01E01, max UDMA/133
+ <6>[ 115.024879] ata8.00: 156299375 sectors, multi 16: LBA48 NCQ (depth 31/32)
+ <6>[ 115.043885] ata8.00: configured for UDMA/133
+
+The number before "." is seconds and after is nanoseconds. It's
+kernel's conception of time and may not match actual wall clock
+depending on power saving setting and other things.
+
+Timestamp is enabled at kernel compile time using CONFIG_PRINTK_TIME
+but it can also be enabled or disabled when booting by specifying
+"printk.time=1" as kernel boot parameter. In addition, by echoing "0"
+or "1" to /sys/module/printk/parameters/printk_time, you can control
+it while the system is running.
+
+klogd(8) automatically prepends timestamps when logging kernel
+messages, so printk timestamp is somewhat redundant; however, printk
+timestamp has the following benefits making it better suited for
+debugging.
+
+* klogd(8) only knows when it read the messages. It can't tell when
+ the message was generated. For example, during boot or resume,
+ userspace is not running and when klogd(8) finally runs it can't
+ tell what happened when and just puts the same timestamp on all the
+ accumulated messages.
+
+* It uses kernel's conception of time and at times this provides
+ better insight into what's going on. For example, if there's a bug
+ in kernel's timer code, kernel's conception of time can be stalled
+ or delayed while gettimeofday(2) still returns valid values.
+
+* Reading messages from the console or running dmesg(1) to dump the
+ message buffer is simpler than having klogd(8) running. Having
+ timestamps available when using simpler methods helps debugging.
+
+There are discussions of automatically stripping and handling
+timestamps from dmesg(1) and klogd(8) to remove the timestamps
+automatically.
+
+
+[1-4] Multiline messages and printk_header
+
+ int printk_header(const char *header, const char *fmt, ...)
+
+Kernel messages are usually fitted to 80 column as many people use 80
+column console or terminal to print out and view log messages, but, at
+times, there are more things to say than fits into one 80 column line.
+
+For example, when an ATA command fails, libata reports the taskfile
+registers for the failed command and the result taskfile registers.
+Both have similar formats and each nearly fills up 80 column. Such
+messages can be printed with separate calls to printk or as a single
+call to printk where the output string contains newline inside it.
+For simplicity, I'll just use simplified string constants for the rest
+of this section.
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n");
+ printk(KERN_ERR "ata1.00: res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+Or
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "ata1.00: res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+Both will print about the same thing but the latter has the benefit
+that the message won't break up in the middle. Another twist is that
+there can be multiple commands in flight, so the output can look like
+the following.
+
+ ata1.00: cmd 60/57:00:69:ab:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/0c:08:c0:ab:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/80:18:e8:aa:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+
+Which is pretty confusing to the eyes. It would be better if there is
+some indication of message boundaries.
+
+ ata1.00: cmd 60/57:00:69:ab:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/0c:08:c0:ab:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/80:18:e8:aa:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+
+Okay, now it gives us visual clue where each multiline message starts,
+so combining the above atomic multiline message and visual clue, the
+driver should do the following.
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "ata1.00 res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+However, this becomes quite clumsy. Port and device numbers are
+variables and should be specified repeatedly for each line. This is
+the problem printk_header solves. It has a notion of message header
+and pretty-print multiline messages. The above example can be done
+using printk_header like the following.
+
+ printk_header(KERN_ERR "ata1.00: ",
+ "cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+printk_header will automatically prepend whole header to the first
+line and prepend without the colon in the second line. In the above
+example, log level is prepended to the header but printk_header also
+allows log level in front of each message line.
+
+ printk_header(KERN_ERR "whiny: ", KERN_DEBUG "it's me again\n"
+ KERN_INFO "I feel depressed today\n"
+ "The machine hates me\n");
+
+Will output
+
+ <7>whiny: it's me again
+ <6>whiny I feel depressed today
+ <6>whiny The machine hates me
+
+Note that the log level of the first message line trumped log level in
+the message header. As seen above, printk_header supports switching
+log level inside a multiline message but it's usually better to stick
+with single log level in a multiline message.
+
+Replacing colon with space is preformed if and only if the header ends
+with ":\s*" where \s is any character which isspace() returns
+non-zero.
+
+
+[1-5] printk's friends
+
+int vprintk(const char *fmt, va_list args)
+
+ Identical to printk but takes va_list @args instead of argument
+ list.
+
+int vprintk_header(const char *header, const char *fmt, va_list args)
+
+ Identical to printk_header but takes va_list @args instead of
+ argument list.
+
+int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst)
+
+ Rate-limited printk. Not more than one kernel message every
+ @ratelimit_jiffies to make a denial-of-service attack impossible.
+ @ratelimit_burst messages are allowed before ratelimit kicks in.
+
+int printk_ratelimit(void)
+
+ Rate-limited printk which uses standard limit and burst
+ parameters. Default parameters can be tuned using sysctl{5}.
+
+bool printk_timed_ratelimit(unsigned long *caller_jiffies,
+ unsigned int interval_msecs)
+
+ Caller-controlled printk ratelimiting. This function returns true
+ if more than @interval_msecs milliseconds have elapsed since the
+ last time it returned true.
+
+
+[2] mprintk - the merging printk
+
+[2-1] What is mprintk?
+
+Let's go back to the libata error message example. Actual ATA error
+message for a failed ATAPI command looks like the following.
+
+ ata1.00: cmd a0/01:00:00:00:00/00:00:00:00:00/b0 tag 0 dma 8 in
+ ata1.00 cdb 25 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
+ ata1.00 res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
+
+On the first line, "dma 8 in" indicates that the failed command DMAs 8
+bytes from the drive to host memory. This segment of message is
+printed only for commands which transfer data. The second line
+reports the SCSI CDB issued to the drive and is only meaningful for
+the ATAPI PACKET command and thus omitted for all other commands. The
+last line reports the status of TF registers and as libata doesn't
+load TF registers after a timeout it should have been omitted but that
+isn't implemented yet.
+
+The example shows you how a message can be composed of multiple parts
+which can be included or omitted depending on the information to
+report. This happens quite often. Another example in libata would be
+the device configuration message.
+
+There are three ways to assemble these multi-part messages.
+
+* Calling printk() on partial message segments. This used to be quite
+ common but has a problem - the message can break up if someone else
+ prints something in the middle.
+
+* Prepping a temp buffer and building message piece-by-piece using
+ snprintf(). This is the most generic method but corner case
+ handling can be tedious and, on overflow, messages can be lost
+ unnoticed if overflow detection isn't properly done.
+
+* Collecting all the partial data and calling printk() once with all
+ the parameters. This is often combined with the second. This
+ usually works but printing messages becomes non-trivial programming
+ problem and can get quite tedious if the message format varies
+ depending on data.
+
+None of the above was satisfactory, so mprintk - merging printk - was
+implemented. It's basically a helper to construct a message
+piece-by-piece into the specified buffer. The caller still has to
+care about buffer size and how the buffer is allocated but mprintk
+makes it easy.
+
+* DEFINE_MPRINTK() macro helps to define a mprintk instance with
+ on-stack buffer.
+
+* mprintk_init_alloc() and mprintk_free() are helpers to use malloc'd
+ buffer.
+
+* Messages are never lost. On buffer overflow, all queued and to be
+ queued messages are printed followed by a warning message and stack
+ dump. The warning message and stack dump are printed once per
+ mprintk instance. Also, the caller doesn't have to handle buffer
+ allocation failure. If buffer is initialized to NULL, mprintk
+ simply bypasses messages to printk(). As free() can cope with NULL
+ pointer too, allocation failure doesn't require any extra care.
+
+* Has good support for multiline messages. A mprintk instance can
+ have header associated with it and the header can have log level.
+ Header log level is used if a message chunk doesn't specify log
+ level explicitly. When log level is specified explicitly in a
+ message chunk, the log level is applied to the chunk only.
+
+
+[2-2] How do I use mprintk?
+
+[2-2-1] Initialization
+
+ MPRINTK_INITIALIZER(buf, size)
+ DEFINE_MPRINTK(name, size)
+ void mprintk_init(struct mprintk *mp, char *buf, size_t size)
+ void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp)
+ void mprintk_free(struct mprintk *mp)
+
+struct mprintk is the data structure used to keep track of the merge
+buffer. This can be allocated anywhere but defining as a local
+variable for the block containing the message assembling code makes
+sense for most cases. struct mprintk doesn't contain buffer space for
+the string. It needs to be defined separately and mprintk should be
+initialized with the pointer to and the size of the buffer.
+
+MPRINTK_INITIALIZER() can be used to initialize mprintk instance.
+
+ char mp_buf[2 * 80];
+ struct mprintk mp0 = MPRINTK_INITIALIZER(mp_buf, 2 * 80);
+ struct mprintk mp1 = MPRINTK_INITIALIZER(A_struct->buffer, A_BUF_LEN);
+
+Function call variant - mprintk_init - can also be used.
+
+ struct mprintk mp;
+
+ mprinkt_init(&mp, buffer, MAX_MESSAGE_LEN);
+
+To malloc buffer, mprintk_init_alloc should be used.
+
+ struct mprintk mp;
+
+ mprintk_init_alloc(&mp, GFP_KERNEL);
+
+The caller doesn't have to care about buffer length. The allocated
+buffer should be freed using mprintk_free. mprintk_free can be called
+on any mprintk instance but if the mprintk instance hasn't been
+initialized with mprintk_init_alloc, it's noop.
+
+ mprintk_free(&mp);
+
+Because defining both mprintk instance and string buffer on stack is
+the most common case, there's a shortcut for it.
+
+ DEFINE_MPRINTK(my_mp, 2 * 80);
+
+Which is equivalent to the following.
+
+ char __my_mp_buf[2 * 80];
+ struct mprintk my_mp = MPRINTK_INITIALIZER(__my_mp_buf, 2 * 80);
+
+Please keep in mind that MPRINTK_INITIALIZER allocates the string
+buffer on stack. If too much is allocated, stack overflow can happen.
+In most cases, a few hundred bytes should be fine and you shouldn't go
+over that anyway. More on this subject later in the guidelines
+section.
+
+
+[2-2-2] Assembling and printing
+
+ int mprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ int mprintk(struct mprintk *mp, const char *fmt, va_list args)
+ int mprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+
+mprintk_set_header() sets the header of the message. This function
+can be called only once after initialization and should be called when
+the buffer is empty, that is, right after intialization or being
+flushed. Returns the length of the formatted string.
+
+mprintk() Appends the formatted string to the specified mprintk
+instance. Returns the length of the formatted string.
+
+mprintk_flush() appends the formatted string to the specified mprintk
+instance, prints out the accumulated message and resets the buffer.
+Returns the length of the formatted string.
+
+Here's a simple example.
+
+ DEFINE_MPRINTK(mp, 2 * 80);
+
+ mprintk_set_header(&mp, KERN_INFO "Marvin: ");
+ mprintk(&mp, "Life.\n");
+ mprintk(&mp, "Don't talk to me ");
+ mprintk_flush("about %s.\n", life);
+
+Which becomes
+
+ <6>Marvin: Life.
+ <6>Marvin Don't talk to me about life.
+
+mprintk allows log levels both in front of the header and in front of
+each message chunk (formatted string of each mprintk[_add]() call).
+Log levels specified in front of a message chunk applies only to that
+message chunk and has priority over the header log level. Message
+chunks without explicit log level use the header log level.
+
+ DEFINE_MPRINTK(mp, 4 * 80);
+
+ mprintk_set_header(&mp, KERN_INFO "Marvin: ");
+ mprintk(&mp, KERN_ERR "Here I am, brain the size of a planet and\n"
+ "they ask me to take you down to the bridge.\n");
+ mprintk(&mp, "Call that job satisfaction?\n");
+ mprintk_flush(&mp, "'Cos I don't.\n");
+
+Which becomes
+
+ <3>Marvin: Here I am, brain the size of a planet and
+ <3>Marvin they ask me to take you down to the bridge.
+ <6>Marvin: Call that job satisfaction?
+ <6>Marvin 'Cos I don't.
+
+Note how KERN_ERR is applied to the first message chunk while the
+header log level is used for the last message chunks which don't have
+explicit log level specified. The header is printed again on the
+third line because of log level change.
+
+Remember log level is only meaningful when a new line starts? That
+applies the same to mprintk message chunks. If a message chunk
+doesn't start a new line, log level in front of it will be treated as
+verbatim string.
+
+Also, mprintk doesn't allow switching log level in the middle of a
+message chunk. Don't do it.
+
+
+[2-2-3] Error handling
+
+One good thing about mprintk is that you don't have to pay attention
+to error handling. There can be two error conditions - buffer
+overflow and NULL buffer due to allocation failure.
+
+If adding a new message chunk overflows the buffer, mprintk prints out
+the accumulated message followed by the new message chunk which caused
+overflow. If the overflow is the first one since mprintk
+initialization, a warning message and stack dump are printed to aid
+debugging.
+
+In rare cases, buffer overflow can also happen while setting the
+header, if this happens, it's handled the same way as message chunk
+overflow; however, after such a failure, if the messasge is multiline,
+lines after the first one won't have proper header or header log level
+- the default log level, WARNING, will be used for lines without
+explicit log level.
+
+When buffer is allocated using kmalloc(), the allocation might fail.
+mprintk allows NULL buffer initialization. In which case, mprintk
+simply forwards messages to printk. As in the header overflow case,
+header handling can be broken but no message is lost.
+
+All in all, you don't need to do any error handling when using
+mprintk. It's just like printk. It's guaranteed to deliver the
+message and there's no need to check the return values.
+
+ struct mprintk mp;
+ int i;
+
+ mprintk_init_alloc(&mp, GFP_KERNEL);
+
+ mprintk_set_header(&mp, "Beeblebrox: ");
+ for (i = 0; i < 5; i++)
+ mprintk(&mp, "Yeah. Listen, I'm Zaphod Beeblebrox,\n"
+ "my father was Zaphod Beeblebrox the Second,\n"
+ "my grandfather Zaphod Beeblebrox the Third...\n");
+ mprintk_flush(&mp, "Rubbish...\n");
+
+ mprintk_free(&mp);
+
+The above code segment will print 16 lines sans one overflow message
+and stack dump no matter what and won't leak memory.
+
+
+[2-3] Some guidelines
+
+* Don't build gigantic messages. Don't span over a few lines. Just
+ put what really needs to be an atomic message into one message.
+ Keep in mind that printk silently clips messages at 1k.
+
+* Prefer on-stack buffer and when using on-stack buffer use
+ DEFINE_MPRINTK(). If you observe the previous guideline, on-stack
+ buffer should be sufficient. It's the simplest and can't leak
+ memory.
+
+* With the header and automatic log level adjustments, the end result
+ can be a bit longer. Give it some extra room. I find it useful to
+ specify buffer length in multiples of 80 as lines shouldn't go over
+ 80 column anyway. If the message can be four lines long,
+ specify 4 * 80.
+
+* Specify log level at the header and refrain from overriding log
+ level from message chunks unless necessary. If you encounter an
+ error condition while building an informational message, printing an
+ error message with a separate call to printk[_header]() and resuming
+ building the informational message is usually the right thing to do.
+
+
+[2-4] mprintk's friends
+
+int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk_set_header but takes va_list @args instead of
+ argument list.
+
+int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk but takes va_list @args instead of argument
+ list.
+
+int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk_flush but takes va_list @args instead of
+ argument list.
+
+
+[3] How libata uses printk_header and mprintk
+
+Me being a libata guy, the first user of printk_header and mprintk is
+libata. libata has printk helpers at each level - port, link and
+device. Let's take a look at the port one.
+
+ int ata_port_printk(struct ata_port *ap, const char *lv,
+ const char *fmt, ...)
+ {
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+ }
+
+It creates a header and calls vprintk_header() with it and passes the
+format string and arguments. Note the separate @lv argument. This is
+remnant of the previous define-based implementation which didn't use
+printk_header and thus had to manually put the message level in front
+of the header. With printk_header, the formatted string can carry the
+log level in front of it and printk_header will do the right thing.
+
+Also, there is a port-level helper to set header of a mprintk buffer.
+
+ void ata_port_mp_header(struct ata_port *ap, const char *lv,
+ struct mprintk *mp)
+ {
+ mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+ }
+
+After initializing mprintk and calling the above function,
+mprintk_add() and mprintk() can be used freely to assemble and print
+messages. For examples, take a look at ata_dev_configure() in
+drivers/ata/libata-core.c and ata_eh_link_report() in
+drivers/ata/libata-eh.c. Note that both functions use ap->sector_buf.
+This is 512 byte buffer owned by the EH thread which happens to be the
+only thread which does EH reporting and device configuration.
+
+Happy hacking.
+
+
+REFERENCES
+
+{1} On SMP, if a CPU does printk while another one is executing
+ console drivers to push out messages, the new message would simply
+ be queued and printk returns.
+
+{2} Documentation/serial-console.txt
+
+{3} Documentation/networking/netconsole.txt
+ Note that netconsole can't be the primary console - the one which
+ provides standard IOs to init - as it can't read from the user.
+ Also, its synchronisity is further limited. On write completion,
+ all that can be assured is that the packets containing the message
+ have been sent. Whether or when the message has arrived on the
+ destination is unknown.
+
+{4} Documentation/sysctl/kernel.txt:printk
+
+{5} Documentation/sysctl/kernel.txt:printk_ratelimit,printk_ratelimit_burst
+
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread* [PATCH 4/5] printk: add Documentation/printk.txt
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Add Documentation/printk.txt which explains printk, mprintk and their
friends.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
Documentation/00-INDEX | 2 +
Documentation/printk.txt | 724 ++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 726 insertions(+), 0 deletions(-)
create mode 100644 Documentation/printk.txt
diff --git a/Documentation/00-INDEX b/Documentation/00-INDEX
index 8d55670..e4c2862 100644
--- a/Documentation/00-INDEX
+++ b/Documentation/00-INDEX
@@ -313,6 +313,8 @@ powerpc/
- directory with info on using Linux with the PowerPC.
preempt-locking.txt
- info on locking under a preemptive kernel.
+printk.txt
+ - info on printk and mprintk.
prio_tree.txt
- info on radix-priority-search-tree use for indexing vmas.
ramdisk.txt
diff --git a/Documentation/printk.txt b/Documentation/printk.txt
new file mode 100644
index 0000000..e510a81
--- /dev/null
+++ b/Documentation/printk.txt
@@ -0,0 +1,724 @@
+printk and mprintk
+==================
+Tejun Heo <teheo@suse.de>, January 18 2008
+
+This document describes printk and mprintk.
+
+TABLE OF CONTENTS
+
+[1] printk
+ [1-1] What is printk and how does it operate?
+ [1-2] Log level
+ [1-2-1] What is log level and how do I use it?
+ [1-2-2] How the log level is treated by kernel and logging tools.
+ [1-3] Timestamps
+ [1-4] Multiline messages and printk_header
+ [1-5] printk's friends
+
+[2] mprintk - the merging printk
+ [2-1] What is mprintk?
+ [2-2] How do I use mprintk?
+ [2-2-1] Initialization
+ [2-2-2] Assembling and printing
+ [2-2-3] Error handling
+ [2-3] Some guidelines
+ [2-4] mprintk's friends
+
+[3] How libata uses printk_header and mprintk
+
+
+[1] printk
+
+[1-1] What is printk and how does it operate?
+
+ int printk(const char *fmt, ...)
+
+printk is the equivalent of print for perl scripts, echo for shell
+scripts and much more closely printf(3) for userland C programs. It
+takes the same arguments as printf(3), formats the string the same way
+and spits the result out. printk is the kernel's primary way to emit
+human-readable messages.
+
+printf(3) prints formatted messages to the default destination -
+standard output. printk also has default destination or rather
+destinations. Messages printed out via printk are stored in a message
+buffer which can be retrieved either by syslog(2) system call or
+reading /proc/kmsg and then printed to one or more registered
+consoles.
+
+The ring buffer is the asynchronous way to access the messages.
+dmesg(1) dumps its content, klogd reads the messages and logs the
+result via syslog facility. The ring buffer is of fixed size which
+can be configured by the 'log_buf_len' kernel parameter. If a new
+message is printed and the ring buffer is full, it wraps around and
+writes over the old messages.
+
+On the other hand, the consoles behave mostly synchronously{1}. The
+most common console device is the virtual console (your graphics
+adapter and monitor). While the machine is booting, if you disable or
+escape from the pretty graphical boot screen, you'll see lots of
+kernel messages scrolling by before the userland starts to run. All
+those messages are from printk and your monitor is serving as a
+console device. Other examples of console devices include serial
+console{2} and netconsole{3}.
+
+The synchronous operation of console devices can be very expensive
+depending on which console devices are attached. For example,
+transferring 160 characters over 9600 baud rate serial line consumes
+around 18.75 milliseconds and the CPU won't be doing anything else
+other than pushing the bytes out.
+
+Accesses to the log buffer are synchronized and messages from separate
+printk invocations never get intermixed; however, there is no
+guarantee that two consecutive calls to printk will show up
+consecutively. printk calls from other threads can be printed
+inbetween.
+
+ Thread A Thread B
+
+ printk("hello "); printk("The answer is ");
+ printk("world!\n"); printk("42\n");
+
+The output can be
+
+ hello The answer is world!
+ 42
+
+or any other combination - 6 of them, so you shouldn't construct
+messages piece-by-piece by calling printk on substrings. You should
+build the complete message first and print it by calling printk once.
+As constructing a message from pieces can be a non-trival task, there
+is a helper mechanism called mprintk. It will be explained later.
+
+
+[1-2] Log level
+
+[1-2-1] What is log level and how do I use it?
+
+Another difference from printf(3) is that printk performs a bit of
+post-processing on the printed messages. Each line printed via printk
+has a log level which is priority or urgency of the message. Eight
+log levels are defined and have the following meanings.
+
+ KERN_EMERG : system is unusable
+ KERN_ALERT : action must be taken immediately
+ KERN_CRIT : critical conditions
+ KERN_ERR : error conditions
+ KERN_WARNING : warning conditions
+ KERN_NOTICE : normal but significant condition
+ KERN_INFO : informational
+ KERN_DEBUG : debug-level message
+
+If you search for the above constants in include/linux/kernel.h,
+you'll see that they are defined as string constants "<N>" where N is
+0 for EMERG and increments for each upto 7 for DEBUG. There's nothing
+magical about it. Lines which start with "<N>" has the priority of N.
+Because C's preprocessor merges string constants, simply putting the
+macro in front of a message suffices.
+
+ printk(KERN_WARNING "I'm a whiny kernel.\n");
+ printk("%sAm I too whiny?\n", KERN_WARNING);
+ printk("<%d>You don't think I'm too whiny, do you?\n", 4);
+
+Will output.
+
+ <4>I'm a whiny kernel.
+ <4>Am I too whiny?
+ <4>You don't think I'm too whiny, do you?
+
+But what happens when you don't specify log level? In such cases,
+printk automatically assigns the default log level which is
+KERN_WARNING by default but can be overridden using sysctl{4}, so
+
+ printk("Please tell me I don't whine too much\n");
+
+is mostly equivalent to
+
+ printk(KERN_WARNING "Please tell me I don't whine too much\n");
+
+Noticed 'mostly'? The output will be different if the message doesn't
+start a new line. Please recall that log level is per-line and thus
+log level string doesn't have any meaning when it's not at the start
+of a line.
+
+ printk(KERN_NOTICE "Why don't you notice me? ");
+ printk(KERN_EMERGE "Do I have to say louder?\n");
+
+The above will result in the following string.
+
+ <5>Why don't you notice me? <0>Do I have to say louder
+
+And printk will treat it as a NOTICE message whose content is
+
+ Why don't you notice me? <0>Do I have to say louder
+
+Putting log level in the middle of string doesn't do anything to the
+log level. It just gets printed verbatim. This is another reason to
+avoid constructing messages piece-by-piece by calling printk multiple
+times. Let's go back to the hello world example and add log levels
+there.
+
+ Thread A Thread B
+
+ printk(KERN_ERR "hello "); printk(KERN_INFO "The answer is ");
+ printk("world!\n"); printk("42\n");
+
+The end result can be
+
+ <3>hello <6>The answer is 42
+ <4>world
+
+The first line is ERR message with weird "<6>" in it and the second
+line is WARNING message where the log level is automatically assigned
+by printk.
+
+Another thing to note about log level handling is that printk
+maintains log level in a multiline message.
+
+ printk(KERN_INFO "whine0\nwhine1\n" KERN_ERR "whine2\nwhine3\n");
+
+Becomes
+
+ <6>whine0
+ <6>whine1
+ <3>whine2
+ <3>whine3
+
+
+[1-2-2] How the log level is treated by kernel and logging tools.
+
+You probably have never noticed the log level markup in the dmesg(1)
+output, /var/log/messages or kernel messages printed on your monitor.
+This is because log level is treated specially. When message buffer
+is accessed via syslog(2) or /proc/kmsg, the log level is printed
+verbatim but the reading program - often klogd(8) or dmesg(1) -
+recognizes the log levels, strips them and routes or treats the
+messages accordingly. You can read the raw messages with the log
+level by stopping klogd(8) and executing "cat /proc/kmsg".
+
+For console devices, printk itself performs similar function. The log
+level is stripped before being submitted to console drivers and
+messages are filtered according to the console log level such that low
+priority messages don't clutter consoles. Console log level can be
+adjusted using either syslog(2) system call or kernel.printk sysctl
+node{4}.
+
+
+[1-3] Timestamps
+
+Another post-processing performed by printk is prepending timestamp.
+When enabled, the kernel's conception of time since boot or resume is
+added between the log level and the actual message. The following is
+excerpt from libata probing messages.
+
+ <6>[ 114.971205] ata8: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
+ <6>[ 114.989200] ata8.00: HPA detected: current 156299375, native 156301488
+ <6>[ 115.007362] ata8.00: ATA-7: WDC WD800JD-00MSA1, 10.01E01, max UDMA/133
+ <6>[ 115.024879] ata8.00: 156299375 sectors, multi 16: LBA48 NCQ (depth 31/32)
+ <6>[ 115.043885] ata8.00: configured for UDMA/133
+
+The number before "." is seconds and after is nanoseconds. It's
+kernel's conception of time and may not match actual wall clock
+depending on power saving setting and other things.
+
+Timestamp is enabled at kernel compile time using CONFIG_PRINTK_TIME
+but it can also be enabled or disabled when booting by specifying
+"printk.time=1" as kernel boot parameter. In addition, by echoing "0"
+or "1" to /sys/module/printk/parameters/printk_time, you can control
+it while the system is running.
+
+klogd(8) automatically prepends timestamps when logging kernel
+messages, so printk timestamp is somewhat redundant; however, printk
+timestamp has the following benefits making it better suited for
+debugging.
+
+* klogd(8) only knows when it read the messages. It can't tell when
+ the message was generated. For example, during boot or resume,
+ userspace is not running and when klogd(8) finally runs it can't
+ tell what happened when and just puts the same timestamp on all the
+ accumulated messages.
+
+* It uses kernel's conception of time and at times this provides
+ better insight into what's going on. For example, if there's a bug
+ in kernel's timer code, kernel's conception of time can be stalled
+ or delayed while gettimeofday(2) still returns valid values.
+
+* Reading messages from the console or running dmesg(1) to dump the
+ message buffer is simpler than having klogd(8) running. Having
+ timestamps available when using simpler methods helps debugging.
+
+There are discussions of automatically stripping and handling
+timestamps from dmesg(1) and klogd(8) to remove the timestamps
+automatically.
+
+
+[1-4] Multiline messages and printk_header
+
+ int printk_header(const char *header, const char *fmt, ...)
+
+Kernel messages are usually fitted to 80 column as many people use 80
+column console or terminal to print out and view log messages, but, at
+times, there are more things to say than fits into one 80 column line.
+
+For example, when an ATA command fails, libata reports the taskfile
+registers for the failed command and the result taskfile registers.
+Both have similar formats and each nearly fills up 80 column. Such
+messages can be printed with separate calls to printk or as a single
+call to printk where the output string contains newline inside it.
+For simplicity, I'll just use simplified string constants for the rest
+of this section.
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n");
+ printk(KERN_ERR "ata1.00: res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+Or
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "ata1.00: res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+Both will print about the same thing but the latter has the benefit
+that the message won't break up in the middle. Another twist is that
+there can be multiple commands in flight, so the output can look like
+the following.
+
+ ata1.00: cmd 60/57:00:69:ab:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/0c:08:c0:ab:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/80:18:e8:aa:03/00:00:00:00:00/40
+ ata1.00: res 40/00:14:cc:ab:03/00:00:00:00:00/40
+
+Which is pretty confusing to the eyes. It would be better if there is
+some indication of message boundaries.
+
+ ata1.00: cmd 60/57:00:69:ab:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/0c:08:c0:ab:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+ ata1.00: cmd 60/80:18:e8:aa:03/00:00:00:00:00/40
+ ata1.00 res 40/00:14:cc:ab:03/00:00:00:00:00/40
+
+Okay, now it gives us visual clue where each multiline message starts,
+so combining the above atomic multiline message and visual clue, the
+driver should do the following.
+
+ printk(KERN_ERR "ata1.00: cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "ata1.00 res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+However, this becomes quite clumsy. Port and device numbers are
+variables and should be specified repeatedly for each line. This is
+the problem printk_header solves. It has a notion of message header
+and pretty-print multiline messages. The above example can be done
+using printk_header like the following.
+
+ printk_header(KERN_ERR "ata1.00: ",
+ "cmd 60/01:00:e0:71:02/00:00:00:00:00/40\n"
+ "res 40/00:34:de:71:02/00:00:00:00:00/40\n");
+
+printk_header will automatically prepend whole header to the first
+line and prepend without the colon in the second line. In the above
+example, log level is prepended to the header but printk_header also
+allows log level in front of each message line.
+
+ printk_header(KERN_ERR "whiny: ", KERN_DEBUG "it's me again\n"
+ KERN_INFO "I feel depressed today\n"
+ "The machine hates me\n");
+
+Will output
+
+ <7>whiny: it's me again
+ <6>whiny I feel depressed today
+ <6>whiny The machine hates me
+
+Note that the log level of the first message line trumped log level in
+the message header. As seen above, printk_header supports switching
+log level inside a multiline message but it's usually better to stick
+with single log level in a multiline message.
+
+Replacing colon with space is preformed if and only if the header ends
+with ":\s*" where \s is any character which isspace() returns
+non-zero.
+
+
+[1-5] printk's friends
+
+int vprintk(const char *fmt, va_list args)
+
+ Identical to printk but takes va_list @args instead of argument
+ list.
+
+int vprintk_header(const char *header, const char *fmt, va_list args)
+
+ Identical to printk_header but takes va_list @args instead of
+ argument list.
+
+int __printk_ratelimit(int ratelimit_jiffies, int ratelimit_burst)
+
+ Rate-limited printk. Not more than one kernel message every
+ @ratelimit_jiffies to make a denial-of-service attack impossible.
+ @ratelimit_burst messages are allowed before ratelimit kicks in.
+
+int printk_ratelimit(void)
+
+ Rate-limited printk which uses standard limit and burst
+ parameters. Default parameters can be tuned using sysctl{5}.
+
+bool printk_timed_ratelimit(unsigned long *caller_jiffies,
+ unsigned int interval_msecs)
+
+ Caller-controlled printk ratelimiting. This function returns true
+ if more than @interval_msecs milliseconds have elapsed since the
+ last time it returned true.
+
+
+[2] mprintk - the merging printk
+
+[2-1] What is mprintk?
+
+Let's go back to the libata error message example. Actual ATA error
+message for a failed ATAPI command looks like the following.
+
+ ata1.00: cmd a0/01:00:00:00:00/00:00:00:00:00/b0 tag 0 dma 8 in
+ ata1.00 cdb 25 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
+ ata1.00 res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
+
+On the first line, "dma 8 in" indicates that the failed command DMAs 8
+bytes from the drive to host memory. This segment of message is
+printed only for commands which transfer data. The second line
+reports the SCSI CDB issued to the drive and is only meaningful for
+the ATAPI PACKET command and thus omitted for all other commands. The
+last line reports the status of TF registers and as libata doesn't
+load TF registers after a timeout it should have been omitted but that
+isn't implemented yet.
+
+The example shows you how a message can be composed of multiple parts
+which can be included or omitted depending on the information to
+report. This happens quite often. Another example in libata would be
+the device configuration message.
+
+There are three ways to assemble these multi-part messages.
+
+* Calling printk() on partial message segments. This used to be quite
+ common but has a problem - the message can break up if someone else
+ prints something in the middle.
+
+* Prepping a temp buffer and building message piece-by-piece using
+ snprintf(). This is the most generic method but corner case
+ handling can be tedious and, on overflow, messages can be lost
+ unnoticed if overflow detection isn't properly done.
+
+* Collecting all the partial data and calling printk() once with all
+ the parameters. This is often combined with the second. This
+ usually works but printing messages becomes non-trivial programming
+ problem and can get quite tedious if the message format varies
+ depending on data.
+
+None of the above was satisfactory, so mprintk - merging printk - was
+implemented. It's basically a helper to construct a message
+piece-by-piece into the specified buffer. The caller still has to
+care about buffer size and how the buffer is allocated but mprintk
+makes it easy.
+
+* DEFINE_MPRINTK() macro helps to define a mprintk instance with
+ on-stack buffer.
+
+* mprintk_init_alloc() and mprintk_free() are helpers to use malloc'd
+ buffer.
+
+* Messages are never lost. On buffer overflow, all queued and to be
+ queued messages are printed followed by a warning message and stack
+ dump. The warning message and stack dump are printed once per
+ mprintk instance. Also, the caller doesn't have to handle buffer
+ allocation failure. If buffer is initialized to NULL, mprintk
+ simply bypasses messages to printk(). As free() can cope with NULL
+ pointer too, allocation failure doesn't require any extra care.
+
+* Has good support for multiline messages. A mprintk instance can
+ have header associated with it and the header can have log level.
+ Header log level is used if a message chunk doesn't specify log
+ level explicitly. When log level is specified explicitly in a
+ message chunk, the log level is applied to the chunk only.
+
+
+[2-2] How do I use mprintk?
+
+[2-2-1] Initialization
+
+ MPRINTK_INITIALIZER(buf, size)
+ DEFINE_MPRINTK(name, size)
+ void mprintk_init(struct mprintk *mp, char *buf, size_t size)
+ void mprintk_init_alloc(struct mprintk *mp, gfp_t gfp)
+ void mprintk_free(struct mprintk *mp)
+
+struct mprintk is the data structure used to keep track of the merge
+buffer. This can be allocated anywhere but defining as a local
+variable for the block containing the message assembling code makes
+sense for most cases. struct mprintk doesn't contain buffer space for
+the string. It needs to be defined separately and mprintk should be
+initialized with the pointer to and the size of the buffer.
+
+MPRINTK_INITIALIZER() can be used to initialize mprintk instance.
+
+ char mp_buf[2 * 80];
+ struct mprintk mp0 = MPRINTK_INITIALIZER(mp_buf, 2 * 80);
+ struct mprintk mp1 = MPRINTK_INITIALIZER(A_struct->buffer, A_BUF_LEN);
+
+Function call variant - mprintk_init - can also be used.
+
+ struct mprintk mp;
+
+ mprinkt_init(&mp, buffer, MAX_MESSAGE_LEN);
+
+To malloc buffer, mprintk_init_alloc should be used.
+
+ struct mprintk mp;
+
+ mprintk_init_alloc(&mp, GFP_KERNEL);
+
+The caller doesn't have to care about buffer length. The allocated
+buffer should be freed using mprintk_free. mprintk_free can be called
+on any mprintk instance but if the mprintk instance hasn't been
+initialized with mprintk_init_alloc, it's noop.
+
+ mprintk_free(&mp);
+
+Because defining both mprintk instance and string buffer on stack is
+the most common case, there's a shortcut for it.
+
+ DEFINE_MPRINTK(my_mp, 2 * 80);
+
+Which is equivalent to the following.
+
+ char __my_mp_buf[2 * 80];
+ struct mprintk my_mp = MPRINTK_INITIALIZER(__my_mp_buf, 2 * 80);
+
+Please keep in mind that MPRINTK_INITIALIZER allocates the string
+buffer on stack. If too much is allocated, stack overflow can happen.
+In most cases, a few hundred bytes should be fine and you shouldn't go
+over that anyway. More on this subject later in the guidelines
+section.
+
+
+[2-2-2] Assembling and printing
+
+ int mprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+ int mprintk(struct mprintk *mp, const char *fmt, va_list args)
+ int mprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+
+mprintk_set_header() sets the header of the message. This function
+can be called only once after initialization and should be called when
+the buffer is empty, that is, right after intialization or being
+flushed. Returns the length of the formatted string.
+
+mprintk() Appends the formatted string to the specified mprintk
+instance. Returns the length of the formatted string.
+
+mprintk_flush() appends the formatted string to the specified mprintk
+instance, prints out the accumulated message and resets the buffer.
+Returns the length of the formatted string.
+
+Here's a simple example.
+
+ DEFINE_MPRINTK(mp, 2 * 80);
+
+ mprintk_set_header(&mp, KERN_INFO "Marvin: ");
+ mprintk(&mp, "Life.\n");
+ mprintk(&mp, "Don't talk to me ");
+ mprintk_flush("about %s.\n", life);
+
+Which becomes
+
+ <6>Marvin: Life.
+ <6>Marvin Don't talk to me about life.
+
+mprintk allows log levels both in front of the header and in front of
+each message chunk (formatted string of each mprintk[_add]() call).
+Log levels specified in front of a message chunk applies only to that
+message chunk and has priority over the header log level. Message
+chunks without explicit log level use the header log level.
+
+ DEFINE_MPRINTK(mp, 4 * 80);
+
+ mprintk_set_header(&mp, KERN_INFO "Marvin: ");
+ mprintk(&mp, KERN_ERR "Here I am, brain the size of a planet and\n"
+ "they ask me to take you down to the bridge.\n");
+ mprintk(&mp, "Call that job satisfaction?\n");
+ mprintk_flush(&mp, "'Cos I don't.\n");
+
+Which becomes
+
+ <3>Marvin: Here I am, brain the size of a planet and
+ <3>Marvin they ask me to take you down to the bridge.
+ <6>Marvin: Call that job satisfaction?
+ <6>Marvin 'Cos I don't.
+
+Note how KERN_ERR is applied to the first message chunk while the
+header log level is used for the last message chunks which don't have
+explicit log level specified. The header is printed again on the
+third line because of log level change.
+
+Remember log level is only meaningful when a new line starts? That
+applies the same to mprintk message chunks. If a message chunk
+doesn't start a new line, log level in front of it will be treated as
+verbatim string.
+
+Also, mprintk doesn't allow switching log level in the middle of a
+message chunk. Don't do it.
+
+
+[2-2-3] Error handling
+
+One good thing about mprintk is that you don't have to pay attention
+to error handling. There can be two error conditions - buffer
+overflow and NULL buffer due to allocation failure.
+
+If adding a new message chunk overflows the buffer, mprintk prints out
+the accumulated message followed by the new message chunk which caused
+overflow. If the overflow is the first one since mprintk
+initialization, a warning message and stack dump are printed to aid
+debugging.
+
+In rare cases, buffer overflow can also happen while setting the
+header, if this happens, it's handled the same way as message chunk
+overflow; however, after such a failure, if the messasge is multiline,
+lines after the first one won't have proper header or header log level
+- the default log level, WARNING, will be used for lines without
+explicit log level.
+
+When buffer is allocated using kmalloc(), the allocation might fail.
+mprintk allows NULL buffer initialization. In which case, mprintk
+simply forwards messages to printk. As in the header overflow case,
+header handling can be broken but no message is lost.
+
+All in all, you don't need to do any error handling when using
+mprintk. It's just like printk. It's guaranteed to deliver the
+message and there's no need to check the return values.
+
+ struct mprintk mp;
+ int i;
+
+ mprintk_init_alloc(&mp, GFP_KERNEL);
+
+ mprintk_set_header(&mp, "Beeblebrox: ");
+ for (i = 0; i < 5; i++)
+ mprintk(&mp, "Yeah. Listen, I'm Zaphod Beeblebrox,\n"
+ "my father was Zaphod Beeblebrox the Second,\n"
+ "my grandfather Zaphod Beeblebrox the Third...\n");
+ mprintk_flush(&mp, "Rubbish...\n");
+
+ mprintk_free(&mp);
+
+The above code segment will print 16 lines sans one overflow message
+and stack dump no matter what and won't leak memory.
+
+
+[2-3] Some guidelines
+
+* Don't build gigantic messages. Don't span over a few lines. Just
+ put what really needs to be an atomic message into one message.
+ Keep in mind that printk silently clips messages at 1k.
+
+* Prefer on-stack buffer and when using on-stack buffer use
+ DEFINE_MPRINTK(). If you observe the previous guideline, on-stack
+ buffer should be sufficient. It's the simplest and can't leak
+ memory.
+
+* With the header and automatic log level adjustments, the end result
+ can be a bit longer. Give it some extra room. I find it useful to
+ specify buffer length in multiples of 80 as lines shouldn't go over
+ 80 column anyway. If the message can be four lines long,
+ specify 4 * 80.
+
+* Specify log level at the header and refrain from overriding log
+ level from message chunks unless necessary. If you encounter an
+ error condition while building an informational message, printing an
+ error message with a separate call to printk[_header]() and resuming
+ building the informational message is usually the right thing to do.
+
+
+[2-4] mprintk's friends
+
+int vmprintk_set_header(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk_set_header but takes va_list @args instead of
+ argument list.
+
+int vmprintk(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk but takes va_list @args instead of argument
+ list.
+
+int vmprintk_flush(struct mprintk *mp, const char *fmt, va_list args)
+
+ Identical to mprintk_flush but takes va_list @args instead of
+ argument list.
+
+
+[3] How libata uses printk_header and mprintk
+
+Me being a libata guy, the first user of printk_header and mprintk is
+libata. libata has printk helpers at each level - port, link and
+device. Let's take a look at the port one.
+
+ int ata_port_printk(struct ata_port *ap, const char *lv,
+ const char *fmt, ...)
+ {
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+ }
+
+It creates a header and calls vprintk_header() with it and passes the
+format string and arguments. Note the separate @lv argument. This is
+remnant of the previous define-based implementation which didn't use
+printk_header and thus had to manually put the message level in front
+of the header. With printk_header, the formatted string can carry the
+log level in front of it and printk_header will do the right thing.
+
+Also, there is a port-level helper to set header of a mprintk buffer.
+
+ void ata_port_mp_header(struct ata_port *ap, const char *lv,
+ struct mprintk *mp)
+ {
+ mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+ }
+
+After initializing mprintk and calling the above function,
+mprintk_add() and mprintk() can be used freely to assemble and print
+messages. For examples, take a look at ata_dev_configure() in
+drivers/ata/libata-core.c and ata_eh_link_report() in
+drivers/ata/libata-eh.c. Note that both functions use ap->sector_buf.
+This is 512 byte buffer owned by the EH thread which happens to be the
+only thread which does EH reporting and device configuration.
+
+Happy hacking.
+
+
+REFERENCES
+
+{1} On SMP, if a CPU does printk while another one is executing
+ console drivers to push out messages, the new message would simply
+ be queued and printk returns.
+
+{2} Documentation/serial-console.txt
+
+{3} Documentation/networking/netconsole.txt
+ Note that netconsole can't be the primary console - the one which
+ provides standard IOs to init - as it can't read from the user.
+ Also, its synchronisity is further limited. On write completion,
+ all that can be assured is that the packets containing the message
+ have been sent. Whether or when the message has arrived on the
+ destination is unknown.
+
+{4} Documentation/sysctl/kernel.txt:printk
+
+{5} Documentation/sysctl/kernel.txt:printk_ratelimit,printk_ratelimit_burst
+
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread
* [PATCH 5/5] libata: make libata use printk_header() and mprintk
2008-02-13 9:09 ` Tejun Heo
@ 2008-02-13 9:09 ` Tejun Heo
-1 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Reimplement libata printk helpers using printk_header, implement
helpers to initialize mprintk and use mprintk during device
configuration and EH reporting.
This fixes various formatting related problems of libata messages such
as misaligned multiline messages, decoded register lines with leading
headers making them difficult to tell to which error they belong to,
awkward manual indents and complex message printing logics. More
importantly, by making message assembly flexible, this patch makes
future changes to device configuration and EH reporting easier.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
drivers/ata/libata-core.c | 204 +++++++++++++++++++++++++++----------------
drivers/ata/libata-eh.c | 182 ++++++++++++++++++--------------------
drivers/ata/libata-pmp.c | 5 +-
drivers/ata/libata-scsi.c | 6 +-
drivers/ata/sata_inic162x.c | 2 +-
drivers/ata/sata_nv.c | 4 +-
include/linux/libata.h | 35 ++++----
7 files changed, 237 insertions(+), 201 deletions(-)
diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 004dae4..da670c0 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -129,6 +129,79 @@ MODULE_LICENSE("GPL");
MODULE_VERSION(DRV_VERSION);
+int ata_port_printk(struct ata_port *ap, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_link_printk(struct ata_link *link, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ if (link->ap->nr_pmp_links)
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ",
+ lv, link->ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_dev_printk(struct ata_device *dev, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, dev->link->ap->print_id, dev->link->pmp + dev->devno);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+void ata_port_mp_header(struct ata_port *ap, const char *lv, struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+}
+
+void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp)
+{
+ if (link->ap->nr_pmp_links)
+ mprintk_set_header(mp, "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ mprintk_set_header(mp, "%sata%u: ", lv, link->ap->print_id);
+}
+
+void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u.%02u: ", lv, dev->link->ap->print_id,
+ dev->link->pmp + dev->devno);
+}
+
/**
* ata_tf_to_fis - Convert ATA taskfile to SATA FIS structure
* @tf: Taskfile to convert
@@ -2006,18 +2079,16 @@ static inline u8 ata_dev_knobble(struct ata_device *dev)
return ((ap->cbl == ATA_CBL_SATA) && (!ata_id_is_sata(dev->id)));
}
-static void ata_dev_config_ncq(struct ata_device *dev,
- char *desc, size_t desc_sz)
+static void ata_dev_config_ncq(struct ata_device *dev, struct mprintk *mp)
{
struct ata_port *ap = dev->link->ap;
int hdepth = 0, ddepth = ata_id_queue_depth(dev->id);
- if (!ata_id_has_ncq(dev->id)) {
- desc[0] = '\0';
+ if (!ata_id_has_ncq(dev->id))
return;
- }
+
if (dev->horkage & ATA_HORKAGE_NONCQ) {
- snprintf(desc, desc_sz, "NCQ (not used)");
+ mprintk(mp, ", NCQ (not used)");
return;
}
if (ap->flags & ATA_FLAG_NCQ) {
@@ -2026,9 +2097,9 @@ static void ata_dev_config_ncq(struct ata_device *dev,
}
if (hdepth >= ddepth)
- snprintf(desc, desc_sz, "NCQ (depth %d)", ddepth);
+ mprintk(mp, ", NCQ (depth %d)", ddepth);
else
- snprintf(desc, desc_sz, "NCQ (depth %d/%d)", hdepth, ddepth);
+ mprintk(mp, ", NCQ (depth %d/%d)", hdepth, ddepth);
}
/**
@@ -2050,8 +2121,8 @@ int ata_dev_configure(struct ata_device *dev)
struct ata_eh_context *ehc = &dev->link->eh_context;
int print_info = ehc->i.flags & ATA_EHI_PRINTINFO;
const u16 *id = dev->id;
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
unsigned long xfer_mask;
- char revbuf[7]; /* XYZ-99\0 */
char fwrevbuf[ATA_ID_FW_REV_LEN+1];
char modelbuf[ATA_ID_PROD_LEN+1];
int rc;
@@ -2065,6 +2136,8 @@ int ata_dev_configure(struct ata_device *dev)
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: ENTER\n", __FUNCTION__);
+ ata_dev_mp_header(dev, KERN_INFO, &mp);
+
/* set horkage */
dev->horkage |= ata_dev_blacklisted(dev);
@@ -2113,57 +2186,49 @@ int ata_dev_configure(struct ata_device *dev)
ata_id_c_string(dev->id, modelbuf, ATA_ID_PROD,
sizeof(modelbuf));
- /* ATA-specific feature tests */
if (dev->class == ATA_DEV_ATA) {
+ /* ATA-specific feature tests */
if (ata_id_is_cfa(id)) {
- if (id[162] & 1) /* CPRM may make this media unusable */
+ /* CPRM may make this media unusable */
+ if ((id[162] & 1) && print_info)
ata_dev_printk(dev, KERN_WARNING,
"supports DRM functions and may "
"not be fully accessable.\n");
- snprintf(revbuf, 7, "CFA");
+ mprintk(&mp, "CFA: ");
} else {
- snprintf(revbuf, 7, "ATA-%d", ata_id_major_version(id));
+ mprintk(&mp, "ATA-%d: ", ata_id_major_version(id));
/* Warn the user if the device has TPM extensions */
- if (ata_id_has_tpm(id))
+ if (ata_id_has_tpm(id) && print_info)
ata_dev_printk(dev, KERN_WARNING,
"supports DRM functions and may "
"not be fully accessable.\n");
}
+ mprintk(&mp, "%s, %s, max %s\n",
+ modelbuf, fwrevbuf, ata_mode_string(xfer_mask));
+
dev->n_sectors = ata_id_n_sectors(id);
+ mprintk(&mp, "%Lu sectors", (unsigned long long)dev->n_sectors);
- if (dev->id[59] & 0x100)
+ if (dev->id[59] & 0x100) {
dev->multi_count = dev->id[59] & 0xff;
+ mprintk(&mp, ", multi %u", dev->multi_count);
+ }
if (ata_id_has_lba(id)) {
- const char *lba_desc;
- char ncq_desc[20];
-
- lba_desc = "LBA";
dev->flags |= ATA_DFLAG_LBA;
+ mprintk(&mp, ", LBA");
+
if (ata_id_has_lba48(id)) {
dev->flags |= ATA_DFLAG_LBA48;
- lba_desc = "LBA48";
-
+ mprintk(&mp, "48");
if (dev->n_sectors >= (1UL << 28) &&
ata_id_has_flush_ext(id))
dev->flags |= ATA_DFLAG_FLUSH_EXT;
}
/* config NCQ */
- ata_dev_config_ncq(dev, ncq_desc, sizeof(ncq_desc));
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u: %s %s\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, lba_desc, ncq_desc);
- }
+ ata_dev_config_ncq(dev, &mp);
} else {
/* CHS */
@@ -2179,27 +2244,13 @@ int ata_dev_configure(struct ata_device *dev)
dev->sectors = id[56];
}
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u, CHS %u/%u/%u\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, dev->cylinders,
- dev->heads, dev->sectors);
- }
+ mprintk(&mp, ", CHS %u/%u/%u",
+ dev->cylinders, dev->heads, dev->sectors);
}
dev->cdb_len = 16;
- }
-
- /* ATAPI-specific feature tests */
- else if (dev->class == ATA_DEV_ATAPI) {
- const char *cdb_intr_string = "";
- const char *atapi_an_string = "";
+ } else if (dev->class == ATA_DEV_ATAPI) {
+ /* ATAPI-specific feature tests */
u32 sntf;
rc = atapi_cdb_len(id);
@@ -2212,6 +2263,14 @@ int ata_dev_configure(struct ata_device *dev)
}
dev->cdb_len = (unsigned int) rc;
+ mprintk(&mp, "ATAPI: %s, %s, max %s", modelbuf, fwrevbuf,
+ ata_mode_string(xfer_mask));
+
+ if (ata_id_cdb_intr(dev->id)) {
+ dev->flags |= ATA_DFLAG_CDB_INTR;
+ mprintk(&mp, ", CDB intr");
+ }
+
/* Enable ATAPI AN if both the host and device have
* the support. If PMP is attached, SNTF is required
* to enable ATAPI AN to discern between PHY status
@@ -2231,22 +2290,9 @@ int ata_dev_configure(struct ata_device *dev)
"(err_mask=0x%x)\n", err_mask);
else {
dev->flags |= ATA_DFLAG_AN;
- atapi_an_string = ", ATAPI AN";
+ mprintk(&mp, ", ATAPI AN");
}
}
-
- if (ata_id_cdb_intr(dev->id)) {
- dev->flags |= ATA_DFLAG_CDB_INTR;
- cdb_intr_string = ", CDB intr";
- }
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "ATAPI: %s, %s, max %s%s%s\n",
- modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask),
- cdb_intr_string, atapi_an_string);
}
/* determine max_sectors */
@@ -2264,9 +2310,7 @@ int ata_dev_configure(struct ata_device *dev)
/* Limit PATA drive on SATA cable bridge transfers to udma5,
200 sectors */
if (ata_dev_knobble(dev)) {
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "applying bridge limits\n");
+ mprintk(&mp, ", applying bridge limits");
dev->udma_mask &= ATA_UDMA5;
dev->max_sectors = ATA_MAX_SECTORS;
}
@@ -2291,21 +2335,21 @@ int ata_dev_configure(struct ata_device *dev)
if (ap->ops->dev_config)
ap->ops->dev_config(dev);
- if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
+ if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
/* Let the user know. We don't want to disallow opens for
rescue purposes, or in case the vendor is just a blithering
idiot. Do this after the dev_config call as some controllers
with buggy firmware may want to avoid reporting false device
bugs */
-
- if (print_info) {
- ata_dev_printk(dev, KERN_WARNING,
-"Drive reports diagnostics failure. This may indicate a drive\n");
- ata_dev_printk(dev, KERN_WARNING,
-"fault or invalid emulation. Contact drive vendor for information.\n");
- }
+ ata_dev_printk(dev, KERN_WARNING,
+ "Drive reports diagnostics failure. This may indicate a drive\n"
+ "fault or invalid emulation. Contact drive vendor for information.\n");
}
+ /* print device info to dmesg */
+ if (ata_msg_drv(ap) && print_info)
+ mprintk_flush(&mp, "\n");
+
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: EXIT, drv_stat = 0x%x\n",
__FUNCTION__, ata_chk_status(ap));
@@ -7544,6 +7588,12 @@ EXPORT_SYMBOL_GPL(sata_deb_timing_hotplug);
EXPORT_SYMBOL_GPL(sata_deb_timing_long);
EXPORT_SYMBOL_GPL(ata_dummy_port_ops);
EXPORT_SYMBOL_GPL(ata_dummy_port_info);
+EXPORT_SYMBOL_GPL(ata_port_printk);
+EXPORT_SYMBOL_GPL(ata_link_printk);
+EXPORT_SYMBOL_GPL(ata_dev_printk);
+EXPORT_SYMBOL_GPL(ata_port_mp_header);
+EXPORT_SYMBOL_GPL(ata_link_mp_header);
+EXPORT_SYMBOL_GPL(ata_dev_mp_header);
EXPORT_SYMBOL_GPL(ata_std_bios_param);
EXPORT_SYMBOL_GPL(ata_std_ports);
EXPORT_SYMBOL_GPL(ata_host_init);
diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 4e31071..2af7755 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -1884,17 +1884,12 @@ static void ata_eh_link_report(struct ata_link *link)
{
struct ata_port *ap = link->ap;
struct ata_eh_context *ehc = &link->eh_context;
- const char *frozen, *desc;
- char tries_buf[6];
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
int tag, nr_failed = 0;
if (ehc->i.flags & ATA_EHI_QUIET)
return;
- desc = NULL;
- if (ehc->i.desc[0] != '\0')
- desc = ehc->i.desc;
-
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
@@ -1911,101 +1906,89 @@ static void ata_eh_link_report(struct ata_link *link)
if (!nr_failed && !ehc->i.err_mask)
return;
- frozen = "";
- if (ap->pflags & ATA_PFLAG_FROZEN)
- frozen = " frozen";
+ if (ehc->i.dev)
+ ata_dev_mp_header(ehc->i.dev, KERN_ERR, &mp);
+ else
+ ata_link_mp_header(link, KERN_ERR, &mp);
- memset(tries_buf, 0, sizeof(tries_buf));
+ mprintk(&mp, "exception Emask 0x%x SAct 0x%x SErr 0x%x action 0x%x",
+ ehc->i.err_mask, link->sactive, ehc->i.serror, ehc->i.action);
+ if (ap->pflags & ATA_PFLAG_FROZEN)
+ mprintk(&mp, " frozen");
if (ap->eh_tries < ATA_EH_MAX_TRIES)
- snprintf(tries_buf, sizeof(tries_buf) - 1, " t%d",
- ap->eh_tries);
+ mprintk(&mp, " t%d", ap->eh_tries);
+ mprintk(&mp, "\n");
- if (ehc->i.dev) {
- ata_dev_printk(ehc->i.dev, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_dev_printk(ehc->i.dev, KERN_ERR, "%s\n", desc);
- } else {
- ata_link_printk(link, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_link_printk(link, KERN_ERR, "%s\n", desc);
- }
+ if (ehc->i.desc[0] != '\0')
+ mprintk(&mp, "%s\n", ehc->i.desc);
if (ehc->i.serror)
- ata_port_printk(ap, KERN_ERR,
- "SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
- ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
- ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
- ehc->i.serror & SERR_DATA ? "UnrecovData " : "",
- ehc->i.serror & SERR_PERSISTENT ? "Persist " : "",
- ehc->i.serror & SERR_PROTOCOL ? "Proto " : "",
- ehc->i.serror & SERR_INTERNAL ? "HostInt " : "",
- ehc->i.serror & SERR_PHYRDY_CHG ? "PHYRdyChg " : "",
- ehc->i.serror & SERR_PHY_INT_ERR ? "PHYInt " : "",
- ehc->i.serror & SERR_COMM_WAKE ? "CommWake " : "",
- ehc->i.serror & SERR_10B_8B_ERR ? "10B8B " : "",
- ehc->i.serror & SERR_DISPARITY ? "Dispar " : "",
- ehc->i.serror & SERR_CRC ? "BadCRC " : "",
- ehc->i.serror & SERR_HANDSHAKE ? "Handshk " : "",
- ehc->i.serror & SERR_LINK_SEQ_ERR ? "LinkSeq " : "",
- ehc->i.serror & SERR_TRANS_ST_ERROR ? "TrStaTrns " : "",
- ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
- ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
+ mprintk(&mp, "SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
+ ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
+ ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
+ ehc->i.serror & SERR_DATA ? "UnrecovData " : "",
+ ehc->i.serror & SERR_PERSISTENT ? "Persist " : "",
+ ehc->i.serror & SERR_PROTOCOL ? "Proto " : "",
+ ehc->i.serror & SERR_INTERNAL ? "HostInt " : "",
+ ehc->i.serror & SERR_PHYRDY_CHG ? "PHYRdyChg " : "",
+ ehc->i.serror & SERR_PHY_INT_ERR ? "PHYInt " : "",
+ ehc->i.serror & SERR_COMM_WAKE ? "CommWake " : "",
+ ehc->i.serror & SERR_10B_8B_ERR ? "10B8B " : "",
+ ehc->i.serror & SERR_DISPARITY ? "Dispar " : "",
+ ehc->i.serror & SERR_CRC ? "BadCRC " : "",
+ ehc->i.serror & SERR_HANDSHAKE ? "Handshk " : "",
+ ehc->i.serror & SERR_LINK_SEQ_ERR ? "LinkSeq " : "",
+ ehc->i.serror & SERR_TRANS_ST_ERROR ? "TrStaTrns " : "",
+ ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
+ ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
+
+ mprintk_flush(&mp, NULL); /* flush link / device wide messages */
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
+ static const char *dma_str[] = {
+ [DMA_BIDIRECTIONAL] = "bidi",
+ [DMA_TO_DEVICE] = "out",
+ [DMA_FROM_DEVICE] = "in",
+ };
+ static const char *prot_str[] = {
+ [ATA_PROT_PIO] = "pio",
+ [ATA_PROT_DMA] = "dma",
+ [ATA_PROT_NCQ] = "ncq",
+ [ATAPI_PROT_PIO] = "pio",
+ [ATAPI_PROT_DMA] = "dma",
+ };
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
struct ata_taskfile *cmd = &qc->tf, *res = &qc->result_tf;
const u8 *cdb = qc->cdb;
- char data_buf[20] = "";
- char cdb_buf[70] = "";
+ int need_newline = 0;
if (!(qc->flags & ATA_QCFLAG_FAILED) ||
qc->dev->link != link || !qc->err_mask)
continue;
- if (qc->dma_dir != DMA_NONE) {
- static const char *dma_str[] = {
- [DMA_BIDIRECTIONAL] = "bidi",
- [DMA_TO_DEVICE] = "out",
- [DMA_FROM_DEVICE] = "in",
- };
- static const char *prot_str[] = {
- [ATA_PROT_PIO] = "pio",
- [ATA_PROT_DMA] = "dma",
- [ATA_PROT_NCQ] = "ncq",
- [ATAPI_PROT_PIO] = "pio",
- [ATAPI_PROT_DMA] = "dma",
- };
-
- snprintf(data_buf, sizeof(data_buf), " %s %u %s",
- prot_str[qc->tf.protocol], qc->nbytes,
- dma_str[qc->dma_dir]);
- }
-
- if (ata_is_atapi(qc->tf.protocol))
- snprintf(cdb_buf, sizeof(cdb_buf),
- "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
- "%02x %02x %02x %02x %02x %02x %02x %02x\n ",
- cdb[0], cdb[1], cdb[2], cdb[3],
- cdb[4], cdb[5], cdb[6], cdb[7],
- cdb[8], cdb[9], cdb[10], cdb[11],
- cdb[12], cdb[13], cdb[14], cdb[15]);
-
- ata_dev_printk(qc->dev, KERN_ERR,
- "cmd %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "tag %d%s\n %s"
- "res %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "Emask 0x%x (%s)%s\n",
+ mprintk(&mp, "cmd %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x tag %d",
cmd->command, cmd->feature, cmd->nsect,
cmd->lbal, cmd->lbam, cmd->lbah,
cmd->hob_feature, cmd->hob_nsect,
cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
- cmd->device, qc->tag, data_buf, cdb_buf,
+ cmd->device, qc->tag);
+
+ if (qc->dma_dir != DMA_NONE)
+ mprintk(&mp, " %s %u %s", prot_str[qc->tf.protocol],
+ qc->nbytes, dma_str[qc->dma_dir]);
+ mprintk(&mp, "\n");
+
+ if (ata_is_atapi(qc->tf.protocol))
+ mprintk(&mp, "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
+ "%02x %02x %02x %02x %02x %02x %02x %02x\n",
+ cdb[0], cdb[1], cdb[2], cdb[3],
+ cdb[4], cdb[5], cdb[6], cdb[7],
+ cdb[8], cdb[9], cdb[10], cdb[11],
+ cdb[12], cdb[13], cdb[14], cdb[15]);
+
+ mprintk(&mp, "res %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x Emask 0x%x (%s)%s\n",
res->command, res->feature, res->nsect,
res->lbal, res->lbam, res->lbah,
res->hob_feature, res->hob_nsect,
@@ -2016,26 +1999,31 @@ static void ata_eh_link_report(struct ata_link *link)
if (res->command & (ATA_BUSY | ATA_DRDY | ATA_DF | ATA_DRQ |
ATA_ERR)) {
if (res->command & ATA_BUSY)
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { Busy }\n");
+ mprintk(&mp, "status: { Busy } ");
else
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { %s%s%s%s}\n",
- res->command & ATA_DRDY ? "DRDY " : "",
- res->command & ATA_DF ? "DF " : "",
- res->command & ATA_DRQ ? "DRQ " : "",
- res->command & ATA_ERR ? "ERR " : "");
+ mprintk(&mp, "status: { %s%s%s%s} ",
+ res->command & ATA_DRDY ? "DRDY " : "",
+ res->command & ATA_DF ? "DF " : "",
+ res->command & ATA_DRQ ? "DRQ " : "",
+ res->command & ATA_ERR ? "ERR " : "");
+ need_newline = 1;
}
if (cmd->command != ATA_CMD_PACKET &&
(res->feature & (ATA_ICRC | ATA_UNC | ATA_IDNF |
- ATA_ABORTED)))
- ata_dev_printk(qc->dev, KERN_ERR,
- "error: { %s%s%s%s}\n",
- res->feature & ATA_ICRC ? "ICRC " : "",
- res->feature & ATA_UNC ? "UNC " : "",
- res->feature & ATA_IDNF ? "IDNF " : "",
- res->feature & ATA_ABORTED ? "ABRT " : "");
+ ATA_ABORTED))) {
+ mprintk(&mp, "error: { %s%s%s%s}",
+ res->feature & ATA_ICRC ? "ICRC " : "",
+ res->feature & ATA_UNC ? "UNC " : "",
+ res->feature & ATA_IDNF ? "IDNF " : "",
+ res->feature & ATA_ABORTED ? "ABRT " : "");
+ need_newline = 1;
+ }
+
+ if (need_newline)
+ mprintk_flush(&mp, "\n");
+ else
+ mprintk_flush(&mp, NULL);
}
}
diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c
index caef2bb..cc6e4ca 100644
--- a/drivers/ata/libata-pmp.c
+++ b/drivers/ata/libata-pmp.c
@@ -408,9 +408,8 @@ static int sata_pmp_configure(struct ata_device *dev, int print_info)
if (!(dev->flags & ATA_DFLAG_AN))
ata_dev_printk(dev, KERN_INFO,
- "Asynchronous notification not supported, "
- "hotplug won't\n work on fan-out "
- "ports. Use warm-plug instead.\n");
+ "Asynchronous notification not supported, hotplug won't\n"
+ "work on fan-out ports. Use warm-plug instead.\n");
}
return 0;
diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
index c02c490..bcf0a3d 100644
--- a/drivers/ata/libata-scsi.c
+++ b/drivers/ata/libata-scsi.c
@@ -3234,9 +3234,9 @@ void ata_scsi_scan_host(struct ata_port *ap, int sync)
goto repeat;
}
- ata_port_printk(ap, KERN_ERR, "WARNING: synchronous SCSI scan "
- "failed without making any progress,\n"
- " switching to async\n");
+ ata_port_printk(ap, KERN_ERR,
+ "WARNING: synchronous SCSI scan failed without making any \n"
+ " progress, switching to async\n");
}
queue_delayed_work(ata_aux_wq, &ap->hotplug_task,
diff --git a/drivers/ata/sata_inic162x.c b/drivers/ata/sata_inic162x.c
index 59e65ed..4ba8534 100644
--- a/drivers/ata/sata_inic162x.c
+++ b/drivers/ata/sata_inic162x.c
@@ -491,7 +491,7 @@ static void inic_dev_config(struct ata_device *dev)
if (dev->n_sectors >= 1 << 28) {
ata_dev_printk(dev, KERN_ERR,
"ERROR: This driver doesn't support LBA48 yet and may cause\n"
- " data corruption on such devices. Disabling.\n");
+ " data corruption on such devices. Disabling.\n");
ata_dev_disable(dev);
}
}
diff --git a/drivers/ata/sata_nv.c b/drivers/ata/sata_nv.c
index ed5473b..85bcfca 100644
--- a/drivers/ata/sata_nv.c
+++ b/drivers/ata/sata_nv.c
@@ -1849,8 +1849,8 @@ static void nv_swncq_ncq_stop(struct ata_port *ap)
"EH in SWNCQ mode,QC:qc_active 0x%X sactive 0x%X\n",
ap->qc_active, ap->link.sactive);
ata_port_printk(ap, KERN_ERR,
- "SWNCQ:qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n "
- "dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
+ "SWNCQ: qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n"
+ " dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
pp->qc_active, pp->defer_queue.defer_bits, pp->last_issue_tag,
pp->dhfis_bits, pp->dmafis_bits, pp->sdbfis_bits);
diff --git a/include/linux/libata.h b/include/linux/libata.h
index bc5a8d0..168170c 100644
--- a/include/linux/libata.h
+++ b/include/linux/libata.h
@@ -787,6 +787,23 @@ static inline int ata_port_is_dummy(struct ata_port *ap)
return ap->ops == &ata_dummy_port_ops;
}
+extern int ata_port_printk(struct ata_port *ap, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_link_printk(struct ata_link *link, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_dev_printk(struct ata_device *dev, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+
+extern void ata_port_mp_header(struct ata_port *ap, const char *lv,
+ struct mprintk *mp);
+extern void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp);
+extern void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp);
+
extern void sata_print_link_status(struct ata_link *link);
extern void ata_port_probe(struct ata_port *);
extern void ata_bus_reset(struct ata_port *ap);
@@ -1074,24 +1091,6 @@ extern void ata_do_eh(struct ata_port *ap, ata_prereset_fn_t prereset,
ata_postreset_fn_t postreset);
/*
- * printk helpers
- */
-#define ata_port_printk(ap, lv, fmt, args...) \
- printk("%sata%u: "fmt, lv, (ap)->print_id , ##args)
-
-#define ata_link_printk(link, lv, fmt, args...) do { \
- if ((link)->ap->nr_pmp_links) \
- printk("%sata%u.%02u: "fmt, lv, (link)->ap->print_id, \
- (link)->pmp , ##args); \
- else \
- printk("%sata%u: "fmt, lv, (link)->ap->print_id , ##args); \
- } while(0)
-
-#define ata_dev_printk(dev, lv, fmt, args...) \
- printk("%sata%u.%02u: "fmt, lv, (dev)->link->ap->print_id, \
- (dev)->link->pmp + (dev)->devno , ##args)
-
-/*
* ata_eh_info helpers
*/
extern void __ata_ehi_push_desc(struct ata_eh_info *ehi, const char *fmt, ...)
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread* [PATCH 5/5] libata: make libata use printk_header() and mprintk
@ 2008-02-13 9:09 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-13 9:09 UTC (permalink / raw)
To: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel, akpm
Cc: Tejun Heo
Reimplement libata printk helpers using printk_header, implement
helpers to initialize mprintk and use mprintk during device
configuration and EH reporting.
This fixes various formatting related problems of libata messages such
as misaligned multiline messages, decoded register lines with leading
headers making them difficult to tell to which error they belong to,
awkward manual indents and complex message printing logics. More
importantly, by making message assembly flexible, this patch makes
future changes to device configuration and EH reporting easier.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
drivers/ata/libata-core.c | 204 +++++++++++++++++++++++++++----------------
drivers/ata/libata-eh.c | 182 ++++++++++++++++++--------------------
drivers/ata/libata-pmp.c | 5 +-
drivers/ata/libata-scsi.c | 6 +-
drivers/ata/sata_inic162x.c | 2 +-
drivers/ata/sata_nv.c | 4 +-
include/linux/libata.h | 35 ++++----
7 files changed, 237 insertions(+), 201 deletions(-)
diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 004dae4..da670c0 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -129,6 +129,79 @@ MODULE_LICENSE("GPL");
MODULE_VERSION(DRV_VERSION);
+int ata_port_printk(struct ata_port *ap, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_link_printk(struct ata_link *link, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ if (link->ap->nr_pmp_links)
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ",
+ lv, link->ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_dev_printk(struct ata_device *dev, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, dev->link->ap->print_id, dev->link->pmp + dev->devno);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+void ata_port_mp_header(struct ata_port *ap, const char *lv, struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+}
+
+void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp)
+{
+ if (link->ap->nr_pmp_links)
+ mprintk_set_header(mp, "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ mprintk_set_header(mp, "%sata%u: ", lv, link->ap->print_id);
+}
+
+void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u.%02u: ", lv, dev->link->ap->print_id,
+ dev->link->pmp + dev->devno);
+}
+
/**
* ata_tf_to_fis - Convert ATA taskfile to SATA FIS structure
* @tf: Taskfile to convert
@@ -2006,18 +2079,16 @@ static inline u8 ata_dev_knobble(struct ata_device *dev)
return ((ap->cbl == ATA_CBL_SATA) && (!ata_id_is_sata(dev->id)));
}
-static void ata_dev_config_ncq(struct ata_device *dev,
- char *desc, size_t desc_sz)
+static void ata_dev_config_ncq(struct ata_device *dev, struct mprintk *mp)
{
struct ata_port *ap = dev->link->ap;
int hdepth = 0, ddepth = ata_id_queue_depth(dev->id);
- if (!ata_id_has_ncq(dev->id)) {
- desc[0] = '\0';
+ if (!ata_id_has_ncq(dev->id))
return;
- }
+
if (dev->horkage & ATA_HORKAGE_NONCQ) {
- snprintf(desc, desc_sz, "NCQ (not used)");
+ mprintk(mp, ", NCQ (not used)");
return;
}
if (ap->flags & ATA_FLAG_NCQ) {
@@ -2026,9 +2097,9 @@ static void ata_dev_config_ncq(struct ata_device *dev,
}
if (hdepth >= ddepth)
- snprintf(desc, desc_sz, "NCQ (depth %d)", ddepth);
+ mprintk(mp, ", NCQ (depth %d)", ddepth);
else
- snprintf(desc, desc_sz, "NCQ (depth %d/%d)", hdepth, ddepth);
+ mprintk(mp, ", NCQ (depth %d/%d)", hdepth, ddepth);
}
/**
@@ -2050,8 +2121,8 @@ int ata_dev_configure(struct ata_device *dev)
struct ata_eh_context *ehc = &dev->link->eh_context;
int print_info = ehc->i.flags & ATA_EHI_PRINTINFO;
const u16 *id = dev->id;
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
unsigned long xfer_mask;
- char revbuf[7]; /* XYZ-99\0 */
char fwrevbuf[ATA_ID_FW_REV_LEN+1];
char modelbuf[ATA_ID_PROD_LEN+1];
int rc;
@@ -2065,6 +2136,8 @@ int ata_dev_configure(struct ata_device *dev)
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: ENTER\n", __FUNCTION__);
+ ata_dev_mp_header(dev, KERN_INFO, &mp);
+
/* set horkage */
dev->horkage |= ata_dev_blacklisted(dev);
@@ -2113,57 +2186,49 @@ int ata_dev_configure(struct ata_device *dev)
ata_id_c_string(dev->id, modelbuf, ATA_ID_PROD,
sizeof(modelbuf));
- /* ATA-specific feature tests */
if (dev->class == ATA_DEV_ATA) {
+ /* ATA-specific feature tests */
if (ata_id_is_cfa(id)) {
- if (id[162] & 1) /* CPRM may make this media unusable */
+ /* CPRM may make this media unusable */
+ if ((id[162] & 1) && print_info)
ata_dev_printk(dev, KERN_WARNING,
"supports DRM functions and may "
"not be fully accessable.\n");
- snprintf(revbuf, 7, "CFA");
+ mprintk(&mp, "CFA: ");
} else {
- snprintf(revbuf, 7, "ATA-%d", ata_id_major_version(id));
+ mprintk(&mp, "ATA-%d: ", ata_id_major_version(id));
/* Warn the user if the device has TPM extensions */
- if (ata_id_has_tpm(id))
+ if (ata_id_has_tpm(id) && print_info)
ata_dev_printk(dev, KERN_WARNING,
"supports DRM functions and may "
"not be fully accessable.\n");
}
+ mprintk(&mp, "%s, %s, max %s\n",
+ modelbuf, fwrevbuf, ata_mode_string(xfer_mask));
+
dev->n_sectors = ata_id_n_sectors(id);
+ mprintk(&mp, "%Lu sectors", (unsigned long long)dev->n_sectors);
- if (dev->id[59] & 0x100)
+ if (dev->id[59] & 0x100) {
dev->multi_count = dev->id[59] & 0xff;
+ mprintk(&mp, ", multi %u", dev->multi_count);
+ }
if (ata_id_has_lba(id)) {
- const char *lba_desc;
- char ncq_desc[20];
-
- lba_desc = "LBA";
dev->flags |= ATA_DFLAG_LBA;
+ mprintk(&mp, ", LBA");
+
if (ata_id_has_lba48(id)) {
dev->flags |= ATA_DFLAG_LBA48;
- lba_desc = "LBA48";
-
+ mprintk(&mp, "48");
if (dev->n_sectors >= (1UL << 28) &&
ata_id_has_flush_ext(id))
dev->flags |= ATA_DFLAG_FLUSH_EXT;
}
/* config NCQ */
- ata_dev_config_ncq(dev, ncq_desc, sizeof(ncq_desc));
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u: %s %s\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, lba_desc, ncq_desc);
- }
+ ata_dev_config_ncq(dev, &mp);
} else {
/* CHS */
@@ -2179,27 +2244,13 @@ int ata_dev_configure(struct ata_device *dev)
dev->sectors = id[56];
}
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u, CHS %u/%u/%u\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, dev->cylinders,
- dev->heads, dev->sectors);
- }
+ mprintk(&mp, ", CHS %u/%u/%u",
+ dev->cylinders, dev->heads, dev->sectors);
}
dev->cdb_len = 16;
- }
-
- /* ATAPI-specific feature tests */
- else if (dev->class == ATA_DEV_ATAPI) {
- const char *cdb_intr_string = "";
- const char *atapi_an_string = "";
+ } else if (dev->class == ATA_DEV_ATAPI) {
+ /* ATAPI-specific feature tests */
u32 sntf;
rc = atapi_cdb_len(id);
@@ -2212,6 +2263,14 @@ int ata_dev_configure(struct ata_device *dev)
}
dev->cdb_len = (unsigned int) rc;
+ mprintk(&mp, "ATAPI: %s, %s, max %s", modelbuf, fwrevbuf,
+ ata_mode_string(xfer_mask));
+
+ if (ata_id_cdb_intr(dev->id)) {
+ dev->flags |= ATA_DFLAG_CDB_INTR;
+ mprintk(&mp, ", CDB intr");
+ }
+
/* Enable ATAPI AN if both the host and device have
* the support. If PMP is attached, SNTF is required
* to enable ATAPI AN to discern between PHY status
@@ -2231,22 +2290,9 @@ int ata_dev_configure(struct ata_device *dev)
"(err_mask=0x%x)\n", err_mask);
else {
dev->flags |= ATA_DFLAG_AN;
- atapi_an_string = ", ATAPI AN";
+ mprintk(&mp, ", ATAPI AN");
}
}
-
- if (ata_id_cdb_intr(dev->id)) {
- dev->flags |= ATA_DFLAG_CDB_INTR;
- cdb_intr_string = ", CDB intr";
- }
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "ATAPI: %s, %s, max %s%s%s\n",
- modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask),
- cdb_intr_string, atapi_an_string);
}
/* determine max_sectors */
@@ -2264,9 +2310,7 @@ int ata_dev_configure(struct ata_device *dev)
/* Limit PATA drive on SATA cable bridge transfers to udma5,
200 sectors */
if (ata_dev_knobble(dev)) {
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "applying bridge limits\n");
+ mprintk(&mp, ", applying bridge limits");
dev->udma_mask &= ATA_UDMA5;
dev->max_sectors = ATA_MAX_SECTORS;
}
@@ -2291,21 +2335,21 @@ int ata_dev_configure(struct ata_device *dev)
if (ap->ops->dev_config)
ap->ops->dev_config(dev);
- if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
+ if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
/* Let the user know. We don't want to disallow opens for
rescue purposes, or in case the vendor is just a blithering
idiot. Do this after the dev_config call as some controllers
with buggy firmware may want to avoid reporting false device
bugs */
-
- if (print_info) {
- ata_dev_printk(dev, KERN_WARNING,
-"Drive reports diagnostics failure. This may indicate a drive\n");
- ata_dev_printk(dev, KERN_WARNING,
-"fault or invalid emulation. Contact drive vendor for information.\n");
- }
+ ata_dev_printk(dev, KERN_WARNING,
+ "Drive reports diagnostics failure. This may indicate a drive\n"
+ "fault or invalid emulation. Contact drive vendor for information.\n");
}
+ /* print device info to dmesg */
+ if (ata_msg_drv(ap) && print_info)
+ mprintk_flush(&mp, "\n");
+
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: EXIT, drv_stat = 0x%x\n",
__FUNCTION__, ata_chk_status(ap));
@@ -7544,6 +7588,12 @@ EXPORT_SYMBOL_GPL(sata_deb_timing_hotplug);
EXPORT_SYMBOL_GPL(sata_deb_timing_long);
EXPORT_SYMBOL_GPL(ata_dummy_port_ops);
EXPORT_SYMBOL_GPL(ata_dummy_port_info);
+EXPORT_SYMBOL_GPL(ata_port_printk);
+EXPORT_SYMBOL_GPL(ata_link_printk);
+EXPORT_SYMBOL_GPL(ata_dev_printk);
+EXPORT_SYMBOL_GPL(ata_port_mp_header);
+EXPORT_SYMBOL_GPL(ata_link_mp_header);
+EXPORT_SYMBOL_GPL(ata_dev_mp_header);
EXPORT_SYMBOL_GPL(ata_std_bios_param);
EXPORT_SYMBOL_GPL(ata_std_ports);
EXPORT_SYMBOL_GPL(ata_host_init);
diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 4e31071..2af7755 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -1884,17 +1884,12 @@ static void ata_eh_link_report(struct ata_link *link)
{
struct ata_port *ap = link->ap;
struct ata_eh_context *ehc = &link->eh_context;
- const char *frozen, *desc;
- char tries_buf[6];
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
int tag, nr_failed = 0;
if (ehc->i.flags & ATA_EHI_QUIET)
return;
- desc = NULL;
- if (ehc->i.desc[0] != '\0')
- desc = ehc->i.desc;
-
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
@@ -1911,101 +1906,89 @@ static void ata_eh_link_report(struct ata_link *link)
if (!nr_failed && !ehc->i.err_mask)
return;
- frozen = "";
- if (ap->pflags & ATA_PFLAG_FROZEN)
- frozen = " frozen";
+ if (ehc->i.dev)
+ ata_dev_mp_header(ehc->i.dev, KERN_ERR, &mp);
+ else
+ ata_link_mp_header(link, KERN_ERR, &mp);
- memset(tries_buf, 0, sizeof(tries_buf));
+ mprintk(&mp, "exception Emask 0x%x SAct 0x%x SErr 0x%x action 0x%x",
+ ehc->i.err_mask, link->sactive, ehc->i.serror, ehc->i.action);
+ if (ap->pflags & ATA_PFLAG_FROZEN)
+ mprintk(&mp, " frozen");
if (ap->eh_tries < ATA_EH_MAX_TRIES)
- snprintf(tries_buf, sizeof(tries_buf) - 1, " t%d",
- ap->eh_tries);
+ mprintk(&mp, " t%d", ap->eh_tries);
+ mprintk(&mp, "\n");
- if (ehc->i.dev) {
- ata_dev_printk(ehc->i.dev, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_dev_printk(ehc->i.dev, KERN_ERR, "%s\n", desc);
- } else {
- ata_link_printk(link, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_link_printk(link, KERN_ERR, "%s\n", desc);
- }
+ if (ehc->i.desc[0] != '\0')
+ mprintk(&mp, "%s\n", ehc->i.desc);
if (ehc->i.serror)
- ata_port_printk(ap, KERN_ERR,
- "SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
- ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
- ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
- ehc->i.serror & SERR_DATA ? "UnrecovData " : "",
- ehc->i.serror & SERR_PERSISTENT ? "Persist " : "",
- ehc->i.serror & SERR_PROTOCOL ? "Proto " : "",
- ehc->i.serror & SERR_INTERNAL ? "HostInt " : "",
- ehc->i.serror & SERR_PHYRDY_CHG ? "PHYRdyChg " : "",
- ehc->i.serror & SERR_PHY_INT_ERR ? "PHYInt " : "",
- ehc->i.serror & SERR_COMM_WAKE ? "CommWake " : "",
- ehc->i.serror & SERR_10B_8B_ERR ? "10B8B " : "",
- ehc->i.serror & SERR_DISPARITY ? "Dispar " : "",
- ehc->i.serror & SERR_CRC ? "BadCRC " : "",
- ehc->i.serror & SERR_HANDSHAKE ? "Handshk " : "",
- ehc->i.serror & SERR_LINK_SEQ_ERR ? "LinkSeq " : "",
- ehc->i.serror & SERR_TRANS_ST_ERROR ? "TrStaTrns " : "",
- ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
- ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
+ mprintk(&mp, "SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
+ ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
+ ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
+ ehc->i.serror & SERR_DATA ? "UnrecovData " : "",
+ ehc->i.serror & SERR_PERSISTENT ? "Persist " : "",
+ ehc->i.serror & SERR_PROTOCOL ? "Proto " : "",
+ ehc->i.serror & SERR_INTERNAL ? "HostInt " : "",
+ ehc->i.serror & SERR_PHYRDY_CHG ? "PHYRdyChg " : "",
+ ehc->i.serror & SERR_PHY_INT_ERR ? "PHYInt " : "",
+ ehc->i.serror & SERR_COMM_WAKE ? "CommWake " : "",
+ ehc->i.serror & SERR_10B_8B_ERR ? "10B8B " : "",
+ ehc->i.serror & SERR_DISPARITY ? "Dispar " : "",
+ ehc->i.serror & SERR_CRC ? "BadCRC " : "",
+ ehc->i.serror & SERR_HANDSHAKE ? "Handshk " : "",
+ ehc->i.serror & SERR_LINK_SEQ_ERR ? "LinkSeq " : "",
+ ehc->i.serror & SERR_TRANS_ST_ERROR ? "TrStaTrns " : "",
+ ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
+ ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
+
+ mprintk_flush(&mp, NULL); /* flush link / device wide messages */
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
+ static const char *dma_str[] = {
+ [DMA_BIDIRECTIONAL] = "bidi",
+ [DMA_TO_DEVICE] = "out",
+ [DMA_FROM_DEVICE] = "in",
+ };
+ static const char *prot_str[] = {
+ [ATA_PROT_PIO] = "pio",
+ [ATA_PROT_DMA] = "dma",
+ [ATA_PROT_NCQ] = "ncq",
+ [ATAPI_PROT_PIO] = "pio",
+ [ATAPI_PROT_DMA] = "dma",
+ };
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
struct ata_taskfile *cmd = &qc->tf, *res = &qc->result_tf;
const u8 *cdb = qc->cdb;
- char data_buf[20] = "";
- char cdb_buf[70] = "";
+ int need_newline = 0;
if (!(qc->flags & ATA_QCFLAG_FAILED) ||
qc->dev->link != link || !qc->err_mask)
continue;
- if (qc->dma_dir != DMA_NONE) {
- static const char *dma_str[] = {
- [DMA_BIDIRECTIONAL] = "bidi",
- [DMA_TO_DEVICE] = "out",
- [DMA_FROM_DEVICE] = "in",
- };
- static const char *prot_str[] = {
- [ATA_PROT_PIO] = "pio",
- [ATA_PROT_DMA] = "dma",
- [ATA_PROT_NCQ] = "ncq",
- [ATAPI_PROT_PIO] = "pio",
- [ATAPI_PROT_DMA] = "dma",
- };
-
- snprintf(data_buf, sizeof(data_buf), " %s %u %s",
- prot_str[qc->tf.protocol], qc->nbytes,
- dma_str[qc->dma_dir]);
- }
-
- if (ata_is_atapi(qc->tf.protocol))
- snprintf(cdb_buf, sizeof(cdb_buf),
- "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
- "%02x %02x %02x %02x %02x %02x %02x %02x\n ",
- cdb[0], cdb[1], cdb[2], cdb[3],
- cdb[4], cdb[5], cdb[6], cdb[7],
- cdb[8], cdb[9], cdb[10], cdb[11],
- cdb[12], cdb[13], cdb[14], cdb[15]);
-
- ata_dev_printk(qc->dev, KERN_ERR,
- "cmd %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "tag %d%s\n %s"
- "res %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "Emask 0x%x (%s)%s\n",
+ mprintk(&mp, "cmd %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x tag %d",
cmd->command, cmd->feature, cmd->nsect,
cmd->lbal, cmd->lbam, cmd->lbah,
cmd->hob_feature, cmd->hob_nsect,
cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
- cmd->device, qc->tag, data_buf, cdb_buf,
+ cmd->device, qc->tag);
+
+ if (qc->dma_dir != DMA_NONE)
+ mprintk(&mp, " %s %u %s", prot_str[qc->tf.protocol],
+ qc->nbytes, dma_str[qc->dma_dir]);
+ mprintk(&mp, "\n");
+
+ if (ata_is_atapi(qc->tf.protocol))
+ mprintk(&mp, "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
+ "%02x %02x %02x %02x %02x %02x %02x %02x\n",
+ cdb[0], cdb[1], cdb[2], cdb[3],
+ cdb[4], cdb[5], cdb[6], cdb[7],
+ cdb[8], cdb[9], cdb[10], cdb[11],
+ cdb[12], cdb[13], cdb[14], cdb[15]);
+
+ mprintk(&mp, "res %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x Emask 0x%x (%s)%s\n",
res->command, res->feature, res->nsect,
res->lbal, res->lbam, res->lbah,
res->hob_feature, res->hob_nsect,
@@ -2016,26 +1999,31 @@ static void ata_eh_link_report(struct ata_link *link)
if (res->command & (ATA_BUSY | ATA_DRDY | ATA_DF | ATA_DRQ |
ATA_ERR)) {
if (res->command & ATA_BUSY)
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { Busy }\n");
+ mprintk(&mp, "status: { Busy } ");
else
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { %s%s%s%s}\n",
- res->command & ATA_DRDY ? "DRDY " : "",
- res->command & ATA_DF ? "DF " : "",
- res->command & ATA_DRQ ? "DRQ " : "",
- res->command & ATA_ERR ? "ERR " : "");
+ mprintk(&mp, "status: { %s%s%s%s} ",
+ res->command & ATA_DRDY ? "DRDY " : "",
+ res->command & ATA_DF ? "DF " : "",
+ res->command & ATA_DRQ ? "DRQ " : "",
+ res->command & ATA_ERR ? "ERR " : "");
+ need_newline = 1;
}
if (cmd->command != ATA_CMD_PACKET &&
(res->feature & (ATA_ICRC | ATA_UNC | ATA_IDNF |
- ATA_ABORTED)))
- ata_dev_printk(qc->dev, KERN_ERR,
- "error: { %s%s%s%s}\n",
- res->feature & ATA_ICRC ? "ICRC " : "",
- res->feature & ATA_UNC ? "UNC " : "",
- res->feature & ATA_IDNF ? "IDNF " : "",
- res->feature & ATA_ABORTED ? "ABRT " : "");
+ ATA_ABORTED))) {
+ mprintk(&mp, "error: { %s%s%s%s}",
+ res->feature & ATA_ICRC ? "ICRC " : "",
+ res->feature & ATA_UNC ? "UNC " : "",
+ res->feature & ATA_IDNF ? "IDNF " : "",
+ res->feature & ATA_ABORTED ? "ABRT " : "");
+ need_newline = 1;
+ }
+
+ if (need_newline)
+ mprintk_flush(&mp, "\n");
+ else
+ mprintk_flush(&mp, NULL);
}
}
diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c
index caef2bb..cc6e4ca 100644
--- a/drivers/ata/libata-pmp.c
+++ b/drivers/ata/libata-pmp.c
@@ -408,9 +408,8 @@ static int sata_pmp_configure(struct ata_device *dev, int print_info)
if (!(dev->flags & ATA_DFLAG_AN))
ata_dev_printk(dev, KERN_INFO,
- "Asynchronous notification not supported, "
- "hotplug won't\n work on fan-out "
- "ports. Use warm-plug instead.\n");
+ "Asynchronous notification not supported, hotplug won't\n"
+ "work on fan-out ports. Use warm-plug instead.\n");
}
return 0;
diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
index c02c490..bcf0a3d 100644
--- a/drivers/ata/libata-scsi.c
+++ b/drivers/ata/libata-scsi.c
@@ -3234,9 +3234,9 @@ void ata_scsi_scan_host(struct ata_port *ap, int sync)
goto repeat;
}
- ata_port_printk(ap, KERN_ERR, "WARNING: synchronous SCSI scan "
- "failed without making any progress,\n"
- " switching to async\n");
+ ata_port_printk(ap, KERN_ERR,
+ "WARNING: synchronous SCSI scan failed without making any \n"
+ " progress, switching to async\n");
}
queue_delayed_work(ata_aux_wq, &ap->hotplug_task,
diff --git a/drivers/ata/sata_inic162x.c b/drivers/ata/sata_inic162x.c
index 59e65ed..4ba8534 100644
--- a/drivers/ata/sata_inic162x.c
+++ b/drivers/ata/sata_inic162x.c
@@ -491,7 +491,7 @@ static void inic_dev_config(struct ata_device *dev)
if (dev->n_sectors >= 1 << 28) {
ata_dev_printk(dev, KERN_ERR,
"ERROR: This driver doesn't support LBA48 yet and may cause\n"
- " data corruption on such devices. Disabling.\n");
+ " data corruption on such devices. Disabling.\n");
ata_dev_disable(dev);
}
}
diff --git a/drivers/ata/sata_nv.c b/drivers/ata/sata_nv.c
index ed5473b..85bcfca 100644
--- a/drivers/ata/sata_nv.c
+++ b/drivers/ata/sata_nv.c
@@ -1849,8 +1849,8 @@ static void nv_swncq_ncq_stop(struct ata_port *ap)
"EH in SWNCQ mode,QC:qc_active 0x%X sactive 0x%X\n",
ap->qc_active, ap->link.sactive);
ata_port_printk(ap, KERN_ERR,
- "SWNCQ:qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n "
- "dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
+ "SWNCQ: qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n"
+ " dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
pp->qc_active, pp->defer_queue.defer_bits, pp->last_issue_tag,
pp->dhfis_bits, pp->dmafis_bits, pp->sdbfis_bits);
diff --git a/include/linux/libata.h b/include/linux/libata.h
index bc5a8d0..168170c 100644
--- a/include/linux/libata.h
+++ b/include/linux/libata.h
@@ -787,6 +787,23 @@ static inline int ata_port_is_dummy(struct ata_port *ap)
return ap->ops == &ata_dummy_port_ops;
}
+extern int ata_port_printk(struct ata_port *ap, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_link_printk(struct ata_link *link, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_dev_printk(struct ata_device *dev, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+
+extern void ata_port_mp_header(struct ata_port *ap, const char *lv,
+ struct mprintk *mp);
+extern void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp);
+extern void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp);
+
extern void sata_print_link_status(struct ata_link *link);
extern void ata_port_probe(struct ata_port *);
extern void ata_bus_reset(struct ata_port *ap);
@@ -1074,24 +1091,6 @@ extern void ata_do_eh(struct ata_port *ap, ata_prereset_fn_t prereset,
ata_postreset_fn_t postreset);
/*
- * printk helpers
- */
-#define ata_port_printk(ap, lv, fmt, args...) \
- printk("%sata%u: "fmt, lv, (ap)->print_id , ##args)
-
-#define ata_link_printk(link, lv, fmt, args...) do { \
- if ((link)->ap->nr_pmp_links) \
- printk("%sata%u.%02u: "fmt, lv, (link)->ap->print_id, \
- (link)->pmp , ##args); \
- else \
- printk("%sata%u: "fmt, lv, (link)->ap->print_id , ##args); \
- } while(0)
-
-#define ata_dev_printk(dev, lv, fmt, args...) \
- printk("%sata%u.%02u: "fmt, lv, (dev)->link->ap->print_id, \
- (dev)->link->pmp + (dev)->devno , ##args)
-
-/*
* ata_eh_info helpers
*/
extern void __ata_ehi_push_desc(struct ata_eh_info *ehi, const char *fmt, ...)
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-13 9:09 ` Tejun Heo
` (5 preceding siblings ...)
(?)
@ 2008-02-13 23:57 ` Andrew Morton
2008-02-14 0:40 ` Tejun Heo
-1 siblings, 1 reply; 24+ messages in thread
From: Andrew Morton @ 2008-02-13 23:57 UTC (permalink / raw)
To: Tejun Heo
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
On Wed, 13 Feb 2008 18:09:28 +0900
Tejun Heo <htejun@gmail.com> wrote:
> This is the third take of implement-printk_header-and-mprintk
> patchset.
>
> Changes from the last take[L] are...
>
> * Now header is printed on every line of a multiline message. If the
> header ends with ':' followed by spaces. The colon is replaced with
> space from the second line.
>
> * s/mprintk/mprintk_flush/ and s/mprintk_add/mprintk/ as suggested.
>
> * mprintk_init_alloc() and mprintk_free() added to ease malloc'd
> buffer handling. No need to specify buffer size. Sizing is left to
> mprintk.
>
> This patchset aims to make printing multiline messages and assembling
> message piece-by-piece easier.
>
> In a nutshell, printk_header() lets you do the following atomically
> (against other messages).
>
> code:
> printk(KERN_INFO "ata1.00: ", "line0\nline1\nline2\n");
>
> output:
> <6>ata1.00: line0
> <6>ata1.00 line1
> <6>ata1.00 line2
That seems sensible.
> And mprintk the following.
>
> code:
> DEFINE_MPRINTK(mp, 2 * 80);
>
> mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
> mprintk_push(&mp, "ATA %d", 7);
> mprintk_push(&mp, ", %u sectors\n", 1024);
> mprintk(&mp, "everything seems dandy\n");
>
> output:
> <6>ata1.00: ATA 7, 1024 sectors
> <6>ata1.00 everything seems dandy
>
And that looks like an awful lot of fuss. Is it really worth doing?
^ permalink raw reply [flat|nested] 24+ messages in thread* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-13 23:57 ` [PATCHSET] printk: implement printk_header() and merging printk, take #3 Andrew Morton
@ 2008-02-14 0:40 ` Tejun Heo
2008-02-14 1:09 ` Andrew Morton
2008-02-14 16:29 ` Mark Lord
0 siblings, 2 replies; 24+ messages in thread
From: Tejun Heo @ 2008-02-14 0:40 UTC (permalink / raw)
To: Andrew Morton
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
Andrew Morton wrote:
>> And mprintk the following.
>>
>> code:
>> DEFINE_MPRINTK(mp, 2 * 80);
>>
>> mprintk_set_header(&mp, KERN_INFO "ata%u.%2u: ", 1, 0);
>> mprintk_push(&mp, "ATA %d", 7);
>> mprintk_push(&mp, ", %u sectors\n", 1024);
>> mprintk(&mp, "everything seems dandy\n");
>>
>> output:
>> <6>ata1.00: ATA 7, 1024 sectors
>> <6>ata1.00 everything seems dandy
>
> And that looks like an awful lot of fuss. Is it really worth doing?
In the above example, s/mprintk(/mprintk_flush(/ and
s/mprintk_push(/mprintk(/
Can you please take a look at ata_eh_link_report() in
drivers/ata/libata-eh.c? Currently, it has some problems.
* All that it wants to do is printing some messages but it's awfully
complex with temp bufs and super-long printk calls containing optional %s's.
* status / error decode print outs are printed separately from cmd/res
making it difficult to tell how they are grouped. Putting them together
would require allocating another temp buf(s) and adding extra %s's to
cmd/res printout.
* For timeouts, result TF isn't available and thus res printout is
misleading. res shouldn't be printed after timeouts. This would
require allocating yest another temp buf and separating out res printing
into separate snprintf.
I was trying to do this and got fed up with all the tricks in the
function. The only sane way out is to build messages piece-by-piece
into a buffer and print it at once. The eh message is gigantic and I
needed to allocate the buffer elsewhere than stack.
ata_eh_link_report() fortunately has fixed place for that -
ap->sector_buf - but let's assume there was no such buffer for the
discussion. I'm still not too sure whether it's wise to use sector_buf
for message building anyway.
The only way is to malloc the buffer. Once the buffer is available,
building message using snprintf is a bit cumbersome but is okay. The
problem is that malloc can fail. To handle that case, we basically need
to do
if (buf)
printed += snprintf(buf + printed, len - printed, ...);
else
printk(...);
which is very cumbersome, so we need a wrapper around the above. As the
wrapper needs to control when the message goes out, a flush function is
necessary too. Combine those with overflow handling - mprintk.
Similar problem exists for ata_dev_configure() in
drivers/ata/libata-core.c although it's a bit better there. Please take
a look at the fifth patch. It doesn't remove a lot of lines but it
streamlines both functions significantly. For ata_dev_configure(),
message reporting becomes what the function does secondarily while
configuring the device, not something it's structured around.
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 24+ messages in thread* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-14 0:40 ` Tejun Heo
@ 2008-02-14 1:09 ` Andrew Morton
2008-02-14 1:26 ` Tejun Heo
2008-02-14 16:29 ` Mark Lord
1 sibling, 1 reply; 24+ messages in thread
From: Andrew Morton @ 2008-02-14 1:09 UTC (permalink / raw)
To: Tejun Heo
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
On Thu, 14 Feb 2008 09:40:51 +0900
Tejun Heo <htejun@gmail.com> wrote:
> Can you please take a look at ata_eh_link_report() in
> drivers/ata/libata-eh.c?
I did. Punishment?
> Currently, it has some problems.
Yes, and the patches do clean that up.
ho hum. What tends to happen with this sort of thing is that fi we merge
it, it ends up getting used more often than one expected...
If you stand back and squint at it, there are quite a few places where we
do this sort of thing: allocate a buffer, squirt characters into it,
reallocating and/or flushing as we proceed. All sysfs and procfs read-side
code, for a start...
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-14 1:09 ` Andrew Morton
@ 2008-02-14 1:26 ` Tejun Heo
2008-02-15 1:49 ` Tejun Heo
0 siblings, 1 reply; 24+ messages in thread
From: Tejun Heo @ 2008-02-14 1:26 UTC (permalink / raw)
To: Andrew Morton
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
Hello,
Andrew Morton wrote:
> On Thu, 14 Feb 2008 09:40:51 +0900
> Tejun Heo <htejun@gmail.com> wrote:
>
>> Can you please take a look at ata_eh_link_report() in
>> drivers/ata/libata-eh.c?
>
> I did. Punishment?
Heh.. :-)
>> Currently, it has some problems.
>
> Yes, and the patches do clean that up.
Yeap, it does.
> ho hum. What tends to happen with this sort of thing is that fi we merge
> it, it ends up getting used more often than one expected...
Hmmm... Okay. mprintk being printk, I'm not too sure how it can go over
usual expectations but well, yeah, that actually is my expectation.
> If you stand back and squint at it, there are quite a few places where we
> do this sort of thing: allocate a buffer, squirt characters into it,
> reallocating and/or flushing as we proceed. All sysfs and procfs read-side
> code, for a start...
printk is a special case, I think. It's the primary logging/debugging
method which can't fail and as it's mostly interpreted by human beings
(and developers in problematic cases), it has different maneuvering room
on errors - ie. it's far better to print messages w/o header or proper
log level than failing to print, which is quite different requirements
from other components.
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-14 1:26 ` Tejun Heo
@ 2008-02-15 1:49 ` Tejun Heo
2008-02-15 2:27 ` Andrew Morton
0 siblings, 1 reply; 24+ messages in thread
From: Tejun Heo @ 2008-02-15 1:49 UTC (permalink / raw)
To: Andrew Morton
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
Tejun Heo wrote:
> Hello,
>
> Andrew Morton wrote:
>> On Thu, 14 Feb 2008 09:40:51 +0900
>> Tejun Heo <htejun@gmail.com> wrote:
>>
>>> Can you please take a look at ata_eh_link_report() in
>>> drivers/ata/libata-eh.c?
>> I did. Punishment?
>
> Heh.. :-)
>
>>> Currently, it has some problems.
>> Yes, and the patches do clean that up.
>
> Yeap, it does.
>
>> ho hum. What tends to happen with this sort of thing is that fi we merge
>> it, it ends up getting used more often than one expected...
>
> Hmmm... Okay. mprintk being printk, I'm not too sure how it can go over
> usual expectations but well, yeah, that actually is my expectation.
>
>> If you stand back and squint at it, there are quite a few places where we
>> do this sort of thing: allocate a buffer, squirt characters into it,
>> reallocating and/or flushing as we proceed. All sysfs and procfs read-side
>> code, for a start...
>
> printk is a special case, I think. It's the primary logging/debugging
> method which can't fail and as it's mostly interpreted by human beings
> (and developers in problematic cases), it has different maneuvering room
> on errors - ie. it's far better to print messages w/o header or proper
> log level than failing to print, which is quite different requirements
> from other components.
Andrew, any more comments or suggestions on how to proceed on this? One
way or the other, I think this is a problem worth solving.
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-15 1:49 ` Tejun Heo
@ 2008-02-15 2:27 ` Andrew Morton
2008-02-15 2:36 ` Tejun Heo
0 siblings, 1 reply; 24+ messages in thread
From: Andrew Morton @ 2008-02-15 2:27 UTC (permalink / raw)
To: Tejun Heo
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
On Fri, 15 Feb 2008 10:49:31 +0900 Tejun Heo <htejun@gmail.com> wrote:
> > printk is a special case, I think. It's the primary logging/debugging
> > method which can't fail and as it's mostly interpreted by human beings
> > (and developers in problematic cases), it has different maneuvering room
> > on errors - ie. it's far better to print messages w/o header or proper
> > log level than failing to print, which is quite different requirements
> > from other components.
>
> Andrew, any more comments or suggestions on how to proceed on this?
Nope.
> One
> way or the other, I think this is a problem worth solving.
There are a lot of such problems ;)
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-15 2:27 ` Andrew Morton
@ 2008-02-15 2:36 ` Tejun Heo
2008-02-15 2:50 ` Andrew Morton
0 siblings, 1 reply; 24+ messages in thread
From: Tejun Heo @ 2008-02-15 2:36 UTC (permalink / raw)
To: Andrew Morton
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
Andrew Morton wrote:
>>> printk is a special case, I think. It's the primary logging/debugging
>>> method which can't fail and as it's mostly interpreted by human beings
>>> (and developers in problematic cases), it has different maneuvering room
>>> on errors - ie. it's far better to print messages w/o header or proper
>>> log level than failing to print, which is quite different requirements
>>> from other components.
>> Andrew, any more comments or suggestions on how to proceed on this?
>
> Nope.
>
>> One
>> way or the other, I think this is a problem worth solving.
>
> There are a lot of such problems ;)
So, I guess it's NACK w/o suggested alternatives, right?
--
tejun
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-15 2:36 ` Tejun Heo
@ 2008-02-15 2:50 ` Andrew Morton
2008-02-15 3:16 ` Tejun Heo
0 siblings, 1 reply; 24+ messages in thread
From: Andrew Morton @ 2008-02-15 2:50 UTC (permalink / raw)
To: Tejun Heo
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
On Fri, 15 Feb 2008 11:36:12 +0900 Tejun Heo <htejun@gmail.com> wrote:
> Andrew Morton wrote:
> >>> printk is a special case, I think. It's the primary logging/debugging
> >>> method which can't fail and as it's mostly interpreted by human beings
> >>> (and developers in problematic cases), it has different maneuvering room
> >>> on errors - ie. it's far better to print messages w/o header or proper
> >>> log level than failing to print, which is quite different requirements
> >>> from other components.
> >> Andrew, any more comments or suggestions on how to proceed on this?
> >
> > Nope.
> >
> >> One
> >> way or the other, I think this is a problem worth solving.
> >
> > There are a lot of such problems ;)
>
> So, I guess it's NACK w/o suggested alternatives, right?
>
I wouldn't nack without good reasons, and I have none here. I don't have
very strong opinions either way.
As a seat-of-the-pants thing, it does seem to be a lot of core code to
solve a fairly minor problem in (afaik) one remote place. But I haven't
looked - perhaps there are other places which could be improved if such
facilities were available.
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-15 2:50 ` Andrew Morton
@ 2008-02-15 3:16 ` Tejun Heo
2008-02-16 14:13 ` Mark Lord
0 siblings, 1 reply; 24+ messages in thread
From: Tejun Heo @ 2008-02-15 3:16 UTC (permalink / raw)
To: Andrew Morton
Cc: jeff, linux-ide, jengelh, matthew, randy.dunlap, daniel.ritz-ml,
linux-kernel
Andrew Morton wrote:
>> So, I guess it's NACK w/o suggested alternatives, right?
>
> I wouldn't nack without good reasons, and I have none here. I don't have
> very strong opinions either way.
I was just wondering whether I should just go with snprintf dancing in
eh_link_report, which does make sense if not many need merging printk.
> As a seat-of-the-pants thing, it does seem to be a lot of core code to
> solve a fairly minor problem in (afaik) one remote place. But I haven't
> looked - perhaps there are other places which could be improved if such
> facilities were available.
Okay, I see. I'll look around and see whether there are other places
which can use it. I can think of a few in SCSI. Let's see.
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-15 3:16 ` Tejun Heo
@ 2008-02-16 14:13 ` Mark Lord
0 siblings, 0 replies; 24+ messages in thread
From: Mark Lord @ 2008-02-16 14:13 UTC (permalink / raw)
To: Tejun Heo
Cc: Andrew Morton, jeff, linux-ide, jengelh, matthew, randy.dunlap,
daniel.ritz-ml, linux-kernel
Tejun Heo wrote:
> Andrew Morton wrote:
>>> So, I guess it's NACK w/o suggested alternatives, right?
>> I wouldn't nack without good reasons, and I have none here. I don't have
>> very strong opinions either way.
>
> I was just wondering whether I should just go with snprintf dancing in
> eh_link_report, which does make sense if not many need merging printk.
..
Any chance you could poke through snprintf() and look for the off-by-one bug
on the return result? (I think it happens when "n" is exceeded).
:)
^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCHSET] printk: implement printk_header() and merging printk, take #3
2008-02-14 0:40 ` Tejun Heo
2008-02-14 1:09 ` Andrew Morton
@ 2008-02-14 16:29 ` Mark Lord
1 sibling, 0 replies; 24+ messages in thread
From: Mark Lord @ 2008-02-14 16:29 UTC (permalink / raw)
To: Tejun Heo
Cc: Andrew Morton, jeff, linux-ide, jengelh, matthew, randy.dunlap,
daniel.ritz-ml, linux-kernel
Tejun Heo wrote:
>..
> * For timeouts, result TF isn't available and thus res printout is
> misleading. res shouldn't be printed after timeouts. This would
> require allocating yest another temp buf and separating out res printing
> into separate snprintf.
..
And snprintf() is buggy, by the way. It does not always seem to return
the correct character fill counts. I've given up trying to use it here
for anything in kernelspace that *must* work.
Someday I'll go back and try to figure out where it's screwing up.
I think it is doing so in the cases where it runs out of space in the buffer.
-ml
^ permalink raw reply [flat|nested] 24+ messages in thread
* [PATCH 5/5] libata: make libata use printk_header() and mprintk
2008-01-21 5:13 [PATCHSET] printk: implement printk_header() and merging printk, take #2 Tejun Heo
@ 2008-01-21 5:13 ` Tejun Heo
0 siblings, 0 replies; 24+ messages in thread
From: Tejun Heo @ 2008-01-21 5:13 UTC (permalink / raw)
To: randy.dunlap, daniel.ritz-ml, matthew, jeff, linux-kernel,
linux-ide
Cc: Tejun Heo
Reimplement libata printk helpers using printk_header, implement
helpers to initialize mprintk and use mprintk during device
configuration and EH reporting.
This fixes various formatting related problems of libata messages such
as misaligned multiline messages, decoded register lines with leading
headers making them difficult to tell to which error they belong to,
awkward manual indents and complex message printing logics. More
importantly, by making message assembly flexible, this patch makes
future changes to device configuration and EH reporting easier.
Signed-off-by: Tejun Heo <htejun@gmail.com>
---
drivers/ata/libata-core.c | 202 +++++++++++++++++++++++++++----------------
drivers/ata/libata-eh.c | 150 +++++++++++++++-----------------
drivers/ata/libata-pmp.c | 5 +-
drivers/ata/libata-scsi.c | 6 +-
drivers/ata/sata_inic162x.c | 2 +-
drivers/ata/sata_nv.c | 4 +-
include/linux/libata.h | 35 ++++----
7 files changed, 223 insertions(+), 181 deletions(-)
diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 6380726..248e1c9 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -125,6 +125,79 @@ MODULE_LICENSE("GPL");
MODULE_VERSION(DRV_VERSION);
+int ata_port_printk(struct ata_port *ap, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ", lv, ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_link_printk(struct ata_link *link, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ if (link->ap->nr_pmp_links)
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ snprintf(hbuf, sizeof(hbuf), "%sata%u: ",
+ lv, link->ap->print_id);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+int ata_dev_printk(struct ata_device *dev, const char *lv, const char *fmt, ...)
+{
+ va_list args;
+ char hbuf[16];
+ int ret;
+
+ snprintf(hbuf, sizeof(hbuf), "%sata%u.%02u: ",
+ lv, dev->link->ap->print_id, dev->link->pmp + dev->devno);
+
+ va_start(args, fmt);
+ ret = vprintk_header(hbuf, fmt, args);
+ va_end(args);
+
+ return ret;
+}
+
+void ata_port_mp_header(struct ata_port *ap, const char *lv, struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u: ", lv, ap->print_id);
+}
+
+void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp)
+{
+ if (link->ap->nr_pmp_links)
+ mprintk_set_header(mp, "%sata%u.%02u: ",
+ lv, link->ap->print_id, link->pmp);
+ else
+ mprintk_set_header(mp, "%sata%u: ", lv, link->ap->print_id);
+}
+
+void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp)
+{
+ mprintk_set_header(mp, "%sata%u.%02u: ", lv, dev->link->ap->print_id,
+ dev->link->pmp + dev->devno);
+}
+
/**
* ata_tf_to_fis - Convert ATA taskfile to SATA FIS structure
* @tf: Taskfile to convert
@@ -2046,18 +2119,16 @@ static inline u8 ata_dev_knobble(struct ata_device *dev)
return ((ap->cbl == ATA_CBL_SATA) && (!ata_id_is_sata(dev->id)));
}
-static void ata_dev_config_ncq(struct ata_device *dev,
- char *desc, size_t desc_sz)
+static void ata_dev_config_ncq(struct ata_device *dev, struct mprintk *mp)
{
struct ata_port *ap = dev->link->ap;
int hdepth = 0, ddepth = ata_id_queue_depth(dev->id);
- if (!ata_id_has_ncq(dev->id)) {
- desc[0] = '\0';
+ if (!ata_id_has_ncq(dev->id))
return;
- }
+
if (dev->horkage & ATA_HORKAGE_NONCQ) {
- snprintf(desc, desc_sz, "NCQ (not used)");
+ mprintk_add(mp, ", NCQ (not used)");
return;
}
if (ap->flags & ATA_FLAG_NCQ) {
@@ -2066,9 +2137,9 @@ static void ata_dev_config_ncq(struct ata_device *dev,
}
if (hdepth >= ddepth)
- snprintf(desc, desc_sz, "NCQ (depth %d)", ddepth);
+ mprintk_add(mp, ", NCQ (depth %d)", ddepth);
else
- snprintf(desc, desc_sz, "NCQ (depth %d/%d)", hdepth, ddepth);
+ mprintk_add(mp, ", NCQ (depth %d/%d)", hdepth, ddepth);
}
/**
@@ -2090,8 +2161,8 @@ int ata_dev_configure(struct ata_device *dev)
struct ata_eh_context *ehc = &dev->link->eh_context;
int print_info = ehc->i.flags & ATA_EHI_PRINTINFO;
const u16 *id = dev->id;
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
unsigned int xfer_mask;
- char revbuf[7]; /* XYZ-99\0 */
char fwrevbuf[ATA_ID_FW_REV_LEN+1];
char modelbuf[ATA_ID_PROD_LEN+1];
int rc;
@@ -2105,6 +2176,8 @@ int ata_dev_configure(struct ata_device *dev)
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: ENTER\n", __FUNCTION__);
+ ata_dev_mp_header(dev, KERN_INFO, &mp);
+
/* set horkage */
dev->horkage |= ata_dev_blacklisted(dev);
@@ -2153,51 +2226,44 @@ int ata_dev_configure(struct ata_device *dev)
ata_id_c_string(dev->id, modelbuf, ATA_ID_PROD,
sizeof(modelbuf));
- /* ATA-specific feature tests */
if (dev->class == ATA_DEV_ATA) {
+ /* ATA-specific feature tests */
if (ata_id_is_cfa(id)) {
- if (id[162] & 1) /* CPRM may make this media unusable */
+ /* CPRM may make this media unusable */
+ if ((id[162] & 1) && print_info)
ata_dev_printk(dev, KERN_WARNING,
"supports DRM functions and may "
"not be fully accessable.\n");
- snprintf(revbuf, 7, "CFA");
+ mprintk_add(&mp, "CFA: ");
} else
- snprintf(revbuf, 7, "ATA-%d", ata_id_major_version(id));
+ mprintk_add(&mp, "ATA-%d: ", ata_id_major_version(id));
+
+ mprintk_add(&mp, "%s, %s, max %s\n",
+ modelbuf, fwrevbuf, ata_mode_string(xfer_mask));
dev->n_sectors = ata_id_n_sectors(id);
+ mprintk_add(&mp, "%Lu sectors",
+ (unsigned long long)dev->n_sectors);
- if (dev->id[59] & 0x100)
+ if (dev->id[59] & 0x100) {
dev->multi_count = dev->id[59] & 0xff;
+ mprintk_add(&mp, ", multi %u", dev->multi_count);
+ }
if (ata_id_has_lba(id)) {
- const char *lba_desc;
- char ncq_desc[20];
-
- lba_desc = "LBA";
dev->flags |= ATA_DFLAG_LBA;
+ mprintk_add(&mp, ", LBA");
+
if (ata_id_has_lba48(id)) {
dev->flags |= ATA_DFLAG_LBA48;
- lba_desc = "LBA48";
-
+ mprintk_add(&mp, "48");
if (dev->n_sectors >= (1UL << 28) &&
ata_id_has_flush_ext(id))
dev->flags |= ATA_DFLAG_FLUSH_EXT;
}
/* config NCQ */
- ata_dev_config_ncq(dev, ncq_desc, sizeof(ncq_desc));
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u: %s %s\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, lba_desc, ncq_desc);
- }
+ ata_dev_config_ncq(dev, &mp);
} else {
/* CHS */
@@ -2213,27 +2279,13 @@ int ata_dev_configure(struct ata_device *dev)
dev->sectors = id[56];
}
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info) {
- ata_dev_printk(dev, KERN_INFO,
- "%s: %s, %s, max %s\n",
- revbuf, modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask));
- ata_dev_printk(dev, KERN_INFO,
- "%Lu sectors, multi %u, CHS %u/%u/%u\n",
- (unsigned long long)dev->n_sectors,
- dev->multi_count, dev->cylinders,
- dev->heads, dev->sectors);
- }
+ mprintk_add(&mp, ", CHS %u/%u/%u",
+ dev->cylinders, dev->heads, dev->sectors);
}
dev->cdb_len = 16;
- }
-
- /* ATAPI-specific feature tests */
- else if (dev->class == ATA_DEV_ATAPI) {
- const char *cdb_intr_string = "";
- const char *atapi_an_string = "";
+ } else if (dev->class == ATA_DEV_ATAPI) {
+ /* ATAPI-specific feature tests */
u32 sntf;
rc = atapi_cdb_len(id);
@@ -2246,6 +2298,14 @@ int ata_dev_configure(struct ata_device *dev)
}
dev->cdb_len = (unsigned int) rc;
+ mprintk_add(&mp, "ATAPI: %s, %s, max %s", modelbuf, fwrevbuf,
+ ata_mode_string(xfer_mask));
+
+ if (ata_id_cdb_intr(dev->id)) {
+ dev->flags |= ATA_DFLAG_CDB_INTR;
+ mprintk_add(&mp, ", CDB intr");
+ }
+
/* Enable ATAPI AN if both the host and device have
* the support. If PMP is attached, SNTF is required
* to enable ATAPI AN to discern between PHY status
@@ -2265,22 +2325,9 @@ int ata_dev_configure(struct ata_device *dev)
"(err_mask=0x%x)\n", err_mask);
else {
dev->flags |= ATA_DFLAG_AN;
- atapi_an_string = ", ATAPI AN";
+ mprintk_add(&mp, ", ATAPI AN");
}
}
-
- if (ata_id_cdb_intr(dev->id)) {
- dev->flags |= ATA_DFLAG_CDB_INTR;
- cdb_intr_string = ", CDB intr";
- }
-
- /* print device info to dmesg */
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "ATAPI: %s, %s, max %s%s%s\n",
- modelbuf, fwrevbuf,
- ata_mode_string(xfer_mask),
- cdb_intr_string, atapi_an_string);
}
/* determine max_sectors */
@@ -2295,23 +2342,18 @@ int ata_dev_configure(struct ata_device *dev)
dev->flags |= ATA_DFLAG_DIPM;
}
- if (dev->horkage & ATA_HORKAGE_DIAGNOSTIC) {
+ if ((dev->horkage & ATA_HORKAGE_DIAGNOSTIC) && print_info) {
/* Let the user know. We don't want to disallow opens for
rescue purposes, or in case the vendor is just a blithering
idiot */
- if (print_info) {
- ata_dev_printk(dev, KERN_WARNING,
-"Drive reports diagnostics failure. This may indicate a drive\n");
- ata_dev_printk(dev, KERN_WARNING,
-"fault or invalid emulation. Contact drive vendor for information.\n");
- }
+ ata_dev_printk(dev, KERN_WARNING,
+ "Drive reports diagnostics failure. This may indicate a drive\n"
+ "fault or invalid emulation. Contact drive vendor for information.\n");
}
/* limit bridge transfers to udma5, 200 sectors */
if (ata_dev_knobble(dev)) {
- if (ata_msg_drv(ap) && print_info)
- ata_dev_printk(dev, KERN_INFO,
- "applying bridge limits\n");
+ mprintk_add(&mp, ", applying bridge limits");
dev->udma_mask &= ATA_UDMA5;
dev->max_sectors = ATA_MAX_SECTORS;
}
@@ -2336,6 +2378,10 @@ int ata_dev_configure(struct ata_device *dev)
if (ap->ops->dev_config)
ap->ops->dev_config(dev);
+ /* print device info to dmesg */
+ if (ata_msg_drv(ap) && print_info)
+ mprintk(&mp, "\n");
+
if (ata_msg_probe(ap))
ata_dev_printk(dev, KERN_DEBUG, "%s: EXIT, drv_stat = 0x%x\n",
__FUNCTION__, ata_chk_status(ap));
@@ -7579,6 +7625,12 @@ EXPORT_SYMBOL_GPL(sata_deb_timing_hotplug);
EXPORT_SYMBOL_GPL(sata_deb_timing_long);
EXPORT_SYMBOL_GPL(ata_dummy_port_ops);
EXPORT_SYMBOL_GPL(ata_dummy_port_info);
+EXPORT_SYMBOL_GPL(ata_port_printk);
+EXPORT_SYMBOL_GPL(ata_link_printk);
+EXPORT_SYMBOL_GPL(ata_dev_printk);
+EXPORT_SYMBOL_GPL(ata_port_mp_header);
+EXPORT_SYMBOL_GPL(ata_link_mp_header);
+EXPORT_SYMBOL_GPL(ata_dev_mp_header);
EXPORT_SYMBOL_GPL(ata_std_bios_param);
EXPORT_SYMBOL_GPL(ata_std_ports);
EXPORT_SYMBOL_GPL(ata_host_init);
diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 21a81cd..a7ad3e7 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -1786,17 +1786,12 @@ static void ata_eh_link_report(struct ata_link *link)
{
struct ata_port *ap = link->ap;
struct ata_eh_context *ehc = &link->eh_context;
- const char *frozen, *desc;
- char tries_buf[6];
+ struct mprintk mp = MPRINTK_INITIALIZER(ap->sector_buf, ATA_SECT_SIZE);
int tag, nr_failed = 0;
if (ehc->i.flags & ATA_EHI_QUIET)
return;
- desc = NULL;
- if (ehc->i.desc[0] != '\0')
- desc = ehc->i.desc;
-
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
@@ -1813,33 +1808,25 @@ static void ata_eh_link_report(struct ata_link *link)
if (!nr_failed && !ehc->i.err_mask)
return;
- frozen = "";
- if (ap->pflags & ATA_PFLAG_FROZEN)
- frozen = " frozen";
+ if (ehc->i.dev)
+ ata_dev_mp_header(ehc->i.dev, KERN_ERR, &mp);
+ else
+ ata_link_mp_header(link, KERN_ERR, &mp);
- memset(tries_buf, 0, sizeof(tries_buf));
+ mprintk_add(&mp, "exception Emask 0x%x SAct 0x%x SErr 0x%x action 0x%x",
+ ehc->i.err_mask, link->sactive, ehc->i.serror,
+ ehc->i.action);
+ if (ap->pflags & ATA_PFLAG_FROZEN)
+ mprintk_add(&mp, " frozen");
if (ap->eh_tries < ATA_EH_MAX_TRIES)
- snprintf(tries_buf, sizeof(tries_buf) - 1, " t%d",
- ap->eh_tries);
+ mprintk_add(&mp, " t%d", ap->eh_tries);
+ mprintk_add(&mp, "\n");
- if (ehc->i.dev) {
- ata_dev_printk(ehc->i.dev, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_dev_printk(ehc->i.dev, KERN_ERR, "%s\n", desc);
- } else {
- ata_link_printk(link, KERN_ERR, "exception Emask 0x%x "
- "SAct 0x%x SErr 0x%x action 0x%x%s%s\n",
- ehc->i.err_mask, link->sactive, ehc->i.serror,
- ehc->i.action, frozen, tries_buf);
- if (desc)
- ata_link_printk(link, KERN_ERR, "%s\n", desc);
- }
+ if (ehc->i.desc[0] != '\0')
+ mprintk_add(&mp, "%s\n", ehc->i.desc);
if (ehc->i.serror)
- ata_port_printk(ap, KERN_ERR,
+ mprintk_add(&mp,
"SError: { %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s}\n",
ehc->i.serror & SERR_DATA_RECOVERED ? "RecovData " : "",
ehc->i.serror & SERR_COMM_RECOVERED ? "RecovComm " : "",
@@ -1859,85 +1846,90 @@ static void ata_eh_link_report(struct ata_link *link)
ehc->i.serror & SERR_UNRECOG_FIS ? "UnrecFIS " : "",
ehc->i.serror & SERR_DEV_XCHG ? "DevExch " : "");
+ mprintk(&mp, NULL); /* flush link / device wide messages */
+
for (tag = 0; tag < ATA_MAX_QUEUE; tag++) {
+ static const char *dma_str[] = {
+ [DMA_BIDIRECTIONAL] = "bidi",
+ [DMA_TO_DEVICE] = "out",
+ [DMA_FROM_DEVICE] = "in",
+ };
+ static const char *prot_str[] = {
+ [ATA_PROT_PIO] = "pio",
+ [ATA_PROT_DMA] = "dma",
+ [ATA_PROT_NCQ] = "ncq",
+ [ATA_PROT_ATAPI] = "pio",
+ [ATA_PROT_ATAPI_DMA] = "dma",
+ };
struct ata_queued_cmd *qc = __ata_qc_from_tag(ap, tag);
struct ata_taskfile *cmd = &qc->tf, *res = &qc->result_tf;
const u8 *cdb = qc->cdb;
- char data_buf[20] = "";
- char cdb_buf[70] = "";
+ int need_newline = 0;
if (!(qc->flags & ATA_QCFLAG_FAILED) ||
qc->dev->link != link || !qc->err_mask)
continue;
- if (qc->dma_dir != DMA_NONE) {
- static const char *dma_str[] = {
- [DMA_BIDIRECTIONAL] = "bidi",
- [DMA_TO_DEVICE] = "out",
- [DMA_FROM_DEVICE] = "in",
- };
- static const char *prot_str[] = {
- [ATA_PROT_PIO] = "pio",
- [ATA_PROT_DMA] = "dma",
- [ATA_PROT_NCQ] = "ncq",
- [ATA_PROT_ATAPI] = "pio",
- [ATA_PROT_ATAPI_DMA] = "dma",
- };
-
- snprintf(data_buf, sizeof(data_buf), " %s %u %s",
- prot_str[qc->tf.protocol], qc->nbytes,
- dma_str[qc->dma_dir]);
- }
+ mprintk_add(&mp, "cmd %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x tag %d",
+ cmd->command, cmd->feature, cmd->nsect,
+ cmd->lbal, cmd->lbam, cmd->lbah,
+ cmd->hob_feature, cmd->hob_nsect,
+ cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
+ cmd->device, qc->tag);
+
+ if (qc->dma_dir != DMA_NONE)
+ mprintk_add(&mp, " %s %u %s",
+ prot_str[qc->tf.protocol],
+ qc->nbytes, dma_str[qc->dma_dir]);
+ mprintk_add(&mp, "\n");
if (is_atapi_taskfile(&qc->tf))
- snprintf(cdb_buf, sizeof(cdb_buf),
- "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
- "%02x %02x %02x %02x %02x %02x %02x %02x\n ",
- cdb[0], cdb[1], cdb[2], cdb[3],
- cdb[4], cdb[5], cdb[6], cdb[7],
- cdb[8], cdb[9], cdb[10], cdb[11],
- cdb[12], cdb[13], cdb[14], cdb[15]);
-
- ata_dev_printk(qc->dev, KERN_ERR,
- "cmd %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "tag %d%s\n %s"
- "res %02x/%02x:%02x:%02x:%02x:%02x/%02x:%02x:%02x:%02x:%02x/%02x "
- "Emask 0x%x (%s)%s\n",
- cmd->command, cmd->feature, cmd->nsect,
- cmd->lbal, cmd->lbam, cmd->lbah,
- cmd->hob_feature, cmd->hob_nsect,
- cmd->hob_lbal, cmd->hob_lbam, cmd->hob_lbah,
- cmd->device, qc->tag, data_buf, cdb_buf,
- res->command, res->feature, res->nsect,
- res->lbal, res->lbam, res->lbah,
- res->hob_feature, res->hob_nsect,
- res->hob_lbal, res->hob_lbam, res->hob_lbah,
- res->device, qc->err_mask, ata_err_string(qc->err_mask),
- qc->err_mask & AC_ERR_NCQ ? " <F>" : "");
+ mprintk_add(&mp, "cdb %02x %02x %02x %02x %02x %02x %02x %02x "
+ "%02x %02x %02x %02x %02x %02x %02x %02x\n",
+ cdb[0], cdb[1], cdb[2], cdb[3],
+ cdb[4], cdb[5], cdb[6], cdb[7],
+ cdb[8], cdb[9], cdb[10], cdb[11],
+ cdb[12], cdb[13], cdb[14], cdb[15]);
+
+ mprintk_add(&mp, "res %02x/%02x:%02x:%02x:%02x:%02x/"
+ "%02x:%02x:%02x:%02x:%02x/%02x Emask 0x%x (%s)%s\n",
+ res->command, res->feature, res->nsect,
+ res->lbal, res->lbam, res->lbah,
+ res->hob_feature, res->hob_nsect,
+ res->hob_lbal, res->hob_lbam, res->hob_lbah,
+ res->device, qc->err_mask,
+ ata_err_string(qc->err_mask),
+ qc->err_mask & AC_ERR_NCQ ? " <F>" : "");
if (res->command & (ATA_BUSY | ATA_DRDY | ATA_DF | ATA_DRQ |
ATA_ERR)) {
if (res->command & ATA_BUSY)
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { Busy }\n");
+ mprintk_add(&mp, "status: { Busy } ");
else
- ata_dev_printk(qc->dev, KERN_ERR,
- "status: { %s%s%s%s}\n",
+ mprintk_add(&mp, "status: { %s%s%s%s} ",
res->command & ATA_DRDY ? "DRDY " : "",
res->command & ATA_DF ? "DF " : "",
res->command & ATA_DRQ ? "DRQ " : "",
res->command & ATA_ERR ? "ERR " : "");
+ need_newline = 1;
}
if (cmd->command != ATA_CMD_PACKET &&
(res->feature & (ATA_ICRC | ATA_UNC | ATA_IDNF |
- ATA_ABORTED)))
- ata_dev_printk(qc->dev, KERN_ERR,
- "error: { %s%s%s%s}\n",
+ ATA_ABORTED))) {
+ mprintk_add(&mp, "error: { %s%s%s%s}",
res->feature & ATA_ICRC ? "ICRC " : "",
res->feature & ATA_UNC ? "UNC " : "",
res->feature & ATA_IDNF ? "IDNF " : "",
res->feature & ATA_ABORTED ? "ABRT " : "");
+ need_newline = 1;
+ }
+
+ if (need_newline)
+ mprintk(&mp, "\n");
+ else
+ mprintk(&mp, NULL);
}
}
diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c
index caef2bb..cc6e4ca 100644
--- a/drivers/ata/libata-pmp.c
+++ b/drivers/ata/libata-pmp.c
@@ -408,9 +408,8 @@ static int sata_pmp_configure(struct ata_device *dev, int print_info)
if (!(dev->flags & ATA_DFLAG_AN))
ata_dev_printk(dev, KERN_INFO,
- "Asynchronous notification not supported, "
- "hotplug won't\n work on fan-out "
- "ports. Use warm-plug instead.\n");
+ "Asynchronous notification not supported, hotplug won't\n"
+ "work on fan-out ports. Use warm-plug instead.\n");
}
return 0;
diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
index 14daf48..a486774 100644
--- a/drivers/ata/libata-scsi.c
+++ b/drivers/ata/libata-scsi.c
@@ -3207,9 +3207,9 @@ void ata_scsi_scan_host(struct ata_port *ap, int sync)
goto repeat;
}
- ata_port_printk(ap, KERN_ERR, "WARNING: synchronous SCSI scan "
- "failed without making any progress,\n"
- " switching to async\n");
+ ata_port_printk(ap, KERN_ERR,
+ "WARNING: synchronous SCSI scan failed without making any \n"
+ " progress, switching to async\n");
}
queue_delayed_work(ata_aux_wq, &ap->hotplug_task,
diff --git a/drivers/ata/sata_inic162x.c b/drivers/ata/sata_inic162x.c
index 323c087..c45bd38 100644
--- a/drivers/ata/sata_inic162x.c
+++ b/drivers/ata/sata_inic162x.c
@@ -502,7 +502,7 @@ static void inic_dev_config(struct ata_device *dev)
if (dev->n_sectors >= 1 << 28) {
ata_dev_printk(dev, KERN_ERR,
"ERROR: This driver doesn't support LBA48 yet and may cause\n"
- " data corruption on such devices. Disabling.\n");
+ " data corruption on such devices. Disabling.\n");
ata_dev_disable(dev);
}
}
diff --git a/drivers/ata/sata_nv.c b/drivers/ata/sata_nv.c
index ed5dc7c..7874f61 100644
--- a/drivers/ata/sata_nv.c
+++ b/drivers/ata/sata_nv.c
@@ -1788,8 +1788,8 @@ static void nv_swncq_ncq_stop(struct ata_port *ap)
"EH in SWNCQ mode,QC:qc_active 0x%X sactive 0x%X\n",
ap->qc_active, ap->link.sactive);
ata_port_printk(ap, KERN_ERR,
- "SWNCQ:qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n "
- "dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
+ "SWNCQ: qc_active 0x%X defer_bits 0x%X last_issue_tag 0x%x\n"
+ " dhfis 0x%X dmafis 0x%X sdbfis 0x%X\n",
pp->qc_active, pp->defer_queue.defer_bits, pp->last_issue_tag,
pp->dhfis_bits, pp->dmafis_bits, pp->sdbfis_bits);
diff --git a/include/linux/libata.h b/include/linux/libata.h
index 124033c..c31ea05 100644
--- a/include/linux/libata.h
+++ b/include/linux/libata.h
@@ -773,6 +773,23 @@ static inline int ata_port_is_dummy(struct ata_port *ap)
return ap->ops == &ata_dummy_port_ops;
}
+extern int ata_port_printk(struct ata_port *ap, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_link_printk(struct ata_link *link, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+extern int ata_dev_printk(struct ata_device *dev, const char *lv,
+ const char *fmt, ...)
+ __attribute__ ((format (printf, 3, 4)));
+
+extern void ata_port_mp_header(struct ata_port *ap, const char *lv,
+ struct mprintk *mp);
+extern void ata_link_mp_header(struct ata_link *link, const char *lv,
+ struct mprintk *mp);
+extern void ata_dev_mp_header(struct ata_device *dev, const char *lv,
+ struct mprintk *mp);
+
extern void sata_print_link_status(struct ata_link *link);
extern void ata_port_probe(struct ata_port *);
extern void ata_bus_reset(struct ata_port *ap);
@@ -1023,24 +1040,6 @@ extern void ata_do_eh(struct ata_port *ap, ata_prereset_fn_t prereset,
ata_postreset_fn_t postreset);
/*
- * printk helpers
- */
-#define ata_port_printk(ap, lv, fmt, args...) \
- printk("%sata%u: "fmt, lv, (ap)->print_id , ##args)
-
-#define ata_link_printk(link, lv, fmt, args...) do { \
- if ((link)->ap->nr_pmp_links) \
- printk("%sata%u.%02u: "fmt, lv, (link)->ap->print_id, \
- (link)->pmp , ##args); \
- else \
- printk("%sata%u: "fmt, lv, (link)->ap->print_id , ##args); \
- } while(0)
-
-#define ata_dev_printk(dev, lv, fmt, args...) \
- printk("%sata%u.%02u: "fmt, lv, (dev)->link->ap->print_id, \
- (dev)->link->pmp + (dev)->devno , ##args)
-
-/*
* ata_eh_info helpers
*/
extern void __ata_ehi_push_desc(struct ata_eh_info *ehi, const char *fmt, ...)
--
1.5.2.4
^ permalink raw reply related [flat|nested] 24+ messages in thread