1262675 – domainMonitor thread blocked/died

Bug 1262675 - domainMonitor thread blocked/died

Summary: domainMonitor thread blocked/died

Keywords:
Status:	CLOSED INSUFFICIENT_DATA
Alias:	None
Product:	Red Hat Enterprise Virtualization Manager
Classification:	Red Hat
Component:	vdsm
Sub Component:
Version:	3.5.3
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	high
Target Milestone:	ovirt-3.6.1
Target Release:	3.6.0
Assignee:	Nir Soffer
QA Contact:	Aharon Canan
Docs Contact:
URL:
Whiteboard:	storage
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2015-09-14 05:10 UTC by Pavel Zhukov
Modified:	2019-10-10 10:11 UTC (History)
CC List:	11 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2015-11-11 02:17:23 UTC
oVirt Team:	Storage
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Description Pavel Zhukov 2015-09-14 05:10:54 UTC

Description of problem:
At some moment of time domainMonitor thread stops monitor activity so lastCheck time is updated anymore leads host moved to NonOperational (After 17000+ seconds vdsmd was restarted)

Version-Release number of selected component (if applicable):
vdsm-4.16.20-1.el6ev.x86_64 

How reproducible:
No reproducer.

Actual results:
Host is NonOperational and cannot be activated (Unassigned)

Expected results:
Active host

Additional info:

Comment 4 Allon Mureinik 2015-09-16 08:47:30 UTC

Tentatively targetting until we know what's going on here.

Nir - can you take a look please?

Comment 5 Nir Soffer 2015-09-16 09:51:42 UTC

Looking in repostat, we see that *all* threads have max lastCheck of 
5400 seconds:

repostat vdsm.log.5 
domain: e1aacd66-fb9d-406c-a1d3-af160feca832
  delay      avg: 0.000306 min: 0.000172 max: 0.007093
  last check avg: 780.627500 min: 0.000000 max: 5416.200000
domain: 01770df2-65da-4855-b6ed-ed7d3ac37824
  delay      avg: 0.000403 min: 0.000169 max: 0.010608
  last check avg: 781.815833 min: 0.000000 max: 5420.000000
domain: 4b820fec-7a8f-4964-ae0c-b051dea2d191
  delay      avg: 0.000254 min: 0.000177 max: 0.005321
  last check avg: 781.385208 min: 0.000000 max: 5418.700000
domain: 5ee54f49-c890-4d59-b9ef-8102f43b9428
  delay      avg: 0.000378 min: 0.000179 max: 0.015049
  last check avg: 780.289792 min: 0.000000 max: 5415.200000
domain: 1fe2e087-eae3-407c-8a49-e7a5a3a56de3
  delay      avg: 0.000314 min: 0.000178 max: 0.008837
  last check avg: 779.525833 min: 0.000000 max: 5413.000000
domain: c4eb674a-75dc-4fca-9454-1063a142d1e0
  delay      avg: 0.000311 min: 0.000158 max: 0.009225
  last check avg: 781.422292 min: 0.000000 max: 5418.800000
domain: 60a88b07-5f91-49a9-a35d-82987f6415af
  delay      avg: 0.000395 min: 0.000186 max: 0.008028
  last check avg: 779.278750 min: 0.100000 max: 5411.900000
domain: 3e11aff4-210e-44ae-a121-88dab7d12e7f
  delay      avg: 0.000345 min: 0.000179 max: 0.010076
  last check avg: 781.433750 min: 0.000000 max: 5418.900000
domain: f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e
  delay      avg: 0.000329 min: 0.000177 max: 0.005819
  last check avg: 780.326250 min: 0.000000 max: 5415.400000
domain: 87743317-af6d-4c68-9a86-be90c63db94d
  delay      avg: 0.000282 min: 0.000168 max: 0.007202
  last check avg: 781.799583 min: 0.000000 max: 5420.000000
domain: e7652076-444b-4c38-aea9-8f2e128c5298
  delay      avg: 0.000318 min: 0.000179 max: 0.009455
  last check avg: 779.608958 min: 0.100000 max: 5413.200000
domain: 17d79935-de71-40b6-b0ae-1d8091ecfd74
  delay      avg: 0.000323 min: 0.000180 max: 0.009318
  last check avg: 781.995208 min: 0.000000 max: 5420.600000
