Project

General

Profile

Bug #63153

Separate ARC reclamation threads to prevent blocking disk I/O under heavy use

Added by Ryan McKenzie almost 3 years ago. Updated over 2 years ago.

Status:
Done
Priority:
Blocks Until Resolved
Assignee:
Alexander Motin
Category:
OS
Target version:
Seen in:
TrueNAS - TrueNAS 11.2
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
No
Needs Merging:
No
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

M40-HA running 11.2 nightly 12-03-2018
Seen on random and sequential iSCSI workloads, all read/write mixes, all dataset sizes
See more error messages and sometimes failover when using high client-side thread counts.

WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): waiting for CTL to terminate 1 tasks
WARNING: 172.27.0.87 (iqn.1994-05.com.redhat:9a61135a8492): no ping reply (NOP-Out) after 5 seconds; dropping connection
ctl_datamove: tag 0x001b on (0:5:1) aborted
ctl_datamove: tag 0x0017 on (0:5:0) aborted
WARNING: 172.27.0.87 (iqn.1994-05.com.redhat:9a61135a8492): waiting for CTL to terminate 3 tasks
ctl_datamove: tag 0x0079 on (0:6:2) aborted
ctl_datamove: tag 0x0021 on (0:5:2) aborted
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): tasks terminated
ctl_datamove: tag 0x006a on (0:8:2) aborted
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): tasks terminated
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.87 (iqn.1994-05.com.redhat:9a61135a8492): tasks terminated
ctl_datamove: tag 0x0056 on (0:7:1) aborted
ctl_datamove: tag 0x0058 on (0:7:2) aborted
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): tasks terminated
ctl_datamove: tag 0x0022 on (0:14:1) aborted
ctl_datamove: tag 0x0010 on (0:3:0) aborted
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): tasks terminated
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): tasks terminated
WARNING: 172.27.0.91 (iqn.1994-05.com.redhat:bde9f425e52): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.91 (iqn.1994-05.com.redhat:bde9f425e52): waiting for CTL to terminate 2 tasks
ctl_datamove: tag 0x0062 on (0:10:0) aborted
WARNING: 172.27.0.91 (iqn.1994-05.com.redhat:bde9f425e52): tasks terminated
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): tasks terminated
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): waiting for CTL to terminate 3 tasks
ctl_datamove: tag 0x10000078 on (0:8:0) aborted
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): tasks terminated
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): tasks terminated
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): waiting for CTL to terminate 7 tasks
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): waiting for CTL to terminate 7 tasks
ctl_datamove: tag 0x20000019 on (0:8:0) aborted
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): waiting for CTL to terminate 1 tasks
ctl_datamove: tag 0x10000024 on (0:12:2) aborted
ctl_datamove: tag 0x20000072 on (0:8:2) aborted
ctl_datamove: tag 0x20000028 on (0:5:1) aborted
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): tasks terminated
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): tasks terminated
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): tasks terminated
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): tasks terminated
WARNING: 172.27.0.92 (iqn.1994-05.com.redhat:24a1ae8819d5): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.92 (iqn.1994-05.com.redhat:24a1ae8819d5): waiting for CTL to terminate 1 tasks
WARNING: 172.27.0.92 (iqn.1994-05.com.redhat:24a1ae8819d5): tasks terminated

Associated revisions

Revision 70a12c4c (diff)
Added by Alexander Motin over 2 years ago

Reduce CTL threads priority to about PUSER. Since in most configurations CTL serves as network service, we found that this change improves local system interactivity under heavy load. Priority of main threads is set slightly higher then worker taskqueues to make them quickly sort incoming requests not creating bottlenecks, while plenty of worker taskqueues should be less sensitive to latency. MFC after: 1 week Sponsored by: iXsystems, Inc. Ticket: #63153 (cherry picked from commit 339ccac400e73da5b579d8586794b5cf2d6a5a04)

Revision 5e9bd9a4 (diff)
Added by Alexander Motin over 2 years ago

Reduce CTL threads priority to about PUSER. Since in most configurations CTL serves as network service, we found that this change improves local system interactivity under heavy load. Priority of main threads is set slightly higher then worker taskqueues to make them quickly sort incoming requests not creating bottlenecks, while plenty of worker taskqueues should be less sensitive to latency. MFC after: 1 week Sponsored by: iXsystems, Inc. Ticket: #63153 (cherry picked from commit 339ccac400e73da5b579d8586794b5cf2d6a5a04) (cherry picked from commit 70a12c4ca1a54af3c0f587b567e96ad78f7bab6f)

Revision fd62bea5 (diff)
Added by Alexander Motin over 2 years ago

MFV r336930: 9284 arc_reclaim_thread has 2 jobs `arc_reclaim_thread()` calls `arc_adjust()` after calling `arc_kmem_reap_now()`; `arc_adjust()` signals `arc_get_data_buf()` to indicate that we may no longer be `arc_is_overflowing()`. The problem is, `arc_kmem_reap_now()` can take several seconds to complete, has no impact on `arc_is_overflowing()`, but due to how the code is structured, can impact how long the ARC will remain in the `arc_is_overflowing()` state. The fix is to use seperate threads to: 1. keep `arc_size` under `arc_c`, by calling `arc_adjust()`, which improves `arc_is_overflowing()` 2. keep enough free memory in the system, by calling `arc_kmem_reap_now()` plus `arc_shrink()`, which improves `arc_available_memory()`. illumos/illumos-gate@de753e34f9c399037936e8bc547d823bba9d4b0d Reviewed by: Matt Ahrens <mahrens@delphix.com> Reviewed by: Serapheim Dimitropoulos <serapheim@delphix.com> Reviewed by: Pavel Zakharov <pavel.zakharov@delphix.com> Reviewed by: Dan Kimmel <dan.kimmel@delphix.com> Reviewed by: Paul Dagnelie <pcd@delphix.com> Reviewed by: Dan McDonald <danmcd@joyent.com> Reviewed by: Tim Kordas <tim.kordas@joyent.com> Approved by: Garrett D'Amore <garrett@damore.org> Author: Brad Lewis <brad.lewis@delphix.com> Ticket: #63153 (cherry picked from commit 892774d4dc64b5040e5de3f5eadcf92f7544c876)

Revision 40062351 (diff)
Added by Alexander Motin over 2 years ago

MFV r336930: 9284 arc_reclaim_thread has 2 jobs `arc_reclaim_thread()` calls `arc_adjust()` after calling `arc_kmem_reap_now()`; `arc_adjust()` signals `arc_get_data_buf()` to indicate that we may no longer be `arc_is_overflowing()`. The problem is, `arc_kmem_reap_now()` can take several seconds to complete, has no impact on `arc_is_overflowing()`, but due to how the code is structured, can impact how long the ARC will remain in the `arc_is_overflowing()` state. The fix is to use seperate threads to: 1. keep `arc_size` under `arc_c`, by calling `arc_adjust()`, which improves `arc_is_overflowing()` 2. keep enough free memory in the system, by calling `arc_kmem_reap_now()` plus `arc_shrink()`, which improves `arc_available_memory()`. illumos/illumos-gate@de753e34f9c399037936e8bc547d823bba9d4b0d Reviewed by: Matt Ahrens <mahrens@delphix.com> Reviewed by: Serapheim Dimitropoulos <serapheim@delphix.com> Reviewed by: Pavel Zakharov <pavel.zakharov@delphix.com> Reviewed by: Dan Kimmel <dan.kimmel@delphix.com> Reviewed by: Paul Dagnelie <pcd@delphix.com> Reviewed by: Dan McDonald <danmcd@joyent.com> Reviewed by: Tim Kordas <tim.kordas@joyent.com> Approved by: Garrett D'Amore <garrett@damore.org> Author: Brad Lewis <brad.lewis@delphix.com> Ticket: #63153 (cherry picked from commit 892774d4dc64b5040e5de3f5eadcf92f7544c876)

History

#1 Updated by Ryan McKenzie almost 3 years ago

Terminal messages from failover case:

