<div dir="ltr"><div style="font-size:12.8px">Hi, the engine logs show high latency on storage domains: &quot;Storage domain &lt;xxxx&gt; experienced a high latency of 19.2814 seconds from ...... This may cause performance and functional issues.&quot;</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Looking at host logs, I found also these locking errors:</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">2017-05-02 20:52:13+0200 33883 [10098]: s1 renewal error -202 delta_length 10 last_success 33853</div><div style="font-size:12.8px">2017-05-02 20:52:19+0200 33889 [10098]: 6a386652 aio collect 0 0x7f1fb80008c0:0x7f1fb80008d0:<wbr>0x7f1fbe9fb000 result 1048576:0 other free</div><div style="font-size:12.8px">2017-05-02 21:08:51+0200 34880 [10098]: 6a386652 aio timeout 0 0x7f1fb80008c0:0x7f1fb80008d0:<wbr>0x7f1fbe4f2000 ioto 10 to_count 24</div><div style="font-size:12.8px">2017-05-02 21:08:51+0200 34880 [10098]: s1 delta_renew read rv -202 offset 0 /dev/6a386652-629d-4045-835b-<wbr>21d2f5c104aa/ids</div><div style="font-size:12.8px">2017-05-02 21:08:51+0200 34880 [10098]: s1 renewal error -202 delta_length 10 last_success 34850</div><div style="font-size:12.8px">2017-05-02 21:08:53+0200 34883 [10098]: 6a386652 aio collect 0 0x7f1fb80008c0:0x7f1fb80008d0:<wbr>0x7f1fbe4f2000 result 1048576:0 other free</div><div style="font-size:12.8px">2017-05-02 21:30:40+0200 36189 [10098]: 6a386652 aio timeout 0 0x7f1fb80008c0:0x7f1fb80008d0:<wbr>0x7f1fbe9fb000 ioto 10 to_count 25</div><div style="font-size:12.8px">2017-05-02 21:30:40+0200 36189 [10098]: s1 delta_renew read rv -202 offset 0 /dev/6a386652-629d-4045-835b-<wbr>21d2f5c104aa/ids</div><div style="font-size:12.8px">2017-05-02 21:30:40+0200 36189 [10098]: s1 renewal error -202 delta_length 10 last_success 36159</div><div style="font-size:12.8px">2017-05-02 21:30:45+0200 36195 [10098]: 6a386652 aio collect 0 0x7f1fb80008c0:0x7f1fb80008d0:<wbr>0x7f1fbe9fb000 result 1048576:0 other free</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">and this vdsm errors too:</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Thread-22::ERROR::2017-05-02 21:53:48,147::sdc::137::<wbr>Storage.StorageDomainCache::(_<wbr>findDomain) looking for unfetched domain f8f21d6c-2425-45c4-aded-<wbr>4cb9b53ebd96</div><div style="font-size:12.8px">Thread-22::ERROR::2017-05-02 21:53:48,148::sdc::154::<wbr>Storage.StorageDomainCache::(_<wbr>findUnfetchedDomain) looking for domain f8f21d6c-2425-45c4-aded-<wbr>4cb9b53ebd96</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Engine instead is showing this errors:</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">2017-05-02 21:40:38,089 ERROR [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>SpmStatusVDSCommand] (DefaultQuartzScheduler_<wbr>Worker-96) Command SpmStatusVDSCommand(HostName = &lt;<a href="http://myhost.example.com/" target="_blank">myhost.example.com</a>&gt;, HostId = dcc0275a-b011-4e33-bb95-<wbr>366ffb0697b3, storagePoolId = 715d1ba2-eabe-48db-9aea-<wbr>c28c30359808) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to SpmStatusVDS, error = (-202, &#39;Sanlock resource read failure&#39;, &#39;Sanlock exception&#39;), code = 100</div><div style="font-size:12.8px">2017-05-02 21:41:08,431 ERROR [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>SpmStatusVDSCommand] (DefaultQuartzScheduler_<wbr>Worker-53) [6e0d5ebf] Failed in SpmStatusVDS method</div><div style="font-size:12.8px">2017-05-02 21:41:08,443 ERROR [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>SpmStatusVDSCommand] (DefaultQuartzScheduler_<wbr>Worker-53) [6e0d5ebf] Command SpmStatusVDSCommand(HostName = &lt;<a href="http://myhost.example.com/" target="_blank">myhost.example.com</a>&gt;, HostId = 7991933e-5f30-48cd-88bf-<wbr>b0b525613384, storagePoolId = 4bd73239-22d0-4c44-ab8c-<wbr>17adcd580309) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to SpmStatusVDS, error = (-202, &#39;Sanlock resource read failure&#39;, &#39;Sanlock exception&#39;), code = 100</div><div style="font-size:12.8px">2017-05-02 21:41:31,975 ERROR [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>SpmStatusVDSCommand] (DefaultQuartzScheduler_<wbr>Worker-61) [2a54a1b2] Failed in SpmStatusVDS method</div><div style="font-size:12.8px">2017-05-02 21:41:31,987 ERROR [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>SpmStatusVDSCommand] (DefaultQuartzScheduler_<wbr>Worker-61) [2a54a1b2] Command SpmStatusVDSCommand(HostName = &lt;<a href="http://myhost.example.com/" target="_blank">myhost.example.com</a>&gt;, HostId = dcc0275a-b011-4e33-bb95-<wbr>366ffb0697b3, storagePoolId = 715d1ba2-eabe-48db-9aea-<wbr>c28c30359808) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to SpmStatusVDS, error = (-202, &#39;Sanlock resource read failure&#39;, &#39;Sanlock exception&#39;), code = 100</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">I&#39;m using Fibre Channel or FCoE connectivity; storage array technical support has analyzed it (also switch and OS configurations), but nothing has been found.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Any advice?</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Thanks</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Installation info:</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">ovirt-release35-006-1.noarch</div><div style="font-size:12.8px">libgovirt-0.3.3-1.el7_2.1.x86_<wbr>64</div><div style="font-size:12.8px">vdsm-4.16.30-0.el7.centos.x86_<wbr>64</div><div style="font-size:12.8px">vdsm-xmlrpc-4.16.30-0.el7.<wbr>centos.noarch</div><div style="font-size:12.8px">vdsm-yajsonrpc-4.16.30-0.el7.<wbr>centos.noarch</div><div style="font-size:12.8px">vdsm-jsonrpc-4.16.30-0.el7.<wbr>centos.noarch</div><div style="font-size:12.8px">vdsm-python-zombiereaper-4.16.<wbr>30-0.el7.centos.noarch</div><div style="font-size:12.8px">vdsm-python-4.16.30-0.el7.<wbr>centos.noarch</div><div style="font-size:12.8px">vdsm-cli-4.16.30-0.el7.centos.<wbr>noarch</div><div style="font-size:12.8px">qemu-kvm-ev-2.3.0-29.1.el7.<wbr>x86_64</div><div style="font-size:12.8px">qemu-kvm-common-ev-2.3.0-29.1.<wbr>el7.x86_64</div><div style="font-size:12.8px">qemu-kvm-tools-ev-2.3.0-29.1.<wbr>el7.x86_64</div><div style="font-size:12.8px">libvirt-client-1.2.17-13.el7_<wbr>2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-storage-<wbr>1.2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-python-1.2.17-2.el7.<wbr>x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-<wbr>nwfilter-1.2.17-13.el7_2.3.<wbr>x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-nodedev-<wbr>1.2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-lock-sanlock-1.2.17-<wbr>13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-glib-0.1.9-1.el7.x86_<wbr>64</div><div style="font-size:12.8px">libvirt-daemon-driver-network-<wbr>1.2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-lxc-1.2.<wbr>17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-<wbr>interface-1.2.17-13.el7_2.3.<wbr>x86_64</div><div style="font-size:12.8px">libvirt-1.2.17-13.el7_2.3.x86_<wbr>64</div><div style="font-size:12.8px">libvirt-daemon-1.2.17-13.el7_<wbr>2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-config-network-<wbr>1.2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-secret-<wbr>1.2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-config-<wbr>nwfilter-1.2.17-13.el7_2.3.<wbr>x86_64</div><div style="font-size:12.8px">libvirt-daemon-kvm-1.2.17-13.<wbr>el7_2.3.x86_64</div><div style="font-size:12.8px">libvirt-daemon-driver-qemu-1.<wbr>2.17-13.el7_2.3.x86_64</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">------- vdsm.log (high latency)</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Thread-21::DEBUG::2017-05-02 18:02:23,646::fileSD::261::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;0+1 records in\n0+1 records out\n331 bytes (331 B) copied, 0.000285529 s, 1.2 MB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">Thread-18::DEBUG::2017-05-02 18:02:24,335::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) /bin/dd if=/dev/2c501858-bf8d-49a5-<wbr>a42b-bca341b47827/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)</div><div style="font-size:12.8px">Thread-18::DEBUG::2017-05-02 18:02:24,343::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000489782 s, 8.4 MB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">Thread-19::DEBUG::2017-05-02 18:02:24,635::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) /bin/dd if=/dev/c5dc09c4-cd79-42d2-<wbr>a5af-89953076f79e/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)</div><div style="font-size:12.8px">Thread-19::DEBUG::2017-05-02 18:02:24,643::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000558622 s, 7.3 MB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">Thread-22::DEBUG::2017-05-02 18:02:24,722::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) /bin/dd if=/dev/f8f21d6c-2425-45c4-<wbr>aded-4cb9b53ebd96/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)</div><div style="font-size:12.8px">Thread-22::DEBUG::2017-05-02 18:02:24,729::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000632576 s, 6.5 MB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">JsonRpc (StompReactor)::DEBUG::2017-<wbr>05-02 18:02:25,056::stompReactor::<wbr>98::Broker.StompAdapter::(<wbr>handle_frame) Handling message &lt;StompFrame command=&#39;SEND&#39;&gt;</div><div style="font-size:12.8px">JsonRpcServer::DEBUG::2017-05-<wbr>02 18:02:25,057::__init__::506::<wbr>jsonrpc.JsonRpcServer::(serve_<wbr>requests) Waiting for request</div><div style="font-size:12.8px">Thread-9372::DEBUG::2017-05-02 18:02:25,060::stompReactor::<wbr>163::yajsonrpc.StompServer::(<wbr>send) Sending response</div><div style="font-size:12.8px">Thread-20::DEBUG::2017-05-02 18:02:25,895::blockSD::596::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 19.2814 s, 0.2 kB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">JsonRpc (StompReactor)::DEBUG::2017-<wbr>05-02 18:02:28,075::stompReactor::<wbr>98::Broker.StompAdapter::(<wbr>handle_frame) Handling message &lt;StompFrame command=&#39;SEND&#39;&gt;</div><div style="font-size:12.8px">JsonRpcServer::DEBUG::2017-05-<wbr>02 18:02:28,076::__init__::506::<wbr>jsonrpc.JsonRpcServer::(serve_<wbr>requests) Waiting for request</div><div style="font-size:12.8px">Thread-9373::DEBUG::2017-05-02 18:02:28,078::stompReactor::<wbr>163::yajsonrpc.StompServer::(<wbr>send) Sending response</div><div style="font-size:12.8px">JsonRpc (StompReactor)::DEBUG::2017-<wbr>05-02 18:02:31,094::stompReactor::<wbr>98::Broker.StompAdapter::(<wbr>handle_frame) Handling message &lt;StompFrame command=&#39;SEND&#39;&gt;</div><div style="font-size:12.8px">JsonRpcServer::DEBUG::2017-05-<wbr>02 18:02:31,095::__init__::506::<wbr>jsonrpc.JsonRpcServer::(serve_<wbr>requests) Waiting for request</div><div style="font-size:12.8px">Thread-9374::DEBUG::2017-05-02 18:02:31,097::stompReactor::<wbr>163::yajsonrpc.StompServer::(<wbr>send) Sending response</div><div style="font-size:12.8px">Thread-21::DEBUG::2017-05-02 18:02:33,652::fileSD::261::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) /bin/dd if=/rhev/data-center/mnt/&lt;<a href="http://myhost.example.com/" target="_blank">myho<wbr>st.example.com</a>&gt;:_ISO/f105bdc6-<wbr>efdc-445c-b49e-aa38c91c2569/<wbr>dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)</div><div style="font-size:12.8px">Thread-21::DEBUG::2017-05-02 18:02:33,660::fileSD::261::<wbr>Storage.Misc.excCmd::(<wbr>getReadDelay) SUCCESS: &lt;err&gt; = &#39;0+1 records in\n0+1 records out\n331 bytes (331 B) copied, 0.000246594 s, 1.3 MB/s\n&#39;; &lt;rc&gt; = 0</div><div style="font-size:12.8px">JsonRpc (StompReactor)::DEBUG::2017-<wbr>05-02 18:02:34,112::stompReactor::<wbr>98::Broker.StompAdapter::(<wbr>handle_frame) Handling message &lt;StompFrame command=&#39;SEND&#39;&gt;</div><div style="font-size:12.8px">JsonRpcServer::DEBUG::2017-05-<wbr>02 18:02:34,114::__init__::506::<wbr>jsonrpc.JsonRpcServer::(serve_<wbr>requests) Waiting for request</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,117::task::595::<wbr>Storage.TaskManager.Task::(_<wbr>updateState) Task=`ea63814e-d25d-4436-8bb5-<wbr>cfc67af6498d`::moving from state init -&gt; state preparing</div><div style="font-size:12.8px">Thread-9375::INFO::2017-05-02 18:02:34,117::logUtils::44::<wbr>dispatcher::(wrapper) Run and protect: repoStats(options=None)</div><div style="font-size:12.8px">Thread-9375::INFO::2017-05-02 18:02:34,118::logUtils::47::<wbr>dispatcher::(wrapper) Run and protect: repoStats, Return response: {&#39;2c501858-bf8d-49a5-a42b-<wbr>bca341b47827&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000489782&#39;, &#39;lastCheck&#39;: &#39;9.8&#39;, &#39;valid&#39;: True}, &#39;f8f21d6c-2425-45c4-aded-<wbr>4cb9b53ebd96&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000632576&#39;, &#39;lastCheck&#39;: &#39;9.4&#39;, &#39;valid&#39;: True}, &#39;6a386652-629d-4045-835b-<wbr>21d2f5c104aa&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;19.2814&#39;, &#39;lastCheck&#39;: &#39;8.2&#39;, &#39;valid&#39;: True}, &#39;f105bdc6-efdc-445c-b49e-<wbr>aa38c91c2569&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 0, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000246594&#39;, &#39;lastCheck&#39;: &#39;0.5&#39;, &#39;valid&#39;: True}, &#39;c5dc09c4-cd79-42d2-a5af-<wbr>89953076f79e&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000558622&#39;, &#39;lastCheck&#39;: &#39;9.5&#39;, &#39;valid&#39;: True}}</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,118::task::1191::<wbr>Storage.TaskManager.Task::(<wbr>prepare) Task=`ea63814e-d25d-4436-8bb5-<wbr>cfc67af6498d`::finished: {&#39;2c501858-bf8d-49a5-a42b-<wbr>bca341b47827&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000489782&#39;, &#39;lastCheck&#39;: &#39;9.8&#39;, &#39;valid&#39;: True}, &#39;f8f21d6c-2425-45c4-aded-<wbr>4cb9b53ebd96&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000632576&#39;, &#39;lastCheck&#39;: &#39;9.4&#39;, &#39;valid&#39;: True}, &#39;6a386652-629d-4045-835b-<wbr>21d2f5c104aa&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;19.2814&#39;, &#39;lastCheck&#39;: &#39;8.2&#39;, &#39;valid&#39;: True}, &#39;f105bdc6-efdc-445c-b49e-<wbr>aa38c91c2569&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 0, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000246594&#39;, &#39;lastCheck&#39;: &#39;0.5&#39;, &#39;valid&#39;: True}, &#39;c5dc09c4-cd79-42d2-a5af-<wbr>89953076f79e&#39;: {&#39;code&#39;: 0, &#39;version&#39;: 3, &#39;acquired&#39;: True, &#39;delay&#39;: &#39;0.000558622&#39;, &#39;lastCheck&#39;: &#39;9.5&#39;, &#39;valid&#39;: True}}</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,119::task::595::<wbr>Storage.TaskManager.Task::(_<wbr>updateState) Task=`ea63814e-d25d-4436-8bb5-<wbr>cfc67af6498d`::moving from state preparing -&gt; state finished</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,119::resourceManager:<wbr>:940::Storage.ResourceManager.<wbr>Owner::(releaseAll) Owner.releaseAll requests {} resources {}</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,119::resourceManager:<wbr>:977::Storage.ResourceManager.<wbr>Owner::(cancelAll) Owner.cancelAll requests {}</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,119::task::993::<wbr>Storage.TaskManager.Task::(_<wbr>decref) Task=`ea63814e-d25d-4436-8bb5-<wbr>cfc67af6498d`::ref 0 aborting False</div><div style="font-size:12.8px">Thread-9375::DEBUG::2017-05-02 18:02:34,122::stompReactor::<wbr>163::yajsonrpc.StompServer::(<wbr>send) Sending response</div><div style="font-size:12.8px">JsonRpc (StompReactor)::DEBUG::2017-<wbr>05-02 18:02:34,128::stompReactor::<wbr>98::Broker.StompAdapter::(<wbr>handle_frame) Handling message &lt;StompFrame command=&#39;SEND&#39;&gt;</div><div style="font-size:12.8px">JsonRpcServer::DEBUG::2017-05-<wbr>02 18:02:34,129::__init__::506::<wbr>jsonrpc.JsonRpcServer::(serve_<wbr>requests) Waiting for request</div><div style="font-size:12.8px">Thread-9376::DEBUG::2017-05-02 18:02:34,132::stompReactor::<wbr>163::yajsonrpc.StompServer::(<wbr>send) Sending response</div></div>