domain: 084505e6-835e-4359-80ea-5cda6ff80c42
  delay      avg: 0.000352 min: 0.000176 max: 0.006644
  last check avg: 781.545625 min: 0.000000 max: 5419.200000
domain: df578737-e18c-4c41-87ad-2c858902ba30
  delay      avg: 0.000368 min: 0.000175 max: 0.008293
  last check avg: 779.158125 min: 0.000000 max: 5411.700000
domain: 7bfe4a5f-2e9f-49b7-b980-374eb60d81ae
  delay      avg: 0.000321 min: 0.000163 max: 0.010011
  last check avg: 781.566875 min: 0.000000 max: 5419.200000
domain: 6307bc56-71e1-44ae-bda8-258b12381a4d
  delay      avg: 0.000359 min: 0.000176 max: 0.009934
  last check avg: 782.070000 min: 0.000000 max: 5420.600000
domain: ff6dc474-662b-4096-ac37-d0b8ec098cc0
  delay      avg: 0.000306 min: 0.000166 max: 0.005204
  last check avg: 779.180417 min: 0.000000 max: 5411.700000

Looking at the domain monitor threads using this command:

for t in $(grep getReadDelay vdsm.log.5 | awk 'BEGIN {FS="::"} { print $1}' | sort -u); do echo ---- $t ----; grep $t vdsm.log.5 | tail -n10; echo; done

---- Thread-108 ----
Thread-108::DEBUG::2015-08-23 18:24:03,828::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_backup__a01_images/60a88b07-5f91-49a9-a35d-82987f6415af/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-108::DEBUG::2015-08-23 18:24:03,841::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000227746 s, 1.6 MB/s\n'; <rc> = 0
Thread-108::DEBUG::2015-08-23 18:24:13,846::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_backup__a01_images/60a88b07-5f91-49a9-a35d-82987f6415af/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-108::DEBUG::2015-08-23 18:24:13,859::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000206724 s, 1.8 MB/s\n'; <rc> = 0
Thread-108::DEBUG::2015-08-23 18:24:23,863::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_backup__a01_images/60a88b07-5f91-49a9-a35d-82987f6415af/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-108::DEBUG::2015-08-23 18:24:23,877::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00022793 s, 1.6 MB/s\n'; <rc> = 0
Thread-108::DEBUG::2015-08-23 18:24:33,882::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_backup__a01_images/60a88b07-5f91-49a9-a35d-82987f6415af/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-108::DEBUG::2015-08-23 18:24:33,895::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000239284 s, 1.5 MB/s\n'; <rc> = 0
Thread-108::DEBUG::2015-08-23 18:24:43,901::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_backup__a01_images/60a88b07-5f91-49a9-a35d-82987f6415af/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-108::DEBUG::2015-08-23 18:24:43,914::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000233062 s, 1.6 MB/s\n'; <rc> = 0

---- Thread-126 ----
Thread-126::DEBUG::2015-08-23 18:23:56,906::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a07_images/3e11aff4-210e-44ae-a121-88dab7d12e7f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-126::DEBUG::2015-08-23 18:23:56,920::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000276086 s, 1.3 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-08-23 18:24:06,924::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a07_images/3e11aff4-210e-44ae-a121-88dab7d12e7f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-126::DEBUG::2015-08-23 18:24:06,938::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000357156 s, 1.0 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-08-23 18:24:16,942::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a07_images/3e11aff4-210e-44ae-a121-88dab7d12e7f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-126::DEBUG::2015-08-23 18:24:16,955::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00020966 s, 1.7 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-08-23 18:24:26,959::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a07_images/3e11aff4-210e-44ae-a121-88dab7d12e7f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-126::DEBUG::2015-08-23 18:24:26,972::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000266761 s, 1.4 MB/s\n'; <rc> = 0
Thread-126::DEBUG::2015-08-23 18:24:36,977::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a07_images/3e11aff4-210e-44ae-a121-88dab7d12e7f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-126::DEBUG::2015-08-23 18:24:36,990::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000246847 s, 1.5 MB/s\n'; <rc> = 0