Dec  6 08:03:18 Dec  6 08:03:20 tn03-a syslog-ng[79124]: I/O error occurred while writing; fd='23', error='Network is down (50)'
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.85 (iqn.1994-05.com.redhat:b9f01ffddbd): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.88 (iqn.1994-05.com.redhat:f7508cb6964c): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.90 (iqn.1994-05.com.redhat:67ddc36f0da): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.93 (iqn.1994-05.com.redhat:1627af8c63ae): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.92 (iqn.1994-05.com.redhat:24a1ae8819d5): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.91 (iqn.1994-05.com.redhat:bde9f425e52): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.87 (iqn.1994-05.com.redhat:9a61135a8492): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.89 (iqn.1994-05.com.redhat:25228623c3e): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.94 (iqn.1994-05.com.redhat:d16d415cfdd): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.84 (iqn.1994-05.com.redhat:eb16ae92a715): no ping reply (NOP-Out) after 5 seconds; dropping connection
Stopping cron.
Waiting for PIDS: 5352.
Stopping zfsd.
Waiting for PIDS: 5342CTL: HA link status changed from 2 to 1
, 5342.

#3 Updated by Ryan McKenzie almost 3 years ago

You can see that the op rate and bandwidth seen from the clients is very unstable and at times has several seconds of low to no activity

Dec 10, 2018  interval        i/o   MB/sec   bytes   read     resp     read    write     resp     resp queue  cpu%  cpu%
                             rate  1024**2     i/o    pct     time     resp     resp      max   stddev depth sys+u   sys
11:36:26.051      6751    2499.00  1249.50  524288   0.00   19.238    0.000   19.238  635.585   61.921  34.3   1.3   0.6
11:36:27.053      6752    2977.00  1488.50  524288   0.00   12.016    0.000   12.016  670.821   32.305  35.8   1.4   0.7
11:36:28.061      6753    2569.00  1284.50  524288   0.00    7.910    0.000    7.910  228.983   10.342  35.8   1.1   0.6
11:36:29.052      6754    2379.00  1189.50  524288   0.00   21.711    0.000   21.711  730.810   87.667  35.8   1.2   0.6
11:36:30.052      6755    2550.00  1275.00  524288   0.00   13.897    0.000   13.897  242.574   26.197  35.8   1.2   0.6
11:36:31.052      6756    3120.00  1560.00  524288   0.00    9.371    0.000    9.371  217.505   12.033  35.7   1.4   0.7
11:36:32.051      6757    1778.00   889.00  524288   0.00   23.126    0.000   23.126  698.348   88.305  35.8   0.9   0.5
11:36:33.052      6758    3763.00  1881.50  524288   0.00    9.854    0.000    9.854  421.349   20.474  35.7   1.5   0.8
11:36:34.052      6759    2504.00  1252.00  524288   0.00   10.519    0.000   10.519  238.756   17.682  35.8   1.1   0.6
11:36:35.052      6760    1744.00   872.00  524288   0.00   25.747    0.000   25.747  856.381  108.393  35.8   1.0   0.5
11:36:36.053      6761    3462.00  1731.00  524288   0.00   10.253    0.000   10.253  243.621   17.783  35.7   1.5   0.8
11:36:37.053      6762    1739.00   869.50  524288   0.00   12.049    0.000   12.049  227.498   22.760  35.9   0.9   0.5
11:36:38.053      6763    1484.00   742.00  524288   0.00   34.666    0.000   34.666  805.154  133.721  35.8   0.9   0.5
11:36:39.053      6764    3443.00  1721.50  524288   0.00   10.413    0.000   10.413  244.071   16.010  35.8   1.4   0.8
11:36:40.051      6765    2626.00  1313.00  524288   0.00   13.469    0.000   13.469  232.831   21.237  35.7   1.2   0.7
11:36:41.053      6766    1660.00   830.00  524288   0.00   20.362    0.000   20.362 1039.175  104.557  35.9   0.6   0.3
11:36:42.052      6767    3022.00  1511.00  524288   0.00   12.282    0.000   12.282 1065.814   28.854  35.7   1.3   0.7
11:36:43.059      6768    3398.00  1699.00  524288   0.00   10.637    0.000   10.637  260.588   17.636  35.7   1.4   0.7
11:36:44.053      6769    2030.00  1015.00  524288   0.00   17.874    0.000   17.874  827.603   95.997  35.9   0.8   0.5
11:36:45.053      6770    3085.00  1542.50  524288   0.00   11.498    0.000   11.498  406.961   20.315  35.7   1.4   0.7
11:36:46.053      6771    3404.00  1702.00  524288   0.00   10.484    0.000   10.484  233.104   20.587  35.7   1.3   0.7
11:36:47.055      6772    1123.00   561.50  524288   0.00   19.187    0.000   19.187  844.495  104.940  36.0   0.4   0.2
11:36:48.053      6773    2589.00  1294.50  524288   0.00   19.422    0.000   19.422  982.126   74.249  35.7   1.4   0.6
11:36:49.054      6774    3751.00  1875.50  524288   0.00    9.553    0.000    9.553  215.191   18.721  35.7   1.5   0.8
11:36:50.053      6775    1694.00   847.00  524288   0.00    9.995    0.000    9.995  424.054   23.877  35.9   0.7   0.3
11:36:51.053      6776    3995.00  1997.50  524288   0.00   13.545    0.000   13.545  694.836   61.446  35.7   1.6   0.8
11:36:52.052      6777    1341.00   670.50  524288   0.00   15.739    0.000   15.739  137.722   14.217  35.9   0.6   0.3
11:36:53.054      6778       8.00     4.00  524288   0.00 1013.425    0.000 1013.425 1307.015  268.304  36.0   0.2   0.0
11:36:54.054      6779       7.00     3.50  524288   0.00 2156.920    0.000 2156.920 2163.305    3.527  36.0   0.2   0.1
11:36:55.053      6780     167.00    83.50  524288   0.00  515.482    0.000  515.482 2870.153  843.795  36.0   0.5   0.2

Dec 10, 2018  interval        i/o   MB/sec   bytes   read     resp     read    write     resp     resp queue  cpu%  cpu%
                             rate  1024**2     i/o    pct     time     resp     resp      max   stddev depth sys+u   sys
11:36:56.056      6781      34.00    17.00  524288   0.00  669.184    0.000  669.184 1499.591  389.992  36.0   0.3   0.1
11:36:57.053      6782      37.00    18.50  524288   0.00  884.992    0.000  884.992 2074.870  626.243  36.0   0.4   0.2
11:36:58.058      6783      35.00    17.50  524288   0.00 1084.675    0.000 1084.675 3131.914  774.194  36.0   0.2   0.1
11:36:59.053      6784      34.00    17.00  524288   0.00 1110.604    0.000 1110.604 3420.981  849.026  36.0   0.3   0.1
11:37:00.053      6785      36.00    18.00  524288   0.00 1033.808    0.000 1033.808 3229.222  748.260  36.0   0.2   0.1
11:37:01.053      6786      34.00    17.00  524288   0.00  841.396    0.000  841.396 2035.739  566.020  36.0   0.3   0.1
11:37:02.051      6787      36.00    18.00  524288   0.00  875.716    0.000  875.716 2629.073  708.557  35.9   0.3   0.1
11:37:03.054      6788      37.00    18.50  524288   0.00 1157.937    0.000 1157.937 4202.278 1075.279  36.0   0.4   0.1
11:37:04.051      6789      36.00    18.00  524288   0.00  843.894    0.000  843.894 2513.159  608.530  36.0   0.2   0.0
11:37:05.051      6790     490.00   245.00  524288   0.00  132.863    0.000  132.863 4584.165  456.367  35.9   0.6   0.3
11:37:06.053      6791       8.00     4.00  524288   0.00  592.536    0.000  592.536 1183.444  364.088  36.0   0.2   0.1
11:37:07.052      6792     251.00   125.50  524288   0.00  285.981    0.000  285.981 1910.368  587.578  36.0   0.5   0.3
11:37:08.053      6793    1461.00   730.50  524288   0.00   25.293    0.000   25.293  496.112   70.111  35.9   0.9   0.5
11:37:09.052      6794    2123.00  1061.50  524288   0.00   17.593    0.000   17.593  549.969   57.401  35.7   1.2   0.7
11:37:10.050      6795    3056.00  1528.00  524288   0.00   11.754    0.000   11.754  217.426   12.496  37.1   1.3   0.7
11:37:11.050      6796    2891.00  1445.50  524288   0.00   10.618    0.000   10.618  478.420   38.982  34.4   1.2   0.5
11:37:12.050      6797    3138.00  1569.00  524288   0.00   12.042    0.000   12.042  518.762   28.630  35.7   1.3   0.7

