>Hmm... that's not my expectation as well, but I've replicated your results. >More interestingly, I tried the same experiment using XFS, and it does the >same thing. I used as my test workload: > >dd if=/mnt/test bs=128k count=32 | sum > >Used strace to verify that dd was in fact issuing 128k reads: > >read(0, >"\377\253a)\307\10\230\6\360,,:\226Rq\204\343\2522&44\307\341\372\271\ >271/\224#?\346"..., 131072) = 131072 write(1, >"\377\253a)\307\10\230\6\360,,:\226Rq\204\343\2522&44\307\341\372\271\ >271/\224#?\346"..., 131072) = 131072 > >And then used btrace to monitor the I/O requests sent to the device: > >252,4 0 413 0.077274997 14645 Q R 4408 + 8 [dd] >252,4 2 77 0.077355648 5529 C R 4408 + 8 [0] >252,4 0 414 0.077393725 14645 Q R 4416 + 8 [dd] >252,4 2 78 0.077630722 5529 C R 4416 + 8 [0] > ... > >... and indeed, the reads are being sent to the device in 4k chunks. >That's indeed surprising. I'd have to do some debugging with tracepoints to >see what requests are being issued from the mm/filemap.c to the file system. > >As others have suggested using O_DIRECT reads will certainly allow the 128k >reads to be passed all the way down to the device: > Yes, if using O_Direct mode read, ext4 will allow 128kB to read. Following is just one 128KB chunk data request sync mode read log: [006] ...1 3032.166796: sys_read(fd: 3, buf: 7790900000, count: 20000) [006] ...1 3032.166798: generic_file_read_iter <-new_sync_read [006] .... 3032.166822: block_bio_remap: 8,48 R 39243888 + 8 <- (8,62) 12400 [006] .... 3032.166823: block_bio_queue: 8,48 R 39243888 + 8 [iotest] [006] ...1 3032.166824: block_getrq: 8,48 R 39243888 + 8 [iotest] [006] ...2 3032.166826: block_rq_insert: 8,48 RS 0 () 39243888 + 8 [iotest] [006] ...3 3032.166827: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.166828: block_rq_issue: 8,48 RS 0 () 39243888 + 8 [iotest] [006] ...2 3032.166829: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4905486 txlen=1 protect=0 raw=28 00 00 4a da 0e 00 00 01 00) [006] ...3 3032.166830: scsi_dma_map <-ufshcd_queuecommand [006] d.h1 3032.166945: irq_handler_entry: irq=4 name=arch_timer [000] dnh1 3032.167126: irq_handler_entry: irq=57 name=ufshcd [000] dnh2 3032.167127: ufshcd_intr <-__handle_irq_event_percpu [000] dnh3 3032.167130: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] dnh2 3032.167132: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4905486 txlen=1 protect=0 raw=28 00 00 4a da 0e 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.167137: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.167138: block_rq_complete: 8,48 RS () 39243888 + 8 [0] [006] .... 3032.167271: block_bio_remap: 8,48 R 39249664 + 8 <- (8,62) 18176 [006] .... 3032.167272: block_bio_queue: 8,48 R 39249664 + 8 [iotest] [006] ...1 3032.167273: block_getrq: 8,48 R 39249664 + 8 [iotest] [006] ...2 3032.167274: block_rq_insert: 8,48 RS 0 () 39249664 + 8 [iotest] [006] ...3 3032.167274: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.167275: block_rq_issue: 8,48 RS 0 () 39249664 + 8 [iotest] [006] ...2 3032.167275: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906208 txlen=1 protect=0 raw=28 00 00 4a dc e0 00 00 01 00) [006] ...3 3032.167276: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.167617: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.167618: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.167621: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.167623: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906208 txlen=1 protect=0 raw=28 00 00 4a dc e0 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.167628: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.167629: block_rq_complete: 8,48 RS () 39249664 + 8 [0] [006] .... 3032.167645: block_bio_remap: 8,48 R 39249672 + 8 <- (8,62) 18184 [006] .... 3032.167646: block_bio_queue: 8,48 R 39249672 + 8 [iotest] [006] ...1 3032.167647: block_getrq: 8,48 R 39249672 + 8 [iotest] [006] ...2 3032.167648: block_rq_insert: 8,48 RS 0 () 39249672 + 8 [iotest] [006] ...3 3032.167649: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.167649: block_rq_issue: 8,48 RS 0 () 39249672 + 8 [iotest] [006] ...2 3032.167650: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906209 txlen=1 protect=0 raw=28 00 00 4a dc e1 00 00 01 00) [006] ...3 3032.167651: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.167735: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.167736: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.167738: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.167741: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906209 txlen=1 protect=0 raw=28 00 00 4a dc e1 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.167745: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.167745: block_rq_complete: 8,48 RS () 39249672 + 8 [0] [006] .... 3032.167758: block_bio_remap: 8,48 R 39249680 + 8 <- (8,62) 18192 [006] .... 3032.167759: block_bio_queue: 8,48 R 39249680 + 8 [iotest] [006] ...1 3032.167759: block_getrq: 8,48 R 39249680 + 8 [iotest] [006] ...2 3032.167760: block_rq_insert: 8,48 RS 0 () 39249680 + 8 [iotest] [006] ...3 3032.167761: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.167761: block_rq_issue: 8,48 RS 0 () 39249680 + 8 [iotest] [006] ...2 3032.167762: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906210 txlen=1 protect=0 raw=28 00 00 4a dc e2 00 00 01 00) [006] ...3 3032.167763: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.167851: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.167852: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.167855: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.167856: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906210 txlen=1 protect=0 raw=28 00 00 4a dc e2 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.167860: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.167861: block_rq_complete: 8,48 RS () 39249680 + 8 [0] [006] .... 3032.167873: block_bio_remap: 8,48 R 39249688 + 8 <- (8,62) 18200 [006] .... 3032.167874: block_bio_queue: 8,48 R 39249688 + 8 [iotest] [006] ...1 3032.167874: block_getrq: 8,48 R 39249688 + 8 [iotest] [006] ...2 3032.167875: block_rq_insert: 8,48 RS 0 () 39249688 + 8 [iotest] [006] ...3 3032.167876: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.167876: block_rq_issue: 8,48 RS 0 () 39249688 + 8 [iotest] [006] ...2 3032.167877: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906211 txlen=1 protect=0 raw=28 00 00 4a dc e3 00 00 01 00) [006] ...3 3032.167878: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.167964: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.167965: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.167968: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.167969: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906211 txlen=1 protect=0 raw=28 00 00 4a dc e3 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.167974: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.167974: block_rq_complete: 8,48 RS () 39249688 + 8 [0] [006] .... 3032.167986: block_bio_remap: 8,48 R 39249696 + 8 <- (8,62) 18208 [006] .... 3032.167987: block_bio_queue: 8,48 R 39249696 + 8 [iotest] [006] ...1 3032.167987: block_getrq: 8,48 R 39249696 + 8 [iotest] [006] ...2 3032.167988: block_rq_insert: 8,48 RS 0 () 39249696 + 8 [iotest] [006] ...3 3032.167989: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.167989: block_rq_issue: 8,48 RS 0 () 39249696 + 8 [iotest] [006] ...2 3032.167990: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906212 txlen=1 protect=0 raw=28 00 00 4a dc e4 00 00 01 00) [006] ...3 3032.167991: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168079: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168079: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168082: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168084: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906212 txlen=1 protect=0 raw=28 00 00 4a dc e4 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168088: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168088: block_rq_complete: 8,48 RS () 39249696 + 8 [0] [006] .... 3032.168100: block_bio_remap: 8,48 R 39249704 + 8 <- (8,62) 18216 [006] .... 3032.168101: block_bio_queue: 8,48 R 39249704 + 8 [iotest] [006] ...1 3032.168101: block_getrq: 8,48 R 39249704 + 8 [iotest] [006] ...2 3032.168102: block_rq_insert: 8,48 RS 0 () 39249704 + 8 [iotest] [006] ...3 3032.168102: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168103: block_rq_issue: 8,48 RS 0 () 39249704 + 8 [iotest] [006] ...2 3032.168104: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906213 txlen=1 protect=0 raw=28 00 00 4a dc e5 00 00 01 00) [006] ...3 3032.168105: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168192: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168192: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168195: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168197: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906213 txlen=1 protect=0 raw=28 00 00 4a dc e5 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168201: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168201: block_rq_complete: 8,48 RS () 39249704 + 8 [0] [006] .... 3032.168219: block_bio_remap: 8,48 R 39249712 + 8 <- (8,62) 18224 [006] .... 3032.168220: block_bio_queue: 8,48 R 39249712 + 8 [iotest] [006] ...1 3032.168221: block_getrq: 8,48 R 39249712 + 8 [iotest] [006] ...2 3032.168222: block_rq_insert: 8,48 RS 0 () 39249712 + 8 [iotest] [006] ...3 3032.168222: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168223: block_rq_issue: 8,48 RS 0 () 39249712 + 8 [iotest] [006] ...2 3032.168224: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906214 txlen=1 protect=0 raw=28 00 00 4a dc e6 00 00 01 00) [006] ...3 3032.168225: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168309: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168310: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168312: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168314: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906214 txlen=1 protect=0 raw=28 00 00 4a dc e6 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168318: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168318: block_rq_complete: 8,48 RS () 39249712 + 8 [0] [006] .... 3032.168330: block_bio_remap: 8,48 R 39249720 + 8 <- (8,62) 18232 [006] .... 3032.168331: block_bio_queue: 8,48 R 39249720 + 8 [iotest] [006] ...1 3032.168332: block_getrq: 8,48 R 39249720 + 8 [iotest] [006] ...2 3032.168332: block_rq_insert: 8,48 RS 0 () 39249720 + 8 [iotest] [006] ...3 3032.168333: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168333: block_rq_issue: 8,48 RS 0 () 39249720 + 8 [iotest] [006] ...2 3032.168334: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906215 txlen=1 protect=0 raw=28 00 00 4a dc e7 00 00 01 00) [006] ...3 3032.168335: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168419: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168420: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168422: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168424: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906215 txlen=1 protect=0 raw=28 00 00 4a dc e7 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168427: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168427: block_rq_complete: 8,48 RS () 39249720 + 8 [0] [006] .... 3032.168439: block_bio_remap: 8,48 R 39249728 + 8 <- (8,62) 18240 [006] .... 3032.168439: block_bio_queue: 8,48 R 39249728 + 8 [iotest] [006] ...1 3032.168441: block_getrq: 8,48 R 39249728 + 8 [iotest] [006] ...2 3032.168441: block_rq_insert: 8,48 RS 0 () 39249728 + 8 [iotest] [006] ...3 3032.168442: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168442: block_rq_issue: 8,48 RS 0 () 39249728 + 8 [iotest] [006] ...2 3032.168443: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906216 txlen=1 protect=0 raw=28 00 00 4a dc e8 00 00 01 00) [006] ...3 3032.168444: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168542: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168543: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168545: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168547: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906216 txlen=1 protect=0 raw=28 00 00 4a dc e8 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168550: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168550: block_rq_complete: 8,48 RS () 39249728 + 8 [0] [006] .... 3032.168569: block_bio_remap: 8,48 R 39249736 + 8 <- (8,62) 18248 [006] .... 3032.168569: block_bio_queue: 8,48 R 39249736 + 8 [iotest] [006] ...1 3032.168570: block_getrq: 8,48 R 39249736 + 8 [iotest] [006] ...2 3032.168571: block_rq_insert: 8,48 RS 0 () 39249736 + 8 [iotest] [006] ...3 3032.168571: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168572: block_rq_issue: 8,48 RS 0 () 39249736 + 8 [iotest] [006] ...2 3032.168572: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906217 txlen=1 protect=0 raw=28 00 00 4a dc e9 00 00 01 00) [006] ...3 3032.168573: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168670: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168670: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168673: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168675: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906217 txlen=1 protect=0 raw=28 00 00 4a dc e9 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168679: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168679: block_rq_complete: 8,48 RS () 39249736 + 8 [0] [006] .... 3032.168698: block_bio_remap: 8,48 R 39249744 + 8 <- (8,62) 18256 [006] .... 3032.168698: block_bio_queue: 8,48 R 39249744 + 8 [iotest] [006] ...1 3032.168699: block_getrq: 8,48 R 39249744 + 8 [iotest] [006] ...2 3032.168700: block_rq_insert: 8,48 RS 0 () 39249744 + 8 [iotest] [006] ...3 3032.168700: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168701: block_rq_issue: 8,48 RS 0 () 39249744 + 8 [iotest] [006] ...2 3032.168701: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906218 txlen=1 protect=0 raw=28 00 00 4a dc ea 00 00 01 00) [006] ...3 3032.168702: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168801: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168802: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168805: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168806: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906218 txlen=1 protect=0 raw=28 00 00 4a dc ea 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168809: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168810: block_rq_complete: 8,48 RS () 39249744 + 8 [0] [006] .... 3032.168826: block_bio_remap: 8,48 R 39249752 + 8 <- (8,62) 18264 [006] .... 3032.168826: block_bio_queue: 8,48 R 39249752 + 8 [iotest] [006] ...1 3032.168827: block_getrq: 8,48 R 39249752 + 8 [iotest] [006] ...2 3032.168828: block_rq_insert: 8,48 RS 0 () 39249752 + 8 [iotest] [006] ...3 3032.168829: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168829: block_rq_issue: 8,48 RS 0 () 39249752 + 8 [iotest] [006] ...2 3032.168830: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906219 txlen=1 protect=0 raw=28 00 00 4a dc eb 00 00 01 00) [006] ...3 3032.168831: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.168932: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.168933: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.168936: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.168938: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906219 txlen=1 protect=0 raw=28 00 00 4a dc eb 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.168941: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.168942: block_rq_complete: 8,48 RS () 39249752 + 8 [0] [006] .... 3032.168957: block_bio_remap: 8,48 R 39249760 + 8 <- (8,62) 18272 [006] .... 3032.168957: block_bio_queue: 8,48 R 39249760 + 8 [iotest] [006] ...1 3032.168958: block_getrq: 8,48 R 39249760 + 8 [iotest] [006] ...2 3032.168959: block_rq_insert: 8,48 RS 0 () 39249760 + 8 [iotest] [006] ...3 3032.168959: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.168960: block_rq_issue: 8,48 RS 0 () 39249760 + 8 [iotest] [006] ...2 3032.168960: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906220 txlen=1 protect=0 raw=28 00 00 4a dc ec 00 00 01 00) [006] ...3 3032.168961: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169062: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169063: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169066: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169068: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906220 txlen=1 protect=0 raw=28 00 00 4a dc ec 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169071: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169071: block_rq_complete: 8,48 RS () 39249760 + 8 [0] [006] .... 3032.169086: block_bio_remap: 8,48 R 39249768 + 8 <- (8,62) 18280 [006] .... 3032.169087: block_bio_queue: 8,48 R 39249768 + 8 [iotest] [006] ...1 3032.169088: block_getrq: 8,48 R 39249768 + 8 [iotest] [006] ...2 3032.169089: block_rq_insert: 8,48 RS 0 () 39249768 + 8 [iotest] [006] ...3 3032.169089: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169090: block_rq_issue: 8,48 RS 0 () 39249768 + 8 [iotest] [006] ...2 3032.169091: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906221 txlen=1 protect=0 raw=28 00 00 4a dc ed 00 00 01 00) [006] ...3 3032.169092: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169177: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169177: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169180: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169182: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906221 txlen=1 protect=0 raw=28 00 00 4a dc ed 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169185: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169186: block_rq_complete: 8,48 RS () 39249768 + 8 [0] [006] .... 3032.169202: block_bio_remap: 8,48 R 39249776 + 8 <- (8,62) 18288 [006] .... 3032.169203: block_bio_queue: 8,48 R 39249776 + 8 [iotest] [006] ...1 3032.169204: block_getrq: 8,48 R 39249776 + 8 [iotest] [006] ...2 3032.169204: block_rq_insert: 8,48 RS 0 () 39249776 + 8 [iotest] [006] ...3 3032.169205: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169205: block_rq_issue: 8,48 RS 0 () 39249776 + 8 [iotest] [006] ...2 3032.169206: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906222 txlen=1 protect=0 raw=28 00 00 4a dc ee 00 00 01 00) [006] ...3 3032.169207: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169357: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169358: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169360: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169362: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906222 txlen=1 protect=0 raw=28 00 00 4a dc ee 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169366: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169367: block_rq_complete: 8,48 RS () 39249776 + 8 [0] [006] .... 3032.169382: block_bio_remap: 8,48 R 39249784 + 8 <- (8,62) 18296 [006] .... 3032.169383: block_bio_queue: 8,48 R 39249784 + 8 [iotest] [006] ...1 3032.169383: block_getrq: 8,48 R 39249784 + 8 [iotest] [006] ...2 3032.169384: block_rq_insert: 8,48 RS 0 () 39249784 + 8 [iotest] [006] ...3 3032.169385: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169385: block_rq_issue: 8,48 RS 0 () 39249784 + 8 [iotest] [006] ...2 3032.169386: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906223 txlen=1 protect=0 raw=28 00 00 4a dc ef 00 00 01 00) [006] ...3 3032.169387: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169534: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169534: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169537: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169539: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906223 txlen=1 protect=0 raw=28 00 00 4a dc ef 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169542: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169543: block_rq_complete: 8,48 RS () 39249784 + 8 [0] [006] .... 3032.169558: block_bio_remap: 8,48 R 39249792 + 8 <- (8,62) 18304 [006] .... 3032.169558: block_bio_queue: 8,48 R 39249792 + 8 [iotest] [006] ...1 3032.169559: block_getrq: 8,48 R 39249792 + 8 [iotest] [006] ...2 3032.169560: block_rq_insert: 8,48 RS 0 () 39249792 + 8 [iotest] [006] ...3 3032.169560: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169561: block_rq_issue: 8,48 RS 0 () 39249792 + 8 [iotest] [006] ...2 3032.169562: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906224 txlen=1 protect=0 raw=28 00 00 4a dc f0 00 00 01 00) [006] ...3 3032.169563: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169710: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169711: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169714: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169716: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906224 txlen=1 protect=0 raw=28 00 00 4a dc f0 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169719: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169719: block_rq_complete: 8,48 RS () 39249792 + 8 [0] [006] .... 3032.169736: block_bio_remap: 8,48 R 39249800 + 8 <- (8,62) 18312 [006] .... 3032.169737: block_bio_queue: 8,48 R 39249800 + 8 [iotest] [006] ...1 3032.169738: block_getrq: 8,48 R 39249800 + 8 [iotest] [006] ...2 3032.169738: block_rq_insert: 8,48 RS 0 () 39249800 + 8 [iotest] [006] ...3 3032.169739: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169739: block_rq_issue: 8,48 RS 0 () 39249800 + 8 [iotest] [006] ...2 3032.169741: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906225 txlen=1 protect=0 raw=28 00 00 4a dc f1 00 00 01 00) [006] ...3 3032.169742: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.169887: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.169888: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.169891: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.169892: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906225 txlen=1 protect=0 raw=28 00 00 4a dc f1 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.169895: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.169896: block_rq_complete: 8,48 RS () 39249800 + 8 [0] [006] .... 3032.169911: block_bio_remap: 8,48 R 39249808 + 8 <- (8,62) 18320 [006] .... 3032.169912: block_bio_queue: 8,48 R 39249808 + 8 [iotest] [006] ...1 3032.169912: block_getrq: 8,48 R 39249808 + 8 [iotest] [006] ...2 3032.169913: block_rq_insert: 8,48 RS 0 () 39249808 + 8 [iotest] [006] ...3 3032.169914: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.169914: block_rq_issue: 8,48 RS 0 () 39249808 + 8 [iotest] [006] ...2 3032.169915: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906226 txlen=1 protect=0 raw=28 00 00 4a dc f2 00 00 01 00) [006] ...3 3032.169916: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.170067: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170067: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170070: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170072: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906226 txlen=1 protect=0 raw=28 00 00 4a dc f2 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170075: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170075: block_rq_complete: 8,48 RS () 39249808 + 8 [0] [006] .... 3032.170092: block_bio_remap: 8,48 R 39249816 + 8 <- (8,62) 18328 [006] .... 3032.170092: block_bio_queue: 8,48 R 39249816 + 8 [iotest] [006] ...1 3032.170093: block_getrq: 8,48 R 39249816 + 8 [iotest] [006] ...2 3032.170094: block_rq_insert: 8,48 RS 0 () 39249816 + 8 [iotest] [006] ...3 3032.170094: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170095: block_rq_issue: 8,48 RS 0 () 39249816 + 8 [iotest] [006] ...2 3032.170096: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906227 txlen=1 protect=0 raw=28 00 00 4a dc f3 00 00 01 00) [006] ...3 3032.170096: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.170245: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170246: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170248: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170250: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906227 txlen=1 protect=0 raw=28 00 00 4a dc f3 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170255: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170255: block_rq_complete: 8,48 RS () 39249816 + 8 [0] [006] .... 3032.170271: block_bio_remap: 8,48 R 39249824 + 8 <- (8,62) 18336 [006] .... 3032.170272: block_bio_queue: 8,48 R 39249824 + 8 [iotest] [006] ...1 3032.170272: block_getrq: 8,48 R 39249824 + 8 [iotest] [006] ...2 3032.170273: block_rq_insert: 8,48 RS 0 () 39249824 + 8 [iotest] [006] ...3 3032.170274: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170274: block_rq_issue: 8,48 RS 0 () 39249824 + 8 [iotest] [006] ...2 3032.170275: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906228 txlen=1 protect=0 raw=28 00 00 4a dc f4 00 00 01 00) [006] ...3 3032.170276: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.170422: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170423: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170425: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170427: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906228 txlen=1 protect=0 raw=28 00 00 4a dc f4 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170432: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170432: block_rq_complete: 8,48 RS () 39249824 + 8 [0] [006] .... 3032.170447: block_bio_remap: 8,48 R 39249832 + 8 <- (8,62) 18344 [006] .... 3032.170448: block_bio_queue: 8,48 R 39249832 + 8 [iotest] [006] ...1 3032.170449: block_getrq: 8,48 R 39249832 + 8 [iotest] [006] ...2 3032.170450: block_rq_insert: 8,48 RS 0 () 39249832 + 8 [iotest] [006] ...3 3032.170450: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170450: block_rq_issue: 8,48 RS 0 () 39249832 + 8 [iotest] [006] ...2 3032.170451: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906229 txlen=1 protect=0 raw=28 00 00 4a dc f5 00 00 01 00) [006] ...3 3032.170452: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.170585: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170586: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170588: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170590: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906229 txlen=1 protect=0 raw=28 00 00 4a dc f5 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170595: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170595: block_rq_complete: 8,48 RS () 39249832 + 8 [0] [006] .... 3032.170611: block_bio_remap: 8,48 R 39249840 + 8 <- (8,62) 18352 [006] .... 3032.170611: block_bio_queue: 8,48 R 39249840 + 8 [iotest] [006] ...1 3032.170612: block_getrq: 8,48 R 39249840 + 8 [iotest] [006] ...2 3032.170613: block_rq_insert: 8,48 RS 0 () 39249840 + 8 [iotest] [006] ...3 3032.170613: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170614: block_rq_issue: 8,48 RS 0 () 39249840 + 8 [iotest] [006] ...2 3032.170615: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906230 txlen=1 protect=0 raw=28 00 00 4a dc f6 00 00 01 00) [006] ...3 3032.170616: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.170761: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170762: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170765: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170767: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906230 txlen=1 protect=0 raw=28 00 00 4a dc f6 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170771: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170772: block_rq_complete: 8,48 RS () 39249840 + 8 [0] [006] .... 3032.170794: block_bio_remap: 8,48 R 39249848 + 8 <- (8,62) 18360 [006] .... 3032.170795: block_bio_queue: 8,48 R 39249848 + 8 [iotest] [006] ...1 3032.170795: block_getrq: 8,48 R 39249848 + 8 [iotest] [006] ...2 3032.170796: block_rq_insert: 8,48 RS 0 () 39249848 + 8 [iotest] [006] ...3 3032.170797: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170797: block_rq_issue: 8,48 RS 0 () 39249848 + 8 [iotest] [006] ...2 3032.170798: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906231 txlen=1 protect=0 raw=28 00 00 4a dc f7 00 00 01 00) [006] ...3 3032.170799: scsi_dma_map <-ufshcd_queuecommand [006] d.h1 3032.170945: irq_handler_entry: irq=4 name=arch_timer [000] d.h1 3032.170947: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.170947: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.170950: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.170952: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906231 txlen=1 protect=0 raw=28 00 00 4a dc f7 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.170957: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.170958: block_rq_complete: 8,48 RS () 39249848 + 8 [0] [006] .... 3032.170977: block_bio_remap: 8,48 R 39249856 + 8 <- (8,62) 18368 [006] .... 3032.170978: block_bio_queue: 8,48 R 39249856 + 8 [iotest] [006] ...1 3032.170979: block_getrq: 8,48 R 39249856 + 8 [iotest] [006] ...2 3032.170980: block_rq_insert: 8,48 RS 0 () 39249856 + 8 [iotest] [006] ...3 3032.170980: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.170981: block_rq_issue: 8,48 RS 0 () 39249856 + 8 [iotest] [006] ...2 3032.170982: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906232 txlen=1 protect=0 raw=28 00 00 4a dc f8 00 00 01 00) [006] ...3 3032.170983: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.171132: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.171133: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.171135: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.171137: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906232 txlen=1 protect=0 raw=28 00 00 4a dc f8 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.171142: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.171142: block_rq_complete: 8,48 RS () 39249856 + 8 [0] [006] .... 3032.171158: block_bio_remap: 8,48 R 39249864 + 8 <- (8,62) 18376 [006] .... 3032.171159: block_bio_queue: 8,48 R 39249864 + 8 [iotest] [006] ...1 3032.171159: block_getrq: 8,48 R 39249864 + 8 [iotest] [006] ...2 3032.171160: block_rq_insert: 8,48 RS 0 () 39249864 + 8 [iotest] [006] ...3 3032.171161: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.171161: block_rq_issue: 8,48 RS 0 () 39249864 + 8 [iotest] [006] ...2 3032.171162: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906233 txlen=1 protect=0 raw=28 00 00 4a dc f9 00 00 01 00) [006] ...3 3032.171163: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.171309: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.171309: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.171312: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.171313: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906233 txlen=1 protect=0 raw=28 00 00 4a dc f9 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.171318: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.171319: block_rq_complete: 8,48 RS () 39249864 + 8 [0] [006] .... 3032.171335: block_bio_remap: 8,48 R 39249872 + 8 <- (8,62) 18384 [006] .... 3032.171335: block_bio_queue: 8,48 R 39249872 + 8 [iotest] [006] ...1 3032.171336: block_getrq: 8,48 R 39249872 + 8 [iotest] [006] ...2 3032.171337: block_rq_insert: 8,48 RS 0 () 39249872 + 8 [iotest] [006] ...3 3032.171337: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.171338: block_rq_issue: 8,48 RS 0 () 39249872 + 8 [iotest] [006] ...2 3032.171339: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906234 txlen=1 protect=0 raw=28 00 00 4a dc fa 00 00 01 00) [006] ...3 3032.171340: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.171485: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.171486: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.171488: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.171491: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906234 txlen=1 protect=0 raw=28 00 00 4a dc fa 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.171495: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.171495: block_rq_complete: 8,48 RS () 39249872 + 8 [0] [006] .... 3032.171511: block_bio_remap: 8,48 R 39249880 + 8 <- (8,62) 18392 [006] .... 3032.171512: block_bio_queue: 8,48 R 39249880 + 8 [iotest] [006] ...1 3032.171512: block_getrq: 8,48 R 39249880 + 8 [iotest] [006] ...2 3032.171513: block_rq_insert: 8,48 RS 0 () 39249880 + 8 [iotest] [006] ...3 3032.171513: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.171514: block_rq_issue: 8,48 RS 0 () 39249880 + 8 [iotest] [006] ...2 3032.171515: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906235 txlen=1 protect=0 raw=28 00 00 4a dc fb 00 00 01 00) [006] ...3 3032.171516: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.171662: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.171663: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.171666: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.171668: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906235 txlen=1 protect=0 raw=28 00 00 4a dc fb 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.171672: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.171672: block_rq_complete: 8,48 RS () 39249880 + 8 [0] [006] .... 3032.171688: block_bio_remap: 8,48 R 39249888 + 8 <- (8,62) 18400 [006] .... 3032.171689: block_bio_queue: 8,48 R 39249888 + 8 [iotest] [006] ...1 3032.171689: block_getrq: 8,48 R 39249888 + 8 [iotest] [006] ...2 3032.171691: block_rq_insert: 8,48 RS 0 () 39249888 + 8 [iotest] [006] ...3 3032.171691: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.171692: block_rq_issue: 8,48 RS 0 () 39249888 + 8 [iotest] [006] ...2 3032.171693: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906236 txlen=1 protect=0 raw=28 00 00 4a dc fc 00 00 01 00) [006] ...3 3032.171694: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.171839: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.171840: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.171843: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.171844: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906236 txlen=1 protect=0 raw=28 00 00 4a dc fc 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.171849: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.171849: block_rq_complete: 8,48 RS () 39249888 + 8 [0] [006] .... 3032.171864: block_bio_remap: 8,48 R 39249896 + 8 <- (8,62) 18408 [006] .... 3032.171866: block_bio_queue: 8,48 R 39249896 + 8 [iotest] [006] ...1 3032.171866: block_getrq: 8,48 R 39249896 + 8 [iotest] [006] ...2 3032.171867: block_rq_insert: 8,48 RS 0 () 39249896 + 8 [iotest] [006] ...3 3032.171868: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.171868: block_rq_issue: 8,48 RS 0 () 39249896 + 8 [iotest] [006] ...2 3032.171869: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906237 txlen=1 protect=0 raw=28 00 00 4a dc fd 00 00 01 00) [006] ...3 3032.171870: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.172002: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.172003: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.172006: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.172007: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906237 txlen=1 protect=0 raw=28 00 00 4a dc fd 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.172012: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.172012: block_rq_complete: 8,48 RS () 39249896 + 8 [0] [006] .... 3032.172029: block_bio_remap: 8,48 R 39249904 + 8 <- (8,62) 18416 [006] .... 3032.172030: block_bio_queue: 8,48 R 39249904 + 8 [iotest] [006] ...1 3032.172031: block_getrq: 8,48 R 39249904 + 8 [iotest] [006] ...2 3032.172032: block_rq_insert: 8,48 RS 0 () 39249904 + 8 [iotest] [006] ...3 3032.172033: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.172033: block_rq_issue: 8,48 RS 0 () 39249904 + 8 [iotest] [006] ...2 3032.172034: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906238 txlen=1 protect=0 raw=28 00 00 4a dc fe 00 00 01 00) [006] ...3 3032.172035: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.172179: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.172180: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.172183: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.172185: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906238 txlen=1 protect=0 raw=28 00 00 4a dc fe 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.172189: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.172189: block_rq_complete: 8,48 RS () 39249904 + 8 [0] [006] .... 3032.172207: block_bio_remap: 8,48 R 39249912 + 8 <- (8,62) 18424 [006] .... 3032.172208: block_bio_queue: 8,48 R 39249912 + 8 [iotest] [006] ...1 3032.172209: block_getrq: 8,48 R 39249912 + 8 [iotest] [006] ...2 3032.172210: block_rq_insert: 8,48 RS 0 () 39249912 + 8 [iotest] [006] ...3 3032.172210: scsi_queue_rq <-__blk_mq_run_hw_queue [006] ...2 3032.172211: block_rq_issue: 8,48 RS 0 () 39249912 + 8 [iotest] [006] ...2 3032.172211: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906239 txlen=1 protect=0 raw=28 00 00 4a dc ff 00 00 01 00) [006] ...3 3032.172212: scsi_dma_map <-ufshcd_queuecommand [000] d.h1 3032.172357: irq_handler_entry: irq=57 name=ufshcd [000] d.h2 3032.172358: ufshcd_intr <-__handle_irq_event_percpu [000] d.h3 3032.172361: scsi_dma_unmap <-__ufshcd_transfer_req_compl [000] d.h2 3032.172362: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=4906239 txlen=1 protect=0 raw=28 00 00 4a dc ff 00 00 01 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD) [006] d.h2 3032.172367: scsi_softirq_done <-__blk_mq_complete_request_remote [006] d.h1 3032.172368: block_rq_complete: 8,48 RS () 39249912 + 8 [0] [006] ...1 3032.172381: sys_read -> 0x20000 [006] ...1 3032.172392: sys_read(fd: 3, buf: 7790900000, count: 20000) [006] ...1 3032.172393: generic_file_read_iter <-new_sync_read [006] ...1 3032.172427: sys_read -> 0x20000 [006] ...1 3032.172428: sys_read(fd: 3, buf: 7790900000, count: 20000) //bean huo