---- Thread-144 ----
Thread-144::DEBUG::2015-08-23 18:24:00,421::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a06_images/f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-144::DEBUG::2015-08-23 18:24:00,434::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000229915 s, 1.6 MB/s\n'; <rc> = 0
Thread-144::DEBUG::2015-08-23 18:24:10,439::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a06_images/f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-144::DEBUG::2015-08-23 18:24:10,452::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000273458 s, 1.3 MB/s\n'; <rc> = 0
Thread-144::DEBUG::2015-08-23 18:24:20,456::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a06_images/f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-144::DEBUG::2015-08-23 18:24:20,470::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00024744 s, 1.5 MB/s\n'; <rc> = 0
Thread-144::DEBUG::2015-08-23 18:24:30,474::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a06_images/f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-144::DEBUG::2015-08-23 18:24:30,488::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000233451 s, 1.6 MB/s\n'; <rc> = 0
Thread-144::DEBUG::2015-08-23 18:24:40,493::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a06_images/f422ee9d-bc96-4a9a-a793-9dbb60ef7f6e/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-144::DEBUG::2015-08-23 18:24:40,506::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00022355 s, 1.6 MB/s\n'; <rc> = 0

---- Thread-162 ----
Thread-162::DEBUG::2015-08-23 18:23:55,630::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b07_images/87743317-af6d-4c68-9a86-be90c63db94d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-162::DEBUG::2015-08-23 18:23:55,657::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000224789 s, 1.6 MB/s\n'; <rc> = 0
Thread-162::DEBUG::2015-08-23 18:24:05,674::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b07_images/87743317-af6d-4c68-9a86-be90c63db94d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-162::DEBUG::2015-08-23 18:24:05,690::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00027731 s, 1.3 MB/s\n'; <rc> = 0
Thread-162::DEBUG::2015-08-23 18:24:15,725::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b07_images/87743317-af6d-4c68-9a86-be90c63db94d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-162::DEBUG::2015-08-23 18:24:15,738::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000249427 s, 1.5 MB/s\n'; <rc> = 0
Thread-162::DEBUG::2015-08-23 18:24:25,749::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b07_images/87743317-af6d-4c68-9a86-be90c63db94d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-162::DEBUG::2015-08-23 18:24:25,768::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000224369 s, 1.6 MB/s\n'; <rc> = 0
Thread-162::DEBUG::2015-08-23 18:24:35,804::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b07_images/87743317-af6d-4c68-9a86-be90c63db94d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-162::DEBUG::2015-08-23 18:24:35,820::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000191629 s, 1.9 MB/s\n'; <rc> = 0

---- Thread-176 ----
Thread-176::DEBUG::2015-08-23 18:24:02,604::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b05_images/e7652076-444b-4c38-aea9-8f2e128c5298/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-176::DEBUG::2015-08-23 18:24:02,618::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00021897 s, 1.7 MB/s\n'; <rc> = 0
Thread-176::DEBUG::2015-08-23 18:24:12,624::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b05_images/e7652076-444b-4c38-aea9-8f2e128c5298/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-176::DEBUG::2015-08-23 18:24:12,636::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000219709 s, 1.7 MB/s\n'; <rc> = 0
Thread-176::DEBUG::2015-08-23 18:24:22,641::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b05_images/e7652076-444b-4c38-aea9-8f2e128c5298/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-176::DEBUG::2015-08-23 18:24:22,653::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00023559 s, 1.5 MB/s\n'; <rc> = 0
Thread-176::DEBUG::2015-08-23 18:24:32,657::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b05_images/e7652076-444b-4c38-aea9-8f2e128c5298/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-176::DEBUG::2015-08-23 18:24:32,670::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000229333 s, 1.6 MB/s\n'; <rc> = 0
Thread-176::DEBUG::2015-08-23 18:24:42,674::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b05_images/e7652076-444b-4c38-aea9-8f2e128c5298/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-176::DEBUG::2015-08-23 18:24:42,687::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000221581 s, 1.6 MB/s\n'; <rc> = 0