...

11:37:42.054      6827    3653.00  1826.50  524288   0.00   10.054    0.000   10.054  265.981   20.167  35.7   1.4   0.7
11:37:43.053      6828    2371.00  1185.50  524288   0.00   14.976    0.000   14.976  615.712   59.670  35.8   0.9   0.5
11:37:44.059      6829    3215.00  1607.50  524288   0.00   10.819    0.000   10.819  225.037   14.869  35.7   1.6   0.8
11:37:45.052      6830    4025.00  2012.50  524288   0.00    8.269    0.000    8.269  248.685   19.638  35.7   1.5   0.7
11:37:46.053      6831    1145.00   572.50  524288   0.00   34.008    0.000   34.008  811.247  128.949  35.9   0.6   0.3
11:37:47.053      6832    2892.00  1446.00  524288   0.00   12.506    0.000   12.506  254.004   22.690  35.7   1.4   0.7
11:37:48.053      6833    2645.00  1322.50  524288   0.00   10.969    0.000   10.969  214.579   13.334  35.8   1.1   0.5
11:37:49.052      6834    1399.00   699.50  524288   0.00   27.807    0.000   27.807  526.049   86.138  35.9   0.8   0.4
11:37:50.052      6835    3272.00  1636.00  524288   0.00   12.167    0.000   12.167  555.686   32.228  35.7   1.6   0.8
11:37:51.053      6836    3125.00  1562.50  524288   0.00    8.803    0.000    8.803  159.040    9.481  35.8   1.1   0.6
11:37:52.053      6837       0.00     0.00       0   0.00    0.000    0.000    0.000    0.000    0.000  36.0   0.2   0.1
11:37:53.053      6838       9.00     4.50  524288   0.00 2237.219    0.000 2237.219 2341.257   49.090  36.0   0.3   0.1
11:37:54.053      6839      37.00    18.50  524288   0.00 1454.016    0.000 1454.016 2632.789 1147.248  36.0   0.2   0.1
11:37:55.051      6840       1.00     0.50  524288   0.00 3306.902    0.000 3306.902 3306.902    0.000  37.4   0.3   0.1

Dec 10, 2018  interval        i/o   MB/sec   bytes   read     resp     read    write     resp     resp queue  cpu%  cpu%
                             rate  1024**2     i/o    pct     time     resp     resp      max   stddev depth sys+u   sys
11:37:56.055      6841      66.00    33.00  524288   0.00 1630.135    0.000 1630.135 5184.673 1378.163  34.6   0.3   0.2
11:37:57.120      6842      60.00    30.00  524288   0.00  290.514    0.000  290.514  989.424  217.373  38.4   0.2   0.1
11:37:58.055      6843      18.00     9.00  524288   0.00 1057.858    0.000 1057.858 1680.392  497.644  33.6   0.3   0.0
11:37:59.062      6844      26.00    13.00  524288   0.00 1639.276    0.000 1639.276 3013.518  824.249  36.0   0.2   0.1
11:38:00.052      6845      44.00    22.00  524288   0.00 1003.817    0.000 1003.817 3637.706  928.708  36.0   0.4   0.2
11:38:01.051      6846    1766.00   883.00  524288   0.00   33.132    0.000   33.132 2717.112  155.376  35.8   1.1   0.5
11:38:02.052      6847    2779.00  1389.50  524288   0.00   10.362    0.000   10.362  447.501   28.262  35.9   0.9   0.5
11:38:03.053      6848       3.00     1.50  524288   0.00  295.774    0.000  295.774  400.081  101.898  36.0   0.2   0.1
11:38:04.055      6849       0.00     0.00       0   0.00    0.000    0.000    0.000    0.000    0.000  36.0   0.2   0.1
11:38:05.054      6850       0.00     0.00       0   0.00    0.000    0.000    0.000    0.000    0.000  36.0   0.2   0.0
11:38:06.056      6851     194.00    97.00  524288   0.00  771.462    0.000  771.462 4316.395 1464.801  35.9   0.4   0.2
11:38:07.053      6852    1046.00   523.00  524288   0.00   15.167    0.000   15.167  243.450   21.316  35.9   0.8   0.4
11:38:08.053      6853     219.00   109.50  524288   0.00  258.785    0.000  258.785 1287.129  363.601  35.9   0.4   0.3
11:38:09.053      6854     137.00    68.50  524288   0.00  163.916    0.000  163.916  773.714  132.250  36.0   0.4   0.1
11:38:10.054      6855    1417.00   708.50  524288   0.00   26.462    0.000   26.462 1006.632   94.210  35.9   0.8   0.4
11:38:11.053      6856     215.00   107.50  524288   0.00  222.710    0.000  222.710  896.816  271.984  35.9   0.4   0.2
11:38:12.051      6857    1574.00   787.00  524288   0.00   23.478    0.000   23.478  347.105   39.881  35.8   1.2   0.6
11:38:13.053      6858    2612.00  1306.00  524288   0.00   13.563    0.000   13.563  287.004   36.126  35.8   1.0   0.5
11:38:14.054      6859    3453.00  1726.50  524288   0.00   10.187    0.000   10.187  240.266   22.436  35.7   1.5   0.8
11:38:15.052      6860    2053.00  1026.50  524288   0.00    9.396    0.000    9.396  252.081   16.779  35.8   0.8   0.3
11:38:16.052      6861    3181.00  1590.50  524288   0.00   16.553    0.000   16.553  597.369   56.996  35.7   1.4   0.8
11:38:17.052      6862    3126.00  1563.00  524288   0.00   11.545    0.000   11.545  303.266   24.111  35.8   1.3   0.6
11:38:18.051      6863    1735.00   867.50  524288   0.00    8.513    0.000    8.513  231.602   19.089  35.9   0.8   0.4
11:38:19.053      6864    3206.00  1603.00  524288   0.00   17.616    0.000   17.616  904.733   80.754  35.7   1.8   1.0
11:38:20.053      6865    3427.00  1713.50  524288   0.00   10.598    0.000   10.598  266.858   13.226  35.8   1.2   0.7
11:38:21.053      6866    1983.00   991.50  524288   0.00   18.034    0.000   18.034  583.391   66.869  35.8   0.8   0.4
11:38:22.054      6867    3582.00  1791.00  524288   0.00    9.772    0.000    9.772  230.614   12.329  35.7   1.4   0.7
11:38:23.053      6868    1462.00   731.00  524288   0.00   10.860    0.000   10.860  499.320   23.078  35.9   0.6   0.3
11:38:24.054      6869    1108.00   554.00  524288   0.00   50.174    0.000   50.174 1284.267  165.353  35.9   0.9   0.4
11:38:25.054      6870    1325.00   662.50  524288   0.00   19.343    0.000   19.343  292.466   48.152  35.9   0.8   0.4

Dec 10, 2018  interval        i/o   MB/sec   bytes   read     resp     read    write     resp     resp queue  cpu%  cpu%
                             rate  1024**2     i/o    pct     time     resp     resp      max   stddev depth sys+u   sys
