Hi all
While building a NAS/SAN server for a local video production company I stumbled
on a couple of issues and errors. It seems that MaxConnections is not
enforced and
MC/S is broken in every target version that I tried when using a Win7 initiator.
With a linux initiator MC/S works as expected.
The show stopper issue in my current use case is bad performance when using 64k
direct I/O.
At first I assumed that Windows iSCSI initiator is broken (like most
things in windows).
In an effort to verify this I connected to the server using a linux
(fedora 20) initiator and the issue
persists. I have tested this using block and ramdisk backstores.
For example: direct i/o to an exported had disk partition is maxed at
around 48MB/s.
This was also verified by monitoring the network traffic.
With ramdisk or nullio backstores transfer maxes at around 60MB/s.
When using buffered i/o transfer speed is limited by 1G ethernet and
maxes at around
112MB/s.
Transfer speed of the hard drive (/dev/sdc6) on the server when using
64k direct i/o
is around 150MB/s.
The hard drive and the exported partition weren't utilized on the
server for anything
else (it's a spare disk for soft raid) and the server was idle.
Centos 7 was used, default kernels (RHEL 3.10 series) and also mainline 4.2.
Target engine versions 4.1 and 5.0
I have attached the target configuration and test outputs and also
errors produced
by target when MC/S is used with Windows initiator.
For easy viewing I also uploaded the attached file to pastebin:
http://pastebin.com/N2xVC8G5
Any ideas on what is causing this issue with direct i/o?
Thanks
Dragan
Server
======================================================================================================================================
/> ls
o- / ......................................................................................................................... [...]
o- backstores .............................................................................................................. [...]
| o- block .................................................................................................. [Storage Objects: 2]
| | o- lv0 ................................................................ [/dev/total_storage/lv4 (8.0GiB) write-thru activated]
| | o- pv0 ............................................................................ [/dev/sdc6 (24.0GiB) write-thru activated]
| o- fileio ................................................................................................. [Storage Objects: 0]
| o- pscsi .................................................................................................. [Storage Objects: 0]
| o- ramdisk ................................................................................................ [Storage Objects: 2]
| o- rd0 .................................................................................................. [(4.0GiB) activated]
| o- rd1 .......................................................................................... [nullio (16.0GiB) activated]
o- iscsi ............................................................................................................ [Targets: 1]
| o- iqn.2015-09.com.total-adv.local.storage:iscsi ..................................................................... [TPGs: 1]
| o- tpg1 ............................................................................................... [no-gen-acls, no-auth]
| o- acls .......................................................................................................... [ACLs: 1]
| | o- iqn.2015-09.com.total-adv.local.storage:staletic ..................................................... [Mapped LUNs: 4]
| | o- mapped_lun0 ................................................................................... [lun0 block/pv0 (rw)]
| | o- mapped_lun1 ................................................................................... [lun1 block/lv0 (rw)]
| | o- mapped_lun2 ................................................................................. [lun2 ramdisk/rd0 (rw)]
| | o- mapped_lun3 ................................................................................. [lun3 ramdisk/rd1 (rw)]
| o- luns .......................................................................................................... [LUNs: 4]
| | o- lun0 .......................................................................................... [block/pv0 (/dev/sdc6)]
| | o- lun1 ............................................................................. [block/lv0 (/dev/total_storage/lv4)]
| | o- lun2 .................................................................................................... [ramdisk/rd0]
| | o- lun3 .................................................................................................... [ramdisk/rd1]
| o- portals .................................................................................................... [Portals: 1]
| o- 0.0.0.0:3260 ..................................................................................................... [OK]
o- loopback ......................................................................................................... [Targets: 0]
-----------------------------
[root@storage ~]# uname -a
Linux storage.local.total-adv.com 4.2.0-1.el7.elrepo.x86_64 #1 SMP Sun Aug 30 21:25:29 EDT 2015 x86_64 x86_64 x86_64 GNU/Linux
-----------------------------
[root@storage ~]# cat /sys/kernel/config/target/version
Target Engine Core ConfigFS Infrastructure v5.0 on Linux/x86_64 on 4.2.0-1.el7.elrepo.x86_64
-----------------------------
[root@storage ~]# dd_rescue -ADv -m 16G -b 64k /dev/zero /dev/sdc6
dd_rescue: (info): Using softbs=64.0kiB, hardbs=4.0kiB
dd_rescue: (warning): We don't handle misalignment of last block w/ O_DIRECT!
dd_rescue: (info): turning on repeat (-R) for /dev/zero
dd_rescue: (info): about to transfer 16777216.0 kiBytes from /dev/zero to /dev/sdc6
dd_rescue: (info): blocksizes: soft 65536, hard 4096
dd_rescue: (info): starting positions: in 0.0kiB, out dd_rescue: (info): Logfile: (none), Maxerr: 0
dd_rescue: (info): Reverse: no , Trunc: no, interactive: no
dd_rescue: (info): abort on Write errs: no , spArse write: never
dd_rescue: (info): preserve: no , splice: no , avoidWrite: no
dd_rescue: (info): fallocate: no , Repeat: yes, O_DIRECT: no /yes
dd_rescue: (info): ipos: 16765952.0k, opos: 16765952.0k, xferd: 16765952.0k
errs: 0, errxfer: 0.0k, succxfer: 16765952.0k
+curr.rate: 153299kB/s, avg.rate: 153440kB/s, avg.load: 2.0%
>----------------------------------------.< 99% ETA: 0:00:00
dd_rescue: (info): Summary for /dev/zero -> /dev/sdc6
dd_rescue: (info): ipos: 16777216.0k, opos: 16777216.0k, xferd: 16777216.0k
errs: 0, errxfer: 0.0k, succxfer: 16777216.0k
+curr.rate: 132995kB/s, avg.rate: 153324kB/s, avg.load: 2.0%
>-----------------------------------------< 100% TOT: 0:01:49
Client
======================================================================================================================================
[root@localhost ~]# lsscsi | grep "LIO"
[11:0:0:0] disk LIO-ORG pv0 4.0 /dev/sdc
[11:0:0:1] disk LIO-ORG lv0 4.0 /dev/sdf
[11:0:0:2] disk LIO-ORG rd0 4.0 /dev/sde
[11:0:0:3] disk LIO-ORG rd1 4.0 /dev/sdd
-----------------------------
[root@localhost ~]# dd_rescue -ADv -m 16G -b 64k /dev/zero /dev/sdc
dd_rescue: (info): Using softbs=64.0kiB, hardbs=4.0kiB
dd_rescue: (warning): We don't handle misalignment of last block w/ O_DIRECT!
dd_rescue: (info): turning on repeat (-R) for /dev/zero
dd_rescue: (info): about to transfer 16777216.0 kiBytes from /dev/zero to /dev/sdc
dd_rescue: (info): blocksizes: soft 65536, hard 4096
dd_rescue: (info): starting positions: in 0.0kiB, out dd_rescue: (info): Logfile: (none), Maxerr: 0
dd_rescue: (info): Reverse: no , Trunc: no, interactive: no
dd_rescue: (info): abort on Write errs: no , spArse write: never
dd_rescue: (info): preserve: no , splice: no , avoidWrite: no
dd_rescue: (info): fallocate: no , Repeat: yes, O_DIRECT: no /yes
dd_rescue: (info): ipos: 16773120.0k, opos: 16773120.0k, xferd: 16773120.0k
errs: 0, errxfer: 0.0k, succxfer: 16773120.0k
+curr.rate: 48464kB/s, avg.rate: 48443kB/s, avg.load: 3.3%
>----------------------------------------.< 99% ETA: 0:00:00
dd_rescue: (info): Summary for /dev/zero -> /dev/sdc
dd_rescue: (info): ipos: 16777216.0k, opos: 16777216.0k, xferd: 16777216.0k
errs: 0, errxfer: 0.0k, succxfer: 16777216.0k
+curr.rate: 45179kB/s, avg.rate: 48439kB/s, avg.load: 3.3%
>-----------------------------------------< 100% TOT: 0:05:46
-----------------------------
[root@localhost ~]# dd_rescue -ADv -m 4G -b 64k /dev/zero /dev/sdd
dd_rescue: (info): Using softbs=64.0kiB, hardbs=4.0kiB
dd_rescue: (warning): We don't handle misalignment of last block w/ O_DIRECT!
dd_rescue: (info): turning on repeat (-R) for /dev/zero
dd_rescue: (info): about to transfer 4194304.0 kiBytes from /dev/zero to /dev/sdd
dd_rescue: (info): blocksizes: soft 65536, hard 4096
dd_rescue: (info): starting positions: in 0.0kiB, out dd_rescue: (info): Logfile: (none), Maxerr: 0
dd_rescue: (info): Reverse: no , Trunc: no, interactive: no
dd_rescue: (info): abort on Write errs: no , spArse write: never
dd_rescue: (info): preserve: no , splice: no , avoidWrite: no
dd_rescue: (info): fallocate: no , Repeat: yes, O_DIRECT: no /yes
dd_rescue: (info): ipos: 4191232.0k, opos: 4191232.0k, xferd: 4191232.0k
errs: 0, errxfer: 0.0k, succxfer: 4191232.0k
+curr.rate: 62343kB/s, avg.rate: 62376kB/s, avg.load: 4.6%
>----------------------------------------.< 99% ETA: 0:00:00
dd_rescue: (info): Summary for /dev/zero -> /dev/sdd
dd_rescue: (info): ipos: 4194304.0k, opos: 4194304.0k, xferd: 4194304.0k
errs: 0, errxfer: 0.0k, succxfer: 4194304.0k
+curr.rate: 61934kB/s, avg.rate: 62375kB/s, avg.load: 4.6%
>-----------------------------------------< 100% TOT: 0:01:07
-----------------------------
[root@localhost ~]# dd_rescue -ADv -m 4G -b 64k /dev/zero /dev/sde
dd_rescue: (info): Using softbs=64.0kiB, hardbs=4.0kiB
dd_rescue: (warning): We don't handle misalignment of last block w/ O_DIRECT!
dd_rescue: (info): turning on repeat (-R) for /dev/zero
dd_rescue: (info): about to transfer 4194304.0 kiBytes from /dev/zero to /dev/sde
dd_rescue: (info): blocksizes: soft 65536, hard 4096
dd_rescue: (info): starting positions: in 0.0kiB, out dd_rescue: (info): Logfile: (none), Maxerr: 0
dd_rescue: (info): Reverse: no , Trunc: no, interactive: no
dd_rescue: (info): abort on Write errs: no , spArse write: never
dd_rescue: (info): preserve: no , splice: no , avoidWrite: no
dd_rescue: (info): fallocate: no , Repeat: yes, O_DIRECT: no /yes
dd_rescue: (info): ipos: 4188160.0k, opos: 4188160.0k, xferd: 4188160.0k
errs: 0, errxfer: 0.0k, succxfer: 4188160.0k
+curr.rate: 62515kB/s, avg.rate: 61642kB/s, avg.load: 4.8%
>----------------------------------------.< 99% ETA: 0:00:00
dd_rescue: (info): Summary for /dev/zero -> /dev/sde
dd_rescue: (info): ipos: 4194304.0k, opos: 4194304.0k, xferd: 4194304.0k
errs: 0, errxfer: 0.0k, succxfer: 4194304.0k
+curr.rate: 62403kB/s, avg.rate: 61643kB/s, avg.load: 4.8%
>-----------------------------------------< 100% TOT: 0:01:08
Buffered I/O
-----------------------------
[root@localhost ~]# dd_rescue -Av -m 16G -b 64k /dev/zero /dev/sdc
dd_rescue: (info): Using softbs=64.0kiB, hardbs=4.0kiB
dd_rescue: (info): turning on repeat (-R) for /dev/zero
dd_rescue: (info): about to transfer 16777216.0 kiBytes from /dev/zero to /dev/sdc
dd_rescue: (info): blocksizes: soft 65536, hard 4096
dd_rescue: (info): starting positions: in 0.0kiB, out dd_rescue: (info): Logfile: (none), Maxerr: 0
dd_rescue: (info): Reverse: no , Trunc: no, interactive: no
dd_rescue: (info): abort on Write errs: no , spArse write: never
dd_rescue: (info): preserve: no , splice: no , avoidWrite: no
dd_rescue: (info): fallocate: no , Repeat: yes, O_DIRECT: no /no
dd_rescue: (info): ipos: 16776192.0k, opos: 16776192.0k, xferd: 16776192.0k
errs: 0, errxfer: 0.0k, succxfer: 16776192.0k
+curr.rate: 115223kB/s, avg.rate: 136634kB/s, avg.load: 14.7%
>----------------------------------------.< 99% ETA: 0:00:00
dd_rescue: (info): Summary for /dev/zero -> /dev/sdc
dd_rescue: (info): ipos: 16777216.0k, opos: 16777216.0k, xferd: 16777216.0k
errs: 0, errxfer: 0.0k, succxfer: 16777216.0k
+curr.rate: 86427kB/s, avg.rate: 112677kB/s, avg.load: 12.5%
>-----------------------------------------< 100% TOT: 0:02:29
4.2.0-1.el7.elrepo.x86_64 MC/S Win 7 Initiator
======================================================================================================================================
Sep 17 02:08:08 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:08 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:14 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:14 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:20 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:20 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:26 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:26 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:32 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:32 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:38 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:38 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:44 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:44 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
Sep 17 02:08:50 storage kernel: Got unknown iSCSI OpCode: 0x43
Sep 17 02:08:50 storage kernel: Cannot recover from unknown opcode while ERL=0, closing iSCSI connection.
3.10.0-229.14.1.el7.x86_64 MC/S Win 7 Initiator
======================================================================================================================================
Sep 17 02:25:04 storage kernel: ------------[ cut here ]------------
Sep 17 02:25:04 storage kernel: WARNING: at mm/page_alloc.c:2477 __alloc_pages_nodemask+0x46a/0xb90()
Sep 17 02:25:04 storage kernel: Modules linked in: target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_mod bonding vfat fat ext4 mbcache jbd2 kvm_amd kvm crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel lrw eeepc_wmi asus_wmi gf128mul glue_helper sparse_keymap rfkill ablk_helper cryptd sp5100_tco tpm_infineon fam15h_power pcspkr k10temp serio_raw edac_mce_amd edac_core i2c_piix4 shpchp acpi_cpufreq xfs libcrc32c raid1 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq sd_mod crc_t10dif crct10dif_common nouveau video i2c_algo_bit drm_kms_helper ttm mxm_wmi r8169 mii drm e1000e ahci libahci i2c_core libata mpt2sas ptp raid_class pps_core scsi_transport_sas wmi dm_mirror dm_region_hash dm_log dm_mod
Sep 17 02:25:04 storage kernel: CPU: 5 PID: 2039 Comm: iscsi_np Not tainted 3.10.0-229.14.1.el7.x86_64 #1
Sep 17 02:25:04 storage kernel: Hardware name: To be filled by O.E.M. To be filled by O.E.M./M5A99FX PRO R2.0, BIOS 2501 04/07/2014
Sep 17 02:25:04 storage kernel: 0000000000000000 0000000046689ffd ffff88023092faa8 ffffffff81604516
Sep 17 02:25:04 storage kernel: ffff88023092fae0 ffffffff8106e29b 000000000012c0d0 0000000000000000
Sep 17 02:25:04 storage kernel: 000000000010c0d0 0000000000000000 0000000000000000 ffff88023092faf0
Sep 17 02:25:04 storage kernel: Call Trace:
Sep 17 02:25:04 storage kernel: [<ffffffff81604516>] dump_stack+0x19/0x1b
Sep 17 02:25:04 storage kernel: [<ffffffff8106e29b>] warn_slowpath_common+0x6b/0xb0
Sep 17 02:25:04 storage kernel: [<ffffffff8106e3ea>] warn_slowpath_null+0x1a/0x20
Sep 17 02:25:04 storage kernel: [<ffffffff8116080a>] __alloc_pages_nodemask+0x46a/0xb90
Sep 17 02:25:04 storage kernel: [<ffffffff813b5ec2>] ? __mix_pool_bytes+0x42/0x90
Sep 17 02:25:04 storage kernel: [<ffffffff813b6a81>] ? extract_buf+0xc1/0x190
Sep 17 02:25:04 storage kernel: [<ffffffff8119f3a9>] alloc_pages_current+0xa9/0x170
Sep 17 02:25:04 storage kernel: [<ffffffff8115b53e>] __get_free_pages+0xe/0x50
Sep 17 02:25:04 storage kernel: [<ffffffff811aa13e>] kmalloc_order_trace+0x2e/0xa0
Sep 17 02:25:04 storage kernel: [<ffffffff811ac9d9>] __kmalloc+0x219/0x230
Sep 17 02:25:04 storage kernel: [<ffffffffa07194f0>] iscsi_decode_text_input+0x50/0x9b0 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffff811ae405>] ? __kmalloc_track_caller+0x55/0x230
Sep 17 02:25:04 storage kernel: [<ffffffffa0718e28>] ? iscsi_update_param_value+0x28/0x80 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffffa0725c7c>] iscsi_target_start_negotiation+0x24c/0x650 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffffa0718e28>] ? iscsi_update_param_value+0x28/0x80 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffffa07237ed>] __iscsi_target_login_thread+0x7bd/0x1580 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffffa0724ec0>] ? iscsit_put_login_tx+0x30/0x30 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffffa0724ee8>] iscsi_target_login_thread+0x28/0x40 [iscsi_target_mod]
Sep 17 02:25:04 storage kernel: [<ffffffff8109727f>] kthread+0xcf/0xe0
Sep 17 02:25:04 storage kernel: [<ffffffff810971b0>] ? kthread_create_on_node+0x140/0x140
Sep 17 02:25:04 storage kernel: [<ffffffff816142d8>] ret_from_fork+0x58/0x90
Sep 17 02:25:04 storage kernel: [<ffffffff810971b0>] ? kthread_create_on_node+0x140/0x140
Sep 17 02:25:04 storage kernel: ---[ end trace 897b13ab9ef7aa9a ]---
Sep 17 02:25:04 storage kernel: Unable to allocate memory for tmpbuf.
Sep 17 02:25:04 storage kernel: iSCSI Login negotiation failed.