---- Thread-187 ----
Thread-187::DEBUG::2015-08-23 18:23:54,998::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a_images/17d79935-de71-40b6-b0ae-1d8091ecfd74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-187::DEBUG::2015-08-23 18:23:55,011::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1179 bytes (1.2 kB) copied, 0.000336322 s, 3.5 MB/s\n'; <rc> = 0
Thread-187::DEBUG::2015-08-23 18:24:05,024::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a_images/17d79935-de71-40b6-b0ae-1d8091ecfd74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-187::DEBUG::2015-08-23 18:24:05,041::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1179 bytes (1.2 kB) copied, 0.000626786 s, 1.9 MB/s\n'; <rc> = 0
Thread-187::DEBUG::2015-08-23 18:24:15,138::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a_images/17d79935-de71-40b6-b0ae-1d8091ecfd74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-187::DEBUG::2015-08-23 18:24:15,156::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1179 bytes (1.2 kB) copied, 0.00119733 s, 985 kB/s\n'; <rc> = 0
Thread-187::DEBUG::2015-08-23 18:24:25,190::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a_images/17d79935-de71-40b6-b0ae-1d8091ecfd74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-187::DEBUG::2015-08-23 18:24:25,201::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1179 bytes (1.2 kB) copied, 0.000199656 s, 5.9 MB/s\n'; <rc> = 0
Thread-187::DEBUG::2015-08-23 18:24:35,227::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a_images/17d79935-de71-40b6-b0ae-1d8091ecfd74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-187::DEBUG::2015-08-23 18:24:35,240::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1179 bytes (1.2 kB) copied, 0.000257967 s, 4.6 MB/s\n'; <rc> = 0

---- Thread-202 ----
Thread-202::DEBUG::2015-08-23 18:23:56,591::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a02_images/084505e6-835e-4359-80ea-5cda6ff80c42/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-202::DEBUG::2015-08-23 18:23:56,605::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000282698 s, 1.3 MB/s\n'; <rc> = 0
Thread-202::DEBUG::2015-08-23 18:24:06,609::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a02_images/084505e6-835e-4359-80ea-5cda6ff80c42/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-202::DEBUG::2015-08-23 18:24:06,620::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00020585 s, 1.8 MB/s\n'; <rc> = 0
Thread-202::DEBUG::2015-08-23 18:24:16,624::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a02_images/084505e6-835e-4359-80ea-5cda6ff80c42/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-202::DEBUG::2015-08-23 18:24:16,637::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000259995 s, 1.4 MB/s\n'; <rc> = 0
Thread-202::DEBUG::2015-08-23 18:24:26,650::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a02_images/084505e6-835e-4359-80ea-5cda6ff80c42/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-202::DEBUG::2015-08-23 18:24:26,669::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000234773 s, 1.6 MB/s\n'; <rc> = 0
Thread-202::DEBUG::2015-08-23 18:24:36,684::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a02_images/084505e6-835e-4359-80ea-5cda6ff80c42/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-202::DEBUG::2015-08-23 18:24:36,696::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000263237 s, 1.4 MB/s\n'; <rc> = 0

---- Thread-211 ----
Thread-211::DEBUG::2015-08-23 18:24:04,011::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a04_images/df578737-e18c-4c41-87ad-2c858902ba30/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-211::DEBUG::2015-08-23 18:24:04,024::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000290445 s, 1.3 MB/s\n'; <rc> = 0
Thread-211::DEBUG::2015-08-23 18:24:14,038::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a04_images/df578737-e18c-4c41-87ad-2c858902ba30/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-211::DEBUG::2015-08-23 18:24:14,050::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00024518 s, 1.5 MB/s\n'; <rc> = 0
Thread-211::DEBUG::2015-08-23 18:24:24,054::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a04_images/df578737-e18c-4c41-87ad-2c858902ba30/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-211::DEBUG::2015-08-23 18:24:24,067::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000390472 s, 932 kB/s\n'; <rc> = 0
Thread-211::DEBUG::2015-08-23 18:24:34,086::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a04_images/df578737-e18c-4c41-87ad-2c858902ba30/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-211::DEBUG::2015-08-23 18:24:34,103::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000204438 s, 1.8 MB/s\n'; <rc> = 0
Thread-211::DEBUG::2015-08-23 18:24:44,127::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a04_images/df578737-e18c-4c41-87ad-2c858902ba30/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-211::DEBUG::2015-08-23 18:24:44,144::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000228129 s, 1.6 MB/s\n'; <rc> = 0

