From: Rik H. <rik...@ya...> - 2006-03-26 13:12:20
|
Hi, I'm not sure if this is an iscsi-linux or IET issue, so I decided to post it on both mailing lists. I have the following environment: Environment: RHEL v4 U2 IET v 0.4.12-6 (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL and iscsitarget-0.4.12-6) iscsi-initiator-utils-4.0.3.0-2 To get a quick idea of how much overhead the iSCSI initiator / target will add to my I/O, I performed the following simple Test: 1) created a ramdisk (512 MB) 2) dd if=/dev/ram0 of=/dev/sda10 bs=1024k count=500. This gave me about 50 MB/s write speed. This was simply to check the speed of sequential writes. I only had a single SATA drive available but should be getting a few more which I'll put in a RAID 0 configuraton to test their performance. I then set up an iSCSI target and the iSCSI initiator both on the same machine (I didn't want the network to be a factor in performance). Here are the contents of my /etc/ietd.conf file: IncomingUser OutgoingUser Target iqn.2001-04.com.example:storage.disk2.sys1.xyz # Users, who can access this target. The same rules as for discovery # users apply here. # (no users means anyone can access the target) IncomingUser OutgoingUser # Logical Unit definition # You must define one logical unit at least. # Block devices, regular files, LVM, and RAID can be offered # to the initiators as a block device. Lun 0 Path=/dev/sda6,Type=fileio Lun 1 Path=/dev/sda7,Type=fileio Lun 2 Path=/dev/sda8,Type=fileio Lun 3 Path=/dev/sda9,Type=fileio Lun 4 Path=/dev/sda10,Type=fileio My /etc/iscsi.conf file is as follows: DiscoveryAddress=localhost:3260 I started both the IET service and iscsi initiator. I checked the log file (/var/log/messages) and the iSCSI initiator can see the iSCSI disks. I decided to test on /dev/sda10 (which IET exposes as /dev/sdf). Here is my first run: time dd if=/dev/ram0 of=/dev/sdf bs=1024k count=500 500+0 records in 500+0 records out real 0m14.595s user 0m0.007s sys 0m4.044s So the average was about 34 MB/s I then decided to rerun the exact same test again so that I can get the average from a few tests. This time, it took exceptionally long (over 6 minutes whereas it had only taken about 15 seconds in the previous test): [root@localhost ~]# time dd if=/dev/ram0 of=/dev/sdf bs=1024k count=500 500+0 records in 500+0 records out real 6m4.884s user 0m0.006s sys 0m3.824s Looking at /var/log/messages, I find it full of messages such as: ar 25 21:33:24 localhost kernel: iscsi-sfnet:host4: task mgmt itt 10320 rejected (0x1) Mar 25 21:33:24 localhost kernel: scsi: Device offlined - not ready after error recovery: host 4 channel 0 id 0 lun 4 Mar 25 21:33:25 localhost last message repeated 31 times Mar 25 21:33:25 localhost kernel: SCSI error : <4 0 0 4> return code = 0x6000000 Mar 25 21:33:25 localhost kernel: end_request: I/O error, dev sdf, sector 265496 Mar 25 21:33:25 localhost kernel: Buffer I/O error on device sdf, logical block 132748 Mar 25 21:33:25 localhost kernel: lost page write due to I/O error on sdf Mar 25 21:33:25 localhost kernel: scsi4 (0:4): rejecting I/O to offline device Mar 25 21:33:25 localhost kernel: Buffer I/O error on device sdf, logical block 132749 ...... [a lot more of the above] Mar 25 21:33:25 localhost kernel: scsi4 (0:4): rejecting I/O to offline device Mar 25 21:33:25 localhost last message repeated 84 times Mar 25 21:33:25 localhost kernel: scne device Mar 25 21:33:25 localhost kernel: scsi4 (0:4): rejecting I/O to offline device Mar 25 21:33:25 localhost last message repeated 2208 times ..... [more of the above] and the last logs are of this nature: Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10190, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10144, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10145, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10146, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10147, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10148, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10149, but no such task Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: recv_cmd - response for itt 10150, but no such task Mar 25 21:33:25 localhost kernel: scsi4 (0:4): rejecting I/O to offline device So it appears to have completed only when the device was finally offlined. I repeated the test several times with the same results. When I reboot the machine and try the tests again, it worked perfectly the first time but any time after that it gives me the same errors shown above. I ran dd=/dev/sdf of=/dev/null bs=1024k and it ran without any errors. It therefore seems that the problem is related with writes and not reads. Futher testing shows that it seems that it never happens when reading but happens when writing. Writing the first time always succeeds without any errors or messages in /var/log/messages. Any ideas on what the problem might be? Thank you for your help. Regards, Rik Herrin __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-26 15:43:38
|
can u try open-iscsi? ming On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin wrote: > Hi, > I'm not sure if this is an iscsi-linux or IET issue, > so I decided to post it on both mailing lists. I have > the following environment: > > Environment: > RHEL v4 U2 > IET v 0.4.12-6 > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL and > iscsitarget-0.4.12-6) > iscsi-initiator-utils-4.0.3.0-2 > > To get a quick idea of how much overhead the iSCSI > initiator / target will add to my I/O, I performed the > following simple Test: > > 1) created a ramdisk (512 MB) > 2) dd if=/dev/ram0 of=/dev/sda10 bs=1024k > count=500. This gave me about 50 MB/s write speed. > This was simply to check the speed of sequential > writes. I only had a single SATA drive available but > should be getting a few more which I'll put in a RAID > 0 configuraton to test their performance. > > I then set up an iSCSI target and the iSCSI > initiator both on the same machine (I didn't want the > network to be a factor in performance). > > Here are the contents of my /etc/ietd.conf file: > > IncomingUser > OutgoingUser > > Target > iqn.2001-04.com.example:storage.disk2.sys1.xyz > # Users, who can access this target. The same > rules as for discovery > # users apply here. > # (no users means anyone can access the > target) > IncomingUser > OutgoingUser > # Logical Unit definition > # You must define one logical unit at least. > # Block devices, regular files, LVM, and RAID > can be offered > # to the initiators as a block device. > Lun 0 Path=/dev/sda6,Type=fileio > Lun 1 Path=/dev/sda7,Type=fileio > Lun 2 Path=/dev/sda8,Type=fileio > Lun 3 Path=/dev/sda9,Type=fileio > Lun 4 Path=/dev/sda10,Type=fileio > > My /etc/iscsi.conf file is as follows: > > DiscoveryAddress=localhost:3260 > > I started both the IET service and iscsi > initiator. I checked the log file (/var/log/messages) > and the iSCSI initiator can see the iSCSI disks. I > decided to test on /dev/sda10 (which IET exposes as > /dev/sdf). > Here is my first run: > > time dd if=/dev/ram0 of=/dev/sdf bs=1024k > count=500 > 500+0 records in > 500+0 records out > > real 0m14.595s > user 0m0.007s > sys 0m4.044s > > So the average was about 34 MB/s > > I then decided to rerun the exact same test again > so that I can get the average from a few tests. This > time, it took exceptionally long (over 6 minutes > whereas it had only taken about 15 seconds in the > previous test): > > [root@localhost ~]# time dd if=/dev/ram0 > of=/dev/sdf bs=1024k count=500 > 500+0 records in > 500+0 records out > > real 6m4.884s > user 0m0.006s > sys 0m3.824s > > Looking at /var/log/messages, I find it full of > messages such as: > > > ar 25 21:33:24 localhost kernel: iscsi-sfnet:host4: > task mgmt itt 10320 rejected (0x1) > Mar 25 21:33:24 localhost kernel: scsi: Device > offlined - not ready after error recovery: host 4 > channel 0 id 0 lun 4 > Mar 25 21:33:25 localhost last message repeated 31 > times > Mar 25 21:33:25 localhost kernel: SCSI error : <4 0 0 > 4> return code = 0x6000000 > Mar 25 21:33:25 localhost kernel: end_request: I/O > error, dev sdf, sector 265496 > Mar 25 21:33:25 localhost kernel: Buffer I/O error on > device sdf, logical block 132748 > Mar 25 21:33:25 localhost kernel: lost page write due > to I/O error on sdf > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > rejecting I/O to offline device > Mar 25 21:33:25 localhost kernel: Buffer I/O error on > device sdf, logical block 132749 > ...... [a lot more of the above] > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > rejecting I/O to offline device > Mar 25 21:33:25 localhost last message repeated 84 > times > Mar 25 21:33:25 localhost kernel: scne device > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > rejecting I/O to offline device > Mar 25 21:33:25 localhost last message repeated 2208 > times > ..... [more of the above] > and the last logs are of this nature: > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10190, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10144, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10145, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10146, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10147, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10148, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10149, but no such task > Mar 25 21:33:25 localhost kernel: iscsi-sfnet:host4: > recv_cmd - response for itt 10150, but no such task > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > rejecting I/O to offline device > > So it appears to have completed only when the > device was finally offlined. I repeated the test > several times with the same results. When I reboot > the machine and try the tests again, it worked > perfectly the first time but any time after that it > gives me the same errors shown above. I ran > dd=/dev/sdf of=/dev/null bs=1024k and it ran without > any errors. It therefore seems that the problem is > related with writes and not reads. Futher testing > shows that it seems that it never happens when reading > but happens when writing. Writing the first time > always succeeds without any errors or messages in > /var/log/messages. > > Any ideas on what the problem might be? Thank you > for your help. > > Regards, > Rik Herrin > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com > > > ------------------------------------------------------- > This SF.Net email is sponsored by xPML, a groundbreaking scripting language > that extends applications into web and mobile media. Attend the live webcast > and join the prime developer group breaking into this new coding territory! > http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 > _______________________________________________ > Iscsitarget-devel mailing list > Isc...@li... > https://lists.sourceforge.net/lists/listinfo/iscsitarget-devel |
From: Rik H. <rik...@ya...> - 2006-03-26 16:30:31
|
I am going to try it with open-iscsi and core-iscsi to see if this issue is initiator-specific or IET specific. In the meantime, I configured a 4-disk RAID 0 SATA configuration and set it as the device exported by IET. Without the iSCSI layer (without running either ietd or iscsi-linux), I saw write throughput of about 212 MB/s. When I started IET and linux-iscsi and ran the sequential write test, I am now getting the following errors: Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 445 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 446 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 447 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 448 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 449 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 450 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 451 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 452 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 453 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 454 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 455 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 456 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 457 with return code = 0x20000 Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: Failing command cdb 0x2a task 458 with return code = 0x20000 ... [a lot more of the above] followed by: Mar 26 18:37:25 localhost kernel: execute_task_management(1177) 1e2 1 bd010000 Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bd 1 0 42 131072 0 0 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: task mgmt itt 482 rejected (0x1) Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Sending ABORT TASK for task itt 446 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Waking tx_thread to send task mgmt function itt 483 Mar 26 18:37:25 localhost kernel: execute_task_management(1177) 1e3 1 be010000 Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1be 1 0 42 131072 0 0 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: task mgmt itt 483 rejected (0x1) Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Sending ABORT TASK for task itt 447 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Waking tx_thread to send task mgmt function itt 484 Mar 26 18:37:25 localhost kernel: execute_task_management(1177) 1e4 1 bf010000 Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bf 1 0 42 131072 0 0 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: task mgmt itt 484 rejected (0x1) Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Sending ABORT TASK for task itt 448 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Waking tx_thread to send task mgmt function itt 485 Mar 26 18:37:25 localhost kernel: execute_task_management(1177) 1e5 1 c0010000 Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1c0 1 0 42 131072 0 0 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: task mgmt itt 485 rejected (0x1) Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Sending ABORT TASK for task itt 449 Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: Waking tx_thread to send task mgmt function itt 486 Mar 26 18:37:25 localhost kernel: execute_task_management(1177) 1e6 1 c1010000 .. [some more errors] scsi5 (0:0): rejecting I/O to offline device scsi5 (0:0): rejecting I/O to offline device scsi5 (0:0): rejecting I/O to offline device scsi5 (0:0): rejecting I/O to offline device scsi5 (0:0): rejecting I/O to offline device real 6m1.986s user 0m0.006s sys 0m1.682s Rik --- Ming Zhang <mi...@el...> wrote: > can u try open-iscsi? > > ming > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin wrote: > > Hi, > > I'm not sure if this is an iscsi-linux or IET > issue, > > so I decided to post it on both mailing lists. I > have > > the following environment: > > > > Environment: > > RHEL v4 U2 > > IET v 0.4.12-6 > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL and > > iscsitarget-0.4.12-6) > > iscsi-initiator-utils-4.0.3.0-2 > > > > To get a quick idea of how much overhead the > iSCSI > > initiator / target will add to my I/O, I performed > the > > following simple Test: > > > > 1) created a ramdisk (512 MB) > > 2) dd if=/dev/ram0 of=/dev/sda10 bs=1024k > > count=500. This gave me about 50 MB/s write > speed. > > This was simply to check the speed of sequential > > writes. I only had a single SATA drive available > but > > should be getting a few more which I'll put in a > RAID > > 0 configuraton to test their performance. > > > > I then set up an iSCSI target and the iSCSI > > initiator both on the same machine (I didn't want > the > > network to be a factor in performance). > > > > Here are the contents of my /etc/ietd.conf > file: > > > > IncomingUser > > OutgoingUser > > > > Target > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > # Users, who can access this target. The > same > > rules as for discovery > > # users apply here. > > # (no users means anyone can access the > > target) > > IncomingUser > > OutgoingUser > > # Logical Unit definition > > # You must define one logical unit at > least. > > # Block devices, regular files, LVM, and > RAID > > can be offered > > # to the initiators as a block device. > > Lun 0 Path=/dev/sda6,Type=fileio > > Lun 1 Path=/dev/sda7,Type=fileio > > Lun 2 Path=/dev/sda8,Type=fileio > > Lun 3 Path=/dev/sda9,Type=fileio > > Lun 4 Path=/dev/sda10,Type=fileio > > > > My /etc/iscsi.conf file is as follows: > > > > DiscoveryAddress=localhost:3260 > > > > I started both the IET service and iscsi > > initiator. I checked the log file > (/var/log/messages) > > and the iSCSI initiator can see the iSCSI disks. I > > decided to test on /dev/sda10 (which IET exposes > as > > /dev/sdf). > > Here is my first run: > > > > time dd if=/dev/ram0 of=/dev/sdf bs=1024k > > count=500 > > 500+0 records in > > 500+0 records out > > > > real 0m14.595s > > user 0m0.007s > > sys 0m4.044s > > > > So the average was about 34 MB/s > > > > I then decided to rerun the exact same test > again > > so that I can get the average from a few tests. > This > > time, it took exceptionally long (over 6 minutes > > whereas it had only taken about 15 seconds in the > > previous test): > > > > [root@localhost ~]# time dd if=/dev/ram0 > > of=/dev/sdf bs=1024k count=500 > > 500+0 records in > > 500+0 records out > > > > real 6m4.884s > > user 0m0.006s > > sys 0m3.824s > > > > Looking at /var/log/messages, I find it full of > > messages such as: > > > > > > ar 25 21:33:24 localhost kernel: > iscsi-sfnet:host4: > > task mgmt itt 10320 rejected (0x1) > > Mar 25 21:33:24 localhost kernel: scsi: Device > > offlined - not ready after error recovery: host 4 > > channel 0 id 0 lun 4 > > Mar 25 21:33:25 localhost last message repeated 31 > > times > > Mar 25 21:33:25 localhost kernel: SCSI error : <4 > 0 0 > > 4> return code = 0x6000000 > > Mar 25 21:33:25 localhost kernel: end_request: I/O > > error, dev sdf, sector 265496 > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > on > > device sdf, logical block 132748 > > Mar 25 21:33:25 localhost kernel: lost page write > due > > to I/O error on sdf > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > rejecting I/O to offline device > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > on > > device sdf, logical block 132749 > > ...... [a lot more of the above] > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > rejecting I/O to offline device > > Mar 25 21:33:25 localhost last message repeated 84 > > times > > Mar 25 21:33:25 localhost kernel: scne device > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > rejecting I/O to offline device > > Mar 25 21:33:25 localhost last message repeated > 2208 > > times > > ..... [more of the above] > > and the last logs are of this nature: > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10190, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10144, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10145, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10146, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10147, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10148, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10149, but no such > task > > Mar 25 21:33:25 localhost kernel: > iscsi-sfnet:host4: > > recv_cmd - response for itt 10150, but no such > task > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > rejecting I/O to offline device > > > > So it appears to have completed only when the > > device was finally offlined. I repeated the test > > several times with the same results. When I > reboot > > the machine and try the tests again, it worked > > perfectly the first time but any time after that > it > > gives me the same errors shown above. I ran > > dd=/dev/sdf of=/dev/null bs=1024k and it ran > without > > any errors. It therefore seems that the problem > is > > related with writes and not reads. Futher testing > > shows that it seems that it never happens when > reading > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-26 16:44:09
|
2a is write_10 there are some dispatch between them and then lead to this. try open-iscsi. or core-ini. ming On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin wrote: > I am going to try it with open-iscsi and core-iscsi to > see if this issue is initiator-specific or IET > specific. In the meantime, I configured a 4-disk RAID > 0 SATA configuration and set it as the device exported > by IET. Without the iSCSI layer (without running > either ietd or iscsi-linux), I saw write throughput of > about 212 MB/s. When I started IET and linux-iscsi > and ran the sequential write test, I am now getting > the following errors: > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 445 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 446 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 447 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 448 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 449 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 450 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 451 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 452 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 453 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 454 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 455 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 456 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 457 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 458 with return code = > 0x20000 > ... [a lot more of the above] > > followed by: > > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e2 1 bd010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bd > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 482 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 446 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 483 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e3 1 be010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1be > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 483 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 447 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 484 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e4 1 bf010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bf > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 484 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 448 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 485 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e5 1 c0010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1c0 > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 485 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 449 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 486 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e6 1 c1010000 > .. [some more errors] > > > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > > real 6m1.986s > user 0m0.006s > sys 0m1.682s > > Rik > > > --- Ming Zhang <mi...@el...> wrote: > > > can u try open-iscsi? > > > > ming > > > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin wrote: > > > Hi, > > > I'm not sure if this is an iscsi-linux or IET > > issue, > > > so I decided to post it on both mailing lists. I > > have > > > the following environment: > > > > > > Environment: > > > RHEL v4 U2 > > > IET v 0.4.12-6 > > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL and > > > iscsitarget-0.4.12-6) > > > iscsi-initiator-utils-4.0.3.0-2 > > > > > > To get a quick idea of how much overhead the > > iSCSI > > > initiator / target will add to my I/O, I performed > > the > > > following simple Test: > > > > > > 1) created a ramdisk (512 MB) > > > 2) dd if=/dev/ram0 of=/dev/sda10 bs=1024k > > > count=500. This gave me about 50 MB/s write > > speed. > > > This was simply to check the speed of sequential > > > writes. I only had a single SATA drive available > > but > > > should be getting a few more which I'll put in a > > RAID > > > 0 configuraton to test their performance. > > > > > > I then set up an iSCSI target and the iSCSI > > > initiator both on the same machine (I didn't want > > the > > > network to be a factor in performance). > > > > > > Here are the contents of my /etc/ietd.conf > > file: > > > > > > IncomingUser > > > OutgoingUser > > > > > > Target > > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > > # Users, who can access this target. The > > same > > > rules as for discovery > > > # users apply here. > > > # (no users means anyone can access the > > > target) > > > IncomingUser > > > OutgoingUser > > > # Logical Unit definition > > > # You must define one logical unit at > > least. > > > # Block devices, regular files, LVM, and > > RAID > > > can be offered > > > # to the initiators as a block device. > > > Lun 0 Path=/dev/sda6,Type=fileio > > > Lun 1 Path=/dev/sda7,Type=fileio > > > Lun 2 Path=/dev/sda8,Type=fileio > > > Lun 3 Path=/dev/sda9,Type=fileio > > > Lun 4 Path=/dev/sda10,Type=fileio > > > > > > My /etc/iscsi.conf file is as follows: > > > > > > DiscoveryAddress=localhost:3260 > > > > > > I started both the IET service and iscsi > > > initiator. I checked the log file > > (/var/log/messages) > > > and the iSCSI initiator can see the iSCSI disks. I > > > decided to test on /dev/sda10 (which IET exposes > > as > > > /dev/sdf). > > > Here is my first run: > > > > > > time dd if=/dev/ram0 of=/dev/sdf bs=1024k > > > count=500 > > > 500+0 records in > > > 500+0 records out > > > > > > real 0m14.595s > > > user 0m0.007s > > > sys 0m4.044s > > > > > > So the average was about 34 MB/s > > > > > > I then decided to rerun the exact same test > > again > > > so that I can get the average from a few tests. > > This > > > time, it took exceptionally long (over 6 minutes > > > whereas it had only taken about 15 seconds in the > > > previous test): > > > > > > [root@localhost ~]# time dd if=/dev/ram0 > > > of=/dev/sdf bs=1024k count=500 > > > 500+0 records in > > > 500+0 records out > > > > > > real 6m4.884s > > > user 0m0.006s > > > sys 0m3.824s > > > > > > Looking at /var/log/messages, I find it full of > > > messages such as: > > > > > > > > > ar 25 21:33:24 localhost kernel: > > iscsi-sfnet:host4: > > > task mgmt itt 10320 rejected (0x1) > > > Mar 25 21:33:24 localhost kernel: scsi: Device > > > offlined - not ready after error recovery: host 4 > > > channel 0 id 0 lun 4 > > > Mar 25 21:33:25 localhost last message repeated 31 > > > times > > > Mar 25 21:33:25 localhost kernel: SCSI error : <4 > > 0 0 > > > 4> return code = 0x6000000 > > > Mar 25 21:33:25 localhost kernel: end_request: I/O > > > error, dev sdf, sector 265496 > > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > > on > > > device sdf, logical block 132748 > > > Mar 25 21:33:25 localhost kernel: lost page write > > due > > > to I/O error on sdf > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > > on > > > device sdf, logical block 132749 > > > ...... [a lot more of the above] > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost last message repeated 84 > > > times > > > Mar 25 21:33:25 localhost kernel: scne device > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost last message repeated > > 2208 > > > times > > > ..... [more of the above] > > > and the last logs are of this nature: > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10190, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10144, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10145, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10146, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10147, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10148, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10149, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10150, but no such > > task > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > > > > So it appears to have completed only when the > > > device was finally offlined. I repeated the test > > > several times with the same results. When I > > reboot > > > the machine and try the tests again, it worked > > > perfectly the first time but any time after that > > it > > > gives me the same errors shown above. I ran > > > dd=/dev/sdf of=/dev/null bs=1024k and it ran > > without > > > any errors. It therefore seems that the problem > > is > > > related with writes and not reads. Futher testing > > > shows that it seems that it never happens when > > reading > > > === message truncated === > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-26 16:44:23
|
ps, any point to run them at same box? ;) ming On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin wrote: > I am going to try it with open-iscsi and core-iscsi to > see if this issue is initiator-specific or IET > specific. In the meantime, I configured a 4-disk RAID > 0 SATA configuration and set it as the device exported > by IET. Without the iSCSI layer (without running > either ietd or iscsi-linux), I saw write throughput of > about 212 MB/s. When I started IET and linux-iscsi > and ran the sequential write test, I am now getting > the following errors: > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 445 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 446 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 447 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 448 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 449 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 450 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 451 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 452 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 453 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 454 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 455 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 456 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 457 with return code = > 0x20000 > Mar 26 18:37:28 localhost kernel: iscsi-sfnet:host5: > Failing command cdb 0x2a task 458 with return code = > 0x20000 > ... [a lot more of the above] > > followed by: > > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e2 1 bd010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bd > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 482 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 446 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 483 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e3 1 be010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1be > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 483 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 447 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 484 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e4 1 bf010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1bf > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 484 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 448 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 485 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e5 1 c0010000 > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) 1c0 > 1 0 42 131072 0 0 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > task mgmt itt 485 rejected (0x1) > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Sending ABORT TASK for task itt 449 > Mar 26 18:37:25 localhost kernel: iscsi-sfnet:host5: > Waking tx_thread to send task mgmt function itt 486 > Mar 26 18:37:25 localhost kernel: > execute_task_management(1177) 1e6 1 c1010000 > .. [some more errors] > > > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > scsi5 (0:0): rejecting I/O to offline device > > real 6m1.986s > user 0m0.006s > sys 0m1.682s > > Rik > > > --- Ming Zhang <mi...@el...> wrote: > > > can u try open-iscsi? > > > > ming > > > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin wrote: > > > Hi, > > > I'm not sure if this is an iscsi-linux or IET > > issue, > > > so I decided to post it on both mailing lists. I > > have > > > the following environment: > > > > > > Environment: > > > RHEL v4 U2 > > > IET v 0.4.12-6 > > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL and > > > iscsitarget-0.4.12-6) > > > iscsi-initiator-utils-4.0.3.0-2 > > > > > > To get a quick idea of how much overhead the > > iSCSI > > > initiator / target will add to my I/O, I performed > > the > > > following simple Test: > > > > > > 1) created a ramdisk (512 MB) > > > 2) dd if=/dev/ram0 of=/dev/sda10 bs=1024k > > > count=500. This gave me about 50 MB/s write > > speed. > > > This was simply to check the speed of sequential > > > writes. I only had a single SATA drive available > > but > > > should be getting a few more which I'll put in a > > RAID > > > 0 configuraton to test their performance. > > > > > > I then set up an iSCSI target and the iSCSI > > > initiator both on the same machine (I didn't want > > the > > > network to be a factor in performance). > > > > > > Here are the contents of my /etc/ietd.conf > > file: > > > > > > IncomingUser > > > OutgoingUser > > > > > > Target > > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > > # Users, who can access this target. The > > same > > > rules as for discovery > > > # users apply here. > > > # (no users means anyone can access the > > > target) > > > IncomingUser > > > OutgoingUser > > > # Logical Unit definition > > > # You must define one logical unit at > > least. > > > # Block devices, regular files, LVM, and > > RAID > > > can be offered > > > # to the initiators as a block device. > > > Lun 0 Path=/dev/sda6,Type=fileio > > > Lun 1 Path=/dev/sda7,Type=fileio > > > Lun 2 Path=/dev/sda8,Type=fileio > > > Lun 3 Path=/dev/sda9,Type=fileio > > > Lun 4 Path=/dev/sda10,Type=fileio > > > > > > My /etc/iscsi.conf file is as follows: > > > > > > DiscoveryAddress=localhost:3260 > > > > > > I started both the IET service and iscsi > > > initiator. I checked the log file > > (/var/log/messages) > > > and the iSCSI initiator can see the iSCSI disks. I > > > decided to test on /dev/sda10 (which IET exposes > > as > > > /dev/sdf). > > > Here is my first run: > > > > > > time dd if=/dev/ram0 of=/dev/sdf bs=1024k > > > count=500 > > > 500+0 records in > > > 500+0 records out > > > > > > real 0m14.595s > > > user 0m0.007s > > > sys 0m4.044s > > > > > > So the average was about 34 MB/s > > > > > > I then decided to rerun the exact same test > > again > > > so that I can get the average from a few tests. > > This > > > time, it took exceptionally long (over 6 minutes > > > whereas it had only taken about 15 seconds in the > > > previous test): > > > > > > [root@localhost ~]# time dd if=/dev/ram0 > > > of=/dev/sdf bs=1024k count=500 > > > 500+0 records in > > > 500+0 records out > > > > > > real 6m4.884s > > > user 0m0.006s > > > sys 0m3.824s > > > > > > Looking at /var/log/messages, I find it full of > > > messages such as: > > > > > > > > > ar 25 21:33:24 localhost kernel: > > iscsi-sfnet:host4: > > > task mgmt itt 10320 rejected (0x1) > > > Mar 25 21:33:24 localhost kernel: scsi: Device > > > offlined - not ready after error recovery: host 4 > > > channel 0 id 0 lun 4 > > > Mar 25 21:33:25 localhost last message repeated 31 > > > times > > > Mar 25 21:33:25 localhost kernel: SCSI error : <4 > > 0 0 > > > 4> return code = 0x6000000 > > > Mar 25 21:33:25 localhost kernel: end_request: I/O > > > error, dev sdf, sector 265496 > > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > > on > > > device sdf, logical block 132748 > > > Mar 25 21:33:25 localhost kernel: lost page write > > due > > > to I/O error on sdf > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost kernel: Buffer I/O error > > on > > > device sdf, logical block 132749 > > > ...... [a lot more of the above] > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost last message repeated 84 > > > times > > > Mar 25 21:33:25 localhost kernel: scne device > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > Mar 25 21:33:25 localhost last message repeated > > 2208 > > > times > > > ..... [more of the above] > > > and the last logs are of this nature: > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10190, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10144, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10145, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10146, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10147, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10148, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10149, but no such > > task > > > Mar 25 21:33:25 localhost kernel: > > iscsi-sfnet:host4: > > > recv_cmd - response for itt 10150, but no such > > task > > > Mar 25 21:33:25 localhost kernel: scsi4 (0:4): > > > rejecting I/O to offline device > > > > > > So it appears to have completed only when the > > > device was finally offlined. I repeated the test > > > several times with the same results. When I > > reboot > > > the machine and try the tests again, it worked > > > perfectly the first time but any time after that > > it > > > gives me the same errors shown above. I ran > > > dd=/dev/sdf of=/dev/null bs=1024k and it ran > > without > > > any errors. It therefore seems that the problem > > is > > > related with writes and not reads. Futher testing > > > shows that it seems that it never happens when > > reading > > > === message truncated === > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-26 17:18:12
|
I'm running them on the same machine to see the maximum throughput and to see what type of bottleneck the disk subsystem will give me. I'm also waiting for a 4-port 1GbE Intel NIC to make sure that the network doesn't end up being the bottleneck. Do you think there's any reason for them running on the same machine to cause a problem? Rik --- Ming Zhang <mi...@el...> wrote: > ps, any point to run them at same box? ;) > > ming > > On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin wrote: > > I am going to try it with open-iscsi and > core-iscsi to > > see if this issue is initiator-specific or IET > > specific. In the meantime, I configured a 4-disk > RAID > > 0 SATA configuration and set it as the device > exported > > by IET. Without the iSCSI layer (without running > > either ietd or iscsi-linux), I saw write > throughput of > > about 212 MB/s. When I started IET and > linux-iscsi > > and ran the sequential write test, I am now > getting > > the following errors: > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 445 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 446 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 447 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 448 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 449 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 450 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 451 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 452 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 453 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 454 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 455 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 456 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 457 with return code > = > > 0x20000 > > Mar 26 18:37:28 localhost kernel: > iscsi-sfnet:host5: > > Failing command cdb 0x2a task 458 with return code > = > > 0x20000 > > ... [a lot more of the above] > > > > followed by: > > > > Mar 26 18:37:25 localhost kernel: > > execute_task_management(1177) 1e2 1 bd010000 > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > 1bd > > 1 0 42 131072 0 0 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > task mgmt itt 482 rejected (0x1) > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Sending ABORT TASK for task itt 446 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Waking tx_thread to send task mgmt function itt > 483 > > Mar 26 18:37:25 localhost kernel: > > execute_task_management(1177) 1e3 1 be010000 > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > 1be > > 1 0 42 131072 0 0 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > task mgmt itt 483 rejected (0x1) > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Sending ABORT TASK for task itt 447 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Waking tx_thread to send task mgmt function itt > 484 > > Mar 26 18:37:25 localhost kernel: > > execute_task_management(1177) 1e4 1 bf010000 > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > 1bf > > 1 0 42 131072 0 0 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > task mgmt itt 484 rejected (0x1) > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Sending ABORT TASK for task itt 448 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Waking tx_thread to send task mgmt function itt > 485 > > Mar 26 18:37:25 localhost kernel: > > execute_task_management(1177) 1e5 1 c0010000 > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > 1c0 > > 1 0 42 131072 0 0 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > task mgmt itt 485 rejected (0x1) > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Sending ABORT TASK for task itt 449 > > Mar 26 18:37:25 localhost kernel: > iscsi-sfnet:host5: > > Waking tx_thread to send task mgmt function itt > 486 > > Mar 26 18:37:25 localhost kernel: > > execute_task_management(1177) 1e6 1 c1010000 > > .. [some more errors] > > > > > > scsi5 (0:0): rejecting I/O to offline device > > scsi5 (0:0): rejecting I/O to offline device > > scsi5 (0:0): rejecting I/O to offline device > > scsi5 (0:0): rejecting I/O to offline device > > scsi5 (0:0): rejecting I/O to offline device > > > > real 6m1.986s > > user 0m0.006s > > sys 0m1.682s > > > > Rik > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > can u try open-iscsi? > > > > > > ming > > > > > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin > wrote: > > > > Hi, > > > > I'm not sure if this is an iscsi-linux or > IET > > > issue, > > > > so I decided to post it on both mailing lists. > I > > > have > > > > the following environment: > > > > > > > > Environment: > > > > RHEL v4 U2 > > > > IET v 0.4.12-6 > > > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL > and > > > > iscsitarget-0.4.12-6) > > > > iscsi-initiator-utils-4.0.3.0-2 > > > > > > > > To get a quick idea of how much overhead > the > > > iSCSI > > > > initiator / target will add to my I/O, I > performed > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-26 17:38:10
|
frankly, i do not know. i assumed they should be ok no matter whether they are on same box or not. but from experience, it was not. maybe some kernel guru here can answer this question. ming On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin wrote: > I'm running them on the same machine to see the > maximum throughput and to see what type of bottleneck > the disk subsystem will give me. I'm also waiting for > a 4-port 1GbE Intel NIC to make sure that the network > doesn't end up being the bottleneck. Do you think > there's any reason for them running on the same > machine to cause a problem? > > Rik > > --- Ming Zhang <mi...@el...> wrote: > > > ps, any point to run them at same box? ;) > > > > ming > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin wrote: > > > I am going to try it with open-iscsi and > > core-iscsi to > > > see if this issue is initiator-specific or IET > > > specific. In the meantime, I configured a 4-disk > > RAID > > > 0 SATA configuration and set it as the device > > exported > > > by IET. Without the iSCSI layer (without running > > > either ietd or iscsi-linux), I saw write > > throughput of > > > about 212 MB/s. When I started IET and > > linux-iscsi > > > and ran the sequential write test, I am now > > getting > > > the following errors: > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 445 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 446 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 447 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 448 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 449 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 450 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 451 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 452 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 453 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 454 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 455 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 456 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 457 with return code > > = > > > 0x20000 > > > Mar 26 18:37:28 localhost kernel: > > iscsi-sfnet:host5: > > > Failing command cdb 0x2a task 458 with return code > > = > > > 0x20000 > > > ... [a lot more of the above] > > > > > > followed by: > > > > > > Mar 26 18:37:25 localhost kernel: > > > execute_task_management(1177) 1e2 1 bd010000 > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > 1bd > > > 1 0 42 131072 0 0 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > task mgmt itt 482 rejected (0x1) > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Sending ABORT TASK for task itt 446 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Waking tx_thread to send task mgmt function itt > > 483 > > > Mar 26 18:37:25 localhost kernel: > > > execute_task_management(1177) 1e3 1 be010000 > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > 1be > > > 1 0 42 131072 0 0 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > task mgmt itt 483 rejected (0x1) > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Sending ABORT TASK for task itt 447 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Waking tx_thread to send task mgmt function itt > > 484 > > > Mar 26 18:37:25 localhost kernel: > > > execute_task_management(1177) 1e4 1 bf010000 > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > 1bf > > > 1 0 42 131072 0 0 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > task mgmt itt 484 rejected (0x1) > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Sending ABORT TASK for task itt 448 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Waking tx_thread to send task mgmt function itt > > 485 > > > Mar 26 18:37:25 localhost kernel: > > > execute_task_management(1177) 1e5 1 c0010000 > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > 1c0 > > > 1 0 42 131072 0 0 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > task mgmt itt 485 rejected (0x1) > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Sending ABORT TASK for task itt 449 > > > Mar 26 18:37:25 localhost kernel: > > iscsi-sfnet:host5: > > > Waking tx_thread to send task mgmt function itt > > 486 > > > Mar 26 18:37:25 localhost kernel: > > > execute_task_management(1177) 1e6 1 c1010000 > > > .. [some more errors] > > > > > > > > > scsi5 (0:0): rejecting I/O to offline device > > > scsi5 (0:0): rejecting I/O to offline device > > > scsi5 (0:0): rejecting I/O to offline device > > > scsi5 (0:0): rejecting I/O to offline device > > > scsi5 (0:0): rejecting I/O to offline device > > > > > > real 6m1.986s > > > user 0m0.006s > > > sys 0m1.682s > > > > > > Rik > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > can u try open-iscsi? > > > > > > > > ming > > > > > > > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin > > wrote: > > > > > Hi, > > > > > I'm not sure if this is an iscsi-linux or > > IET > > > > issue, > > > > > so I decided to post it on both mailing lists. > > I > > > > have > > > > > the following environment: > > > > > > > > > > Environment: > > > > > RHEL v4 U2 > > > > > IET v 0.4.12-6 > > > > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL > > and > > > > > iscsitarget-0.4.12-6) > > > > > iscsi-initiator-utils-4.0.3.0-2 > > > > > > > > > > To get a quick idea of how much overhead > > the > > > > iSCSI > > > > > initiator / target will add to my I/O, I > > performed > > > === message truncated === > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-26 17:39:34
|
forgot to say, the reason i ask u to check open-iscsi is that we tested open-iscsi + iet on same box before, it is not ok, then after a certain version, open-iscsi can run ok with iet on same box, but nobody do extensive tests. ming On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang wrote: > frankly, i do not know. i assumed they should be ok no matter whether > they are on same box or not. but from experience, it was not. > > maybe some kernel guru here can answer this question. > > ming > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin wrote: > > I'm running them on the same machine to see the > > maximum throughput and to see what type of bottleneck > > the disk subsystem will give me. I'm also waiting for > > a 4-port 1GbE Intel NIC to make sure that the network > > doesn't end up being the bottleneck. Do you think > > there's any reason for them running on the same > > machine to cause a problem? > > > > Rik > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > ps, any point to run them at same box? ;) > > > > > > ming > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin wrote: > > > > I am going to try it with open-iscsi and > > > core-iscsi to > > > > see if this issue is initiator-specific or IET > > > > specific. In the meantime, I configured a 4-disk > > > RAID > > > > 0 SATA configuration and set it as the device > > > exported > > > > by IET. Without the iSCSI layer (without running > > > > either ietd or iscsi-linux), I saw write > > > throughput of > > > > about 212 MB/s. When I started IET and > > > linux-iscsi > > > > and ran the sequential write test, I am now > > > getting > > > > the following errors: > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 445 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 446 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 447 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 448 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 449 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 450 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 451 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 452 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 453 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 454 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 455 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 456 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 457 with return code > > > = > > > > 0x20000 > > > > Mar 26 18:37:28 localhost kernel: > > > iscsi-sfnet:host5: > > > > Failing command cdb 0x2a task 458 with return code > > > = > > > > 0x20000 > > > > ... [a lot more of the above] > > > > > > > > followed by: > > > > > > > > Mar 26 18:37:25 localhost kernel: > > > > execute_task_management(1177) 1e2 1 bd010000 > > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > > 1bd > > > > 1 0 42 131072 0 0 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > task mgmt itt 482 rejected (0x1) > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Sending ABORT TASK for task itt 446 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Waking tx_thread to send task mgmt function itt > > > 483 > > > > Mar 26 18:37:25 localhost kernel: > > > > execute_task_management(1177) 1e3 1 be010000 > > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > > 1be > > > > 1 0 42 131072 0 0 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > task mgmt itt 483 rejected (0x1) > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Sending ABORT TASK for task itt 447 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Waking tx_thread to send task mgmt function itt > > > 484 > > > > Mar 26 18:37:25 localhost kernel: > > > > execute_task_management(1177) 1e4 1 bf010000 > > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > > 1bf > > > > 1 0 42 131072 0 0 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > task mgmt itt 484 rejected (0x1) > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Sending ABORT TASK for task itt 448 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Waking tx_thread to send task mgmt function itt > > > 485 > > > > Mar 26 18:37:25 localhost kernel: > > > > execute_task_management(1177) 1e5 1 c0010000 > > > > Mar 26 18:37:25 localhost kernel: cmnd_abort(1114) > > > 1c0 > > > > 1 0 42 131072 0 0 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > task mgmt itt 485 rejected (0x1) > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Sending ABORT TASK for task itt 449 > > > > Mar 26 18:37:25 localhost kernel: > > > iscsi-sfnet:host5: > > > > Waking tx_thread to send task mgmt function itt > > > 486 > > > > Mar 26 18:37:25 localhost kernel: > > > > execute_task_management(1177) 1e6 1 c1010000 > > > > .. [some more errors] > > > > > > > > > > > > scsi5 (0:0): rejecting I/O to offline device > > > > scsi5 (0:0): rejecting I/O to offline device > > > > scsi5 (0:0): rejecting I/O to offline device > > > > scsi5 (0:0): rejecting I/O to offline device > > > > scsi5 (0:0): rejecting I/O to offline device > > > > > > > > real 6m1.986s > > > > user 0m0.006s > > > > sys 0m1.682s > > > > > > > > Rik > > > > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > > > can u try open-iscsi? > > > > > > > > > > ming > > > > > > > > > > On Sun, 2006-03-26 at 05:12 -0800, Rik Herrin > > > wrote: > > > > > > Hi, > > > > > > I'm not sure if this is an iscsi-linux or > > > IET > > > > > issue, > > > > > > so I decided to post it on both mailing lists. > > > I > > > > > have > > > > > > the following environment: > > > > > > > > > > > > Environment: > > > > > > RHEL v4 U2 > > > > > > IET v 0.4.12-6 > > > > > > (iscsitarget-kernel-smp-0.4.12-6_2.6.9_22.EL > > > and > > > > > > iscsitarget-0.4.12-6) > > > > > > iscsi-initiator-utils-4.0.3.0-2 > > > > > > > > > > > > To get a quick idea of how much overhead > > > the > > > > > iSCSI > > > > > > initiator / target will add to my I/O, I > > > performed > > > > > === message truncated === > > > > > > __________________________________________________ > > Do You Yahoo!? > > Tired of spam? Yahoo! Mail has the best spam protection around > > http://mail.yahoo.com > |
From: Rik H. <rik...@ya...> - 2006-03-26 19:47:42
|
Thanks a lot for your input Ming. In the meantime, here's my experimentation with the core-iscsi initiator. I was able to compile it as well as the necessary kernel modules although I'm using 2.6.9-22 smp while it recommends a minimum of 2.6.11 (probably due to all the backporting Red Hat does in it's kernel). The initiator was able to see the target as shown from the log messages below: When I run /etc/rc.d/init.d/initiator start, it starts successfully and I'm able to partition the hard drive and create a filesystem. localhost kernel: iCHANNEL[0] - Incremented iSCSI connection count to 1 to node: iqn.2001-04.com.example:storage.disk2.sys1.xyz localhost kernel: iCHANNEL[0] - Established iSCSI session to node: iqn.2001-04.com.example:storage.disk2.sys1.xyz localhost kernel: iSCSI Core Stack[1] - Incremented number of active iSCSI sessions to 1. localhost kernel: Vendor: IET Model: VIRTUAL-DISK Rev: 0 localhost kernel: Type: Direct-Access ANSI SCSI revision: 04 localhost kernel: SCSI device sde: 703345408 512-byte hdwr sectors (360113 MB) localhost kernel: SCSI device sde: drive cache: write back localhost kernel: sde: unknown partition table localhost kernel: Attached scsi disk sde at scsi4, channel 0, id 0, lun 0 localhost kernel: SCSI device sde: 703345408 512-byte hdwr sectors (360113 MB) localhost kernel: SCSI device sde: drive cache: write back localhost kernel: sde: sde1 localhost kernel: SCSI device sde: 703345408 512-byte hdwr sectors (360113 MB) localhost kernel: SCSI device sde: drive cache: write back localhost kernel: sde: sde1 I again did the same test as before: dd if=/dev/zero of=/dev/sde bs=1024k count=5000 My /etc/sysconfig/initiator looks like this. CHANNEL="0 1 lo 127.0.0.1 3260 0" It would give me a lot of messages such as: check_segment_length(1552) too lond data 15a 32768 8192 check_segment_length(1552) too lond data 15b 32768 8192 iscsi_session_push_cmnd(1531) too large cmd_sn (56,1) ... [and so forth] before finally completing: real 1m31.320s user 0m0.001s sys 0m0.139s Sometimes it finishes while at other times, it gives the errors above and then goes into a loop trying to reconnect and then disconnecting again: localhost kernel: iCHANNEL[0]_LU[0] - SCSI Task Timeout with ITT: 0x00000264 localhost kernel: iCHANNEL[0]_LU[0] - Forcing Session Reinstatement for timed-out SCSI Task to ONLINE Logical Unit localhost kernel: iCHANNEL[0] - Performing Cleanup for failed iSCSI CID: 0 to iqn.2001-04.com.example:storage.disk2.sys1.xyz localhost kernel: iCHANNEL[0] - Decremented iSCSI connection count to 0 to node: iqn.2001-04.com.example:storage.disk2.sys1.xyz localhost kernel: iCHANNEL[0] - released iSCSI session to node: iqn.2001-04.com.example:storage.disk2.sys1.xyz localhost kernel: iSCSI Core Stack[1] - Decremented number of active iSCSI sessions to 0 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 PS. I'll check out open-iscsi tomorrow morning and tell you how it goes. --- Ming Zhang <mi...@el...> wrote: > forgot to say, the reason i ask u to check > open-iscsi is that we tested > open-iscsi + iet on same box before, it is not ok, > then after a certain > version, open-iscsi can run ok with iet on same box, > but nobody do > extensive tests. > > ming > > On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang wrote: > > frankly, i do not know. i assumed they should be > ok no matter whether > > they are on same box or not. but from experience, > it was not. > > > > maybe some kernel guru here can answer this > question. > > > > ming > > > > > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin > wrote: > > > I'm running them on the same machine to see the > > > maximum throughput and to see what type of > bottleneck > > > the disk subsystem will give me. I'm also > waiting for > > > a 4-port 1GbE Intel NIC to make sure that the > network > > > doesn't end up being the bottleneck. Do you > think > > > there's any reason for them running on the same > > > machine to cause a problem? > > > > > > Rik > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > ps, any point to run them at same box? ;) > > > > > > > > ming > > > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin > wrote: > > > > > I am going to try it with open-iscsi and > > > > core-iscsi to > > > > > see if this issue is initiator-specific or > IET > > > > > specific. In the meantime, I configured a > 4-disk > > > > RAID > > > > > 0 SATA configuration and set it as the > device > > > > exported > > > > > by IET. Without the iSCSI layer (without > running > > > > > either ietd or iscsi-linux), I saw write > > > > throughput of > > > > > about 212 MB/s. When I started IET and > > > > linux-iscsi > > > > > and ran the sequential write test, I am now > > > > getting > > > > > the following errors: > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 445 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 446 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 447 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 448 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 449 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 450 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 451 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 452 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 453 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 454 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 455 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 456 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 457 with > return code > > > > = > > > > > 0x20000 > > > > > Mar 26 18:37:28 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Failing command cdb 0x2a task 458 with > return code > > > > = > > > > > 0x20000 > > > > > ... [a lot more of the above] > > > > > > > > > > followed by: > > > > > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > execute_task_management(1177) 1e2 1 bd010000 > > > > > Mar 26 18:37:25 localhost kernel: > cmnd_abort(1114) > > > > 1bd > > > > > 1 0 42 131072 0 0 > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > task mgmt itt 482 rejected (0x1) > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Sending ABORT TASK for task itt 446 > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Waking tx_thread to send task mgmt function > itt > > > > 483 > > > > > Mar 26 18:37:25 localhost kernel: > > > > > execute_task_management(1177) 1e3 1 be010000 > > > > > Mar 26 18:37:25 localhost kernel: > cmnd_abort(1114) > > > > 1be > > > > > 1 0 42 131072 0 0 > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > task mgmt itt 483 rejected (0x1) > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Sending ABORT TASK for task itt 447 > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Waking tx_thread to send task mgmt function > itt > > > > 484 > > > > > Mar 26 18:37:25 localhost kernel: > > > > > execute_task_management(1177) 1e4 1 bf010000 > > > > > Mar 26 18:37:25 localhost kernel: > cmnd_abort(1114) > > > > 1bf > > > > > 1 0 42 131072 0 0 > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > task mgmt itt 484 rejected (0x1) > > > > > Mar 26 18:37:25 localhost kernel: > > > > iscsi-sfnet:host5: > > > > > Sending ABORT TASK for task itt 448 > > > > > Mar 26 18:37:25 localhost kernel: > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-27 01:11:36
|
On Sun, 2006-03-26 at 11:47 -0800, Rik Herrin wrote: > My /etc/sysconfig/initiator looks like this. > > CHANNEL="0 1 lo 127.0.0.1 3260 0" > > It would give me a lot of messages such as: > > check_segment_length(1552) too lond data 15a 32768 > 8192 > check_segment_length(1552) too lond data 15b 32768 > 8192 looks like iet try to only accept pdu with 8K while ini send out 32K. could u send us a tcpdump capture of the login process? we solve this first. > iscsi_session_push_cmnd(1531) too large cmd_sn (56,1) > ... [and so forth] > > before finally completing: > > real 1m31.320s > user 0m0.001s > sys 0m0.139s > > Sometimes it finishes while at other times, it gives > the errors above and then goes into a loop trying to > reconnect and then disconnecting again: > > localhost kernel: iCHANNEL[0]_LU[0] - SCSI Task > Timeout with ITT: 0x00000264 > localhost kernel: iCHANNEL[0]_LU[0] - Forcing Session > Reinstatement for timed-out SCSI Task to ONLINE > Logical Unit > localhost kernel: iCHANNEL[0] - Performing Cleanup for > failed iSCSI CID: 0 to > iqn.2001-04.com.example:storage.disk2.sys1.xyz > localhost kernel: iCHANNEL[0] - Decremented iSCSI > connection count to 0 to node: > iqn.2001-04.com.example:storage.disk2.sys1.xyz > localhost kernel: iCHANNEL[0] - released iSCSI session > to node: > iqn.2001-04.com.example:storage.disk2.sys1.xyz > localhost kernel: iSCSI Core Stack[1] - Decremented > number of active iSCSI sessions to 0 > localhost kernel: iCHANNEL[0] - No defined iSCSI > Authentication Methods, skipping SecurityNegotiation > phase. > localhost kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data returned -512, expecting 48. > localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > localhost kernel: iscsi_handle_authetication:108: > ***ERROR*** sock_recvmsg() returned 0 > localhost kernel: iCHANNEL[0] - No defined iSCSI > Authentication Methods, skipping SecurityNegotiation > phase. > localhost kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data returned -512, expecting 48. > localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > localhost kernel: iscsi_handle_authetication:108: > ***ERROR*** sock_recvmsg() returned 0 > localhost kernel: iCHANNEL[0] - No defined iSCSI > Authentication Methods, skipping SecurityNegotiation > phase. > localhost kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data returned -512, expecting 48. > localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > localhost kernel: iscsi_handle_authetication:108: > ***ERROR*** sock_recvmsg() returned 0 > localhost kernel: iCHANNEL[0] - No defined iSCSI > Authentication Methods, skipping SecurityNegotiation > phase. > localhost kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data returned -512, expecting 48. > localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > localhost kernel: iscsi_handle_authetication:108: > ***ERROR*** sock_recvmsg() returned 0 > localhost kernel: iCHANNEL[0] - No defined iSCSI > Authentication Methods, skipping SecurityNegotiation > phase. > localhost kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data returned -512, expecting 48. > localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > localhost kernel: iscsi_handle_authetication:108: > ***ERROR*** sock_recvmsg() returned 0 > > PS. I'll check out open-iscsi tomorrow morning and > tell you how it goes. > > --- Ming Zhang <mi...@el...> wrote: > > > forgot to say, the reason i ask u to check > > open-iscsi is that we tested > > open-iscsi + iet on same box before, it is not ok, > > then after a certain > > version, open-iscsi can run ok with iet on same box, > > but nobody do > > extensive tests. > > > > ming > > > > On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang wrote: > > > frankly, i do not know. i assumed they should be > > ok no matter whether > > > they are on same box or not. but from experience, > > it was not. > > > > > > maybe some kernel guru here can answer this > > question. > > > > > > ming > > > > > > > > > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin > > wrote: > > > > I'm running them on the same machine to see the > > > > maximum throughput and to see what type of > > bottleneck > > > > the disk subsystem will give me. I'm also > > waiting for > > > > a 4-port 1GbE Intel NIC to make sure that the > > network > > > > doesn't end up being the bottleneck. Do you > > think > > > > there's any reason for them running on the same > > > > machine to cause a problem? > > > > > > > > Rik > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > > > ps, any point to run them at same box? ;) > > > > > > > > > > ming > > > > > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik Herrin > > wrote: > > > > > > I am going to try it with open-iscsi and > > > > > core-iscsi to > > > > > > see if this issue is initiator-specific or > > IET > > > > > > specific. In the meantime, I configured a > > 4-disk > > > > > RAID > > > > > > 0 SATA configuration and set it as the > > device > > > > > exported > > > > > > by IET. Without the iSCSI layer (without > > running > > > > > > either ietd or iscsi-linux), I saw write > > > > > throughput of > > > > > > about 212 MB/s. When I started IET and > > > > > linux-iscsi > > > > > > and ran the sequential write test, I am now > > > > > getting > > > > > > the following errors: > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 445 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 446 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 447 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 448 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 449 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 450 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 451 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 452 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 453 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 454 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 455 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 456 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 457 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > Mar 26 18:37:28 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Failing command cdb 0x2a task 458 with > > return code > > > > > = > > > > > > 0x20000 > > > > > > ... [a lot more of the above] > > > > > > > > > > > > followed by: > > > > > > > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > > execute_task_management(1177) 1e2 1 bd010000 > > > > > > Mar 26 18:37:25 localhost kernel: > > cmnd_abort(1114) > > > > > 1bd > > > > > > 1 0 42 131072 0 0 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > task mgmt itt 482 rejected (0x1) > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Sending ABORT TASK for task itt 446 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Waking tx_thread to send task mgmt function > > itt > > > > > 483 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > > execute_task_management(1177) 1e3 1 be010000 > > > > > > Mar 26 18:37:25 localhost kernel: > > cmnd_abort(1114) > > > > > 1be > > > > > > 1 0 42 131072 0 0 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > task mgmt itt 483 rejected (0x1) > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Sending ABORT TASK for task itt 447 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Waking tx_thread to send task mgmt function > > itt > > > > > 484 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > > execute_task_management(1177) 1e4 1 bf010000 > > > > > > Mar 26 18:37:25 localhost kernel: > > cmnd_abort(1114) > > > > > 1bf > > > > > > 1 0 42 131072 0 0 > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > task mgmt itt 484 rejected (0x1) > > > > > > Mar 26 18:37:25 localhost kernel: > > > > > iscsi-sfnet:host5: > > > > > > Sending ABORT TASK for task itt 448 > > > > > > Mar 26 18:37:25 localhost kernel: > > > === message truncated === > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-27 15:10:59
|
The problem with the above 2 is that Core-ISCSI is trying to send 32k PDUs while IET only accepts 8K PDUs. So I replaced it with the following: CHANNEL="0 1 lo 127.0.0.1 3260 0 AuthMethod=None;MaxRecvDataSegmentLength=8192 nopout_timeout=5" which should send 8K PDUs instead. In either case, I added a tcpdump of the login process at the end of my email. I then ran the same dd as before which should write 500 MB of sequential data onto the iSCSI target. It's talking a very long time to dd 500M onto the iSCSI target disc and looking at top, it gives me the following: istd1 taking 99.9% CPU with them split up as 50.1% sy and 49.9% wait Looking into /var/log/messages, I see messages such as: Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. Mar 27 17:25:46 localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. Mar 27 17:25:46 localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. Mar 27 17:25:46 localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 Mar 27 17:25:48 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. Mar 27 17:26:13 localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. Mar 27 17:26:13 localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. Mar 27 17:26:13 localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. ............. Could it be, as you mentioned in a previous mail, that since IET doesn't get back to the initiator and tell it that it's successfully written the data, the core-iscsi initiator believes that the connection is lost and tries to start a new session and fails because there's already the old session and IET doesn't support MCS? I'm off to try open-iscsi. Thanks for your help. Rik Herrin --- Ming Zhang <mi...@el...> wrote: > On Sun, 2006-03-26 at 11:47 -0800, Rik Herrin wrote: > > > My /etc/sysconfig/initiator looks like this. > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0" > > > > It would give me a lot of messages such as: > > > > check_segment_length(1552) too lond data 15a 32768 > > 8192 > > check_segment_length(1552) too lond data 15b 32768 > > 8192 > > looks like iet try to only accept pdu with 8K while > ini send out 32K. > could u send us a tcpdump capture of the login > process? > > we solve this first. > > > iscsi_session_push_cmnd(1531) too large cmd_sn > (56,1) > > ... [and so forth] > > > > before finally completing: > > > > real 1m31.320s > > user 0m0.001s > > sys 0m0.139s > > > > Sometimes it finishes while at other times, it > gives > > the errors above and then goes into a loop trying > to > > reconnect and then disconnecting again: > > > > localhost kernel: iCHANNEL[0]_LU[0] - SCSI Task > > Timeout with ITT: 0x00000264 > > localhost kernel: iCHANNEL[0]_LU[0] - Forcing > Session > > Reinstatement for timed-out SCSI Task to ONLINE > > Logical Unit > > localhost kernel: iCHANNEL[0] - Performing Cleanup > for > > failed iSCSI CID: 0 to > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iCHANNEL[0] - Decremented iSCSI > > connection count to 0 to node: > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iCHANNEL[0] - released iSCSI > session > > to node: > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iSCSI Core Stack[1] - > Decremented > > number of active iSCSI sessions to 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > > > PS. I'll check out open-iscsi tomorrow morning and > > tell you how it goes. > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > forgot to say, the reason i ask u to check > > > open-iscsi is that we tested > > > open-iscsi + iet on same box before, it is not > ok, > > > then after a certain > > > version, open-iscsi can run ok with iet on same > box, > > > but nobody do > > > extensive tests. > > > > > > ming > > > > > > On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang > wrote: > > > > frankly, i do not know. i assumed they should > be > > > ok no matter whether > > > > they are on same box or not. but from > experience, > > > it was not. > > > > > > > > maybe some kernel guru here can answer this > > > question. > > > > > > > > ming > > > > > > > > > > > > > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin > > > wrote: > > > > > I'm running them on the same machine to see > the > > > > > maximum throughput and to see what type of > > > bottleneck > > > > > the disk subsystem will give me. I'm also > > > waiting for > > > > > a 4-port 1GbE Intel NIC to make sure that > the > > > network > > > > > doesn't end up being the bottleneck. Do you > > > think > > > > > there's any reason for them running on the > same > > > > > machine to cause a problem? > > > > > > > > > > Rik > > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > > > > > ps, any point to run them at same box? ;) > > > > > > > > > > > > ming > > > > > > > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik > Herrin > > > wrote: > > > > > > > I am going to try it with open-iscsi and > > > > > > core-iscsi to > > > > > > > see if this issue is initiator-specific > or > > > IET > > > > > > > specific. In the meantime, I configured > a > > > 4-disk > > > > > > RAID > > > > > > > 0 SATA configuration and set it as the > > > device > > > > > > exported > > > > > > > by IET. Without the iSCSI layer > (without > > > running > > > > > > > either ietd or iscsi-linux), I saw write > > > > > > throughput of > > > > > > > about 212 MB/s. When I started IET and > > > > > > linux-iscsi > > > > > > > and ran the sequential write test, I am > now > > > > > > getting > > > > > > > the following errors: > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-27 15:33:30
|
(This is the exact same email I sent 10 minutes ago. I just forgot to add the tcpdump output.) "The problem with the above 2 is that Core-ISCSI is trying to send 32k PDUs while IET only accepts 8K PDUs." So I replaced it with the following: CHANNEL="0 1 lo 127.0.0.1 3260 0 AuthMethod=None;MaxRecvDataSegmentLength=8192 nopout_timeout=5" which should send 8K PDUs instead. In either case, I added a tcpdump of the login process at the end of my email. I then ran the same dd as before which should write 500 MB of sequential data onto the iSCSI target. It's talking a very long time to dd 500M onto the iSCSI target disc and looking at top, it gives me the following: istd1 taking 99.9% CPU with them split up as 50.1% sy and 49.9% wait Looking into /var/log/messages, I see messages such as: Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. Mar 27 17:25:46 localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. Mar 27 17:25:46 localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. Mar 27 17:25:46 localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 Mar 27 17:25:48 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. Mar 27 17:26:13 localhost kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data returned -512, expecting 48. Mar 27 17:26:13 localhost kernel: iscsi_initiator_start_negotiation:754: ***ERROR*** iSCSI Login negotiation failed. Mar 27 17:26:13 localhost kernel: iscsi_handle_authetication:108: ***ERROR*** sock_recvmsg() returned 0 Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No defined iSCSI Authentication Methods, skipping SecurityNegotiation phase. ............. Could it be, as you mentioned in a previous mail, that since IET doesn't get back to the initiator and tell it that it's successfully written the data, the core-iscsi initiator believes that the connection is lost and tries to start a new session and fails because there's already the old session and IET doesn't support MCS? I'm off to try open-iscsi. Thanks for your help. Rik Herrin TCP Dump of Login: 17:59:49.597309 IP localhost.localdomain.32771 > localhost.localdomain.3260: S 1001746800:1001746800(0) win 32767 <mss 16396,sackOK,timestamp 179287 0,nop,wscale 5> 17:59:49.597760 IP localhost.localdomain.3260 > localhost.localdomain.32771: S 990883816:990883816(0) ack 1001746801 win 32767 <mss 16396,sackOK,timestamp 179287 179287,nop,wscale 5> 17:59:49.597789 IP localhost.localdomain.32771 > localhost.localdomain.3260: . ack 1 win 1024 <nop,nop,timestamp 179287 179287> 17:59:49.597804 IP localhost.localdomain.32771 > localhost.localdomain.3260: P 1:233(232) ack 1 win 1024 <nop,nop,timestamp 179287 179287> 17:59:49.597819 IP localhost.localdomain.3260 > localhost.localdomain.32771: . ack 233 win 1058 <nop,nop,timestamp 179287 179287> 17:59:49.597352 IP localhost.localdomain.3260 > localhost.localdomain.32771: P 1:109(108) ack 233 win 1058 <nop,nop,timestamp 179287 179287> 17:59:49.597498 IP localhost.localdomain.32771 > localhost.localdomain.3260: . ack 109 win 1024 <nop,nop,timestamp 179287 179287> 17:59:49.597814 IP localhost.localdomain.32771 > localhost.localdomain.3260: P 233:297(64) ack 109 win 1024 <nop,nop,timestamp 179287 179287> 17:59:49.597957 IP localhost.localdomain.3260 > localhost.localdomain.32771: P 109:249(140) ack 297 win 1058 <nop,nop,timestamp 179288 179287> 17:59:49.598540 IP localhost.localdomain.32771 > localhost.localdomain.3260: P 297:345(48) ack 249 win 1024 <nop,nop,timestamp 179288 179288> 17:59:49.598590 IP localhost.localdomain.3260 > localhost.localdomain.32771: P 249:297(48) ack 345 win 1058 <nop,nop,timestamp 179288 179288> 17:59:49.598679 IP localhost.localdomain.32771 > localhost.localdomain.3260: F 345:345(0) ack 297 win 1024 <nop,nop,timestamp 179288 179288> 17:59:49.598715 IP localhost.localdomain.32772 > localhost.localdomain.3260: S 991579803:991579803(0) win 32767 <mss 16396,sackOK,timestamp 179288 0,nop,wscale 5> 17:59:49.598730 IP localhost.localdomain.3260 > localhost.localdomain.32772: S 1003662361:1003662361(0) ack 991579804 win 32767 <mss 16396,sackOK,timestamp 179288 179288,nop,wscale 5> 17:59:49.598746 IP localhost.localdomain.32772 > localhost.localdomain.3260: . ack 1 win 1024 <nop,nop,timestamp 179288 179288> 17:59:49.598825 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 1:533(532) ack 1 win 1024 <nop,nop,timestamp 179288 179288> 17:59:49.598846 IP localhost.localdomain.3260 > localhost.localdomain.32772: . ack 533 win 1058 <nop,nop,timestamp 179288 179288> 17:59:49.598893 IP localhost.localdomain.3260 > localhost.localdomain.32771: F 297:297(0) ack 346 win 1058 <nop,nop,timestamp 179289 179288> 17:59:49.598902 IP localhost.localdomain.32771 > localhost.localdomain.3260: . ack 298 win 1024 <nop,nop,timestamp 179289 179289> 17:59:49.599141 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 1:353(352) ack 533 win 1058 <nop,nop,timestamp 179289 179288> 17:59:49.599160 IP localhost.localdomain.32772 > localhost.localdomain.3260: . ack 353 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599520 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 533:581(48) ack 353 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599592 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 353:401(48) ack 581 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599604 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 401:437(36) ack 581 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599707 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 581:629(48) ack 437 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599750 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 437:485(48) ack 629 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.599759 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 485:549(64) ack 629 win 1058 <nop,nop,timestamp 179289 179289> 17:59:49.603000 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 629:677(48) ack 549 win 1058 <nop,nop,timestamp 179293 179289> 17:59:49.603069 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 549:597(48) ack 677 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603240 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 677:725(48) ack 597 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603298 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 597:645(48) ack 725 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603313 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 645:653(8) ack 725 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603447 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 725:773(48) ack 653 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603511 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 653:701(48) ack 773 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.603525 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 701:705(4) ack 773 win 1058 <nop,nop,timestamp 179293 179293> 17:59:49.610514 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 773:821(48) ack 705 win 1058 <nop,nop,timestamp 179300 179293> 17:59:49.610723 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 705:753(48) ack 821 win 1058 <nop,nop,timestamp 179300 179300> 17:59:49.610744 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 753:785(32) ack 821 win 1058 <nop,nop,timestamp 179300 179300> 17:59:49.611513 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 821:869(48) ack 785 win 1058 <nop,nop,timestamp 179301 179300> 17:59:49.611615 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 785:833(48) ack 869 win 1058 <nop,nop,timestamp 179301 179301> 17:59:49.611635 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 833:4929(4096) ack 869 win 1058 <nop,nop,timestamp 179301 179301> 17:59:49.611660 IP localhost.localdomain.32772 > localhost.localdomain.3260: . ack 4929 win 2082 <nop,nop,timestamp 179301 179301> 17:59:49.636795 IP localhost.localdomain.32772 > localhost.localdomain.3260: P 869:917(48) ack 4929 win 2082 <nop,nop,timestamp 179326 179301> 17:59:49.636902 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 4929:4977(48) ack 917 win 1058 <nop,nop,timestamp 179327 179326> 17:59:49.636916 IP localhost.localdomain.3260 > localhost.localdomain.32772: P 4977:4993(16) ack 917 win 1058 <nop,nop,timestamp 179327 179326> 17:59:49.677493 IP localhost.localdomain.32772 > localhost.localdomain.3260: . ack 4993 win 2082 <nop,nop,timestamp 179367 179327> --- Ming Zhang <mi...@el...> wrote: > On Sun, 2006-03-26 at 11:47 -0800, Rik Herrin wrote: > > > My /etc/sysconfig/initiator looks like this. > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0" > > > > It would give me a lot of messages such as: > > > > check_segment_length(1552) too lond data 15a 32768 > > 8192 > > check_segment_length(1552) too lond data 15b 32768 > > 8192 > > looks like iet try to only accept pdu with 8K while > ini send out 32K. > could u send us a tcpdump capture of the login > process? > > we solve this first. > > > iscsi_session_push_cmnd(1531) too large cmd_sn > (56,1) > > ... [and so forth] > > > > before finally completing: > > > > real 1m31.320s > > user 0m0.001s > > sys 0m0.139s > > > > Sometimes it finishes while at other times, it > gives > > the errors above and then goes into a loop trying > to > > reconnect and then disconnecting again: > > > > localhost kernel: iCHANNEL[0]_LU[0] - SCSI Task > > Timeout with ITT: 0x00000264 > > localhost kernel: iCHANNEL[0]_LU[0] - Forcing > Session > > Reinstatement for timed-out SCSI Task to ONLINE > > Logical Unit > > localhost kernel: iCHANNEL[0] - Performing Cleanup > for > > failed iSCSI CID: 0 to > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iCHANNEL[0] - Decremented iSCSI > > connection count to 0 to node: > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iCHANNEL[0] - released iSCSI > session > > to node: > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > localhost kernel: iSCSI Core Stack[1] - > Decremented > > number of active iSCSI sessions to 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > Authentication Methods, skipping > SecurityNegotiation > > phase. > > localhost kernel: iscsi_login_rx_data:54: > ***ERROR*** > > rx_data returned -512, expecting 48. > > localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > localhost kernel: iscsi_handle_authetication:108: > > ***ERROR*** sock_recvmsg() returned 0 > > > > PS. I'll check out open-iscsi tomorrow morning and > > tell you how it goes. > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > forgot to say, the reason i ask u to check > > > open-iscsi is that we tested > > > open-iscsi + iet on same box before, it is not > ok, > > > then after a certain > > > version, open-iscsi can run ok with iet on same > box, > > > but nobody do > > > extensive tests. > > > > > > ming > > > > > > On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang > wrote: > > > > frankly, i do not know. i assumed they should > be > > > ok no matter whether > > > > they are on same box or not. but from > experience, > > > it was not. > > > > > > > > maybe some kernel guru here can answer this > > > question. > > > > > > > > ming > > > > > > > > > > > > > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin > > > wrote: > > > > > I'm running them on the same machine to see > the > > > > > maximum throughput and to see what type of > > > bottleneck > > > > > the disk subsystem will give me. I'm also > > > waiting for > > > > > a 4-port 1GbE Intel NIC to make sure that > the > > > network > > > > > doesn't end up being the bottleneck. Do you > > > think > > > > > there's any reason for them running on the > same > > > > > machine to cause a problem? > > > > > > > > > > Rik > > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > > > > > ps, any point to run them at same box? ;) > > > > > > > > > > > > ming > > > > > > > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik > Herrin > > > wrote: > > > > > > > I am going to try it with open-iscsi and > > > > > > core-iscsi to > > > > > > > see if this issue is initiator-specific > or > > > IET > > > > > > > specific. In the meantime, I configured > a > > > 4-disk > > > > > > RAID > > > > > > > 0 SATA configuration and set it as the > > > device > > > > > > exported > > > > > > > by IET. Without the iSCSI layer > (without > > > running > > > > > > > either ietd or iscsi-linux), I saw write > > > > > > throughput of > > > > > > > about 212 MB/s. When I started IET and > > > > > > linux-iscsi > > > > > > > and ran the sequential write test, I am > now > > > > > > getting > > > > > > > the following errors: > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-27 16:57:49
|
On Mon, 2006-03-27 at 07:33 -0800, Rik Herrin wrote: > (This is the exact same email I sent 10 minutes ago. > I just forgot to add the tcpdump output.) > > "The problem with the above 2 is that Core-ISCSI is > trying to send 32k PDUs while IET only accepts 8K > PDUs." i forgot since iet which version, we correctly handle this. so i want to see u tcpdump trace for detail. if u adjust the ini parameter, it is ok well. but a tcpdump log before u adjusting this parameter will be useful. i need a log captured with "tcpdump -s1600 -w log" and send us the log, or bziped if it is large. ming > > So I replaced it with the following: > > CHANNEL="0 1 lo 127.0.0.1 3260 0 > AuthMethod=None;MaxRecvDataSegmentLength=8192 > nopout_timeout=5" > > which should send 8K PDUs instead. In either case, I > added a tcpdump of the login process at the end of my > email. I then ran the same dd as before which should > write 500 MB of sequential data onto the iSCSI target. > It's talking a very long time to dd 500M onto the > iSCSI target disc and looking at top, it gives me the > following: > > istd1 taking 99.9% CPU with them split up as 50.1% sy > and 49.9% wait > > Looking into /var/log/messages, I see messages such > as: > > Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No > defined iSCSI Authentication Methods, skipping > SecurityNegotiation phase. Mar 27 17:25:46 localhost > kernel: iscsi_login_rx_data:54: ***ERROR*** rx_data > returned -512, expecting 48. Mar 27 > 17:25:46 localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. Mar 27 > 17:25:46 localhost kernel: > iscsi_handle_authetication:108: ***ERROR*** > sock_recvmsg() returned 0 Mar 27 > 17:25:48 localhost kernel: iCHANNEL[0] - No defined > iSCSI Authentication Methods, skipping > SecurityNegotiation phase. > Mar 27 17:26:13 localhost kernel: > iscsi_login_rx_data:54: ***ERROR*** rx_data returned > -512, expecting 48. > Mar 27 17:26:13 localhost kernel: > iscsi_initiator_start_negotiation:754: ***ERROR*** > iSCSI Login negotiation failed. > Mar 27 17:26:13 localhost kernel: > iscsi_handle_authetication:108: ***ERROR*** > sock_recvmsg() returned 0 > Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No > defined iSCSI Authentication Methods, skipping > SecurityNegotiation phase. > ............. > > Could it be, as you mentioned in a previous mail, that > since IET doesn't get back to the initiator and tell > it that it's successfully written the data, the > core-iscsi initiator believes that the connection is > lost and tries to start a new session and fails > because there's already the old session and IET > doesn't support MCS? I'm off to try open-iscsi. > Thanks for your help. > > Rik Herrin > > TCP Dump of Login: > > 17:59:49.597309 IP localhost.localdomain.32771 > > localhost.localdomain.3260: S 1001746800:1001746800(0) > win 32767 <mss 16396,sackOK,timestamp 179287 > 0,nop,wscale 5> > 17:59:49.597760 IP localhost.localdomain.3260 > > localhost.localdomain.32771: S 990883816:990883816(0) > ack 1001746801 win 32767 <mss 16396,sackOK,timestamp > 179287 179287,nop,wscale 5> > 17:59:49.597789 IP localhost.localdomain.32771 > > localhost.localdomain.3260: . ack 1 win 1024 > <nop,nop,timestamp 179287 179287> > 17:59:49.597804 IP localhost.localdomain.32771 > > localhost.localdomain.3260: P 1:233(232) ack 1 win > 1024 <nop,nop,timestamp 179287 179287> > 17:59:49.597819 IP localhost.localdomain.3260 > > localhost.localdomain.32771: . ack 233 win 1058 > <nop,nop,timestamp 179287 179287> > 17:59:49.597352 IP localhost.localdomain.3260 > > localhost.localdomain.32771: P 1:109(108) ack 233 win > 1058 <nop,nop,timestamp 179287 179287> > 17:59:49.597498 IP localhost.localdomain.32771 > > localhost.localdomain.3260: . ack 109 win 1024 > <nop,nop,timestamp 179287 179287> > 17:59:49.597814 IP localhost.localdomain.32771 > > localhost.localdomain.3260: P 233:297(64) ack 109 win > 1024 <nop,nop,timestamp 179287 179287> > 17:59:49.597957 IP localhost.localdomain.3260 > > localhost.localdomain.32771: P 109:249(140) ack 297 > win 1058 <nop,nop,timestamp 179288 179287> > 17:59:49.598540 IP localhost.localdomain.32771 > > localhost.localdomain.3260: P 297:345(48) ack 249 win > 1024 <nop,nop,timestamp 179288 179288> > 17:59:49.598590 IP localhost.localdomain.3260 > > localhost.localdomain.32771: P 249:297(48) ack 345 win > 1058 <nop,nop,timestamp 179288 179288> > 17:59:49.598679 IP localhost.localdomain.32771 > > localhost.localdomain.3260: F 345:345(0) ack 297 win > 1024 <nop,nop,timestamp 179288 179288> > 17:59:49.598715 IP localhost.localdomain.32772 > > localhost.localdomain.3260: S 991579803:991579803(0) > win 32767 <mss 16396,sackOK,timestamp 179288 > 0,nop,wscale 5> > 17:59:49.598730 IP localhost.localdomain.3260 > > localhost.localdomain.32772: S > 1003662361:1003662361(0) ack 991579804 win 32767 <mss > 16396,sackOK,timestamp 179288 179288,nop,wscale 5> > 17:59:49.598746 IP localhost.localdomain.32772 > > localhost.localdomain.3260: . ack 1 win 1024 > <nop,nop,timestamp 179288 179288> > 17:59:49.598825 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 1:533(532) ack 1 win > 1024 <nop,nop,timestamp 179288 179288> > 17:59:49.598846 IP localhost.localdomain.3260 > > localhost.localdomain.32772: . ack 533 win 1058 > <nop,nop,timestamp 179288 179288> > 17:59:49.598893 IP localhost.localdomain.3260 > > localhost.localdomain.32771: F 297:297(0) ack 346 win > 1058 <nop,nop,timestamp 179289 179288> > 17:59:49.598902 IP localhost.localdomain.32771 > > localhost.localdomain.3260: . ack 298 win 1024 > <nop,nop,timestamp 179289 179289> > 17:59:49.599141 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 1:353(352) ack 533 win > 1058 <nop,nop,timestamp 179289 179288> > 17:59:49.599160 IP localhost.localdomain.32772 > > localhost.localdomain.3260: . ack 353 win 1058 > <nop,nop,timestamp 179289 179289> > 17:59:49.599520 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 533:581(48) ack 353 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.599592 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 353:401(48) ack 581 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.599604 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 401:437(36) ack 581 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.599707 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 581:629(48) ack 437 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.599750 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 437:485(48) ack 629 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.599759 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 485:549(64) ack 629 win > 1058 <nop,nop,timestamp 179289 179289> > 17:59:49.603000 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 629:677(48) ack 549 win > 1058 <nop,nop,timestamp 179293 179289> > 17:59:49.603069 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 549:597(48) ack 677 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603240 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 677:725(48) ack 597 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603298 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 597:645(48) ack 725 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603313 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 645:653(8) ack 725 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603447 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 725:773(48) ack 653 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603511 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 653:701(48) ack 773 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.603525 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 701:705(4) ack 773 win > 1058 <nop,nop,timestamp 179293 179293> > 17:59:49.610514 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 773:821(48) ack 705 win > 1058 <nop,nop,timestamp 179300 179293> > 17:59:49.610723 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 705:753(48) ack 821 win > 1058 <nop,nop,timestamp 179300 179300> > 17:59:49.610744 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 753:785(32) ack 821 win > 1058 <nop,nop,timestamp 179300 179300> > 17:59:49.611513 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 821:869(48) ack 785 win > 1058 <nop,nop,timestamp 179301 179300> > 17:59:49.611615 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 785:833(48) ack 869 win > 1058 <nop,nop,timestamp 179301 179301> > 17:59:49.611635 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 833:4929(4096) ack 869 > win 1058 <nop,nop,timestamp 179301 179301> > 17:59:49.611660 IP localhost.localdomain.32772 > > localhost.localdomain.3260: . ack 4929 win 2082 > <nop,nop,timestamp 179301 179301> > 17:59:49.636795 IP localhost.localdomain.32772 > > localhost.localdomain.3260: P 869:917(48) ack 4929 win > 2082 <nop,nop,timestamp 179326 179301> > 17:59:49.636902 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 4929:4977(48) ack 917 > win 1058 <nop,nop,timestamp 179327 179326> > 17:59:49.636916 IP localhost.localdomain.3260 > > localhost.localdomain.32772: P 4977:4993(16) ack 917 > win 1058 <nop,nop,timestamp 179327 179326> > 17:59:49.677493 IP localhost.localdomain.32772 > > localhost.localdomain.3260: . ack 4993 win 2082 > <nop,nop,timestamp 179367 179327> > > --- Ming Zhang <mi...@el...> wrote: > > > On Sun, 2006-03-26 at 11:47 -0800, Rik Herrin wrote: > > > > > My /etc/sysconfig/initiator looks like this. > > > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0" > > > > > > It would give me a lot of messages such as: > > > > > > check_segment_length(1552) too lond data 15a 32768 > > > 8192 > > > check_segment_length(1552) too lond data 15b 32768 > > > 8192 > > > > looks like iet try to only accept pdu with 8K while > > ini send out 32K. > > could u send us a tcpdump capture of the login > > process? > > > > we solve this first. > > > > > iscsi_session_push_cmnd(1531) too large cmd_sn > > (56,1) > > > ... [and so forth] > > > > > > before finally completing: > > > > > > real 1m31.320s > > > user 0m0.001s > > > sys 0m0.139s > > > > > > Sometimes it finishes while at other times, it > > gives > > > the errors above and then goes into a loop trying > > to > > > reconnect and then disconnecting again: > > > > > > localhost kernel: iCHANNEL[0]_LU[0] - SCSI Task > > > Timeout with ITT: 0x00000264 > > > localhost kernel: iCHANNEL[0]_LU[0] - Forcing > > Session > > > Reinstatement for timed-out SCSI Task to ONLINE > > > Logical Unit > > > localhost kernel: iCHANNEL[0] - Performing Cleanup > > for > > > failed iSCSI CID: 0 to > > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > > localhost kernel: iCHANNEL[0] - Decremented iSCSI > > > connection count to 0 to node: > > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > > localhost kernel: iCHANNEL[0] - released iSCSI > > session > > > to node: > > > iqn.2001-04.com.example:storage.disk2.sys1.xyz > > > localhost kernel: iSCSI Core Stack[1] - > > Decremented > > > number of active iSCSI sessions to 0 > > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > > Authentication Methods, skipping > > SecurityNegotiation > > > phase. > > > localhost kernel: iscsi_login_rx_data:54: > > ***ERROR*** > > > rx_data returned -512, expecting 48. > > > localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > localhost kernel: iscsi_handle_authetication:108: > > > ***ERROR*** sock_recvmsg() returned 0 > > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > > Authentication Methods, skipping > > SecurityNegotiation > > > phase. > > > localhost kernel: iscsi_login_rx_data:54: > > ***ERROR*** > > > rx_data returned -512, expecting 48. > > > localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > localhost kernel: iscsi_handle_authetication:108: > > > ***ERROR*** sock_recvmsg() returned 0 > > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > > Authentication Methods, skipping > > SecurityNegotiation > > > phase. > > > localhost kernel: iscsi_login_rx_data:54: > > ***ERROR*** > > > rx_data returned -512, expecting 48. > > > localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > localhost kernel: iscsi_handle_authetication:108: > > > ***ERROR*** sock_recvmsg() returned 0 > > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > > Authentication Methods, skipping > > SecurityNegotiation > > > phase. > > > localhost kernel: iscsi_login_rx_data:54: > > ***ERROR*** > > > rx_data returned -512, expecting 48. > > > localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > localhost kernel: iscsi_handle_authetication:108: > > > ***ERROR*** sock_recvmsg() returned 0 > > > localhost kernel: iCHANNEL[0] - No defined iSCSI > > > Authentication Methods, skipping > > SecurityNegotiation > > > phase. > > > localhost kernel: iscsi_login_rx_data:54: > > ***ERROR*** > > > rx_data returned -512, expecting 48. > > > localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > localhost kernel: iscsi_handle_authetication:108: > > > ***ERROR*** sock_recvmsg() returned 0 > > > > > > PS. I'll check out open-iscsi tomorrow morning and > > > tell you how it goes. > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > forgot to say, the reason i ask u to check > > > > open-iscsi is that we tested > > > > open-iscsi + iet on same box before, it is not > > ok, > > > > then after a certain > > > > version, open-iscsi can run ok with iet on same > > box, > > > > but nobody do > > > > extensive tests. > > > > > > > > ming > > > > > > > > On Sun, 2006-03-26 at 12:37 -0500, Ming Zhang > > wrote: > > > > > frankly, i do not know. i assumed they should > > be > > > > ok no matter whether > > > > > they are on same box or not. but from > > experience, > > > > it was not. > > > > > > > > > > maybe some kernel guru here can answer this > > > > question. > > > > > > > > > > ming > > > > > > > > > > > > > > > > > > > > On Sun, 2006-03-26 at 09:18 -0800, Rik Herrin > > > > wrote: > > > > > > I'm running them on the same machine to see > > the > > > > > > maximum throughput and to see what type of > > > > bottleneck > > > > > > the disk subsystem will give me. I'm also > > > > waiting for > > > > > > a 4-port 1GbE Intel NIC to make sure that > > the > > > > network > > > > > > doesn't end up being the bottleneck. Do you > > > > think > > > > > > there's any reason for them running on the > > same > > > > > > machine to cause a problem? > > > > > > > > > > > > Rik > > > > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > > > > > > > ps, any point to run them at same box? ;) > > > > > > > > > > > > > > ming > > > > > > > > > > > > > > On Sun, 2006-03-26 at 08:30 -0800, Rik > > Herrin > > > > wrote: > > > > > > > > I am going to try it with open-iscsi and > > > > > > > core-iscsi to > > > > > > > > see if this issue is initiator-specific > > or > > > > IET > > > > > > > > specific. In the meantime, I configured > > a > > > > 4-disk > > > > > > > RAID > > > > > > > > 0 SATA configuration and set it as the > > > > device > > > > > > > exported > > > > > > > > by IET. Without the iSCSI layer > > (without > > > > running > > > > > > > > either ietd or iscsi-linux), I saw write > > > > > > > throughput of > > > > > > > > about 212 MB/s. When I started IET and > > > > > > > linux-iscsi > > > > > > > > and ran the sequential write test, I am > > now > > > > > > > getting > > > > > > > > the following errors: > > > === message truncated === > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-28 07:45:51
Attachments:
log
|
I'm using IET v 0.4.12-6 and I attached the log file for the login process. --- Ming Zhang <mi...@el...> wrote: > > On Mon, 2006-03-27 at 07:33 -0800, Rik Herrin wrote: > > (This is the exact same email I sent 10 minutes > ago. > > I just forgot to add the tcpdump output.) > > > > "The problem with the above 2 is that Core-ISCSI > is > > trying to send 32k PDUs while IET only accepts 8K > > PDUs." > > i forgot since iet which version, we correctly > handle this. so i want to > see u tcpdump trace for detail. if u adjust the ini > parameter, it is ok > well. but a tcpdump log before u adjusting this > parameter will be > useful. > > i need a log captured with "tcpdump -s1600 -w log" > and send us the log, > or bziped if it is large. > > ming > > > > > So I replaced it with the following: > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0 > > AuthMethod=None;MaxRecvDataSegmentLength=8192 > > nopout_timeout=5" > > > > which should send 8K PDUs instead. In either > case, I > > added a tcpdump of the login process at the end of > my > > email. I then ran the same dd as before which > should > > write 500 MB of sequential data onto the iSCSI > target. > > It's talking a very long time to dd 500M onto the > > iSCSI target disc and looking at top, it gives me > the > > following: > > > > istd1 taking 99.9% CPU with them split up as 50.1% > sy > > and 49.9% wait > > > > Looking into /var/log/messages, I see messages > such > > as: > > > > Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No > > defined iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. Mar 27 17:25:46 > localhost > > kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data > > returned -512, expecting 48. Mar > 27 > > 17:25:46 localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. Mar 27 > > 17:25:46 localhost kernel: > > iscsi_handle_authetication:108: ***ERROR*** > > sock_recvmsg() returned 0 Mar > 27 > > 17:25:48 localhost kernel: iCHANNEL[0] - No > defined > > iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. > > Mar 27 17:26:13 localhost kernel: > > iscsi_login_rx_data:54: ***ERROR*** rx_data > returned > > -512, expecting 48. > > Mar 27 17:26:13 localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > Mar 27 17:26:13 localhost kernel: > > iscsi_handle_authetication:108: ***ERROR*** > > sock_recvmsg() returned 0 > > Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No > > defined iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. > > ............. > > > > Could it be, as you mentioned in a previous mail, > that > > since IET doesn't get back to the initiator and > tell > > it that it's successfully written the data, the > > core-iscsi initiator believes that the connection > is > > lost and tries to start a new session and fails > > because there's already the old session and IET > > doesn't support MCS? I'm off to try open-iscsi. > > Thanks for your help. > > > > Rik Herrin > > > > TCP Dump of Login: > > > > 17:59:49.597309 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: S > 1001746800:1001746800(0) > > win 32767 <mss 16396,sackOK,timestamp 179287 > > 0,nop,wscale 5> > > 17:59:49.597760 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: S > 990883816:990883816(0) > > ack 1001746801 win 32767 <mss > 16396,sackOK,timestamp > > 179287 179287,nop,wscale 5> > > 17:59:49.597789 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 1 win 1024 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597804 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 1:233(232) ack 1 win > > 1024 <nop,nop,timestamp 179287 179287> > > 17:59:49.597819 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: . ack 233 win 1058 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597352 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 1:109(108) ack 233 > win > > 1058 <nop,nop,timestamp 179287 179287> > > 17:59:49.597498 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 109 win 1024 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597814 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 233:297(64) ack 109 > win > > 1024 <nop,nop,timestamp 179287 179287> > > 17:59:49.597957 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 109:249(140) ack > 297 > > win 1058 <nop,nop,timestamp 179288 179287> > > 17:59:49.598540 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 297:345(48) ack 249 > win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598590 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 249:297(48) ack 345 > win > > 1058 <nop,nop,timestamp 179288 179288> > > 17:59:49.598679 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: F 345:345(0) ack 297 > win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598715 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: S > 991579803:991579803(0) > > win 32767 <mss 16396,sackOK,timestamp 179288 > > 0,nop,wscale 5> > > 17:59:49.598730 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: S > > 1003662361:1003662361(0) ack 991579804 win 32767 > <mss > > 16396,sackOK,timestamp 179288 179288,nop,wscale 5> > > 17:59:49.598746 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: . ack 1 win 1024 > > <nop,nop,timestamp 179288 179288> > > 17:59:49.598825 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 1:533(532) ack 1 win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598846 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: . ack 533 win 1058 > > <nop,nop,timestamp 179288 179288> > > 17:59:49.598893 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: F 297:297(0) ack 346 > win > > 1058 <nop,nop,timestamp 179289 179288> > > 17:59:49.598902 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 298 win 1024 > > <nop,nop,timestamp 179289 179289> > > 17:59:49.599141 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 1:353(352) ack 533 > win > > 1058 <nop,nop,timestamp 179289 179288> > > 17:59:49.599160 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: . ack 353 win 1058 > > <nop,nop,timestamp 179289 179289> > > 17:59:49.599520 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 533:581(48) ack 353 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599592 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 353:401(48) ack 581 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599604 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 401:437(36) ack 581 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599707 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 581:629(48) ack 437 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599750 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 437:485(48) ack 629 > win > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-28 14:22:38
Attachments:
log
|
Sorry Ming. The previously attached log was with 8K specified in the core-iscsi configuration file. Here's one with the configuration file (/etc/sysconfig/initiator) w/: CHANNEL="0 1 lo 127.0.0.1 3260 0" --- Ming Zhang <mi...@el...> wrote: > > On Mon, 2006-03-27 at 07:33 -0800, Rik Herrin wrote: > > (This is the exact same email I sent 10 minutes > ago. > > I just forgot to add the tcpdump output.) > > > > "The problem with the above 2 is that Core-ISCSI > is > > trying to send 32k PDUs while IET only accepts 8K > > PDUs." > > i forgot since iet which version, we correctly > handle this. so i want to > see u tcpdump trace for detail. if u adjust the ini > parameter, it is ok > well. but a tcpdump log before u adjusting this > parameter will be > useful. > > i need a log captured with "tcpdump -s1600 -w log" > and send us the log, > or bziped if it is large. > > ming > > > > > So I replaced it with the following: > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0 > > AuthMethod=None;MaxRecvDataSegmentLength=8192 > > nopout_timeout=5" > > > > which should send 8K PDUs instead. In either > case, I > > added a tcpdump of the login process at the end of > my > > email. I then ran the same dd as before which > should > > write 500 MB of sequential data onto the iSCSI > target. > > It's talking a very long time to dd 500M onto the > > iSCSI target disc and looking at top, it gives me > the > > following: > > > > istd1 taking 99.9% CPU with them split up as 50.1% > sy > > and 49.9% wait > > > > Looking into /var/log/messages, I see messages > such > > as: > > > > Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No > > defined iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. Mar 27 17:25:46 > localhost > > kernel: iscsi_login_rx_data:54: ***ERROR*** > rx_data > > returned -512, expecting 48. Mar > 27 > > 17:25:46 localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. Mar 27 > > 17:25:46 localhost kernel: > > iscsi_handle_authetication:108: ***ERROR*** > > sock_recvmsg() returned 0 Mar > 27 > > 17:25:48 localhost kernel: iCHANNEL[0] - No > defined > > iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. > > Mar 27 17:26:13 localhost kernel: > > iscsi_login_rx_data:54: ***ERROR*** rx_data > returned > > -512, expecting 48. > > Mar 27 17:26:13 localhost kernel: > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > iSCSI Login negotiation failed. > > Mar 27 17:26:13 localhost kernel: > > iscsi_handle_authetication:108: ***ERROR*** > > sock_recvmsg() returned 0 > > Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No > > defined iSCSI Authentication Methods, skipping > > SecurityNegotiation phase. > > ............. > > > > Could it be, as you mentioned in a previous mail, > that > > since IET doesn't get back to the initiator and > tell > > it that it's successfully written the data, the > > core-iscsi initiator believes that the connection > is > > lost and tries to start a new session and fails > > because there's already the old session and IET > > doesn't support MCS? I'm off to try open-iscsi. > > Thanks for your help. > > > > Rik Herrin > > > > TCP Dump of Login: > > > > 17:59:49.597309 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: S > 1001746800:1001746800(0) > > win 32767 <mss 16396,sackOK,timestamp 179287 > > 0,nop,wscale 5> > > 17:59:49.597760 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: S > 990883816:990883816(0) > > ack 1001746801 win 32767 <mss > 16396,sackOK,timestamp > > 179287 179287,nop,wscale 5> > > 17:59:49.597789 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 1 win 1024 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597804 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 1:233(232) ack 1 win > > 1024 <nop,nop,timestamp 179287 179287> > > 17:59:49.597819 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: . ack 233 win 1058 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597352 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 1:109(108) ack 233 > win > > 1058 <nop,nop,timestamp 179287 179287> > > 17:59:49.597498 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 109 win 1024 > > <nop,nop,timestamp 179287 179287> > > 17:59:49.597814 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 233:297(64) ack 109 > win > > 1024 <nop,nop,timestamp 179287 179287> > > 17:59:49.597957 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 109:249(140) ack > 297 > > win 1058 <nop,nop,timestamp 179288 179287> > > 17:59:49.598540 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: P 297:345(48) ack 249 > win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598590 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: P 249:297(48) ack 345 > win > > 1058 <nop,nop,timestamp 179288 179288> > > 17:59:49.598679 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: F 345:345(0) ack 297 > win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598715 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: S > 991579803:991579803(0) > > win 32767 <mss 16396,sackOK,timestamp 179288 > > 0,nop,wscale 5> > > 17:59:49.598730 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: S > > 1003662361:1003662361(0) ack 991579804 win 32767 > <mss > > 16396,sackOK,timestamp 179288 179288,nop,wscale 5> > > 17:59:49.598746 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: . ack 1 win 1024 > > <nop,nop,timestamp 179288 179288> > > 17:59:49.598825 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 1:533(532) ack 1 win > > 1024 <nop,nop,timestamp 179288 179288> > > 17:59:49.598846 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: . ack 533 win 1058 > > <nop,nop,timestamp 179288 179288> > > 17:59:49.598893 IP localhost.localdomain.3260 > > > localhost.localdomain.32771: F 297:297(0) ack 346 > win > > 1058 <nop,nop,timestamp 179289 179288> > > 17:59:49.598902 IP localhost.localdomain.32771 > > > localhost.localdomain.3260: . ack 298 win 1024 > > <nop,nop,timestamp 179289 179289> > > 17:59:49.599141 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 1:353(352) ack 533 > win > > 1058 <nop,nop,timestamp 179289 179288> > > 17:59:49.599160 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: . ack 353 win 1058 > > <nop,nop,timestamp 179289 179289> > > 17:59:49.599520 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 533:581(48) ack 353 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599592 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 353:401(48) ack 581 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599604 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 401:437(36) ack 581 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599707 IP localhost.localdomain.32772 > > > localhost.localdomain.3260: P 581:629(48) ack 437 > win > > 1058 <nop,nop,timestamp 179289 179289> > > 17:59:49.599750 IP localhost.localdomain.3260 > > > localhost.localdomain.32772: P 437:485(48) ack 629 > win > === message truncated === __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-28 15:05:14
|
@Arne, could you help me to check this as well. i guess ietd.conf does not contain this parameter, so it is left to default and thus iet does not declare it. but core-ini does not use default value 8192 as the maxrecvdsl for ini, i guess it uses what it declared. @Rik, could you test this with a parameter after target in ietd.conf as "MaxRecvDataSegmentLength 16384", and capture a log again. also see if u will get many "data too long" msg. ming On Tue, 2006-03-28 at 06:22 -0800, Rik Herrin wrote: > Sorry Ming. The previously attached log was with 8K > specified in the core-iscsi configuration file. > Here's one with the configuration file > (/etc/sysconfig/initiator) w/: > > CHANNEL="0 1 lo 127.0.0.1 3260 0" > > --- Ming Zhang <mi...@el...> wrote: > > > > > On Mon, 2006-03-27 at 07:33 -0800, Rik Herrin wrote: > > > (This is the exact same email I sent 10 minutes > > ago. > > > I just forgot to add the tcpdump output.) > > > > > > "The problem with the above 2 is that Core-ISCSI > > is > > > trying to send 32k PDUs while IET only accepts 8K > > > PDUs." > > > > i forgot since iet which version, we correctly > > handle this. so i want to > > see u tcpdump trace for detail. if u adjust the ini > > parameter, it is ok > > well. but a tcpdump log before u adjusting this > > parameter will be > > useful. > > > > i need a log captured with "tcpdump -s1600 -w log" > > and send us the log, > > or bziped if it is large. > > > > ming > > > > > > > > So I replaced it with the following: > > > > > > CHANNEL="0 1 lo 127.0.0.1 3260 0 > > > AuthMethod=None;MaxRecvDataSegmentLength=8192 > > > nopout_timeout=5" > > > > > > which should send 8K PDUs instead. In either > > case, I > > > added a tcpdump of the login process at the end of > > my > > > email. I then ran the same dd as before which > > should > > > write 500 MB of sequential data onto the iSCSI > > target. > > > It's talking a very long time to dd 500M onto the > > > iSCSI target disc and looking at top, it gives me > > the > > > following: > > > > > > istd1 taking 99.9% CPU with them split up as 50.1% > > sy > > > and 49.9% wait > > > > > > Looking into /var/log/messages, I see messages > > such > > > as: > > > > > > Mar 27 17:25:21 localhost kernel: iCHANNEL[0] - No > > > defined iSCSI Authentication Methods, skipping > > > SecurityNegotiation phase. Mar 27 17:25:46 > > localhost > > > kernel: iscsi_login_rx_data:54: ***ERROR*** > > rx_data > > > returned -512, expecting 48. Mar > > 27 > > > 17:25:46 localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. Mar 27 > > > 17:25:46 localhost kernel: > > > iscsi_handle_authetication:108: ***ERROR*** > > > sock_recvmsg() returned 0 Mar > > 27 > > > 17:25:48 localhost kernel: iCHANNEL[0] - No > > defined > > > iSCSI Authentication Methods, skipping > > > SecurityNegotiation phase. > > > Mar 27 17:26:13 localhost kernel: > > > iscsi_login_rx_data:54: ***ERROR*** rx_data > > returned > > > -512, expecting 48. > > > Mar 27 17:26:13 localhost kernel: > > > iscsi_initiator_start_negotiation:754: ***ERROR*** > > > iSCSI Login negotiation failed. > > > Mar 27 17:26:13 localhost kernel: > > > iscsi_handle_authetication:108: ***ERROR*** > > > sock_recvmsg() returned 0 > > > Mar 27 17:26:15 localhost kernel: iCHANNEL[0] - No > > > defined iSCSI Authentication Methods, skipping > > > SecurityNegotiation phase. > > > ............. > > > > > > Could it be, as you mentioned in a previous mail, > > that > > > since IET doesn't get back to the initiator and > > tell > > > it that it's successfully written the data, the > > > core-iscsi initiator believes that the connection > > is > > > lost and tries to start a new session and fails > > > because there's already the old session and IET > > > doesn't support MCS? I'm off to try open-iscsi. > > > Thanks for your help. > > > > > > Rik Herrin > > > > > > TCP Dump of Login: > > > > > > 17:59:49.597309 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: S > > 1001746800:1001746800(0) > > > win 32767 <mss 16396,sackOK,timestamp 179287 > > > 0,nop,wscale 5> > > > 17:59:49.597760 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: S > > 990883816:990883816(0) > > > ack 1001746801 win 32767 <mss > > 16396,sackOK,timestamp > > > 179287 179287,nop,wscale 5> > > > 17:59:49.597789 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: . ack 1 win 1024 > > > <nop,nop,timestamp 179287 179287> > > > 17:59:49.597804 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: P 1:233(232) ack 1 win > > > 1024 <nop,nop,timestamp 179287 179287> > > > 17:59:49.597819 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: . ack 233 win 1058 > > > <nop,nop,timestamp 179287 179287> > > > 17:59:49.597352 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: P 1:109(108) ack 233 > > win > > > 1058 <nop,nop,timestamp 179287 179287> > > > 17:59:49.597498 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: . ack 109 win 1024 > > > <nop,nop,timestamp 179287 179287> > > > 17:59:49.597814 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: P 233:297(64) ack 109 > > win > > > 1024 <nop,nop,timestamp 179287 179287> > > > 17:59:49.597957 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: P 109:249(140) ack > > 297 > > > win 1058 <nop,nop,timestamp 179288 179287> > > > 17:59:49.598540 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: P 297:345(48) ack 249 > > win > > > 1024 <nop,nop,timestamp 179288 179288> > > > 17:59:49.598590 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: P 249:297(48) ack 345 > > win > > > 1058 <nop,nop,timestamp 179288 179288> > > > 17:59:49.598679 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: F 345:345(0) ack 297 > > win > > > 1024 <nop,nop,timestamp 179288 179288> > > > 17:59:49.598715 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: S > > 991579803:991579803(0) > > > win 32767 <mss 16396,sackOK,timestamp 179288 > > > 0,nop,wscale 5> > > > 17:59:49.598730 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: S > > > 1003662361:1003662361(0) ack 991579804 win 32767 > > <mss > > > 16396,sackOK,timestamp 179288 179288,nop,wscale 5> > > > 17:59:49.598746 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: . ack 1 win 1024 > > > <nop,nop,timestamp 179288 179288> > > > 17:59:49.598825 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: P 1:533(532) ack 1 win > > > 1024 <nop,nop,timestamp 179288 179288> > > > 17:59:49.598846 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: . ack 533 win 1058 > > > <nop,nop,timestamp 179288 179288> > > > 17:59:49.598893 IP localhost.localdomain.3260 > > > > localhost.localdomain.32771: F 297:297(0) ack 346 > > win > > > 1058 <nop,nop,timestamp 179289 179288> > > > 17:59:49.598902 IP localhost.localdomain.32771 > > > > localhost.localdomain.3260: . ack 298 win 1024 > > > <nop,nop,timestamp 179289 179289> > > > 17:59:49.599141 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: P 1:353(352) ack 533 > > win > > > 1058 <nop,nop,timestamp 179289 179288> > > > 17:59:49.599160 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: . ack 353 win 1058 > > > <nop,nop,timestamp 179289 179289> > > > 17:59:49.599520 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: P 533:581(48) ack 353 > > win > > > 1058 <nop,nop,timestamp 179289 179289> > > > 17:59:49.599592 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: P 353:401(48) ack 581 > > win > > > 1058 <nop,nop,timestamp 179289 179289> > > > 17:59:49.599604 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: P 401:437(36) ack 581 > > win > > > 1058 <nop,nop,timestamp 179289 179289> > > > 17:59:49.599707 IP localhost.localdomain.32772 > > > > localhost.localdomain.3260: P 581:629(48) ack 437 > > win > > > 1058 <nop,nop,timestamp 179289 179289> > > > 17:59:49.599750 IP localhost.localdomain.3260 > > > > localhost.localdomain.32772: P 437:485(48) ack 629 > > win > > > === message truncated === > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Arne R. <arn...@xi...> - 2006-03-28 15:45:35
|
Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb Ming Zhang: > @Arne, could you help me to check this as well. > > i guess ietd.conf does not contain this parameter, so it is left to > default and thus iet does not declare it. but core-ini does not use > default value 8192 as the maxrecvdsl for ini, i guess it uses what it > declared. Yep, that's rather likely. At least core-iscsi 1.6.2.2 had this bug: http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 Skimming through the changelogs of 1.6.2.{3,4}, it doesn't look as if it has been fixed. Nicholas? Arne -- Arne Redlich Xiranet Communications GmbH |
From: Ming Z. <mi...@el...> - 2006-03-28 15:52:28
|
On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich wrote: > Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb Ming Zhang: > > @Arne, could you help me to check this as well. > > > > i guess ietd.conf does not contain this parameter, so it is left to > > default and thus iet does not declare it. but core-ini does not use > > default value 8192 as the maxrecvdsl for ini, i guess it uses what it > > declared. > > Yep, that's rather likely. At least core-iscsi 1.6.2.2 had this bug: > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > Skimming through the changelogs of 1.6.2.{3,4}, it doesn't look as if it > has been fixed. Nicholas? thanks for pointing out this. :P > > Arne |
From: Rik H. <rik...@ya...> - 2006-03-28 17:26:07
Attachments:
log2
|
Hi, I modified it and set it to 16384 as requested. I attached the tcpdump of the login process. I also still get the too lond messages and the dd takes a realy long time. Running top shows istd1 using 99.9% of CPU usage. A sample follows of the lond data messages follows: Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data 9f 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a0 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a1 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a2 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a3 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a4 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a5 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a6 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a7 65536 8192 --- Ming Zhang <mi...@el...> wrote: > On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich > wrote: > > Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb > Ming Zhang: > > > @Arne, could you help me to check this as well. > > > > > > i guess ietd.conf does not contain this > parameter, so it is left to > > > default and thus iet does not declare it. but > core-ini does not use > > > default value 8192 as the maxrecvdsl for ini, i > guess it uses what it > > > declared. > > > > Yep, that's rather likely. At least core-iscsi > 1.6.2.2 had this bug: > > > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > > > Skimming through the changelogs of 1.6.2.{3,4}, it > doesn't look as if it > > has been fixed. Nicholas? > > thanks for pointing out this. :P > > > > > Arne > > __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Ming Z. <mi...@el...> - 2006-03-28 17:43:32
|
On Tue, 2006-03-28 at 09:25 -0800, Rik Herrin wrote: > Hi, > > I modified it and set it to 16384 as requested. I > attached the tcpdump of the login process. I also > still get the too lond messages and the dd takes a > realy long time. Running top shows istd1 using 99.9% > of CPU usage. A sample follows of the lond data > messages follows: > > Mar 28 19:50:35 localhost kernel: > check_segment_length(1552) too lond data 9f 65536 8192 this is still 8192. i thought i will see 16384 here. could u post us u ietd.conf here? seems that parameter is not used at all. > Mar 28 19:50:35 localhost kernel: > check_segment_length(1552) too lond data a0 65536 8192 > Mar 28 19:50:35 localhost kernel: > check_segment_length(1552) too lond data a1 65536 8192 > Mar 28 19:50:35 localhost kernel: > check_segment_length(1552) too lond data a2 65536 8192 > Mar 28 19:50:35 localhost kernel: > check_segment_length(1552) too lond data a3 65536 8192 > Mar 28 19:50:36 localhost kernel: > check_segment_length(1552) too lond data a4 65536 8192 > Mar 28 19:50:36 localhost kernel: > check_segment_length(1552) too lond data a5 65536 8192 > Mar 28 19:50:36 localhost kernel: > check_segment_length(1552) too lond data a6 65536 8192 > Mar 28 19:50:36 localhost kernel: > check_segment_length(1552) too lond data a7 65536 8192 > > > --- Ming Zhang <mi...@el...> wrote: > > > On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich > > wrote: > > > Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb > > Ming Zhang: > > > > @Arne, could you help me to check this as well. > > > > > > > > i guess ietd.conf does not contain this > > parameter, so it is left to > > > > default and thus iet does not declare it. but > > core-ini does not use > > > > default value 8192 as the maxrecvdsl for ini, i > > guess it uses what it > > > > declared. > > > > > > Yep, that's rather likely. At least core-iscsi > > 1.6.2.2 had this bug: > > > > > > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > > > > > Skimming through the changelogs of 1.6.2.{3,4}, it > > doesn't look as if it > > > has been fixed. Nicholas? > > > > thanks for pointing out this. :P > > > > > > > > Arne > > > > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-28 18:13:37
|
Ming, Here's my ietd.conf. When you told me to set it to 16384, were you referring to ietd.conf or /etc/sysconfig/initiator? I took it to refer to /etc/sysconfig/initiator so I left my ietd.conf as it was: IncomingUser OutgoingUser Target iqn.2001-04.com.example:storage.disk2.sys1.xyz IncomingUser OutgoingUser # Logical Unit definition # You must define one logical unit at least. # Block devices, regular files, LVM, and RAID can be offered # to the initiators as a block device. Lun 0 Path=/dev/md0,Type=fileio #Lun 1 Path=/dev/sda7,Type=fileio #Lun 2 Path=/dev/sda8,Type=fileio #Lun 3 Path=/dev/sda9,Type=fileio #Lun 4 Path=/dev/sda10,Type=fileio # Alias name for this target # Alias Test # various iSCSI parameters # (not all are used right now, see also iSCSI spec for details) #MaxConnections 1 #InitialR2T Yes #ImmediateData No #MaxRecvDataSegmentLength 8192 #MaxXmitDataSegmentLength 8192 #MaxBurstLength 262144 #FirstBurstLength 65536 #DefaultTime2Wait 2 #DefaultTime2Retain 20 #MaxOutstandingR2T 8 #DataPDUInOrder Yes #DataSequenceInOrder Yes #ErrorRecoveryLevel 0 #HeaderDigest CRC32C,None #DataDigest CRC32C,None # various target parameters #Wthreads 8 Regards, Rik... --- Ming Zhang <mi...@el...> wrote: > On Tue, 2006-03-28 at 09:25 -0800, Rik Herrin wrote: > > Hi, > > > > I modified it and set it to 16384 as requested. I > > attached the tcpdump of the login process. I also > > still get the too lond messages and the dd takes a > > realy long time. Running top shows istd1 using > 99.9% > > of CPU usage. A sample follows of the lond data > > messages follows: > > > > Mar 28 19:50:35 localhost kernel: > > check_segment_length(1552) too lond data 9f 65536 > 8192 > > this is still 8192. i thought i will see 16384 here. > could u post us u > ietd.conf here? seems that parameter is not used at > all. > > > > > Mar 28 19:50:35 localhost kernel: > > check_segment_length(1552) too lond data a0 65536 > 8192 > > Mar 28 19:50:35 localhost kernel: > > check_segment_length(1552) too lond data a1 65536 > 8192 > > Mar 28 19:50:35 localhost kernel: > > check_segment_length(1552) too lond data a2 65536 > 8192 > > Mar 28 19:50:35 localhost kernel: > > check_segment_length(1552) too lond data a3 65536 > 8192 > > Mar 28 19:50:36 localhost kernel: > > check_segment_length(1552) too lond data a4 65536 > 8192 > > Mar 28 19:50:36 localhost kernel: > > check_segment_length(1552) too lond data a5 65536 > 8192 > > Mar 28 19:50:36 localhost kernel: > > check_segment_length(1552) too lond data a6 65536 > 8192 > > Mar 28 19:50:36 localhost kernel: > > check_segment_length(1552) too lond data a7 65536 > 8192 > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich > > > wrote: > > > > Am Dienstag, den 28.03.2006, 10:04 -0500 > schrieb > > > Ming Zhang: > > > > > @Arne, could you help me to check this as > well. > > > > > > > > > > i guess ietd.conf does not contain this > > > parameter, so it is left to > > > > > default and thus iet does not declare it. > but > > > core-ini does not use > > > > > default value 8192 as the maxrecvdsl for > ini, i > > > guess it uses what it > > > > > declared. > > > > > > > > Yep, that's rather likely. At least core-iscsi > > > 1.6.2.2 had this bug: > > > > > > > > > > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > > > > > > > Skimming through the changelogs of > 1.6.2.{3,4}, it > > > doesn't look as if it > > > > has been fixed. Nicholas? > > > > > > thanks for pointing out this. :P > > > > > > > > > > > Arne > > > > > > > > > > __________________________________________________ > > Do You Yahoo!? > > Tired of spam? Yahoo! Mail has the best spam > protection around > > http://mail.yahoo.com > > __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Arne R. <ag...@po...> - 2006-03-28 18:27:09
|
Am Dienstag, den 28.03.2006, 10:13 -0800 schrieb Rik Herrin: > Ming, > Here's my ietd.conf. When you told me to set it to > 16384, were you referring to ietd.conf or > /etc/sysconfig/initiator? I took it to refer to > /etc/sysconfig/initiator so I left my ietd.conf as it > was: Ming was referring to ietd.conf. Judging from the trace and IETs error message, setting it on the initiator side has failed anyway - it's still declaring 128k during login and trying to send 65k SCSI data. Arne |
From: Ming Z. <mi...@el...> - 2006-03-28 18:35:59
|
sorry for confusing. Arne was correct. On Tue, 2006-03-28 at 10:13 -0800, Rik Herrin wrote: > Ming, > Here's my ietd.conf. When you told me to set it to > 16384, were you referring to ietd.conf or > /etc/sysconfig/initiator? I took it to refer to > /etc/sysconfig/initiator so I left my ietd.conf as it > was: > > IncomingUser > OutgoingUser also remove these 2 lines. if u do not want to use chap. then do not use these 2 line at all. > Target iqn.2001-04.com.example:storage.disk2.sys1.xyz > IncomingUser > OutgoingUser same here > # Logical Unit definition > # You must define one logical unit at least. > # Block devices, regular files, LVM, and RAID > can be offered > # to the initiators as a block device. > Lun 0 Path=/dev/md0,Type=fileio > #Lun 1 Path=/dev/sda7,Type=fileio > #Lun 2 Path=/dev/sda8,Type=fileio > #Lun 3 Path=/dev/sda9,Type=fileio > #Lun 4 Path=/dev/sda10,Type=fileio > # Alias name for this target > # Alias Test > # various iSCSI parameters > # (not all are used right now, see also iSCSI > spec for details) > #MaxConnections 1 > #InitialR2T Yes > #ImmediateData No > #MaxRecvDataSegmentLength 8192 ~~i mean here > #MaxXmitDataSegmentLength 8192 > #MaxBurstLength 262144 > #FirstBurstLength 65536 > #DefaultTime2Wait 2 > #DefaultTime2Retain 20 > #MaxOutstandingR2T 8 > #DataPDUInOrder Yes > #DataSequenceInOrder Yes > #ErrorRecoveryLevel 0 > #HeaderDigest CRC32C,None > #DataDigest CRC32C,None > # various target parameters > #Wthreads 8 > > Regards, > Rik... > > > --- Ming Zhang <mi...@el...> wrote: > > > On Tue, 2006-03-28 at 09:25 -0800, Rik Herrin wrote: > > > Hi, > > > > > > I modified it and set it to 16384 as requested. I > > > attached the tcpdump of the login process. I also > > > still get the too lond messages and the dd takes a > > > realy long time. Running top shows istd1 using > > 99.9% > > > of CPU usage. A sample follows of the lond data > > > messages follows: > > > > > > Mar 28 19:50:35 localhost kernel: > > > check_segment_length(1552) too lond data 9f 65536 > > 8192 > > > > this is still 8192. i thought i will see 16384 here. > > could u post us u > > ietd.conf here? seems that parameter is not used at > > all. > > > > > > > > > Mar 28 19:50:35 localhost kernel: > > > check_segment_length(1552) too lond data a0 65536 > > 8192 > > > Mar 28 19:50:35 localhost kernel: > > > check_segment_length(1552) too lond data a1 65536 > > 8192 > > > Mar 28 19:50:35 localhost kernel: > > > check_segment_length(1552) too lond data a2 65536 > > 8192 > > > Mar 28 19:50:35 localhost kernel: > > > check_segment_length(1552) too lond data a3 65536 > > 8192 > > > Mar 28 19:50:36 localhost kernel: > > > check_segment_length(1552) too lond data a4 65536 > > 8192 > > > Mar 28 19:50:36 localhost kernel: > > > check_segment_length(1552) too lond data a5 65536 > > 8192 > > > Mar 28 19:50:36 localhost kernel: > > > check_segment_length(1552) too lond data a6 65536 > > 8192 > > > Mar 28 19:50:36 localhost kernel: > > > check_segment_length(1552) too lond data a7 65536 > > 8192 > > > > > > > > > --- Ming Zhang <mi...@el...> wrote: > > > > > > > On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich > > > > wrote: > > > > > Am Dienstag, den 28.03.2006, 10:04 -0500 > > schrieb > > > > Ming Zhang: > > > > > > @Arne, could you help me to check this as > > well. > > > > > > > > > > > > i guess ietd.conf does not contain this > > > > parameter, so it is left to > > > > > > default and thus iet does not declare it. > > but > > > > core-ini does not use > > > > > > default value 8192 as the maxrecvdsl for > > ini, i > > > > guess it uses what it > > > > > > declared. > > > > > > > > > > Yep, that's rather likely. At least core-iscsi > > > > 1.6.2.2 had this bug: > > > > > > > > > > > > > > > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > > > > > > > > > Skimming through the changelogs of > > 1.6.2.{3,4}, it > > > > doesn't look as if it > > > > > has been fixed. Nicholas? > > > > > > > > thanks for pointing out this. :P > > > > > > > > > > > > > > Arne > > > > > > > > > > > > > > __________________________________________________ > > > Do You Yahoo!? > > > Tired of spam? Yahoo! Mail has the best spam > > protection around > > > http://mail.yahoo.com > > > > > > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com |
From: Rik H. <rik...@ya...> - 2006-03-28 17:29:02
Attachments:
log2
|
Hi, I modified it and set it to 16384 as requested. I attached the tcpdump of the login process. I also still get the too lond messages and the dd takes a realy long time. Running top shows istd1 using 99.9% of CPU usage. A sample follows of the lond data messages follows: Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data 9f 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a0 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a1 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a2 65536 8192 Mar 28 19:50:35 localhost kernel: check_segment_length(1552) too lond data a3 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a4 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a5 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a6 65536 8192 Mar 28 19:50:36 localhost kernel: check_segment_length(1552) too lond data a7 65536 8192 --- Ming Zhang <mi...@el...> wrote: > On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich > wrote: > > Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb > Ming Zhang: > > > @Arne, could you help me to check this as well. > > > > > > i guess ietd.conf does not contain this > parameter, so it is left to > > > default and thus iet does not declare it. but > core-ini does not use > > > default value 8192 as the maxrecvdsl for ini, i > guess it uses what it > > > declared. > > > > Yep, that's rather likely. At least core-iscsi > 1.6.2.2 had this bug: > > > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > > > Skimming through the changelogs of 1.6.2.{3,4}, it > doesn't look as if it > > has been fixed. Nicholas? > > thanks for pointing out this. :P > > > > > Arne > > __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com |
From: Nicholas A. B. <na...@ke...> - 2006-03-30 19:15:21
|
Greetings Arne, Sorry for the delay on this, I have been backlogged recently.. On Tue, 2006-03-28 at 17:44 +0200, Arne Redlich wrote: > Am Dienstag, den 28.03.2006, 10:04 -0500 schrieb Ming Zhang: > > @Arne, could you help me to check this as well. > > > > i guess ietd.conf does not contain this parameter, so it is left to > > default and thus iet does not declare it. but core-ini does not use > > default value 8192 as the maxrecvdsl for ini, i guess it uses what it > > declared. > > Yep, that's rather likely. At least core-iscsi 1.6.2.2 had this bug: > http://groups.google.com/group/Core-iSCSI/browse_frm/thread/a0b66ade9417b738/79c039a6a2f7a940#79c039a6a2f7a940 > > Skimming through the changelogs of 1.6.2.{3,4}, it doesn't look as if it > has been fixed. Nicholas? > Correct, I was waiting for a bit of additional feedback when the patch was originally posted by Tony Battersby a few months back, and Bill Studenmund recently gave a confirmation on this. I have not applied the patch in its current form (because it was using CPP defines) but I will take a look at saving both sides declared values and using these instead of CONN_OPS(conn)->MaxRecvDataSegmentLength in the transmit cases. Thanks for the heads up on this! -- Nicholas A. Bellinger <na...@ke...> |