consolidate and log scsi command on send and completion
PATCH 1/1 consolidate and log scsi command on send and completion
Hi -
Patch against 2.6.0-test6.
Consolidate and nicely log the scsi_device and scsi command before sending and after completing a command to an adapter driver.
drivers/scsi/scsi.c +125 -69
@@ -351,6 +351,124 @@ void scsi_destroy_command_freelist(strucup (&host_cmd_pool_mutex); } +#ifdef CONFIG_SCSI_LOGGING +void scsi_log_send (struct scsi_cmnd *cmd) +{ +unsigned int level; +struct scsi_device *sdev; + +/* +* If ML QUEUE log level is greater than or equal to: +* +* 1: nothing (match completion) +* +* 2: log opcode + command of all commands +* +* 3: same as 2 plus dump cmd address +* +* 4: same as 3 plus dump extra junk +*/ +if (unlikely (scsi_logging_level)) { + level =SCSI_LOG_LEVEL (SCSI_LOG_MLQUEUE_SHIFT , +SCSI_LOG_MLQUEUE_BITS ); +if (level >1 ) { + sdev = cmd->device; +printk (KERN_INFO "scsi <%d:%d:%d:%d> send " , + sdev->host->host_no, sdev->channel, sdev->id, + sdev->lun); +if (level >2 ) +printk ("0x%p " , cmd); +/* +* spaces to match disposition and cmd->result +* output in scsi_log_completion. +*/ +printk (" " ); +print_command (cmd->cmnd); +if (level >3 ) { +printk (KERN_INFO "buffer = 0x%p, bufflen = %d," +" done = 0x%p, queuecommand 0x%p\n" , + cmd->buffer, cmd->bufflen, + cmd->done, + sdev->host->hostt->queuecommand); + + } + } + } +} + +void scsi_log_completion (struct scsi_cmnd *cmd,int disposition) +{ +unsigned int level; +struct scsi_device *sdev; + +/* +* If ML COMPLETE log level is greater than or equal to: +* +* 1: log disposition, result, opcode + command, and conditionally +* sense data for failures or non SUCCESS dispositions. +* +* 2: same as 1 but for all command completions. +* +* 3: same as 2 plus dump cmd address +* +* 4: same as 3 plus dump extra junk +*/ +if (unlikely (scsi_logging_level)) { + level =SCSI_LOG_LEVEL (SCSI_LOG_MLCOMPLETE_SHIFT , +SCSI_LOG_MLCOMPLETE_BITS ); +if (((level >0 ) && (cmd->result || disposition !=SUCCESS )) || + (level >1 )) { + sdev = cmd->device; +printk (KERN_INFO "scsi <%d:%d:%d:%d> done " , + sdev->host->host_no, sdev->channel, sdev->id, + sdev->lun); +if (level >2 ) +printk ("0x%p " , cmd); +/* +* Dump truncated values, so we usually fit within +* 80 chars. +*/ +switch (disposition) { +case SUCCESS : +printk ("SUCCESS" ); +break ; +case NEEDS_RETRY : +printk ("RETRY " ); +break ; +case ADD_TO_MLQUEUE : +printk ("MLQUEUE" ); +break ; +case FAILED : +printk ("FAILED " ); +break ; +case TIMEOUT : +/* +* If called via scsi_times_out. +*/ +printk ("TIMEOUT" ); +break ; +default : +printk ("UNKNOWN" ); + } +printk (" %8x " , cmd->result); +print_command (cmd->cmnd); +if (status_byte (cmd->result) &CHECK_CONDITION ) { +/* +* XXX The print_sense formatting/prefix +* doesn't match this function. +*/ +print_sense ("" , cmd); + } +if (level >3 ) { +printk (KERN_INFO "scsi host busy %d failed %d\n" , + sdev->host->host_busy, + sdev->host->host_failed); + } + } + } +} +#endif +/* * Function: scsi_dispatch_command *
@@ -406,16 +524,12 @@ int scsi_dispatch_cmd(struct scsi_cmnd *scsi_add_timer (cmd, cmd->timeout_per_command, scsi_times_out); +scsi_log_send (cmd); +/* * We will use a queued command if possible, otherwise we will * emulate the queuing and calling of completion function ourselves. */ -SCSI_LOG_MLQUEUE (3 ,printk ("scsi_dispatch_cmnd (host = %d, " -"channel = %d, target = %d, command = %p, " -"buffer = %p, \nbufflen = %d, done = %p)\n" , - host->host_no, cmd->device->channel, - cmd->device->id, cmd->cmnd, cmd->buffer, - cmd->bufflen, cmd->done)); cmd->state =SCSI_STATE_QUEUED ; cmd->owner =SCSI_OWNER_LOWLEVEL ;
@@ -435,9 +549,6 @@ int scsi_dispatch_cmd(struct scsi_cmnd * goto out; } -SCSI_LOG_MLQUEUE (3 ,printk ("queuecommand : routine at %p\n" , - host->hostt->queuecommand)); -spin_lock_irqsave (host->host_lock, flags);if (unlikely (test_bit (SHOST_CANCEL , &host->shost_state))) { cmd->result = (DID_NO_CONNECT <<16 );
@@ -594,6 +705,7 @@ void scsi_done(struct scsi_cmnd *cmd)*/ static void scsi_softirq (struct softirq_action *h) { +int disposition;LIST_HEAD (local_q);local_irq_disable ();
@@ -605,75 +717,19 @@ static void scsi_softirq(struct softirq_ struct scsi_cmnd, eh_entry);list_del_init (&cmd->eh_entry); -switch (scsi_decide_disposition (cmd)) { + disposition =scsi_decide_disposition (cmd); +scsi_log_completion (cmd, disposition); +switch (disposition) {case SUCCESS : -/* -* Add to BH queue. -*/ -SCSI_LOG_MLCOMPLETE (3 , -printk ("Command finished %d %d " -"0x%x\n" , - cmd->device->host->host_busy, - cmd->device->host->host_failed, - cmd->result)); -scsi_finish_command (cmd);break ;case NEEDS_RETRY : -/* -* We only come in here if we want to retry a -* command. The test to see whether the -* command should be retried should be keeping -* track of the number of tries, so we don't -* end up looping, of course. -*/ -SCSI_LOG_MLCOMPLETE (3 ,printk ("Command needs retry " -"%d %d 0x%x\n" , - cmd->device->host->host_busy, - cmd->device->host->host_failed, - cmd->result)); -scsi_retry_command (cmd);break ;case ADD_TO_MLQUEUE : -/* -* This typically happens for a QUEUE_FULL -* message - typically only when the queue -* depth is only approximate for a given -* device. Adding a command to the queue for -* the device will prevent further commands -* from being sent to the device, so we -* shouldn't end up with tons of things being -* sent down that shouldn't be. -*/ -SCSI_LOG_MLCOMPLETE (3 ,printk ("Command rejected as " -"device queue full, " -"put on ml queue %p\n" , - cmd));scsi_queue_insert (cmd,SCSI_MLQUEUE_DEVICE_BUSY );break ;default : -/* -* Here we have a fatal error of some sort. -* Turn it over to the error handler. -*/ -SCSI_LOG_MLCOMPLETE (3 , -printk ("Command failed %p %x " -"busy=%d failed=%d\n" , - cmd, cmd->result, - cmd->device->host->host_busy, - cmd->device->host->host_failed)); - -/* -* Dump the sense information too. -*/ -if (status_byte (cmd->result) &CHECK_CONDITION ) -SCSI_LOG_MLCOMPLETE (3 ,print_sense ("bh" , cmd)); - -/* -* We only fail here if the error recovery thread -* has died. -*/ if (!scsi_eh_scmd_add (cmd,0 ))scsi_finish_command (cmd); }
@@ -739,7 +795,7 @@ void scsi_finish_command(struct scsi_cmnif (SCSI_SENSE_VALID (cmd)) cmd->result |= (DRIVER_SENSE <<24 ); -SCSI_LOG_MLCOMPLETE (3 ,printk ("Notifying upper driver of completion " +SCSI_LOG_MLCOMPLETE (4 ,printk ("Notifying upper driver of completion " "for device %d %x\n" , sdev->id, cmd->result)); cmd->owner =SCSI_OWNER_HIGHLEVEL ;
drivers/scsi/scsi_error.c +3 -4
@@ -164,14 +164,11 @@ int scsi_delete_timer(struct scsi_cmnd ***/ void scsi_times_out (struct scsi_cmnd *scmd) { +scsi_log_completion (scmd,TIMEOUT );if (unlikely (!scsi_eh_scmd_add (scmd,SCSI_EH_CANCEL_CMD ))) {panic ("Error handler thread not present at %p %p %s %d" , scmd, scmd->device->host, __FILE__, __LINE__); } - -SCSI_LOG_TIMEOUT (3 ,printk ("Command timed out busy=%d failed=%d\n" , - scmd->device->host->host_busy, - scmd->device->host->host_failed)); }/**
@@ -446,10 +443,12 @@ static int scsi_send_eh_cmnd(struct scsi scmd->request->rq_status =RQ_SCSI_BUSY ;spin_lock_irqsave (scmd->device->host->host_lock, flags); +scsi_log_send (scmd); host->hostt->queuecommand (scmd, scsi_eh_done);spin_unlock_irqrestore (scmd->device->host->host_lock, flags);down (&sem); +scsi_log_completion (scmd,SUCCESS ); scmd->device->host->eh_action =NULL ;
drivers/scsi/scsi_logging.h +5 -2
@@ -40,10 +40,13 @@extern unsigned int scsi_logging_level;#ifdef CONFIG_SCSI_LOGGING + +#define SCSI_LOG_LEVEL (SHIFT ,BITS ) \ + ((scsi_logging_level >> (SHIFT)) & ((1 << (BITS)) - 1)) +#define SCSI_CHECK_LOGGING (SHIFT ,BITS ,LEVEL ,CMD ) \ { \ - unsigned int mask = (1 << (BITS)) - 1; \ - if (((scsi_logging_level >> (SHIFT)) & mask) > (LEVEL)) \ + if ((SCSI_LOG_LEVEL(SHIFT, BITS)) > (LEVEL)) \ (CMD); \ }#else
drivers/scsi/scsi_priv.h +9 -0
@@ -83,6 +83,15 @@ extern int scsi_insert_special_req(strucextern void scsi_init_cmd_from_req (struct scsi_cmnd *cmd,struct scsi_request *sreq);extern void __scsi_release_request (struct scsi_request *sreq); +#ifdef CONFIG_SCSI_LOGGING +void scsi_log_send (struct scsi_cmnd *cmd); +void scsi_log_completion (struct scsi_cmnd *cmd,int disposition); +#else +static inline void scsi_log_send (struct scsi_cmnd *cmd) + { }; +static inline void scsi_log_completion (struct scsi_cmnd *cmd,int disposition) + { }; +#endif /* scsi_devinfo.c */ extern int scsi_get_device_flags (unsigned char *vendor,unsigned char *model);
include/scsi/scsi.h +1 -0
@@ -302,6 +302,7 @@ struct scsi_lun {#define QUEUED 0x2004#define SOFT_ERROR 0x2005#define ADD_TO_MLQUEUE 0x2006 +#define TIMEOUT 0x2007/* * Midlevel queue return values.
Some sample output showing the command logging (with CONFIG_SCSI_CONSTANTS enabled).
Of course after shutting off syslogd :-(
And with scsi logging for ml queue of 2 and ml complete of 2 via:
sysctl -w dev.scsi.logging_level=0x2400
FYI, if you want both ml queue and ml complete both set:
to use scsi_logging_level 1 0x1200 2 0x2400 3 0x3600 4 0x4800
Output for scanning host3 id 0, a0 is REPORT LUNS, interspersed with writes to the root disk <0:0:0:0>, and partition information:
scsi <3:0:0:0> send UNKNOWN(0xa0) 00 00 00 00 00 00 00 04 08 00 00
scsi <3:0:0:0> done SUCCESS 0 UNKNOWN(0xa0) 00 00 00 00 00 00 00 04 08 00 00
scsi <3:0:0:1> send Inquiry 00 00 00 24 00
scsi <3:0:0:1> done SUCCESS 0 Inquiry 00 00 00 24 00
Vendor: IBM Model: 3542 Rev: 0520
Type: Direct-Access ANSI SCSI revision: 03
scsi(3:0:0:1): Enabled tagged queuing, queue depth 64.
scsi <3:0:0:1> send Test Unit Ready 00 00 00 00 00
scsi <3:0:0:1> done SUCCESS 0 Test Unit Ready 00 00 00 00 00
scsi <3:0:0:1> send Read Capacity 00 00 00 00 00 00 00 00 00
scsi <3:0:0:1> done SUCCESS 0 Read Capacity 00 00 00 00 00 00 00 00 00
SCSI device sdi: 11087872 512-byte hdwr sectors (5677 MB)
scsi <3:0:0:1> send Mode Sense 00 08 00 04 00
scsi <3:0:0:1> done SUCCESS 0 Mode Sense 00 08 00 04 00
scsi <3:0:0:1> send Mode Sense 00 08 00 20 00
scsi <3:0:0:1> done SUCCESS<6>scsi <0:0:0:0> send Write (10) 00 00 28 00 47 00 00 08 00
scsi <0:0:0:0> done SUCCESS 0 Write (10) 00 00 28 00 47 00 00 08 00
scsi <0:0:0:0> send Write (10) 00 00 28 02 67 00 00 08 00
scsi <0:0:0:0> done SUCCESS 0 Write (10) 00 00 28 02 67 00 00 08 00
scsi <0:0:0:0> send Write (10) 00 00 28 18 3f 00 00 08 00
scsi <0:0:0:0> done SUCCESS 0 Write (10) 00 00 28 18 3f 00 00 08 00
scsi <0:0:0:0> send Write (10) 00 00 34 00 a7 00 00 08 00
0 Mode Sense 00 08 00 20 00
scsi <0:0:0:0> done <5>SCSI device sdi: drive cache: write back
sdi:<6>scsi <3:0:0:1> send Read (10) 00 00 00 00 00 00 00 08 00
scsi <3:0:0:1> done SUCCESS 0 Read (10) 00 00 00 00 00 00 00 08 00
unknown partition table
Attached scsi disk sdi at scsi3, channel 0, id 0, lun 1
SUCCESS 0 Write (10) 00 00 34 00 a7 00 00 08 00
Example of a device not supporting INQUIRY page code 0x83 (with sense data dump):
scsi <0:0:0:0> send Inquiry 01 83 00 ff 00
scsi <0:0:0:0> done SUCCESS 2 Inquiry 01 83 00 ff 00
Current sda: sense key Illegal Request
Additional sense: Invalid field in cdb
scsi <0:0:0:0> done SUCCESS 2 Inquiry 01 83 00 ff 00
Current sda: sense key Illegal Request
Additional sense: Invalid field in cdb
Ard example output on timeout, with scsi logging for ml queue of 3 and ml complete of 3:
scsi <2:0:0:0> done 0xf4abd560 TIMEOUT 0 Read (10) 00 00 00 00 00 00 00 80 00
scsi <2:0:0:0> send 0xf4abd560 Test Unit Ready 00 00 00 00 00
scsi <2:0:0:0> done 0xf4abd560 SUCCESS 0 Test Unit Ready 00 00 00 00 00
Inserting command f4abd560 into mlqueue
scsi <2:0:0:0> send 0xf4abd560 Read (10) 00 00 00 00 00 00 00 80 00
scsi <2:0:0:0> done 0xf4abd560 SUCCESS 0 Read (10) 00 00 00 00 00 00 00 80 00
PATCH 1/1 constants.c [was: consolidate and log scsi command on send and completion]
Quoted 17 lines · Patrick Mansfield
Some sample output showing the command logging (with
CONFIG_SCSI_CONSTANTSenabled).Of course after shutting off syslogd :-(
And with scsi logging for ml queue of 2 and ml complete of 2 via:
sysctl -w dev.scsi.logging_level=0x2400FYI, if you want both ml queue and ml complete both set:
to use scsi_logging_level 1 0x1200 2 0x2400 3 0x3600 4 0x4800
Quoted 3 lines
Output for scanning host3 id 0, a0 is REPORT LUNS, interspersed with writes to the root disk <0:0:0:0>, and partition information:
scsi <3:0:0:0> send UNKNOWN(0xa0) 00 00 00 00 00 00 00 04 08 00 00 scsi <3:0:0:0> done SUCCESS 0 UNKNOWN(0xa0) 00 00 00 00 00 00 00 04 08 00 00
looks good ....
However, drivers/scsi/constants.c does know about Report Luns?? Looks like a merging problem by Andries and me sometime back. See attachment.
Doug Gilbert
drivers/scsi/constants.c260t6pl renamed from drivers/scsi/constants.c +37 -25
@@ -62,42 +62,54 @@ static const char *group_2_commands[] = { -/* 40-41 */ "Change Definition", "Write Same", -/* 42-48 */ "Read sub-channel", "Read TOC", "Read header", - "Play audio (10)", unknown, "Play audio msf", - "Play audio track/index", -/* 49-4f */ "Play track relative (10)", unknown, "Pause/resume", - "Log Select", "Log Sense", unknown, unknown, -/* 50-55 */ unknown, unknown, unknown, unknown, unknown, "Mode Select (10)", -/* 56-5b */ unknown, unknown, unknown, unknown, "Mode Sense (10)", unknown, -/* 5c-5f */ unknown, unknown, unknown, +/* 40-41 */ "Change Definition", "Write Same", +/* 42-48 */ "Read sub-channel", "Read TOC", "Read header", + "Play audio (10)", "Get configuration", "Play audio msf", + "Play audio track/index", +/* 49-4f */ "Play track relative (10)", "Get event status notification", + "Pause/resume", "Log Select", "Log Sense", "Stop play/scan", + unknown, +/* 50-55 */ "Xdwrite", "Xpwrite, Read disk info", "Xdread, Read track info", + "Reserve track", "Send OPC onfo", "Mode Select (10)", +/* 56-5b */ "Reserve (10)", "Release (10)", "Repair track", "Read master cue", + "Mode Sense (10)", "Close track/session", +/* 5c-5f */ "Read buffer capacity", "Send cue sheet", "Persistent reserve in", + "Persistent reserve out", }; /* The following are 16 byte commands in group 4 */ static const char *group_4_commands[] = { -/* 80-84 */ unknown, unknown, unknown, unknown, unknown, -/* 85-89 */ "Memory Export In (16)", unknown, unknown, unknown, - "Memory Export Out (16)", -/* 8a-8f */ unknown, unknown, unknown, unknown, unknown, unknown, -/* 90-94 */ unknown, unknown, unknown, unknown, unknown, +/* 80-84 */ "Xdwrite (16)", "Rebuild (16)", "Regenerate (16)", "Extended copy", + "Receive copy results", +/* 85-89 */ "Memory Export In (16)", "Access control in", "Access control out", + "Read (16)", "Memory Export Out (16)", +/* 8a-8f */ "Write (16)", unknown, "Read attributes", "Write attributes", + "Write and verify (16)", "Verify (16)", +/* 90-94 */ "Pre-fetch (16)", "Synchronize cache (16)", + "Lock/unlock cache (16)", "Write same (16)", unknown, /* 95-99 */ unknown, unknown, unknown, unknown, unknown, -/* 9a-9f */ unknown, unknown, unknown, unknown, unknown, unknown, +/* 9a-9f */ unknown, unknown, unknown, unknown, "Service action in", + "Service action out", }; - /* The following are 12 byte commands in group 5 */ static const char *group_5_commands[] = { -/* a0-a5 */ unknown, unknown, unknown, unknown, unknown, - "Move medium/play audio(12)", -/* a6-a9 */ "Exchange medium", unknown, "Read(12)", "Play track relative(12)", -/* aa-ae */ "Write(12)", unknown, "Erase(12)", unknown, - "Write and verify(12)", +/* a0-a5 */ "Report luns", "Blank", "Send event", "Maintenance (in)", + "Maintenance (out)", "Move medium/play audio(12)", +/* a6-a9 */ "Exchange medium", "Move medium attached", "Read(12)", + "Play track relative(12)", +/* aa-ae */ "Write(12)", unknown, "Erase(12), Get Performance", + "Read DVD structure", "Write and verify(12)", /* af-b1 */ "Verify(12)", "Search data high(12)", "Search data equal(12)", -/* b2-b4 */ "Search data low(12)", "Set limits(12)", unknown, -/* b5-b6 */ "Request volume element address", "Send volume tag", -/* b7-b9 */ "Read defect data(12)", "Read element status", unknown, -/* ba-bf */ unknown, unknown, unknown, unknown, unknown, unknown, +/* b2-b4 */ "Search data low(12)", "Set limits(12)", + "Read element status attached", +/* b5-b6 */ "Request volume element address", "Send volume tag, set streaming", +/* b7-b9 */ "Read defect data(12)", "Read element status", "Read CD msf", +/* ba-bc */ "Redundancy group (in), Scan", + "Redundancy group (out), Set cd-rom speed", "Spare (in), Play cd", +/* bd-bf */ "Spare (out), Mechanism status", "Volume set (in), Read cd", + "Volume set (out), Send DVD structure", };