Re: WRITE BUFFER commands through SG_IO getting rounded up to sector past 32k

[Aravind Parchuri <aravind.parchuri@gmail.com>]

michaelc@cs.wisc.edu wrote:
> Aravind Parchuri wrote:
>> michaelc@cs.wisc.edu wrote:
>>> Aravind Parchuri wrote:
>>>   
>>>> My log messages were getting all mixed up, so I cleaned up my little
>>>> test to send just one command at a time. It actually looks like the mid
>>>> layer passes the command through to open-iscsi with the right size the
>>>> first time, but then it sends a second command with request_bufflen = 0.
>>>>
>>>> I can verify that the command completed on the target just like the
>>>> regular ones did, so there should be no reason for a retry of any sort.
>>>>
>>>> Here's the log for a 32896 byte command:
>>>> Mar  9 11:27:43 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcbadc000
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_build_indirect:
>>>> buff_size=32768, blk_size=32768
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_add_sfp:   bufflen=32768,
>>>> k_use_sg=1
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_common_write:  scsi
>>>> opcode=0x3b, cmd_size=10
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=32896
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_build_indirect:
>>>> buff_size=32896, blk_size=33280
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=32896,
>>>> iovec_count=0, k_use_sg=2
>>>> Mar  8 11:27:43 ITX000c292c3c8d kernel: iscsi_queuecommand: opcode 3b
>>>> request_bufflen 32896 transfersize 32896
>>>>     
>>> Did you add your own output? Could you enable iscsi debugging? What
>>> kernel is this with and what versions of open-iscsi (upstream or svn or
>>> tarball release)?
>>>   
>> No custom output, all of this is from scsi (SCSI_LOG_TIMEOUT=5) and
>> open-iscsi (DEBUG_SCSI enabled). I thought I mentioned this in an
>> earlier mail -  the kernel is 2.6.19, but the open-iscsi drivers and
> 
> The output here does not have DEBUG_SCSI enabled. It just has your
> custom iscsi output. The first log had DEBUG_SCSI iscsi output.
> 

I'm extremely sorry - I think I forgot to enable it while recompiling 
stuff with your patch, and I was fooled by that print that we put in 
iscsi_queuecommand.

> But what I want is not just parts you cut out. I am looking for all of
> it. If I run:
> 
> sg_write_buffer /dev/sdi -l 32896

I wasn't aware that such a utility existed - it must be part of 
sg_utils, I guess. I just hacked up a test to fire an SG_IO ioctl to a 
given device. I guess I should try with this one next, just to check.

> 
> with my patch and a netapp target, I get the error:
> 
> Write buffer command not supported
> 
> If I look at the iscsi log, I see
> 
> Mar 12 12:59:54 madmax kernel: iscsi: cmd [itt 0x25 total 32896 imm_data
> 32896 unsol count 0, unsol offset 32896]
> Mar 12 12:59:54 madmax kernel: iscsi: ctask enq [write cid 0 sc
> ffff81000e82d6c0 cdb 0x3b itt 0x25 len 32896 cmdsn 294 win 128]
> Mar 12 12:59:54 madmax kernel: iscsi: ctask deq [cid 0 xmstate 2 itt 0x25]
> Mar 12 12:59:55 madmax kernel: iscsi: cmdrsp [op 0x21 cid 0 itt 0x25 len 24]
> Mar 12 12:59:55 madmax kernel: iscsi: copied 22 bytes of sense
> Mar 12 12:59:55 madmax kernel: iscsi: done [sc ffff81000e82d6c0 res 2
> itt 0x25]
> 
> 
> which shows the len got set and that the target failed the target and we
> got some sense back. The command is then failed to sg and sg returns to
> userspace.
> 
> Your output just shows that we may be retrying the same command over and
> over and it never completes which would be strange because the command
> is a block pc command. It would help to see what happens with iscsi's
> DEBUG_SCSI option to see if the command failed or completed ok. It would
> also be nice to get the scsi-ml output to see what the sense is and what
> is going on there, but as a first step we can look at the iscsi output.
>

