scsi: core: Log SCSI command age with errors
PATCH 1/1 scsi: core: Log SCSI command age with errors
Couple of users had requested to print the SCSI command age along with command failure errors. This is a small change, but allows users to get more important information about the command that was failed, it would help the users in debugging the command failures:
---
drivers/scsi/scsi_logging.c +8 -2
@@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg,const char *mlret_string =scsi_mlreturn_string (disposition);const char *hb_string =scsi_hostbyte_string (cmd->result);const char *db_string =scsi_driverbyte_string (cmd->result); +unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) /HZ ; logbuf =scsi_log_reserve_buffer (&logbuf_len);if (!logbuf)
@@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg,if (db_string) off +=scnprintf (logbuf + off, logbuf_len - off, -"driverbyte=%s" , db_string); +"driverbyte=%s " , db_string);else off +=scnprintf (logbuf + off, logbuf_len - off, -"driverbyte=0x%02x" ,driver_byte (cmd->result)); +"driverbyte=0x%02x " , +driver_byte (cmd->result)); + + off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age); + out_printk:dev_printk (KERN_INFO , &cmd->device->sdev_gendev,"%s" , logbuf);scsi_log_release_buffer (logbuf);
Quoted 40 lines · Milan P. Gandhi
Couple of users had requested to print the SCSI command age along with command failure errors. This is a small change, but allows users to get more important information about the command that was failed, it would help the users in debugging the command failures:
Signed-off-by Milan P. Gandhi <[email protected]>---
drivers/scsi/scsi_logging.c +1
-0@@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, const char *mlret_string = scsi_mlreturn_string(disposition);const char *hb_string =scsi_hostbyte_string (cmd->result);const char *db_string =scsi_driverbyte_string (cmd->result); +unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) /HZ ; logbuf =scsi_log_reserve_buffer (&logbuf_len);drivers/scsi/scsi_logging.c +7
-2if (!logbuf)@@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, if (db_string) off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=%s", db_string); + "driverbyte=%s ", db_string); else off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=0x%02x", driver_byte(cmd- >result)); +"driverbyte=0x%02x " , + driver_byte(cmd->result)); + + off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age); + out_printk:
drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, · line 493
Quoted 2 lines
drivers/scsi/scsi_logging.c +0
-0dev_printk (KERN_INFO , &cmd->device->sdev_gendev,"%s" , logbuf);scsi_log_release_buffer (logbuf);
This looks to be a useful debug addition to me, and the code looks correct.
I believe this has also been tested by Milan in our lab.
Quoted 48 lines · Laurence Oberman
Quoted 40 lines · Milan P. Gandhi
Couple of users had requested to print the SCSI command age along with command failure errors. This is a small change, but allows users to get more important information about the command that was failed, it would help the users in debugging the command failures:
Signed-off-by Milan P. Gandhi <[email protected]>---
drivers/scsi/scsi_logging.c +1
-0@@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, const char *mlret_string = scsi_mlreturn_string(disposition);const char *hb_string =scsi_hostbyte_string (cmd->result);const char *db_string =scsi_driverbyte_string (cmd->result); +unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) /HZ ; logbuf =scsi_log_reserve_buffer (&logbuf_len);drivers/scsi/scsi_logging.c +7
-2if (!logbuf)@@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, if (db_string) off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=%s", db_string); + "driverbyte=%s ", db_string); else off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=0x%02x", driver_byte(cmd- > result)); +"driverbyte=0x%02x " , + driver_byte(cmd->result)); + + off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age); + out_printk:drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, · line 493
Quoted 2 lines
drivers/scsi/scsi_logging.c +0
-0dev_printk (KERN_INFO , &cmd->device->sdev_gendev,"%s" , logbuf);scsi_log_release_buffer (logbuf);This looks to be a useful debug addition to me, and the code looks correct.
I believe this has also been tested by Milan in our lab.
Quoted 2 lines
Reviewed-by Laurence Oberman <[email protected]>
Yes, the patch was tested locally using scsi_debug as well as in real storage issues caused by bad disks in customer environment.
Thanks,
Milan.
drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, · line 489
Quoted 2 lines · Milan P. Gandhi
drivers/scsi/scsi_logging.c +2
-0+ off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age);
Have you considered to change cmd-age into cmd_age? I'm afraid otherwise someone might interpret the hyphen as a subtraction sign...
Thanks,
Bart.
Quoted 5 lines · Bart Van Assche
Quoted 2 lines · Milan P. Gandhi
+ off +=
scnprintf(logbuf + off, logbuf_len - off, + "cmd-age=%lus", cmd_age);Have you considered to change cmd-age into
cmd_age? I'm afraid otherwise someone might interpret the hyphen as a subtraction sign...
Thanks for your suggestion Bart.
Yes, it would be better to use cmd_age to avoid any confusion. I will change it and send the updated patch.
Thanks,
Milan.
Quoted 13 lines · Milan P. Gandhi
Couple of users had requested to print the SCSI command age along with command failure errors. This is a small change, but allows users to get more important information about the command that was failed, it would help the users in debugging the command failures:
Signed-off-by Milan P. Gandhi <[email protected]>---
drivers/scsi/scsi_logging.c +0
-0
drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd · line 441
Quoted 5 lines
drivers/scsi/scsi_logging.c +1
-0@@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, const char *mlret_string = scsi_mlreturn_string(disposition);const char *hb_string =scsi_hostbyte_string (cmd->result);const char *db_string =scsi_driverbyte_string (cmd->result); +unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) /HZ ;
This comes down to pretty coarse time resolution, does it not? More often than not, the time difference shown will be 0. I'd recommend at least millisecond resolution.
Quoted 9 lines
drivers/scsi/scsi_logging.c +0
-1logbuf =scsi_log_reserve_buffer (&logbuf_len);if (!logbuf)@@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, if (db_string) off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=%s", db_string);
drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd · line 491
Quoted 10 lines
drivers/scsi/scsi_logging.c +6
-1+ "driverbyte=%s ", db_string); else off += scnprintf(logbuf + off, logbuf_len - off, -"driverbyte=0x%02x" ,driver_byte (cmd- >result)); +"driverbyte=0x%02x " , + driver_byte(cmd->result)); + + off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age);
This is certainly helpful in some situations. Yet I am unsure if it should *always* be printed. I wouldn't say it's as important as the other stuff scsi_print_result() provides. After all, by activating MLQUEUE+MLCOMPLETE, the time on-wire can be extracted with better accuracy from currently available logs.
So perhaps make this depend on a module parameter?
Also, we should carefully ponder if we want to put this on the same line as the driver byte, as users may have created scripts for parsing this output.
Regards,
Martin
Quoted 53 lines · Martin Wilck
Quoted 13 lines · Milan P. Gandhi
Couple of users had requested to print the SCSI command age along with command failure errors. This is a small change, but allows users to get more important information about the command that was failed, it would help the users in debugging the command failures:
Signed-off-by Milan P. Gandhi <[email protected]>---
drivers/scsi/scsi_logging.c +0
-0drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd · line 441
Quoted 5 lines
drivers/scsi/scsi_logging.c +1
-0@@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, const char *mlret_string = scsi_mlreturn_string(disposition);const char *hb_string =scsi_hostbyte_string (cmd->result);const char *db_string =scsi_driverbyte_string (cmd->result); +unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) /HZ ;This comes down to pretty coarse time resolution, does it not? More often than not, the time difference shown will be 0. I'd recommend at least millisecond resolution.
Quoted 10 lines
drivers/scsi/scsi_logging.c +1
-1logbuf =scsi_log_reserve_buffer (&logbuf_len);if (!logbuf)@@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd *cmd, const char *msg, if (db_string) off += scnprintf(logbuf + off, logbuf_len - off, - "driverbyte=%s", db_string); + "driverbyte=%s ", db_string);drivers/scsi/scsi_logging.c void scsi_print_result(const struct scsi_cmnd · line 492
Quoted 10 lines
drivers/scsi/scsi_logging.c +5
-1else off +=scnprintf (logbuf + off, logbuf_len - off, -"driverbyte=0x%02x" ,driver_byte (cmd- > result)); +"driverbyte=0x%02x " , + driver_byte(cmd->result)); + + off +=scnprintf (logbuf + off, logbuf_len - off, +"cmd-age=%lus" , cmd_age);This is certainly helpful in some situations. Yet I am unsure if it should *always* be printed. I wouldn't say it's as important as the other stuff
scsi_print_result()provides. After all, by activating MLQUEUE+MLCOMPLETE, the time on-wire can be extracted with better accuracy from currently available logs.So perhaps make this depend on a module parameter?
Quoted 9 lines
Also, we should carefully ponder if we want to put this on the same line as the driver byte, as users may have created scripts for parsing
this output.Regards,
Martin
Hi Martin
Agreed about log extraction, but turning that on with a busy workload in a production environment is not practical. We cant do it with systems with 1000's of luns and 1000's of IOPS/sec.
Also second resolution is good enough for the debug we want to see.
Regards
Laurence
Quoted 7 lines · Laurence Oberman
Hi Martin
Agreed about log extraction, but turning that on with a busy workload in a production environment is not practical. We cant do it with systems with 1000's of luns and 1000's of IOPS/sec.
Also second resolution is good enough for the debug we want to see.
I gather that you look at a specific problem where second resolution is sufficient. For upstream, the generic usefulness should be considered, and I don't think we can say today that better-than-second resolution will never be useful, so I still vote for milliseconds.
Wrt the enablement of the option on highly loaded systems, I'm not sure I understand. You need to enable SCSI logging anyway, don't you? Is it an issue to have to set 2 sysfs values rather than just one?
Regards,
Martin
Quoted 4 lines
Regards
Laurence
Quoted 9 lines · Martin Wilck
Quoted 7 lines · Laurence Oberman
Hi Martin
Agreed about log extraction, but turning that on with a busy workload in a production environment is not practical. We cant do it with systems with 1000's of luns and 1000's of IOPS/sec.
Also second resolution is good enough for the debug we want to see.
Quoted 4 lines
I gather that you look at a specific problem where second resolution is sufficient. For upstream, the generic usefulness should be considered, and I don't think we can say today that better-than-second resolution will never be useful, so I still vote for milliseconds.
Ok, I will change it to ms.
Quoted 2 lines
Wrt the enablement of the option on highly loaded systems, I'm not sure I understand. You need to enable SCSI logging anyway, don't you?
By default we keep the SCSI debug logging disabled or am I missing something?
Quoted 1 line
Is it an issue to have to set 2 sysfs values rather than just one?
The idea here is to capture the above debug data even without any user interventions to change any sysfs entries or to enable debug logging on busy, critical production systems.
Also, we are not changing the existing text in SCSI command error log, but we are only adding one single word at the end of message. Ideally the user scripts are written to grep specific pattern from the logs. Since we are not replacing any existing text from the logs, the scripts should still work with this change as well.
Thanks,
Milan.
Hello Milan,
Quoted 6 lines · Milan P. Gandhi
Quoted 3 lines · Martin Wilck
Wrt the enablement of the option on highly loaded systems, I'm not sure
I understand. You need to enable SCSI logging anyway, don't you?
Quoted 8 lines
By default we keep the SCSI debug logging disabled or am I missing something?
Quoted 1 line
Is it an issue to have to set 2 sysfs values rather than just one?
The idea here is to capture the above debug data even without any user interventions to change any sysfs entries or to enable debug logging on busy, critical production systems.
So, you're looking at the scsi_io_completion() code path. In my experience that isn't reliable for bug hunting because of the the message rate limiting. Therefore I prefer using SCSI logging MLCOMPLETE=1, where no rate limiting applies. But that's just a side note, it depends on the case what's more useful.
Back to the cmd age output, IMO we're are on a thin line between capturing useful information and keeping the logs neat. As I already said, I'm not convinced that this information, as important it may be for the case(s) you're currently investigating, has the same generic degree of importance or usefulness as what's currently printed (the CDB and the sense data). But OTOH, that's just a gut feeling, and I can't claim to have the experience to make general statement on it. If noone else has issues with this being printed by default, I'm not going oppose it.
Quoted 6 lines
Also, we are not changing the existing text in SCSI command error log,
but we are only adding one single word at the end of message. Ideally the user scripts are written to grep specific pattern from the logs. Since we are not replacing any existing text from the logs, the scripts should still work with this change as well.
You are certainly aware that such scripts don't necessarily conform to what kernel developers would consider "ideal" :-) But again, I just wanted to raise the issue; if noone else thinks it matters, fine with me.
Thanks
Martin