---- Thread-219 ----
Thread-219::DEBUG::2015-08-23 18:23:55,024::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_exp__imp__a_images/6307bc56-71e1-44ae-bda8-258b12381a4d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-219::DEBUG::2015-08-23 18:23:55,041::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00462222 s, 78.8 kB/s\n'; <rc> = 0
Thread-219::DEBUG::2015-08-23 18:24:05,060::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_exp__imp__a_images/6307bc56-71e1-44ae-bda8-258b12381a4d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-219::DEBUG::2015-08-23 18:24:05,082::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000290695 s, 1.3 MB/s\n'; <rc> = 0
Thread-219::DEBUG::2015-08-23 18:24:15,121::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_exp__imp__a_images/6307bc56-71e1-44ae-bda8-258b12381a4d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-219::DEBUG::2015-08-23 18:24:15,150::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000286317 s, 1.3 MB/s\n'; <rc> = 0
Thread-219::DEBUG::2015-08-23 18:24:25,168::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_exp__imp__a_images/6307bc56-71e1-44ae-bda8-258b12381a4d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-219::DEBUG::2015-08-23 18:24:25,183::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000211165 s, 1.7 MB/s\n'; <rc> = 0
Thread-219::DEBUG::2015-08-23 18:24:35,203::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_exp__imp__a_images/6307bc56-71e1-44ae-bda8-258b12381a4d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-219::DEBUG::2015-08-23 18:24:35,221::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000236952 s, 1.5 MB/s\n'; <rc> = 0

---- Thread-234 ----
Thread-234::DEBUG::2015-08-23 18:23:56,539::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b02_images/7bfe4a5f-2e9f-49b7-b980-374eb60d81ae/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-234::DEBUG::2015-08-23 18:23:56,552::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000383872 s, 948 kB/s\n'; <rc> = 0
Thread-234::DEBUG::2015-08-23 18:24:06,556::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b02_images/7bfe4a5f-2e9f-49b7-b980-374eb60d81ae/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-234::DEBUG::2015-08-23 18:24:06,569::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000225198 s, 1.6 MB/s\n'; <rc> = 0
Thread-234::DEBUG::2015-08-23 18:24:16,573::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b02_images/7bfe4a5f-2e9f-49b7-b980-374eb60d81ae/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-234::DEBUG::2015-08-23 18:24:16,586::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000301831 s, 1.2 MB/s\n'; <rc> = 0
Thread-234::DEBUG::2015-08-23 18:24:26,595::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b02_images/7bfe4a5f-2e9f-49b7-b980-374eb60d81ae/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-234::DEBUG::2015-08-23 18:24:26,610::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000254228 s, 1.4 MB/s\n'; <rc> = 0
Thread-234::DEBUG::2015-08-23 18:24:36,622::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b02_images/7bfe4a5f-2e9f-49b7-b980-374eb60d81ae/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-234::DEBUG::2015-08-23 18:24:36,635::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000196667 s, 1.9 MB/s\n'; <rc> = 0

---- Thread-31 ----
Thread-31::DEBUG::2015-08-23 18:23:59,558::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b03_images/e1aacd66-fb9d-406c-a1d3-af160feca832/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-08-23 18:23:59,571::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000229515 s, 1.6 MB/s\n'; <rc> = 0
Thread-31::DEBUG::2015-08-23 18:24:09,575::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b03_images/e1aacd66-fb9d-406c-a1d3-af160feca832/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-08-23 18:24:09,588::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000240762 s, 1.5 MB/s\n'; <rc> = 0
Thread-31::DEBUG::2015-08-23 18:24:19,593::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b03_images/e1aacd66-fb9d-406c-a1d3-af160feca832/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-08-23 18:24:19,606::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000241095 s, 1.5 MB/s\n'; <rc> = 0
Thread-31::DEBUG::2015-08-23 18:24:29,610::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b03_images/e1aacd66-fb9d-406c-a1d3-af160feca832/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-08-23 18:24:29,626::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000765412 s, 476 kB/s\n'; <rc> = 0
Thread-31::DEBUG::2015-08-23 18:24:39,630::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b03_images/e1aacd66-fb9d-406c-a1d3-af160feca832/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-08-23 18:24:39,643::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000252066 s, 1.4 MB/s\n'; <rc> = 0