Thanks for explaining in detail what's useful in debugging the problem. 
Here are logs with DEBUG_SCSI enabled, SCSI_LOG_TIMEOUT set to level 5, 
SCSI_LOG_MLQUEUE to 4 and SCSI_LOG_MLCOMPLETE to 4. This is everything 
in /var/log/messages from the time I issued the ioctl.

Command with 32896 bytes:

Mar 12 11:02:33 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt 
0xffffffff datalen 0]
Mar 12 11:02:33 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4 
itt 0xa05]
Mar 12 11:03:03 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt 
0xffffffff datalen 0]
Mar 12 11:03:03 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4 
itt 0xa06]
Mar 12 11:03:32 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt 
0xffffffff datalen 0]
Mar 12 11:03:32 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4 
itt 0xa07]
Mar 12 11:04:02 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt 
0xffffffff datalen 0]
Mar 12 11:04:02 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4 
itt 0xa08]
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcb554000
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_indirect: 
buff_size=32768, blk_size=32768
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_add_sfp:   bufflen=32768, 
k_use_sg=1
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_common_write:  scsi 
opcode=0x3b, cmd_size=10
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=32896
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_indirect: 
buff_size=32896, blk_size=33280
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=32896, 
iovec_count=0, k_use_sg=2
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380 
                scsi 4:0:0:0:
Mar 12 11:04:21 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:21 ITX000c292c3c8d kernel: buffer = 0xd7497c80, bufflen = 
32896, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: cmd [itt 0x3 total 32896 
imm_data 32896 unsol count 0, unsol offset 32896]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: ctask enq [write cid 0 sc 
d7b16380 cdb 0x3b itt 0x3 len 32896 cmdsn 4 win 257]
Mar 12 11:04:21 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate 
2 itt 0x3]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt 
0x3 len 0]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: done [sc d7b16380 res 0 
itt 0x3]
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16380 
SUCCESS        0 scsi 4:0:0:0:
Mar 12 11:04:21 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper 
driver of completion (result 0)
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380 
                scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: buffer = 0xd749be00, bufflen = 
0, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: ctask enq [read cid 0 sc 
d7b16380 cdb 0x3b itt 0x4 len 0 cmdsn 5 win 257]
Mar 12 11:04:22 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate 
1 itt 0x4]
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt 
0x4 len 0]
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: done [sc d7b16380 res 0 
itt 0x4]
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16380 
SUCCESS        0 scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper 
driver of completion (result 0)
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380 
                scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: buffer = 0xd749be00, bufflen = 
0, done = 0xd8876a7b, queuecommand 0xd8a9de6e
.
.
.
[repeats forever]


33k command (successfully completes):

Mar 12 11:00:19 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt 
0xffffffff datalen 0]
Mar 12 11:00:19 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4 
itt 0xa01]
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcb43f000
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_indirect: 
buff_size=32768, blk_size=32768
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_add_sfp:   bufflen=32768, 
k_use_sg=1
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_common_write:  scsi 
opcode=0x3b, cmd_size=10
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=33792
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_indirect: 
buff_size=33792, blk_size=33792
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=33792, 
iovec_count=0, k_use_sg=2
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16080 
                scsi 4:0:0:0:
Mar 12 11:00:35 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 84 00 00
Mar 12 11:00:35 ITX000c292c3c8d kernel: buffer = 0xd7497080, bufflen = 
33792, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: cmd [itt 0x2 total 33792 
imm_data 33792 unsol count 0, unsol offset 33792]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: ctask enq [write cid 0 sc 
d7b16080 cdb 0x3b itt 0x2 len 33792 cmdsn 3 win 257]
Mar 12 11:00:35 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate 
2 itt 0x2]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt 
0x2 len 0]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: done [sc d7b16080 res 0 
itt 0x2]
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16080 
SUCCESS        0 scsi 4:0:0:0:
Mar 12 11:00:35 ITX000c292c3c8d kernel:         command: Write Buffer: 
3b 01 01 00 00 00 00 84 00 00
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper 
driver of completion (result 0)
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_cmd_done: sg0, pack_id=0, res=0x0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_finish_rem_req: res_used=0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_remove_scat: k_use_sg=2
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_release: sg0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_fasync: sg0, mode=0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_remove_scat: k_use_sg=1


> Also what target are you using?

We're using a slightly modified unh-iscsi target.

Aravind.