Linux kernel mirror (for testing) git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel os linux

scsi: trace: Print driver_tag and scheduler_tag in SCSI trace

Trace events like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done are
useful for tracking a command throughout its lifetime. But for some ATA
passthrough commands, the information printed in current logs is not enough
to identify and match them. For example, if two threads send SMART cmd to
the same disk at the same time, their trace logs may look the same, which
makes it hard to match scsi_dispatch_cmd_done and scsi_dispatch_cmd_start.

Printing tags can help us solve the problem. Further, if a command failed
for some reason and then is retried, its driver_tag will change. So
scheduler_tag is also included such that we can track the retries of a
command.

Link: https://lore.kernel.org/r/20220621181125.3211399-1-changyuanl@google.com
Reviewed-by: Vishakha Channapattan <vishakhavc@google.com>
Reviewed-by: Jolly Shah <jollys@google.com>
Reviewed-by: Bart Van Assche <bvanassche@acm.org>
Signed-off-by: Changyuan Lyu <changyuanl@google.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>

authored by

Changyuan Lyu and committed by
Martin K. Petersen
cc06af0b bc98b503

+24 -11
+24 -11
include/trace/events/scsi.h
··· 166 166 __field( unsigned int, lun ) 167 167 __field( unsigned int, opcode ) 168 168 __field( unsigned int, cmd_len ) 169 + __field( int, driver_tag) 170 + __field( int, scheduler_tag) 169 171 __field( unsigned int, data_sglen ) 170 172 __field( unsigned int, prot_sglen ) 171 173 __field( unsigned char, prot_op ) ··· 181 179 __entry->lun = cmd->device->lun; 182 180 __entry->opcode = cmd->cmnd[0]; 183 181 __entry->cmd_len = cmd->cmd_len; 182 + __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag; 183 + __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag; 184 184 __entry->data_sglen = scsi_sg_count(cmd); 185 185 __entry->prot_sglen = scsi_prot_sg_count(cmd); 186 186 __entry->prot_op = scsi_get_prot_op(cmd); ··· 190 186 ), 191 187 192 188 TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \ 193 - " prot_op=%s cmnd=(%s %s raw=%s)", 189 + " prot_op=%s driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s)", 194 190 __entry->host_no, __entry->channel, __entry->id, 195 191 __entry->lun, __entry->data_sglen, __entry->prot_sglen, 196 - show_prot_op_name(__entry->prot_op), 197 - show_opcode_name(__entry->opcode), 192 + show_prot_op_name(__entry->prot_op), __entry->driver_tag, 193 + __entry->scheduler_tag, show_opcode_name(__entry->opcode), 198 194 __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len), 199 195 __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len)) 200 196 ); ··· 213 209 __field( int, rtn ) 214 210 __field( unsigned int, opcode ) 215 211 __field( unsigned int, cmd_len ) 212 + __field( int, driver_tag) 213 + __field( int, scheduler_tag) 216 214 __field( unsigned int, data_sglen ) 217 215 __field( unsigned int, prot_sglen ) 218 216 __field( unsigned char, prot_op ) ··· 229 223 __entry->rtn = rtn; 230 224 __entry->opcode = cmd->cmnd[0]; 231 225 __entry->cmd_len = cmd->cmd_len; 226 + __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag; 227 + __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag; 232 228 __entry->data_sglen = scsi_sg_count(cmd); 233 229 __entry->prot_sglen = scsi_prot_sg_count(cmd); 234 230 __entry->prot_op = scsi_get_prot_op(cmd); ··· 238 230 ), 239 231 240 232 TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \ 241 - " prot_op=%s cmnd=(%s %s raw=%s) rtn=%d", 233 + " prot_op=%s driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s)" \ 234 + " rtn=%d", 242 235 __entry->host_no, __entry->channel, __entry->id, 243 236 __entry->lun, __entry->data_sglen, __entry->prot_sglen, 244 - show_prot_op_name(__entry->prot_op), 245 - show_opcode_name(__entry->opcode), 237 + show_prot_op_name(__entry->prot_op), __entry->driver_tag, 238 + __entry->scheduler_tag, show_opcode_name(__entry->opcode), 246 239 __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len), 247 240 __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len), 248 241 __entry->rtn) ··· 263 254 __field( int, result ) 264 255 __field( unsigned int, opcode ) 265 256 __field( unsigned int, cmd_len ) 257 + __field( int, driver_tag) 258 + __field( int, scheduler_tag) 266 259 __field( unsigned int, data_sglen ) 267 260 __field( unsigned int, prot_sglen ) 268 261 __field( unsigned char, prot_op ) ··· 279 268 __entry->result = cmd->result; 280 269 __entry->opcode = cmd->cmnd[0]; 281 270 __entry->cmd_len = cmd->cmd_len; 271 + __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag; 272 + __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag; 282 273 __entry->data_sglen = scsi_sg_count(cmd); 283 274 __entry->prot_sglen = scsi_prot_sg_count(cmd); 284 275 __entry->prot_op = scsi_get_prot_op(cmd); 285 276 memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len); 286 277 ), 287 278 288 - TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \ 289 - "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s) result=(driver=" \ 290 - "%s host=%s message=%s status=%s)", 279 + TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u " \ 280 + "prot_op=%s driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s) " \ 281 + "result=(driver=%s host=%s message=%s status=%s)", 291 282 __entry->host_no, __entry->channel, __entry->id, 292 283 __entry->lun, __entry->data_sglen, __entry->prot_sglen, 293 - show_prot_op_name(__entry->prot_op), 294 - show_opcode_name(__entry->opcode), 284 + show_prot_op_name(__entry->prot_op), __entry->driver_tag, 285 + __entry->scheduler_tag, show_opcode_name(__entry->opcode), 295 286 __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len), 296 287 __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len), 297 288 "DRIVER_OK",