---- Thread-32 ----
Thread-32::DEBUG::2015-08-23 18:23:55,632::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a03_images/01770df2-65da-4855-b6ed-ed7d3ac37824/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-08-23 18:23:55,660::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000271435 s, 1.3 MB/s\n'; <rc> = 0
Thread-32::DEBUG::2015-08-23 18:24:05,703::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a03_images/01770df2-65da-4855-b6ed-ed7d3ac37824/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-08-23 18:24:05,724::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000297625 s, 1.2 MB/s\n'; <rc> = 0
Thread-32::DEBUG::2015-08-23 18:24:15,744::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a03_images/01770df2-65da-4855-b6ed-ed7d3ac37824/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-08-23 18:24:15,756::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000230179 s, 1.6 MB/s\n'; <rc> = 0
Thread-32::DEBUG::2015-08-23 18:24:25,779::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a03_images/01770df2-65da-4855-b6ed-ed7d3ac37824/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-08-23 18:24:25,798::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000196931 s, 1.8 MB/s\n'; <rc> = 0
Thread-32::DEBUG::2015-08-23 18:24:35,829::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a03_images/01770df2-65da-4855-b6ed-ed7d3ac37824/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-08-23 18:24:35,846::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000249619 s, 1.5 MB/s\n'; <rc> = 0

---- Thread-39 ----
Thread-39::DEBUG::2015-08-23 18:23:56,956::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b_images/4b820fec-7a8f-4964-ae0c-b051dea2d191/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-39::DEBUG::2015-08-23 18:23:56,972::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000208003 s, 1.7 MB/s\n'; <rc> = 0
Thread-39::DEBUG::2015-08-23 18:24:07,018::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b_images/4b820fec-7a8f-4964-ae0c-b051dea2d191/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-39::DEBUG::2015-08-23 18:24:07,038::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000225548 s, 1.6 MB/s\n'; <rc> = 0
Thread-39::DEBUG::2015-08-23 18:24:17,059::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b_images/4b820fec-7a8f-4964-ae0c-b051dea2d191/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-39::DEBUG::2015-08-23 18:24:17,071::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000224135 s, 1.6 MB/s\n'; <rc> = 0
Thread-39::DEBUG::2015-08-23 18:24:27,081::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b_images/4b820fec-7a8f-4964-ae0c-b051dea2d191/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-39::DEBUG::2015-08-23 18:24:27,097::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000343736 s, 1.0 MB/s\n'; <rc> = 0
Thread-39::DEBUG::2015-08-23 18:24:37,117::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b_images/4b820fec-7a8f-4964-ae0c-b051dea2d191/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-39::DEBUG::2015-08-23 18:24:37,128::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000184414 s, 2.0 MB/s\n'; <rc> = 0

---- Thread-50 ----
Thread-50::DEBUG::2015-08-23 18:24:03,987::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b04_images/ff6dc474-662b-4096-ac37-d0b8ec098cc0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-50::DEBUG::2015-08-23 18:24:04,000::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000258772 s, 1.4 MB/s\n'; <rc> = 0
Thread-50::DEBUG::2015-08-23 18:24:14,005::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b04_images/ff6dc474-662b-4096-ac37-d0b8ec098cc0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-50::DEBUG::2015-08-23 18:24:14,018::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000230687 s, 1.6 MB/s\n'; <rc> = 0
Thread-50::DEBUG::2015-08-23 18:24:24,023::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b04_images/ff6dc474-662b-4096-ac37-d0b8ec098cc0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-50::DEBUG::2015-08-23 18:24:24,036::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000224879 s, 1.6 MB/s\n'; <rc> = 0
Thread-50::DEBUG::2015-08-23 18:24:34,052::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b04_images/ff6dc474-662b-4096-ac37-d0b8ec098cc0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-50::DEBUG::2015-08-23 18:24:34,068::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000276158 s, 1.3 MB/s\n'; <rc> = 0
Thread-50::DEBUG::2015-08-23 18:24:44,104::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b04_images/ff6dc474-662b-4096-ac37-d0b8ec098cc0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-50::DEBUG::2015-08-23 18:24:44,119::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000279155 s, 1.3 MB/s\n'; <rc> = 0