11:38:26.054      6871    1697.00   848.50  524288   0.00   27.629    0.000   27.629  918.113  101.829  35.8   1.0   0.5
11:38:27.051      6872    3382.00  1691.00  524288   0.00   10.640    0.000   10.640  258.491   20.490  35.7   1.6   0.8
11:38:28.052      6873    2229.00  1114.50  524288   0.00   15.722    0.000   15.722  616.724   58.954  35.8   1.0   0.5

#4 Updated by Dru Lavigne almost 3 years ago

  • Assignee changed from Release Council to Alexander Motin

#5 Updated by Alexander Motin almost 3 years ago

  • Status changed from Unscreened to Screened

In the provided `ctladm dumpooa` I see two sort of things: normal requests with latency of few milliseconds, and two groups of requests blocked on collision with one request hopelessly waiting for data to write from iSCSI stack:

LUN 6 tag 0x1000006f DMA ABORT RTR: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (3247840 ms)                                         
LUN 6 tag 0x2000001d BLOCKED ABORT: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (3240428 ms)                                         
LUN 6 tag 0x20000073 BLOCKED ABORT: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (3178790 ms)                                         
LUN 6 tag 0x2000003f BLOCKED ABORT: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (3117038 ms)                                         
LUN 6 tag 0x2000001a BLOCKED ABORT: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (3054960 ms)                                         
LUN 6 tag 0x20000059 BLOCKED ABORT: WRITE(10). CDB: 2a 00 01 3b 09 00 00 00 80 00  (2993014 ms)                                         

Our iSCSI target stack has no any timeouts for that kind of operations. If request for data was sent to initiator, one must respond. Case of network problems should be covered by regular pings sent if link is idle. How some requests could stuck in that state for an hours I have no clue. But may be it is somehow related (race triggered by it?) to the massive ping timeouts logged.

#6 Updated by Ryan McKenzie almost 3 years ago

Now that the M50 has been fixed from issue https://redmine.ixsystems.com/issues/64548 I am running to larger dataset sizes and seeing these same iSCSI issues with failover. Build is 11.2 nightly 12-07-2018. Interesting excerpts from the SOL are below. Full log attached.

