[OmniOS-discuss] zpool import with iSCSI vdevs hangs on ioctl-syscall w/cmd 5a06
Harald Paier
hp at pawaq.at
Wed Jun 1 10:21:43 UTC 2016
Hello,
I find strange behavior of zpool import when accessing a pool via iscsi: It either completes quickly, takes 61-72 s or 121-127 s.
Using dtrace I found 2 ioctl syscalls (fd = 3, cmd = 5a06, arg = 804237c) which either return quickly (< 10 s) or take about 60 s.
I have no idea what ioctl command 5a06 is supposed to do or even where to look for that information.
While the ioctl command hangs there is no CPU load on both head and backends (idle 99-100%).
I don't think there is any dependency on the number of devices in the pool, because there are always 2 ioctl-5a06 syscalls.
Also during zpool import a lot of SCSI errors are reported in fmdump, but I do not see any difference whether or not the affected ioctls run normally. No SCSI errors occur during the hanging ioctls.
The reported errors are either generic write errors (key 0x3 asc 0xc ascq 0x0) or bus resets (key 0x6 asc 0x29 ascq 0x0).
There are no SCSI errors once the pool is imported and used for normal IO.
On the backends there are no errors reported in fmdump and no problems with long running syscalls.
I also tried the following without any success:
- Run the tests in both stable (r151014) and bloody (20160422) release.
- Configure target-params timeout of the initiator to 3 seconds
- Reconfigure io_time and retries of the sd driver to 3 s / 1 retry.
Any help to find/resolve the root cause of those sysctl hangs would be greatly appreciated.
Kind Regards
harald
My test setups are:
A: VMware Workstation 12 (laptop with i7 at 2.5GHz, 16GB RAM, fast SSD disk):
- 3 backends with 768MB RAM, 1 vCPU, stable release (r151014)
- 1 head with 2GB RAM, 1 vCPU, stable release (r151014)
- 1 alternative head with 2GB RAM, 1 vCPU, bloody release (20160422)
B: VMware ESXi 6 (server with E5620 at 2.4GHz, 24GB RAM, RAID 0 over 3 300GB 15K SAS disks)
- 3 backends with 1GB RAM, 1 vCPU, stable release (r151014)
- 1 head with 6GB RAM, 2 vCPU, stable release (r151014)
Each backend presents 2 virtual disks as LUNs.
On the head I have created a zpool consiting of 2 raidz1 vdevs spanning the backends:
pool: pool1
id: 12810568181218589176
state: ONLINE
status: Some supported features are not enabled on the pool.
action: The pool can be imported using its name or numeric identifier, though
some features will not be available without an explicit 'zpool upgrade'.
config:
pool1 ONLINE
raidz1-0 ONLINE
c3t600144F03AB7625F00005723BE320001d0 ONLINE
c3t600144F03AB7625F00005723BEFB0001d0 ONLINE
c3t600144F03AB7625F00005723BF1E0001d0 ONLINE
raidz1-1 ONLINE
c3t600144F03AB7625F00005723BE320002d0 ONLINE
c3t600144F03AB7625F00005723BEFB0002d0 ONLINE
c3t600144F03AB7625F00005723BF1E0002d0 ONLINE
There is no iSCSI authentication configured, no host or target groups are used.
I did run zpool import in a loop on both virtual setups using the following script:
for i in {1..100}; do
sudo dtrace -n '
syscall::ioctl:entry
/pid == $target/
{
self->ts = timestamp;
}
syscall::ioctl:return
/pid == $target && self->ts/
{
@time = sum(timestamp - self->ts);
self->ts = 0;
}
END
{
printa(@time);
}' -c "zpool import"
sleep 30;
done
After 100 test runs on 2 test setups I got 3 groups of runtimes:
- below 16 sec
- between 61 and 72 sec
- between 121 and 127 sec
Setup A B
Result <=16 s +1 min +2 min <=16 s +1 min +2 min
Count 36 49 15 53 38 9
Min 5.8 61.0 121.6 1.0 61.2 121.8
Max 15.9 71.9 126.9 11.2 71.3 127.0
Avg 10.8 66.6 122.4 4.2 65.3 123.1
StDev 0.9 0.9 0.7 2.7 2.1 1.1
Setup B is on faster hardware and does suffer less often from the problem.
But still there is something going very wrong here.
So I used dtrace to find out where the additional 1 or 2 minutes come from:
sudo dtrace -qn '
BEGIN
{
printf("\n");
}
syscall::ioctl:entry
/pid == $target/
{
self->ts = timestamp;
self->arg0 = arg0;
self->arg1 = arg1;
self->arg2 = arg2;
}
syscall::ioctl:return
/pid == $target && self->ts/
{
printf("time = %Y, fd = %d, cmd = %lx, arg = %lx, runtime %d s\n",
walltimestamp, self->arg0, self->arg1, self->arg2, (timestamp - self->ts) / 1000000000);
@time[probefunc] = lquantize((timestamp - self->ts) / 1000000000, 0, 180, 60);
self->ts = 0;
}
END
{
printa(@time);
}' -c "zpool import"
Example 1 (normal run):
fmdump output:
May 26 14:11:24.4887 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:24.5464 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:11:24.5464 ereport.io.scsi.cmd.disk.recovered
May 26 14:11:24.8359 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.dev.serr
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.dev.serr
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:11:24.8395 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:24.8397 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:24.9291 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.recovered
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.recovered
May 26 14:11:24.8366 ereport.io.scsi.cmd.disk.recovered
May 26 14:11:29.8392 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:11:29.8392 ereport.io.scsi.cmd.disk.dev.rqs.merr
dtrace output:
time = 2016 May 26 14:11:19, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 403, arg = fe2ce9cc, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:11:19, fd = 9, cmd = 403, arg = fe1cf9cc, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:11:19, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:11:19, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:11:24, fd = 3, cmd = 5a06, arg = 804237c, runtime 5 s
time = 2016 May 26 14:11:29, fd = 3, cmd = 5a06, arg = 804237c, runtime 5 s
time = 2016 May 26 14:11:29, fd = 1, cmd = 5401, arg = 8042bbe, runtime 0 s
time = 2016 May 26 14:11:29, fd = 3, cmd = 5a3f, arg = 80429d0, runtime 0 s
ioctl
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 40
60 | 0
Example 2 (2 additional minutes):
fmdump output:
May 26 14:13:27.6296 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:13:27.6395 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:13:27.6400 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:13:28.4369 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:13:28.4369 ereport.io.scsi.cmd.disk.recovered
May 26 14:14:27.8696 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:27.9694 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:27.9695 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:28.2196 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:28.2230 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:28.2235 ereport.io.scsi.cmd.disk.dev.serr
May 26 14:14:28.2235 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:14:28.2256 ereport.io.scsi.cmd.disk.dev.serr
May 26 14:14:28.3194 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:28.4767 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:14:28.4767 ereport.io.scsi.cmd.disk.recovered
May 26 14:14:28.2256 ereport.io.scsi.cmd.disk.recovered
May 26 14:14:28.2256 ereport.io.scsi.cmd.disk.recovered
May 26 14:14:28.2235 ereport.io.scsi.cmd.disk.recovered
May 26 14:14:33.2385 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:14:33.3183 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:15:28.8692 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:15:28.9333 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:15:28.9333 ereport.io.scsi.cmd.disk.recovered
dtrace output:
time = 2016 May 26 14:13:27, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 403, arg = fe2ce9cc, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:13:27, fd = 9, cmd = 403, arg = fe1cf9cc, runtime 0 s
time = 2016 May 26 14:13:27, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:13:27, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:13:27, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:14:28, fd = 3, cmd = 5a06, arg = 804237c, runtime 60 s
time = 2016 May 26 14:15:29, fd = 3, cmd = 5a06, arg = 804237c, runtime 61 s
time = 2016 May 26 14:15:29, fd = 1, cmd = 5401, arg = 8042bbe, runtime 0 s
time = 2016 May 26 14:15:29, fd = 3, cmd = 5a3f, arg = 80429d0, runtime 0 s
ioctl
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 38
60 |@@ 2
120 | 0
Example 3 (1 addional minute in first 0x5a06-ioctl):
fmdump output:
May 26 14:19:16.6490 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:19:16.7392 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:19:16.7393 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:19:16.7400 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:19:16.7401 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.0794 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.1439 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:20:17.1439 ereport.io.scsi.cmd.disk.recovered
May 26 14:20:17.4295 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.4303 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.4390 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.4457 ereport.io.scsi.cmd.disk.tran
May 26 14:20:17.4457 ereport.io.scsi.cmd.disk.tran
May 26 14:20:17.5292 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.4457 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:20:17.5394 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:20:17.4457 ereport.io.scsi.cmd.disk.recovered
May 26 14:20:17.4457 ereport.io.scsi.cmd.disk.recovered
May 26 14:20:17.6890 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:20:17.6890 ereport.io.scsi.cmd.disk.recovered
May 26 14:20:22.4392 ereport.io.scsi.cmd.disk.dev.rqs.merr
dtrace output:
time = 2016 May 26 14:19:16, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 403, arg = fe2ce9cc, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:19:16, fd = 9, cmd = 403, arg = fe1cf9cc, runtime 0 s
time = 2016 May 26 14:19:16, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:19:16, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:19:16, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:20:17, fd = 3, cmd = 5a06, arg = 804237c, runtime 60 s
time = 2016 May 26 14:20:22, fd = 3, cmd = 5a06, arg = 804237c, runtime 5 s
time = 2016 May 26 14:20:22, fd = 1, cmd = 5401, arg = 8042bbe, runtime 0 s
time = 2016 May 26 14:20:22, fd = 3, cmd = 5a3f, arg = 80429d0, runtime 0 s
ioctl
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
60 |@ 1
120 | 0
Example 4 (1 addional minute in second 0x5a06-ioctl):
fmdump output:
May 26 14:23:12.8093 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:12.8099 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:12.8099 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:17.8093 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:17.8094 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:17.9194 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:17.9383 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:23:17.9383 ereport.io.scsi.cmd.disk.recovered
May 26 14:23:18.2694 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:18.2893 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:18.2898 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:23:18.8060 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:23:18.8060 ereport.io.scsi.cmd.disk.recovered
May 26 14:23:23.3696 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:24:18.8897 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:24:18.9897 ereport.io.scsi.cmd.disk.dev.rqs.merr
May 26 14:24:19.0218 ereport.io.scsi.cmd.disk.dev.rqs.derr
May 26 14:24:19.0218 ereport.io.scsi.cmd.disk.recovered
dtrace output:
time = 2016 May 26 14:23:12, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 403, arg = fe2ce9cc, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 403, arg = fe1cf974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 42a, arg = fe1cf9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 417, arg = fe2ceb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 403, arg = fe2ce974, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 42a, arg = fe2ce9d0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 412, arg = fe1cf9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 417, arg = fe1cfb58, runtime 0 s
time = 2016 May 26 14:23:12, fd = 9, cmd = 403, arg = fe1cf9cc, runtime 0 s
time = 2016 May 26 14:23:12, fd = 8, cmd = 412, arg = fe2ce9b8, runtime 0 s
time = 2016 May 26 14:23:12, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:23:12, fd = 3, cmd = 5a05, arg = 80422f0, runtime 0 s
time = 2016 May 26 14:23:18, fd = 3, cmd = 5a06, arg = 804237c, runtime 5 s
time = 2016 May 26 14:24:19, fd = 3, cmd = 5a06, arg = 804237c, runtime 61 s
time = 2016 May 26 14:24:19, fd = 1, cmd = 5401, arg = 8042bbe, runtime 0 s
time = 2016 May 26 14:24:19, fd = 3, cmd = 5a3f, arg = 80429d0, runtime 0 s
ioctl
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
60 |@ 1
120 | 0
Configure target-params timeout of the initiator to 3 seconds:
sysadm at head1:/export/home/sysadm$ pfexec iscsiadm list target-param -v
Target: iqn.2010-08.org.illumos:02:74d64faf-ebe7-e811-c715-f427f6bd76f9
Alias: backend3
Bi-directional Authentication: disabled
Authentication Type: NONE
Login Parameters (Default/Configured):
Data Sequence In Order: yes/-
Data PDU In Order: yes/-
Default Time To Retain: 20/-
Default Time To Wait: 2/-
Error Recovery Level: 0/-
First Burst Length: 65536/-
Immediate Data: yes/-
Initial Ready To Transfer (R2T): yes/-
Max Burst Length: 262144/-
Max Outstanding R2T: 1/-
Max Receive Data Segment Length: 8192/-
Max Connections: 1/-
Header Digest: NONE/-
Data Digest: NONE/-
Tunable Parameters (Default/Configured):
Session Login Response Time: 60/3
Maximum Connection Retry Time: 180/3
Login Retry Time Interval: 60/3
Configured Sessions: 1
Target: iqn.2010-08.org.illumos:02:43ccef91-f911-4c16-c4df-8d99967c3a29
Alias: backend2
Bi-directional Authentication: disabled
Authentication Type: NONE
Login Parameters (Default/Configured):
Data Sequence In Order: yes/-
Data PDU In Order: yes/-
Default Time To Retain: 20/-
Default Time To Wait: 2/-
Error Recovery Level: 0/-
First Burst Length: 65536/-
Immediate Data: yes/-
Initial Ready To Transfer (R2T): yes/-
Max Burst Length: 262144/-
Max Outstanding R2T: 1/-
Max Receive Data Segment Length: 8192/-
Max Connections: 1/-
Header Digest: NONE/-
Data Digest: NONE/-
Tunable Parameters (Default/Configured):
Session Login Response Time: 60/3
Maximum Connection Retry Time: 180/3
Login Retry Time Interval: 60/3
Configured Sessions: 1
Target: iqn.2010-08.org.illumos:02:3e79a87e-125f-c11c-ef19-e30aa9d5fd54
Alias: backend1
Bi-directional Authentication: disabled
Authentication Type: NONE
Login Parameters (Default/Configured):
Data Sequence In Order: yes/-
Data PDU In Order: yes/-
Default Time To Retain: 20/-
Default Time To Wait: 2/-
Error Recovery Level: 0/-
First Burst Length: 65536/-
Immediate Data: yes/-
Initial Ready To Transfer (R2T): yes/-
Max Burst Length: 262144/-
Max Outstanding R2T: 1/-
Max Receive Data Segment Length: 8192/-
Max Connections: 1/-
Header Digest: NONE/-
Data Digest: NONE/-
Tunable Parameters (Default/Configured):
Session Login Response Time: 60/3
Maximum Connection Retry Time: 180/3
Login Retry Time Interval: 60/3
Configured Sessions: 1
Configure io_time and retries for the sd driver:
echo 'set sd:sd_io_time=3' >> /etc/system
echo 'sd-config-list = "SUN COMSTAR", "retries-timeout:1";' >> /kernel/drv/sd.conf
shutdown -i6 -g0 -y
Harald Paier
PAWAQ GmbH
+43 1 2365078 10
hp at pawaq.at - www.pawaq.com
Lerchenfelder Straße 36/2 - 1080 Wien - Austria - Fn312475y - ATU64308378 - office at pawaq.at - www.pawaq.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://omniosce.org/ml-archive/attachments/20160601/593a8c8e/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logo_pawaq_mail.png
Type: image/png
Size: 4964 bytes
Desc: not available
URL: <https://omniosce.org/ml-archive/attachments/20160601/593a8c8e/attachment-0004.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: PARTNER_SOLUTION_PROVIDER_ENT.png
Type: image/png
Size: 2551 bytes
Desc: not available
URL: <https://omniosce.org/ml-archive/attachments/20160601/593a8c8e/attachment-0005.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: PARTNER_SERVICE_PROVIDER_PRO.png
Type: image/png
Size: 4564 bytes
Desc: not available
URL: <https://omniosce.org/ml-archive/attachments/20160601/593a8c8e/attachment-0006.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: VCP-DCV-s.png
Type: image/png
Size: 3722 bytes
Desc: not available
URL: <https://omniosce.org/ml-archive/attachments/20160601/593a8c8e/attachment-0007.png>
More information about the OmniOS-discuss
mailing list