---- Thread-63 ----
Thread-63::DEBUG::2015-08-23 18:24:00,555::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_iso__a_images/5ee54f49-c890-4d59-b9ef-8102f43b9428/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-08-23 18:24:00,566::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n390 bytes (390 B) copied, 0.000239856 s, 1.6 MB/s\n'; <rc> = 0
Thread-63::DEBUG::2015-08-23 18:24:10,570::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_iso__a_images/5ee54f49-c890-4d59-b9ef-8102f43b9428/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-08-23 18:24:10,582::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n390 bytes (390 B) copied, 0.000257235 s, 1.5 MB/s\n'; <rc> = 0
Thread-63::DEBUG::2015-08-23 18:24:20,586::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_iso__a_images/5ee54f49-c890-4d59-b9ef-8102f43b9428/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-08-23 18:24:20,597::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n390 bytes (390 B) copied, 0.00020517 s, 1.9 MB/s\n'; <rc> = 0
Thread-63::DEBUG::2015-08-23 18:24:30,601::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_iso__a_images/5ee54f49-c890-4d59-b9ef-8102f43b9428/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-08-23 18:24:30,613::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n390 bytes (390 B) copied, 0.000228847 s, 1.7 MB/s\n'; <rc> = 0
Thread-63::DEBUG::2015-08-23 18:24:40,617::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_iso__a_images/5ee54f49-c890-4d59-b9ef-8102f43b9428/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-63::DEBUG::2015-08-23 18:24:40,629::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n390 bytes (390 B) copied, 0.000252261 s, 1.5 MB/s\n'; <rc> = 0

---- Thread-75 ----
Thread-75::DEBUG::2015-08-23 18:24:02,726::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a05_images/1fe2e087-eae3-407c-8a49-e7a5a3a56de3/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-75::DEBUG::2015-08-23 18:24:02,741::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000256937 s, 1.4 MB/s\n'; <rc> = 0
Thread-75::DEBUG::2015-08-23 18:24:12,754::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a05_images/1fe2e087-eae3-407c-8a49-e7a5a3a56de3/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-75::DEBUG::2015-08-23 18:24:12,768::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000320056 s, 1.1 MB/s\n'; <rc> = 0
Thread-75::DEBUG::2015-08-23 18:24:22,782::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a05_images/1fe2e087-eae3-407c-8a49-e7a5a3a56de3/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-75::DEBUG::2015-08-23 18:24:22,796::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000202335 s, 1.8 MB/s\n'; <rc> = 0
Thread-75::DEBUG::2015-08-23 18:24:32,810::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a05_images/1fe2e087-eae3-407c-8a49-e7a5a3a56de3/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-75::DEBUG::2015-08-23 18:24:32,825::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.00025666 s, 1.4 MB/s\n'; <rc> = 0
Thread-75::DEBUG::2015-08-23 18:24:42,843::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port1.doskoi:_guests__a05_images/1fe2e087-eae3-407c-8a49-e7a5a3a56de3/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-75::DEBUG::2015-08-23 18:24:42,860::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000255944 s, 1.4 MB/s\n'; <rc> = 0

---- Thread-91 ----
Thread-91::DEBUG::2015-08-23 18:23:56,935::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b06_images/c4eb674a-75dc-4fca-9454-1063a142d1e0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-91::DEBUG::2015-08-23 18:23:56,954::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000180403 s, 2.0 MB/s\n'; <rc> = 0
Thread-91::DEBUG::2015-08-23 18:24:06,982::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b06_images/c4eb674a-75dc-4fca-9454-1063a142d1e0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-91::DEBUG::2015-08-23 18:24:06,999::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000199116 s, 1.8 MB/s\n'; <rc> = 0
Thread-91::DEBUG::2015-08-23 18:24:17,022::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b06_images/c4eb674a-75dc-4fca-9454-1063a142d1e0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-91::DEBUG::2015-08-23 18:24:17,035::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000256241 s, 1.4 MB/s\n'; <rc> = 0
Thread-91::DEBUG::2015-08-23 18:24:27,040::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b06_images/c4eb674a-75dc-4fca-9454-1063a142d1e0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-91::DEBUG::2015-08-23 18:24:27,052::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000219371 s, 1.7 MB/s\n'; <rc> = 0
Thread-91::DEBUG::2015-08-23 18:24:37,056::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /bin/dd if=/rhev/data-center/mnt/iosvm01-port3.doskoi:_guests__b06_images/c4eb674a-75dc-4fca-9454-1063a142d1e0/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-91::DEBUG::2015-08-23 18:24:37,068::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000233535 s, 1.6 MB/s\n'; <rc> = 0

So all monitor threads stopped monitoring at about 18:24, after the last successful check.

All of them should be waiting on a threading.Event.