ctl_datamove: tag 0x002e on (0:137:2) aborted
ctl_datamove: tag 0x001f on (0:137:2) aborted
ctl_datamove: tag 0x0046 on (0:137:2) aborted
ctl_datamove: tag 0x0031 on (0:138:2) aborted
ctl_datamove: tag 0x0022 on (0:143:2) aborted
ctl_datamove: tag 0x002f on (0:137:2) aborted
ctl_datamove: tag 0x0013 on (0:138:2) aborted
ctl_datamove: tag 0x004d on (0:138:2) aborted
ctl_datamove: tag 0x0068 on (0:138:2) aborted
ctl_datamove: tag 0x0006 on (0:144:2) aborted
ctl_datamove: tag 0x0007 on (0:140:2) aborted
ctl_datamove: tag 0x006a on (0:140:2) aborted
ctl_datamove: tag 0xf0000029 on (0:139:2) aborted
ctl_datamove: tag 0xf000007b on (0:141:2) aborted
ctl_datamove: tag 0xf0000076 on (0:142:2) aborted
ctl_datamove: tag 0xf0000074 on (0:136:2) aborted
ctl_datamove: tag 0x0014 on (0:138:2) aborted
ctl_datamove: tag 0x0004 on (0:138:2) aborted
ctl_datamove: tag 0x0007 on (0:137:2) aborted
ctl_datamove: tag 0x0016 on (0:137:2) aborted
ctl_datamove: tag 0x006c on (0:138:2) aborted
ctl_datamove: tag 0xf0000052 on (0:139:2) aborted
ctl_datamove: tag 0xf0000051 on (0:139:2) aborted
ctl_datamove: tag 0x0056 on (0:140:2) aborted
ctl_datamove: tag 0xf0000042 on (0:139:2) aborted
Jan  3 19:18:56 tn11b uwsgi: [sentry.errors:674] Sentry responded with an API error: RateLimited(None)
Jan  3 19:18:56 tn11b uwsgi: [sentry.errors.uncaught:702] ['timeout: timed out', '  File "django/core/handlers/exception.py", line 42, in inner', '  File "django/core/handlers/base.py", line 249, in _legacy_get_response', '  File "django/core/handlers/base.py", line 178, in _get_response', '  File "freenasUI/freeadmin/middleware.py", line 163, in process_view', '  File "django/contrib/auth/decorators.py", line 23, in _wrapped_view', '  File "freenasUI/freeadmin/site.py", line 156, in wrapper', '  File "django/utils/decorators.py", line 149, in _wrapped_view', '  File "django/views/decorators/cache.py", line 57, in _wrapped_view_func', '  File "freenasUI/freeadmin/site.py", line 143, in inner', '  File "django/views/decorators/cache.py", line 57, in _wrapped_view_func', '  File "freenasUI/freeadmin/site.py", line 279, in alert_status', '  File "freenasUI/middleware/client.py", line 20, in __enter__', '  File "middlewared/client/client.py", line 320, in __init__', ' 
Jan  3 19:18:56 tn11b uwsgi:  File "middlewared/client/client.py", line 313, in __init__', '  File "middlewared/client/client.py", line 170, in connect', '  File "ws4py/client/__init__.py", line 215, in connect']
ctl_datamove: tag 0x0038 on (0:143:2) aborted
ctl_datamove: tag 0x0036 on (0:140:2) aborted
ctl_datamove: tag 0x0072 on (0:137:2) aborted
ctl_datamove: tag 0x0072 on (0:140:2) aborted
ctl_datamove: tag 0xf000000b on (0:142:2) aborted
ctl_datamove: tag 0x001f on (0:140:2) aborted
ctl_datamove: tag 0xf0000022 on (0:142:2) aborted
ctl_datamove: tag 0x005f on (0:140:2) aborted
ctl_datamove: tag 0x0005 on (0:140:2) aborted
ctl_datamove: tag 0x0016 on (0:137:2) aborted
ctl_datamove: tag 0x0034 on (0:133:2) aborted
ctl_datamove: tag 0xf0000026 on (0:134:2) aborted
WARNING: 172.27.0.63 (iqn.1994-05.com.redhat:dceba8f78dda): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.55 (iqn.1994-05.com.redhat:352c98abaeb): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.63 (iqn.1994-05.com.redhat:dceba8f78dda): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.58 (iqn.1994-05.com.redhat:cb98f93dba59): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.61 (iqn.1994-05.com.redhat:20774716c8da): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.62 (iqn.1994-05.com.redhat:9c4b43cf4617): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.56 (iqn.1994-05.com.redhat:3134793edcef): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.54 (iqn.1994-05.com.redhat:b8c7e2dd5e6c): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.55 (iqn.1994-05.com.redhat:352c98abaeb): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.61 (iqn.1994-05.com.redhat:20774716c8da): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.54 (iqn.1994-05.com.redhat:b8c7e2dd5e6c): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.62 (iqn.1994-05.com.redhat:9c4b43cf4617): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.56 (iqn.1994-05.com.redhat:3134793edcef): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.58 (iqn.1994-05.com.redhat:cb98f93dba59): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.53 (iqn.1994-05.com.redhat:a06148bd137): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.60 (iqn.1994-05.com.redhat:2b3bdb7da48): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.59 (iqn.1994-05.com.redhat:415b2fd13a20): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.64 (iqn.1994-05.com.redhat:bce4766934d3): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.53 (iqn.1994-05.com.redhat:a06148bd137): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.60 (iqn.1994-05.com.redhat:2b3bdb7da48): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.57 (iqn.1994-05.com.redhat:b2cb56dcc44): no ping reply (NOP-Out) after 5 seconds; dropping connection
WARNING: 172.27.0.59 (iqn.1994-05.com.redhat:415b2fd13a20): waiting for CTL to terminate 3 tasks
WARNING: 172.27.0.64 (iqn.1994-05.com.redhat:bce4766934d3): waiting for CTL to terminate 2 tasks
WARNING: 172.27.0.57 (iqn.1994-05.com.redhat:b2cb56dcc44): waiting for CTL to terminate 3 tasks
(0:135:2/8): READ(10). CDB: 28 00 00 03 f0 00 00 01 00 00 
(0:135:2/8): Tag: 0xf0000048, type 1
(0:135:2/8): ctl_datamove: 112 seconds
ctl_datamove: tag 0xf0000048 on (0:135:2) aborted
(0:135:2/8): READ(10). CDB: 28 00 00 03 f0 00 00 01 00 00 
(0:135:2/8): Tag: 0xf0000048, type 1
(0:135:2/8): ctl_process_done: 112 seconds
(0:143:2/32): WRITE(10). CDB: 2a 00 00 36 e6 00 00 01 00 00 
(0:143:2/32): Tag: 0x0011, type 1
(0:143:2/32): ctl_process_done: 175 seconds
(da66:mpr1:0:249:0): READ(10). CDB: 28 00 14 1f 38 f5 00 00 20 00 
(da66:mpr1:0:249:0): CAM status: SCSI Status Error
(da66:mpr1:0:249:0): SCSI status: Check Condition
(da66:mpr1:0:249:0): SCSI sense: UNIT ATTENTION asc:2a,3 (Reservations preempted)
(da66:mpr1:0:249:0): 
(da66:mpr1:0:249:0): Field Replaceable Unit: 0
(da66:mpr1:0:249:0): Command Specific Info: 0
(da66:mpr1:0:249:0): 
(da66:mpr1:0:249:0): Descriptor 0x80: f5 1e
(da66:mpr1:0:249:0): Descriptor 0x81: 00 00 00 00 00 00
(da66:mpr1:0:249:0): Retrying command (per sense data)
(da15:mpr0:0:48:0): CAM status: SCSI Status Error
(da15:mpr0:0:48:0): SCSI status: Reservation Conflict
(da15:mpr0:0:48:0): Error 5, Unretryable error
(da42:mpr1:0:194:0): WRITE(10). CDB: 2a 00 14 40 21 a7 00 00 04 00 
(da42:mpr1:0:194:0): CAM status: SCSI Status Error
(da42:mpr1:0:194:0): SCSI status: Reservation Conflict
(da42:mpr1:0:194:0): (da130:mpr2:0:253:0): Error 5, Unretryable error
(da130:mpr2:0:253:0): READ(6). CDB: 08 00 00 c2 02 00 
(da130:mpr2:0:253:0): CAM status: SCSI Status Error
(da130:mpr2:0:253:0): SCSI status: Check Condition
(da130:mpr2:0:253:0): SCSI sense: UNIT ATTENTION asc:2a,3 (Reservations preempted)
(da130:mpr2:0:253:0): 
(da130:mpr2:0:253:0): Field Replaceable Unit: 0
(da130:mpr2:0:253:0): Command Specific Info: 0
(da130:mpr2:0:253:0): 
(da130:mpr2:0:253:0): Descriptor 0x80: f5 1e
(da130:mpr2:0:253:0): Descriptor 0x81: 00 00 00 00 00 00
(da130:mpr2:0:253:0): Retrying command (per sense data)
(da141:mpr2:0:264:0): CAM status: SCSI Status Error
(da141:mpr2:0:264:0): SCSI status: Reservation Conflict
(da141:mpr2:0:264:0): Error 5, Unretryable error
 is not subscriptable", '  File "django/core/handlers/exception.py", line 42, in inner', '  File "django/core/handlers/base.py", line 249, in _legacy_get_response', '  File "django/core/handlers/base.py", line 187, in _get_re
sponse', '  File "django/core/handlers/base.py", line 185, in _get_response', '(da140:mpr2:0:263:0): WRITE(6). CDB: 0a 00 00 c2 02 00 
(da140:mpr2:0:263:0): CAM status: SCSI Status Error
(da140:mpr2:0:263:0): SCSI status: Reservation Conflict
(da140:mpr2:0:263:0): Error 5, Unretryable error
(da140:mpr2:0:263:0): WRITE(10). CDB: 2a 00 1d 1c 10 82 00 00 02 00 
(da140:mpr2:0:263:0): CAM status: SCSI Status Error
(da140:mpr2:0:263:0): SCSI status: Reservation Conflict
(da140:mpr2:0:263:0): Error 5, Unretryable error
(da140:mpr2:0:263:0): WRITE(10). CDB: 2a 00 1d 1c 10 c2 00 00 02 00 
(da140:mpr2:0:263:0): CAM status: SCSI Status Error
(da140:mpr2:0:263:0): SCSI status: Reservation Conflict
(da140:mpr2:0:263:0): Error 5, Unretryable error
(da117:mpr2:0:237:0): WRITE(10). CDB: 2a 00 13 40 46 e9 00 00 08 00 
(da117:mpr2:0:237:0): CAM status: SCSI Status Error
(da117:mpr2:0:237:0): SCSI status: Reservation Conflict
(da117:mpr2:0:237:0): Error 5, Unretryable error
(da116:mpr2:0:236:0): WRITE(10). CDB: 2a 00 13 40 46 f1 00 00 02 00 
(da116:mpr2:0:236:0): CAM status: SCSI Status Error
(da116:mpr2:0:236:0): SCSI status: Reservation Conflict
(da116:mpr2:0:236:0): Error 5, Unretryable error

This is followed immediately by a reboot, no HA or fenced message, no dump.

#13 Updated by Ryan McKenzie almost 3 years ago

  • File debug-20190222084212.tar added
  • Subject changed from iSCSI errors on M40, sometimes causing failover to iSCSI errors on M series, often causing failover

These symptoms are also occurring on the M50-HA. Just like the M40, it runs fine with sequential workloads. Random workloads (4k IO with 4k block size, 16k IO with 16k block size) begin to show below errors on console, most of the time run to completion. Adding L2ARC to the mix exacerbates the frequency of the console errors. With L2ARC it is nearly impossible to complete a full test sequence without a failover (usually fenced).

This is with a much newer nightly build (2019-01-29). Next step I will run with HA disabled via UI to see if I can get a complete run in.

Note these are the same errors as seen on the M40 (rrd/collectd update time errors, iSCSI errors, reservation conflicts)

Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-mfu-hit.rrd, [1550813116:189753691], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-prefetch_metadata-miss.rrd, [1550813116:3291], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-demand_metadata-miss.rrd, [1550813116:5096799], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-mfu_ghost-hit.rrd, [1550813116:3577851], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-mru-hit.rrd, [1550813116:132940365], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1(0:133:0/0): READ(10). CDB: 28 00 00 6f bd 69 00 00 01 00 
(0:133:0/0): Tag: 0x4000006d, type 1
(0:133:0/0): ctl_datamove: 352 seconds
ctl_datamove: tag 0x4000006d on (0:133:0) aborted
(0:135:0/6): READ(10). CDB: 28 00 01 2e d6 77 00 00 01 00 
(0:135:0/6): Tag: 0x40000017, type 1
(0:135:0/6): ctl_datamove: 352 seconds
ctl_datamove: tag 0x40000017 on (0:135:0) aborted
(0:140:0/21): READ(10). CDB: 28 00 00 1e e2 2b 00 00 01 00 
(0:140:0/21): READ(10). CDB: 28 00 00 31 ee 36 00 00 01 00 
(0:140:0/21): Tag: 0x40000035, type 1
(0:140:0/21): ctl_datamove: 352 seconds
ctl_datamove: tag 0x40000035 on (0:140:0) aborted
(0:140:0/21): WRITE(10). CDB: 2a 00 01 08 58 f3 00 00 01 00 
(0:140:0/21): Tag: 0x4000001a, type 1
(0:140:0/21): ctl_datamove: 352 seconds
ctl_datamove: tag 0x4000001a on (0:140:0) aborted
(0:136:0/9): READ(10). CDB: 28 00 00 17 8d a2 00 00 01 00 
(0:136:0/9): Tag: 0x40000011, type 1
(0:136:0/9): ctl_datamove: 352 seconds
ctl_datamove: tag 0x40000011 on (0:136:0) aborted
(0:135:0/6): READ(10). CDB: 28 00 01 2e d6 77 00 00 01 00 
(0:138:0/15): READ(10). CDB: 28 00 01 3d 3a 12 00 00 01 00 
(0:138:0/15): Tag: 0x5000000a, type 1
(0:138:0/15): ctl_datamove: 352 seconds
ctl_datamove: tag 0x5000000a on (0:138:0) aborted

...

(0:133:0/0): READ(10). CDB: 28 00 00 87 47 f5 00 00 01 00 
(0:133:0/0): Tag: 0x40000016, type 1
(0:133:0/0): ctl_datamove: 353 seconds
ctl_datamove: tag 0x40000016 on (0:133:0) aborted
(0:133:0/0): READ(10). CDB: 28 00 01 64 7a cb 00 00 01 00 
(0:133:0/0): Tag: 0x40000049, type 1
ctl_datamove: tag 0x40000058 on (0:143:0) aborted
(da79:mpr1:0:262:0): SCSI sense: UNIT ATTENTION asc:2a,3 (Reservations preempted)
(da79:mpr1:0:262:0): 
(da79:mpr1:0:262::0): Command Specific Info: 0
(da79:mpr1:0:262:0): 
(da59:mpr1:0:239:0): SCSI status: Check Condition
(da59:mpr1:0:239:0): SCSI sense: UNIT ATTENTION asc:2a,3 (Reservations preempte Replaceable Unit: 0
(0:134:0/3): READ(10). CDB: 28 00 00 6c 05 4d 00 00 01 00 
(0:134:0/3): Tag: 0x40000043, type 1
(0:134:0/3): ctl_datamove: 292 seconds
ctl_datamove: ta: Descriptor 0x80: f5 1e
(da79:mpr1:0:262:0): Descriptor 0x81: 00 00 00 00 00 00
(da79:mpr1:0:262:0): Retrying command (per sense data)
(0:133:0/0): READ(10). CDB: 28 00 01 2d 44 99pe 1
(0:134:0/3): READ(10). CDB: 28 00 01 88 53 80 00 00 01 00 
(0:133:0/0): ctl_datamove: 293 seconds
ctl_datamove: tag 0x4000002d on (0:133:0) aborted
(0:144:0/33): READ(10). CDB: Tag: 0x40000035, type 1
(0:134:0/3): READ(10). CDB: 28 00 01 71 a4 66 00 00 01 00 
(0:134:0/3): Tag: 0x40000068, type 1
(0:134:0/3): ctl_datamove: 292 seconds
ctl_datamove: tag 0AD(10). CDB: 28 00 00 68 0f 80 00 00 01 00 
(0:134:0/3): Tag: 0x40000042, type 1
(0:134:0/3): ctl_datamove: 293 seconds
ctl_datamove: tag 0x40000042 on (0:134:0) aborted
(0:134:0/3): READ(10). CDB: 28 00 00 06 31 84 00 00 01 00 
(0:134:0/3): Tag: 0x40000048, type 1
(0:134:0/3): ctl_datamove: 293 seconds
(da39:mpr1:0:191:0): CAM status: SCSI Status Error

...

(0:135:0/6): READ(10). CDB: 28 00 01 0a 9f 6e 00 00 01 00 
(0:135:0/6): Tag: 0x40000064, type 1
(0:135:0/6): ctl_process_done: 298 seconds
(0:135:0/6): READ(10). CDB: 28 00 00 3b f7 59 00 00 01 00 
ctl_datamove: tag 0x40000004 on (0:144:0) aborted
(0:144:0/33): READ(10). CDB: 28 00 01 87 b1 32 00 00 01 00 
(0:144:0/33): Tag: 0x4000005a, type 1
(0:139:0/18): WRITE(10). CDB: 2a 00 00 d6 1e db 00 00 01 00 
(0:139:0/18): Tag: 0x4000007f, type 1
(0:139:0/18): ctl_process_done: 359 seconds
(0:139:0/18): READ(10). CDB: 28 00 00 37 2e 70 00 00 01 00 
WARNING: 172.27.0.86 (iqn.1994-05.com.redhat:9bc6eacaa04b): no ping reply (NOP-Out) after 5 seconds; dropping connection

...

(da69:mpr1:0:252:0): WRITE(10). CDB: 2a 00 0b 87 0e 07 00 00 04 00 
(da69:mpr1:0:252:0): CAM status: SCSI Status Error
(da69:mpr1:0:252:0): SCSI status: Reservation Conflict
(da69:mpr1:0:252:0): Error 5, Unretryable error
(da76:mpr1:0:259:0): WRITE(10). CDB: 2a 00 0a d6 45 ae 00 00 01 00 
WARNING: 172.27.0.85 (iqn.1994-05.com.redhat:b9f01ffddbd): tasks terminated
WARNING: 172.27.0.83 (iqn.1994-05.com.redhat:2cf9887b4c76): tasks terminated
(da60:mpr1:0:243:0): Descriptor 0x81: 00 00 00 00 00 00
(da60:mpr1:0:243:0): Retrying command (per sense data)
(da60:mpr1:0:243:0): WRITE(10). CDB: 2a 00 0a 5d 6f d5 00 00 0d 00 
(da60:mpr1:0:243:0): CAM status: SCSI Status Error
(da60:mpr1:0:243:0): SCSI status: Reservation Conflict
(da60:mpr1:0:243:0): Error 5, Unretryable error
(da67:mpr1:0:250:0): WRITE(10). CDB: 2a 00 0b 47 04 03 00 00 20 00 
(da67:mpr1:0:250:0): CAM status: SCSI Status Error
(da67:mpr1:0:250:0): SCSI status: Reservation Conflict
(da67:mpr1:0:250:0): Error 5, Unretryable error
(da67:mpr1:0:250:0): WRITE(10). CDB: 2a 00 0b 47 04 23 00 00 20 00 
(da67:mpr1:0:250:0): CAM status: SCSI Status Error
(da67:mpr1:0:250:0): SCSI status: Reservation Conflict
(da67:mpr1:0:250:0): Error 5, Unretryable error
(da67:mpr1:0:250:0): WRITE(10). CDB: 2a 00 0b 47 04 43 00 00 20 00 
(da67:mpr1:0:250:0): CAM status: SCSI Status Error
(da67:mpr1:0:250:0): SCSI status: Reservation Conflict
(da67:mpr1:0:250:0): Error 5, Unretryable error
(da67:mpr1:0:250:0): WRITE(10). CDB: 2a 00 0b 47 04 63 00 00 05 00 
(da67:mpr1:0:250:0): CAM status: SCSI Status Error
(da67:mpr1:0:250:0): SCSI status: Reservation Conflict
(da67:mpr1:0:250:0): Error 5, Unretryable error

...

(da8:mpr0:0:41:0): WRITE(10). CDB: 2a 00 09 91 18 1d 00 00 04 00 
(da8:mpr0:0:41:0): CAM status: SCSI Status Error
(da8:mpr0:0:41:0): SCSI status: Reservation Conflict
(da8:mpr0:0:41:0): Error 5, Unretryable error
(da1:mpr0:0:34:0): WRITE(10). CDB: 2a 00 0a 90 b7 06 00 00 08 00 
(da1:mpr0:0:34:0): CAM status: SCSI Status Error
(da1:mpr0:0:34:0): SCSI status: Reservation Conflict
(da1:mpr0:0:34:0): Error 5, Unretryable error
c_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_result-mru_ghost-hit.rrd, [1550813116:1058300], 1) failed: rrdcached: illegal attempt to update using time 1550813116.000000 when last update time is 1550813
116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/cache_ratio-L2.rrd, [1550813116:nan], 1) failed: rrdcached: illegal attempt to update using time 1550813116.0
00000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:00 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc/io_octets-L2.rrd, [1550813116:64026460672:787050118656], 1) failed: rrdcached: illegal attempt to update usin
g time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:01 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc_v2/gauge_arcstats_raw_hits_misses-hits.rrd, [1550813116:3.000000], 1) failed: rrdcached: illegal attempt to u
pdate using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:01 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc_v2/gauge_arcstats_raw_demand-demand_data_hits.rrd, [1550813116:0.000000], 1) failed: rrdcached: illegal attem
pt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:01 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc_v2/gauge_arcstats_raw_demand-demand_metadata_hits.rrd, [1550813116:3.000000], 1) failed: rrdcached: illegal a
ttempt to update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)
Feb 22 00:28:01 collectd[48078]: rrdcached plugin: rrdc_update (/var/db/collectd/rrd/tn11b.lab.ixsystems.com/zfs_arc_v2/gauge_arcstats_raw_hits_misses-misses.rrd, [1550813116:0.000000], 1) failed: rrdcached: illegal attempt to
 update using time 1550813116.000000 when last update time is 1550813116.000000 (minimum one second step) (status=-1)

