Re: Re: [PATCH RESEND] scsi: Output error messages using structured printk in single line
Hi Hannes,
(2014/05/21 15:30), Hannes Reinecke wrote:
On 05/21/2014 05:18 AM, Elliott, Robert (Server Storage) wrote:
-Original Message-
From: linux-scsi-ow...@vger.kernel.org [mailto:linux-scsi-
ow...@vger.kernel.org] On Behalf Of James Bottomley
Sent: Tuesday, May 20, 2014 9:22 PM
To: Yoshihiro YUNOMAE
Cc: Hannes Reinecke; Prarit Bhargava; linux-scsi@vger.kernel.org; Kay
Sievers; linux-ker...@vger.kernel.org; Hidehiro Kawai; yrl.pp-
manager...@hitachi.com; Masami Hiramatsu
Subject: Re: [PATCH RESEND] scsi: Output error messages using structured
printk in single line
On Thu, 2014-02-27 at 13:17 +0900, Yoshihiro YUNOMAE wrote:
+/* Maximum size of a local buffer for structured printk */
+#define SCSI_LOG_LINE_MAX 512
+
+/* Local buffer for structured printk */
+struct scsi_log_line {
+int offset;
+char buf[SCSI_LOG_LINE_MAX];
+};
This piece isn't going to fly; it's an on stack allocation of 0.5kb;
that's too much for small stack kernels. Just changing this to a kalloc
is going be problematic too because we're in the io paths and the
allocation may fail. So I appreciate the problem, but I don't think the
solution works. Could we just tag the messages and use grep to put them
back together?
James
When the system gets busy, I've seen CDB bytes strung out with each
byte getting its own timestamp, with messages from different devices
and threads interleaved together, so like the idea of printing each
line with a single printk() call.
Most lines aren't anywhere near 512 bytes long. Can this be coded to
let the calling function define an appropriate buffer size for
whatever it is printing, with sizeof() used to bounds check?
As mentioned several times, I'm working on a patchset to update
scsi logging.
The original patchset tried to convert any logging message into a single
statement, which wouldn't be broken up even under heavy load.
While this works reasonably well for most things, printing out decoded
sense with just one line (and not end up in massive switch()
statements) is near impossible.
Plus you'll end up having to use a static buffer at one point, which
again increases the stack size.
The alternative approach as discussed at LSF is to move scsi_logging
over to tracing. There is already some coding for scsi tracing, but
Oh, I didn't attend the meeting, so I didn't know it.
Did you completely change the development from fixing scsi_logging
to using tracing?
in most cases it just duplicates existing logging statements.
So if we were to replace the entire scsi_logging infrastructure
with scsi tracing most of the issues (like chopped-up CDBs) would
be gone.
Plus we would have a far better control about _what_ is being printed.
And yes, I do have some patches for that :-)
I would like to develop the feature together because this
is an important problem.
Would you upload the patches to your tree?
And, would you share current status and issues with us?
Thank you,
Yoshihiro YUNOMAE
--
Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: yoshihiro.yunomae...@hitachi.com
--
To unsubscribe from this list: send the line unsubscribe linux-scsi in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH RESEND] scsi: Output error messages using structured printk in single line
On Wed, May 21, 2014 at 08:30:58AM +0200, Hannes Reinecke wrote: While this works reasonably well for most things, printing out decoded sense with just one line (and not end up in massive switch() statements) is near impossible. Plus you'll end up having to use a static buffer at one point, which again increases the stack size. The alternative approach as discussed at LSF is to move scsi_logging over to tracing. There is already some coding for scsi tracing, but in most cases it just duplicates existing logging statements. So if we were to replace the entire scsi_logging infrastructure with scsi tracing most of the issues (like chopped-up CDBs) would be gone. Plus we would have a far better control about _what_ is being printed. And yes, I do have some patches for that :-) I think any detailed logging of sense codes, cdbs and co should move to tracing. In fact generally any non-defauly logging probably is better off in the tracing subsystems, but there might be a few exceptions. -- To unsubscribe from this list: send the line unsubscribe linux-scsi in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH RESEND] scsi: Output error messages using structured printk in single line
On 05/21/2014 05:18 AM, Elliott, Robert (Server Storage) wrote:
-Original Message-
From: linux-scsi-ow...@vger.kernel.org [mailto:linux-scsi-
ow...@vger.kernel.org] On Behalf Of James Bottomley
Sent: Tuesday, May 20, 2014 9:22 PM
To: Yoshihiro YUNOMAE
Cc: Hannes Reinecke; Prarit Bhargava; linux-scsi@vger.kernel.org; Kay
Sievers; linux-ker...@vger.kernel.org; Hidehiro Kawai; yrl.pp-
manager...@hitachi.com; Masami Hiramatsu
Subject: Re: [PATCH RESEND] scsi: Output error messages using structured
printk in single line
On Thu, 2014-02-27 at 13:17 +0900, Yoshihiro YUNOMAE wrote:
+/* Maximum size of a local buffer for structured printk */
+#define SCSI_LOG_LINE_MAX 512
+
+/* Local buffer for structured printk */
+struct scsi_log_line {
+ int offset;
+ char buf[SCSI_LOG_LINE_MAX];
+};
This piece isn't going to fly; it's an on stack allocation of 0.5kb;
that's too much for small stack kernels. Just changing this to a kalloc
is going be problematic too because we're in the io paths and the
allocation may fail. So I appreciate the problem, but I don't think the
solution works. Could we just tag the messages and use grep to put them
back together?
James
When the system gets busy, I've seen CDB bytes strung out with each
byte getting its own timestamp, with messages from different devices
and threads interleaved together, so like the idea of printing each
line with a single printk() call.
Most lines aren't anywhere near 512 bytes long. Can this be coded to
let the calling function define an appropriate buffer size for
whatever it is printing, with sizeof() used to bounds check?
As mentioned several times, I'm working on a patchset to update
scsi logging.
The original patchset tried to convert any logging message into a
single statement, which wouldn't be broken up even under heavy load.
While this works reasonably well for most things, printing out
decoded sense with just one line (and not end up in massive switch()
statements) is near impossible.
Plus you'll end up having to use a static buffer at one point, which
again increases the stack size.
The alternative approach as discussed at LSF is to move scsi_logging
over to tracing. There is already some coding for scsi tracing, but
in most cases it just duplicates existing logging statements.
So if we were to replace the entire scsi_logging infrastructure
with scsi tracing most of the issues (like chopped-up CDBs) would
be gone.
Plus we would have a far better control about _what_ is being printed.
And yes, I do have some patches for that :-)
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries Storage
h...@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line unsubscribe linux-scsi in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH RESEND] scsi: Output error messages using structured printk in single line
On Thu, 2014-02-27 at 13:17 +0900, Yoshihiro YUNOMAE wrote:
+/* Maximum size of a local buffer for structured printk */
+#define SCSI_LOG_LINE_MAX 512
+
+/* Local buffer for structured printk */
+struct scsi_log_line {
+ int offset;
+ char buf[SCSI_LOG_LINE_MAX];
+};
This piece isn't going to fly; it's an on stack allocation of 0.5kb;
that's too much for small stack kernels. Just changing this to a kalloc
is going be problematic too because we're in the io paths and the
allocation may fail. So I appreciate the problem, but I don't think the
solution works. Could we just tag the messages and use grep to put them
back together?
James
--
To unsubscribe from this list: send the line unsubscribe linux-scsi in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
RE: [PATCH RESEND] scsi: Output error messages using structured printk in single line
-Original Message-
From: linux-scsi-ow...@vger.kernel.org [mailto:linux-scsi-
ow...@vger.kernel.org] On Behalf Of James Bottomley
Sent: Tuesday, May 20, 2014 9:22 PM
To: Yoshihiro YUNOMAE
Cc: Hannes Reinecke; Prarit Bhargava; linux-scsi@vger.kernel.org; Kay
Sievers; linux-ker...@vger.kernel.org; Hidehiro Kawai; yrl.pp-
manager...@hitachi.com; Masami Hiramatsu
Subject: Re: [PATCH RESEND] scsi: Output error messages using structured
printk in single line
On Thu, 2014-02-27 at 13:17 +0900, Yoshihiro YUNOMAE wrote:
+/* Maximum size of a local buffer for structured printk */
+#define SCSI_LOG_LINE_MAX 512
+
+/* Local buffer for structured printk */
+struct scsi_log_line {
+ int offset;
+ char buf[SCSI_LOG_LINE_MAX];
+};
This piece isn't going to fly; it's an on stack allocation of 0.5kb;
that's too much for small stack kernels. Just changing this to a kalloc
is going be problematic too because we're in the io paths and the
allocation may fail. So I appreciate the problem, but I don't think the
solution works. Could we just tag the messages and use grep to put them
back together?
James
When the system gets busy, I've seen CDB bytes strung out with each
byte getting its own timestamp, with messages from different devices
and threads interleaved together, so like the idea of printing each
line with a single printk() call.
Most lines aren't anywhere near 512 bytes long. Can this be coded to
let the calling function define an appropriate buffer size for
whatever it is printing, with sizeof() used to bounds check?
--
To unsubscribe from this list: send the line unsubscribe linux-scsi in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
[PATCH RESEND] scsi: Output error messages using structured printk in single line
Output error messages using structured printk in single line.
In SCSI drivers, some error messages which should be output in single line are
divided in multiple lines. When user tools handle the error messages, those
divided messages will create some inconveniences.
The reason why this problem is induced is structured printk for error messages.
Structured printk can add device information for printk, and it is used in
scmd_printk() and sd_printk(). The printk aims at output in atomic, so we
cannot use those functions for connecting multiple messages like KERN_CONT.
However, some error messages is implemented as follows:
structured_printk(DEVICE INFORMATION:);
printk(KERN_CONT, DETAIL INFORMATION\n);
This implementation will be expected to output like DEVICE INFORMATION: DETAIL
INFORMATION, but actually, this will be output as follows:
DEVICE INFORMATION:
DETAIL INFORMATION
For instance, in a following pseudo SCSI error test, the device information and
the detail information are divided:
-- Pseudo SCSI error test for current kernel
# modprobe scsi_debug
# cd /sys/bus/pseudo/drivers/scsi_debug
# echo 2 opts
# dd if=/dev/sdb of=/dev/null 2 /dev/null
-- Result for current kernel
# dmesg
[ 17.842110] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 18.859098] sd 2:0:0:0: [sdb] Unhandled sense code
[ 18.859103] sd 2:0:0:0: [sdb]
[ 18.859106] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 18.859108] sd 2:0:0:0: [sdb]
[ 18.859110] Sense Key : Medium Error [current]
[ 18.859114] Info fld=0x1234
[ 18.859116] sd 2:0:0:0: [sdb]
[ 18.859119] Add. Sense: Unrecovered read error
[ 18.859122] sd 2:0:0:0: [sdb] CDB:
[ 18.859124] Read(10): 28 00 00 00 11 e0 00 01 00 00
In a SCSI device driver, sd_print_result() is implemented as follows:
sd_print_result()
{
sd_printk(KERN_INFO, sdkp, );
scsi_show_result(result);
}
Here, first sd_printk() outputs sd 2:0:0:0: [sdb] , then scsi_show_sense_hdr()
outputs Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE. sd_printk() does not
include \n, but it forcibly starts a new line. Therefore, when the driver
outputs error messages, those messages are divided.
This patch makes those multiple line messages output in single line as follows:
# dmesg
[ 17.145085] sdb: unknown partition table
[ 17.149096] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 18.166090] sd 2:0:0:0: [sdb] Unhandled sense code
[ 18.166095] sd 2:0:0:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 18.166099] sd 2:0:0:0: [sdb] Sense Key : Medium Error [current]
[ 18.166104] Info fld=0x1234
[ 18.166106] sd 2:0:0:0: [sdb] Add. Sense: Unrecovered read error
[ 18.166111] sd 2:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 11 e0 00 01 00 00
Signed-off-by: Yoshihiro YUNOMAE yoshihiro.yunomae...@hitachi.com
Cc: James E.J. Bottomley jbottom...@parallels.com
Cc: Hannes Reinecke h...@suse.de
Cc: Kay Sievers k...@vrfy.org
Cc: linux-ker...@vger.kernel.org
Cc: linux-scsi@vger.kernel.org
---
drivers/scsi/constants.c | 206 --
drivers/scsi/scsi.c | 28 --
drivers/scsi/sd.c| 19 +++-
include/scsi/scsi_dbg.h | 23 -
4 files changed, 176 insertions(+), 100 deletions(-)
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index d35a5d6..cb93435 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -256,8 +256,26 @@ static const char * get_sa_name(const struct
value_name_pair * arr,
return (k arr_sz) ? arr-name : NULL;
}
+/* Store a SCSI logging event to buf. */
+__printf(2, 3)
+void scsi_log_add(struct scsi_log_line *log, const char *fmt, ...)
+{
+ va_list args;
+ int len;
+
+ va_start(args, fmt);
+ len = vscnprintf(log-buf + log-offset,
+SCSI_LOG_LINE_MAX - log-offset, fmt, args);
+ WARN_ONCE(!len, Cannot store the message '%s' in a local log buffer\n,
+ fmt);
+ log-offset += len;
+ va_end(args);
+}
+EXPORT_SYMBOL(scsi_log_add);
+
/* attempt to guess cdb length if cdb_len==0 . No trailing linefeed. */
-static void print_opcode_name(unsigned char * cdbp, int cdb_len)
+static void print_opcode_name(unsigned char *cdbp, int cdb_len,
+ struct scsi_log_line *log)
{
int sa, len, cdb0;
int fin_name = 0;
@@ -268,20 +286,22 @@ static void print_opcode_name(unsigned char * cdbp, int
cdb_len)
case VARIABLE_LENGTH_CMD:
len = scsi_varlen_cdb_length(cdbp);
if (len 10) {
- printk(short variable length command,
- len=%d ext_len=%d, len, cdb_len);
+ scsi_log_add(log,
+short variable length command, len=%d ext_len=%d,
+len, cdb_len);
break;
}
sa = (cdbp[8] 8) + cdbp[9];
name =
Re: [PATCH RESEND] scsi: Output error messages using structured printk in single line
Hi Hannes,
Although I sent you a message 6 days ago to ask your work which
is similar to my patch, I resend my patch because I'm considering
this problem should be fixed as soon as possible.
Thank you,
Yoshihiro YUNOMAE
(2014/02/27 13:17), Yoshihiro YUNOMAE wrote:
Output error messages using structured printk in single line.
In SCSI drivers, some error messages which should be output in single line are
divided in multiple lines. When user tools handle the error messages, those
divided messages will create some inconveniences.
The reason why this problem is induced is structured printk for error messages.
Structured printk can add device information for printk, and it is used in
scmd_printk() and sd_printk(). The printk aims at output in atomic, so we
cannot use those functions for connecting multiple messages like KERN_CONT.
However, some error messages is implemented as follows:
structured_printk(DEVICE INFORMATION:);
printk(KERN_CONT, DETAIL INFORMATION\n);
This implementation will be expected to output like DEVICE INFORMATION: DETAIL
INFORMATION, but actually, this will be output as follows:
DEVICE INFORMATION:
DETAIL INFORMATION
For instance, in a following pseudo SCSI error test, the device information and
the detail information are divided:
-- Pseudo SCSI error test for current kernel
# modprobe scsi_debug
# cd /sys/bus/pseudo/drivers/scsi_debug
# echo 2 opts
# dd if=/dev/sdb of=/dev/null 2 /dev/null
-- Result for current kernel
# dmesg
[ 17.842110] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 18.859098] sd 2:0:0:0: [sdb] Unhandled sense code
[ 18.859103] sd 2:0:0:0: [sdb]
[ 18.859106] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 18.859108] sd 2:0:0:0: [sdb]
[ 18.859110] Sense Key : Medium Error [current]
[ 18.859114] Info fld=0x1234
[ 18.859116] sd 2:0:0:0: [sdb]
[ 18.859119] Add. Sense: Unrecovered read error
[ 18.859122] sd 2:0:0:0: [sdb] CDB:
[ 18.859124] Read(10): 28 00 00 00 11 e0 00 01 00 00
In a SCSI device driver, sd_print_result() is implemented as follows:
sd_print_result()
{
sd_printk(KERN_INFO, sdkp, );
scsi_show_result(result);
}
Here, first sd_printk() outputs sd 2:0:0:0: [sdb] , then scsi_show_sense_hdr()
outputs Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE. sd_printk() does not
include \n, but it forcibly starts a new line. Therefore, when the driver
outputs error messages, those messages are divided.
This patch makes those multiple line messages output in single line as follows:
# dmesg
[ 17.145085] sdb: unknown partition table
[ 17.149096] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 18.166090] sd 2:0:0:0: [sdb] Unhandled sense code
[ 18.166095] sd 2:0:0:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 18.166099] sd 2:0:0:0: [sdb] Sense Key : Medium Error [current]
[ 18.166104] Info fld=0x1234
[ 18.166106] sd 2:0:0:0: [sdb] Add. Sense: Unrecovered read error
[ 18.166111] sd 2:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 11 e0 00 01 00 00
Signed-off-by: Yoshihiro YUNOMAE yoshihiro.yunomae...@hitachi.com
Cc: James E.J. Bottomley jbottom...@parallels.com
Cc: Hannes Reinecke h...@suse.de
Cc: Kay Sievers k...@vrfy.org
Cc: linux-ker...@vger.kernel.org
Cc: linux-scsi@vger.kernel.org
---
drivers/scsi/constants.c | 206 --
drivers/scsi/scsi.c | 28 --
drivers/scsi/sd.c| 19 +++-
include/scsi/scsi_dbg.h | 23 -
4 files changed, 176 insertions(+), 100 deletions(-)
diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
index d35a5d6..cb93435 100644
--- a/drivers/scsi/constants.c
+++ b/drivers/scsi/constants.c
@@ -256,8 +256,26 @@ static const char * get_sa_name(const struct
value_name_pair * arr,
return (k arr_sz) ? arr-name : NULL;
}
+/* Store a SCSI logging event to buf. */
+__printf(2, 3)
+void scsi_log_add(struct scsi_log_line *log, const char *fmt, ...)
+{
+ va_list args;
+ int len;
+
+ va_start(args, fmt);
+ len = vscnprintf(log-buf + log-offset,
+SCSI_LOG_LINE_MAX - log-offset, fmt, args);
+ WARN_ONCE(!len, Cannot store the message '%s' in a local log buffer\n,
+ fmt);
+ log-offset += len;
+ va_end(args);
+}
+EXPORT_SYMBOL(scsi_log_add);
+
/* attempt to guess cdb length if cdb_len==0 . No trailing linefeed. */
-static void print_opcode_name(unsigned char * cdbp, int cdb_len)
+static void print_opcode_name(unsigned char *cdbp, int cdb_len,
+ struct scsi_log_line *log)
{
int sa, len, cdb0;
int fin_name = 0;
@@ -268,20 +286,22 @@ static void print_opcode_name(unsigned char * cdbp, int
cdb_len)
case VARIABLE_LENGTH_CMD:
len = scsi_varlen_cdb_length(cdbp);
if (len 10) {
- printk(short variable length command,
- len=%d ext_len=%d, len, cdb_len);
+