Pavel, what is the status of this machine - is it still running in this state?

Can you get a core dump of the vdsm process?

Comment 6 Pavel Zhukov 2015-09-16 12:01:06 UTC

The state is up now, vdsmd service was restarted and running fine afterwards.

Comment 7 Nir Soffer 2015-10-07 12:42:07 UTC

Reducing priority since is is not reproducible and the customer system
is up and running.

Comment 8 Nir Soffer 2015-10-07 13:16:20 UTC

This is the last monitoring thread log:

Thread-211::DEBUG::2015-08-23 18:24:44,144::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n364 bytes (364 B) copied, 0.000228129 s, 1.6 MB/s\n'; <rc> = 0

Then there are unexplained "holes" in the log (the empty lines bellow are the actual log content):

Thread-346::DEBUG::2015-08-23 18:24:44,745::task::993::Storage.TaskManager.Task::(_decref) Task=`a814dd94-4a6f-4768-a7fa-31a5a281c7be`::ref 0 aborting False





Thread-132466::DEBUG::2015-08-23 18:24:45,182::task::595::Storage.TaskManager.Task::(_updateState) Task=`6b6b095a-c60f-40e0-938d-2609050bc3f8`::moving from state init -> state preparing

And another hole here:

Thread-132106::DEBUG::2015-08-23 18:24:59,336::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present





Thread-346::DEBUG::2015-08-23 18:25:00,186::task::595::Storage.TaskManager.Task::(_updateState) Task=`93d4bb90-7e0e-489d-8687-27f74759b5f8`::moving from state init -> state preparing

Pavel, what was the available disk space in /var/log/vdsm when this happened?

Comment 9 Pavel Zhukov 2015-10-07 13:36:34 UTC

(In reply to Nir Soffer from comment #8)
> Pavel, what was the available disk space in /var/log/vdsm when this happened?

The only data I have:
# select log_time, message from audit_log where log_type in (23,24);
(No rows)

The holes in vdsm.log occur pretty often in last releases. I have many examples but don't have reproducer.

Comment 10 Nir Soffer 2015-10-07 15:11:26 UTC

(In reply to Pavel Zhukov from comment #9)
> (In reply to Nir Soffer from comment #8)
> > Pavel, what was the available disk space in /var/log/vdsm when this happened?
> 
> The only data I have:
> # select log_time, message from audit_log where log_type in (23,24);
> (No rows)

Can you elaborate on this?

> The holes in vdsm.log occur pretty often in last releases. I have many
> examples but don't have reproducer.

Please open a vdsm bug about this with these examples.

Comment 11 Pavel Zhukov 2015-10-08 07:10:00 UTC

(In reply to Nir Soffer from comment #10)
> (In reply to Pavel Zhukov from comment #9)
> > (In reply to Nir Soffer from comment #8)
> > > Pavel, what was the available disk space in /var/log/vdsm when this happened?
> > 
> > The only data I have:
> > # select log_time, message from audit_log where log_type in (23,24);
> > (No rows)
> 
> Can you elaborate on this?
Vdsm didn't report low disk space. 
Otherwise we'd see:
#  select log_time, message from audit_log where log_type in (23,24);
          log_time          |                                          message                                           
----------------------------+--------------------------------------------------------------------------------------------
 2015-08-03 00:00:21.264+02 | Critical, Low disk space. Host rhev6 has less than 500 MB of free space left on: /var/log.
 2015-08-03 01:31:06.43+02  | Critical, Low disk space. Host rhev6 has less than 500 MB of free space left on: /var/log.
 2015-08-03 01:15:58.808+02 | Critical, Low disk space. Host rhev6 has less than 500 MB of free space left on: /var/log.
 2015-08-03 01:46:13.991+02 | Critical, Low disk space. Host rhev6 has less than 500 MB of free space left on: /var/log.


> 
> > The holes in vdsm.log occur pretty often in last releases. I have many
> > examples but don't have reproducer.
> 
> Please open a vdsm bug about this with these examples.
I'll do once I have reproducer or/and case opened.

Comment 13 Tal Nisan 2015-11-11 02:17:23 UTC

Currently we don't have enough data to find the root cause and the problem does not reproduce, feel free to open if the issue reproduces or new data is available

Note You need to log in before you can comment on or make changes to this bug.