...

After about 2 minutes of the RRD/collectd messages, primary controller reboots. It comes up as "freenas" without the config (unable to load the database). There are no textdumps.

#14 Updated by Ryan McKenzie almost 3 years ago

Watching "top" with options SHIz you can see that the CPUs are very busy with kernel zio reads and writes constantly, as expected. However, when the arc reclaim thread is called it uses 100% of system CPU time for a second or two, this coincides with the rrd/collectd delays. Further, when our automation kicks of stats collection, several instances of python36 (probably middleware?) occupy all of CPU resources for several seconds, corresponding to a collection of rrd/collectd AND iSCSI errors.

So far this is at low thread count load points so the frequency of the errors is not very high yet. It is interesting to see this correlation.

#15 Updated by Alexander Motin almost 3 years ago

I have a proposition to try. Right now all CTL threads are running with absolute kernel priorities. But looking through the kernel I see number places where kernel threads are using time-share user priorities. I think we could try that to make CTL less hurt system interactivity under heavy load. But I suppose that may significantly affect performance patterns. If I build the custom kernel with those changes, will we be able to test it?

#16 Updated by Alexander Motin almost 3 years ago

Closer look made me think that it may be impossible to make kernel thread to really do dynamic priority same as user-space thread, but I made a patch to reduce CTL priority to the top for user-space. The same priority is used for GELI threads. We'll see what it give us.

#17 Updated by Ryan McKenzie almost 3 years ago

The kernel I tried with Mav's two changes (I/OAT support and CTL thread priority) did help with system responsiveness at low to mid level load but under heavy load the system still goes unresponsive and IO stalls for long enough to trigger fenced (or with HA disabled will cause client initiators to time out and benchmark to fail).

#19 Updated by Dru Lavigne over 2 years ago

  • Priority changed from No priority to Blocks Until Resolved
  • Target version changed from Backlog to TrueNAS 11.2-U3

#20 Updated by Ryan McKenzie over 2 years ago

To sanity check hardware and 11.1 vs 11.2 code and pool versions, I have began to run the following sequence. I will post daily updates.

Fresh install M50 to 11.1u7
Initial configuration (time zone, network, SSH, serial console, install automation scripts, etc.)
Build pool (142 drives -> 71 mirror vdevs, 2 spare drives, NVDIMM SLOG)
Build zvols, configure iSCSI, disable failover in UI

Fill 4k and 16k blocksize LUNs
Automation tests, collecting full complements of stats and profiles
-Run 4k random IOs on 4k blocksize zvols (No L2ARC baseline)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, default tunings)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, increased L2ARC write speed)
-Run 4k random IOs on 4k blocksize zvols (4x NVMe L2ARC, increased L2ARC write speed)

Upgrade to latest nightly 11.2 build (DO NOT UPGRADE POOL)
Automation tests, collecting full complements of stats and profiles
-Run 4k random IOs on 4k blocksize zvols (No L2ARC baseline)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, default tunings)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, increased L2ARC write speed)
-Run 4k random IOs on 4k blocksize zvols (4x NVMe L2ARC, increased L2ARC write speed)

Destroy pool, recreate pool on 11.2
Fill 4k and 16k blocksize LUNs
Automation tests, collecting full complements of stats and profiles
-Run 4k random IOs on 4k blocksize zvols (No L2ARC baseline)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, default tunings)
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, increased L2ARC write speed)
-Run 4k random IOs on 4k blocksize zvols (4x NVMe L2ARC, increased L2ARC write speed)

#21 Updated by Ryan McKenzie over 2 years ago

All of the 11.1u7 testing ran to completion, had no issues with rrd/collectd or iSCSI errors on the console, exhibited no UI/CLI unresponsiveness.

#22 Updated by Ryan McKenzie over 2 years ago

  • File RUN01-11.2_20190307_M50_L2config-HAdisable_1xNVMeL2ARC_L2defaults_4kBLKSZ_iscsi_RAN4k_100gADSS_0r100w.txt added
  • File RUN01-11.2_20190307_M50_L2config-HAdisable_1xNVMeL2ARC_L2write4x_4kBLKSZ_iscsi_RAN4k_100gADSS_0r100w.txt added

Upon upgrading the system to 11.2 nightly build 20190307, the console is showing CTL/iSCSI errors near the beginning of write workloads. However the system stabilizes and has been able to run tests to completion without failover or long periods of stalled IO. The system also remains responsive on UI, CLI, and console.

Note that this is with the pool built on 11.1u7. Next step is to destroy and rebuild the pool with 11.2 to rule out the pool version.

#23 Updated by Ryan McKenzie over 2 years ago

All performance tests with 11.1u7 completed.
All performance tests with 11.2 20190307 using the 11.1u7 pool completed.

After deleting the old pool and creating a new pool, the very first test (lun fill) failed. iSCSI IO stalled for several minutes, console was flooding with iSCSI errors, UI/CLI became unresponsive. At this time I issued an NMI vial ipmi and got the following on console.

(0:136:0/15): Tag: 0x002c, type 1
(0:136:0/15): ctl_process_done: 138 seconds
(0:139:1/25): WRITE(10). CDB: 2a 00 00 2d c0 80 00 00 80 00 
(0:139:1/25): Tag: 0x0042, type 1
(0:135:1/13): WRITE(10). CDB: 2a 00 00 2e 2f 80 00 00 80 00 
(0:135:1/13): Tag: 0x0040, type 1
(0:135:1/13): ctl_process_done: 138 seconds
(0:132:0/3): WRITE(10). CDB: 2a 00 00 28 1e 00 00 00 80 00 
(0:132:0/3): Tag: 0x0057, type 1
(0:132:0/3): ctl_process_done: 138 seconds
(0:141:0/30): WRITE(10). CDB: 2a 00 00 26 8e 80 00 00 80 00 
(0:141:0/30): Tag: 0x005d, type 1
(0:141:0/30): ctl_process_done: 138 seconds
(0:131:0/0): WRITE(10). CDB: 2a 00 00 26 5d 80 00 00 80 00 
(0:131:0/0): Tag: 0x007a, type 1
(0:131:0/0): ctl_process_done: 138 seconds
(0:134:1/10): WRITE(10). CDB: 2a 00 00 2d 74 00 00 00 80 00 
(0:134:1/10): Tag: 0x0027, type 1
(0:134:1/10): ctl_process_done: 138 seconds
(0:137:0/18): WRITE(10). CDB: 2a 00 00 26 5d 80 00 00 80 00 
(0:137:0/18): Tag: 0x0055, type 1
(0:137:0/18): ctl_process_done: 138 seconds
(0:140:1/28): WRITE(10). CDB: 2a 00 00 34 2e 80 00 00 80 00 
(0:140:1/28): Tag: 0x0049, type 1
(0:140:1/28): ctl_process_done: 138 seconds
(0:139:1/25): ctl_process_done: 138 seconds
(0:142:0/33): WRITE(10). CDB: 2a 00 00 28 64 80 00 00 80 00 
(0:142:0/33): Tag: 0x001b, type 1
(0:142:0/33): ctl_process_done: 138 seconds
NMI/cpu13 ... going to debugger
[ thread pid 11 tid 100016 ]
Stopped at      acpi_cpu_idle_mwait+0x70:       testq   %rsi,%rsi
db:0:kdb.enter.default> write cn_mute 1
cn_mute                0        =            0x1
db:0:kdb.enter.default>  textdump dump
db:0:kdb.enter.default>  reset
cpu_reset: Restarting BSP
cpu_reset: Failed to restart BSP

I believe this testing implicates something in the pool version changes from 11.1 to 11.2. Mav is working with me to get better diagnostic information from the system.

#24 Updated by Ryan McKenzie over 2 years ago

The system is exhibiting two separate failure modes during the LUN fill workload on 11.2 code with 11.2 pool

1) Full lockup - Client visible iSCSI IO stalls to zero for several minutes, UI not responsive, CLI not responsive, console flooded with iSCSI/CTL errors

2) Limp along - Client visible iSCSI IO slows to very few OPS for several minutes with bursts of normal IO rates, UI responsive and shows CPU utilization at or near 100% corresponding to slow IO, CLI responsive and top -SHIz shows mostly zio write threads at 100% on most cores during slow IO, console showing some bursts iSCSI/CTL errors as the slow IO transitions to a burst of faster/normal IO

Reboot, new pool , new zvols = full lockup
No reboot, existing pool, existing zvols = limp along
Reboot, existing pool, existing zvols = limp along
Reboot, existing pool, new zvols = limp along
Reboot, new pool , new zvols = full lockup

#25 Updated by Alexander Motin over 2 years ago

What I see in debugger is that all ZFS write submission threads and many others are blocked waiting for ARC reclamation, blocking all possible disk I/O:

103595                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_0]
103596                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_1]
103597                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_2]
103598                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_3]
103599                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_4]
103600                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_5]
103601                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_6]
103602                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_7]
103603                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_8]
103604                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_9]
101932                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_10]
103605                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_11]
103606                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_12]
103607                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_13]
103608                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_14]
103609                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_15]
103610                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_16]
103611                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_17]
103612                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_18]
103613                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_19]
103614                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_20]
103615                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_21]
103616                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_22]
103617                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_23]
103618                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_24]
103619                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_25]
103620                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_26]
103621                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_27]
103622                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_28]
103623                   D       arc_recl 0xffffffff8167a7c0 [zio_write_issue_29]

Same time ARC reclamation thread is busy draining UMA caches:

100434                   Run     CPU 5                       [arc_reclaim_thread]
db> bt
Tracing pid 15 tid 100434 td 0xfffff8013b03a620
nmi_call_kdb_smp() at nmi_call_kdb_smp+0x6b/frame 0xfffffe3eaa974e10
trap() at trap+0x20d/frame 0xfffffe3eaa974f20
nmi_calltrap() at nmi_calltrap+0x8/frame 0xfffffe3eaa974f20
--- trap 0x13, rip = 0xffffffff80de0e42, rsp = 0xfffffe4fb3cb2ff0, rbp = 0xfffffe4fb3cb3050 ---
smp_targeted_tlb_shootdown() at smp_targeted_tlb_shootdown+0x2f2/frame 0xfffffe4fb3cb3050
smp_masked_invltlb() at smp_masked_invltlb+0x3d/frame 0xfffffe4fb3cb3080
pmap_invalidate_all() at pmap_invalidate_all+0x232/frame 0xfffffe4fb3cb30d0
pmap_remove() at pmap_remove+0x49d/frame 0xfffffe4fb3cb3150
kmem_unback() at kmem_unback+0x27/frame 0xfffffe4fb3cb3190
kmem_free() at kmem_free+0x43/frame 0xfffffe4fb3cb31c0
zone_drain_wait() at zone_drain_wait+0x3a5/frame 0xfffffe4fb3cb3230
arc_kmem_reap_now() at arc_kmem_reap_now+0x8b/frame 0xfffffe4fb3cb3260
arc_reclaim_thread() at arc_reclaim_thread+0x24f/frame 0xfffffe4fb3cb32f0
fork_exit() at fork_exit+0x83/frame 0xfffffe4fb3cb3330
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe4fb3cb3330
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---

So I guess either there is too much in UMA caches to block reclaim thread for minutes, or something is wrong with that with drain process making it too slow.

Some time ago Illumos split the ARC reclamation threat in two, so that one could do ARC reclamation and another drain UMA caches, but unfortunately I haven't found a way to port that to FreeBSD so far due to lowmem KPI differences.

#26 Updated by Alexander Motin over 2 years ago

  • Status changed from Screened to In Progress

I hope this commit I've just made to FreeBSD (https://svnweb.freebsd.org/changeset/base/345200) should help with the issue, or at least reduce its effects on ZFS. I'll build experimental TrueNAS kernel to try.

#27 Updated by Alexander Motin over 2 years ago

  • Status changed from In Progress to Ready for Testing

11-stable commit: https://github.com/freenas/os/commit/400623517186924ddb2ff200584280c2c052cd44
11.2-stable commit: https://github.com/freenas/os/commit/fd62bea52dbd4babb04503a7489f4ca5782fc85d

QE: I run initial tests myself, and what I see looks good. Now performance team will do deeper testing, trying to reproduce this particular issue. Other then that testing priority should be a memory pressure handling by ZFS. Under load there should be no artifacts: should be no unexpected swapping, ARC/Wired/Free memory should have reasonable sizes, etc. We may also wish to test correct memory pressure operation in combination with some plugins/jails/VMs consuming lots of memory.

#28 Updated by Ryan McKenzie over 2 years ago

After receiving the test kernel, I loaded it and quickly ran the 16k and 4k LUN fill workloads on the existing pool/zvols. No iSCSI IO stalls were observed, no missing rrd/collectd data in the reporting charts, UI and CLI remained responsive, and no errors of any kind showed up on the console.

Today I will run with 4k random workloads and add L2ARC into the mix to further test the kernel.

#29 Updated by Dru Lavigne over 2 years ago

  • File deleted (ctlLOG.txt)

#30 Updated by Dru Lavigne over 2 years ago

  • Target version changed from TrueNAS 11.2-U3 to 11.2-U4

#31 Updated by Dru Lavigne over 2 years ago

  • Target version changed from 11.2-U4 to 11.2-U3

#32 Updated by Dru Lavigne over 2 years ago

  • File deleted (debug-20190110150820.tar)

#33 Updated by Dru Lavigne over 2 years ago

  • File deleted (debug-20190222084212.tar)

#34 Updated by Dru Lavigne over 2 years ago

  • File deleted (RUN01-11.2_20190307_M50_L2config-HAdisable_1xNVMeL2ARC_L2write4x_4kBLKSZ_iscsi_RAN4k_100gADSS_0r100w.txt)

#35 Updated by Dru Lavigne over 2 years ago

  • File deleted (RUN01-11.2_20190307_M50_L2config-HAdisable_1xNVMeL2ARC_L2defaults_4kBLKSZ_iscsi_RAN4k_100gADSS_0r100w.txt)

#36 Updated by Dru Lavigne over 2 years ago

  • Subject changed from iSCSI errors on M series, often causing failover to Separate ARC reclamation threads to prevent blocking disk I/O under heavy use
  • Private changed from Yes to No
  • Needs QA changed from No to Yes

#37 Updated by Ryan McKenzie over 2 years ago

  • Status changed from Ready for Testing to Passed Testing

As far as these test conditions are concerned, the previously reported stability issues are not reproducing with the fix Alexander checked in.

Destroy pool, create pool, create zvols
Fill 4k and 16k blocksize LUNs
-Run 4k random IOs on 4k blocksize zvols (1x NVMe L2ARC, increased L2ARC write speed)
-Run 4k random IOs on 4k blocksize zvols (4x NVMe L2ARC, increased L2ARC write speed)

#38 Updated by Dru Lavigne over 2 years ago

  • Status changed from Passed Testing to Done
  • Needs QA changed from Yes to No

Also available in: Atom PDF