Bug 1388261

Summary:	Using cinder with LVM backend and slow drive creates oslo messaging timeouts and leads image creation to fail
Product:	Red Hat OpenStack	Reporter:	Andreas Karis <akaris>
Component:	openstack-cinder	Assignee:	Jon Bernard <jobernar>
Status:	CLOSED DEFERRED	QA Contact:	Avi Avraham <aavraham>
Severity:	low	Docs Contact:
Priority:	low
Version:	8.0 (Liberty)	CC:	abishop, akaris, chris.kacher, eharney, geguileo, justin.rackliffe, pgrist, scohen, srevivo, tshefi, tvignaud
Target Milestone:	---	Keywords:	Triaged, ZStream
Target Release:	12.0 (Pike)	Flags:	pgrist: needinfo? (akaris)
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-12-13 20:02:18 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:

Description Andreas Karis 2016-10-24 22:06:04 UTC

Description of problem:
Customer is using the LVM driver, which is creating LVs on /dev/sdb. During image conversion, we can see that one CPU hits ca. 100%, and IO on /dev/sdb is 100% as well during the whole operation. Network seems not to be the bottleneck (in any case, the image downloads quite fast). The bottleneck seems to be the fact that /dev/sdb is a slow drive (some older 500GB 7200RPM SATA), and this slows down the whole operation. The target block device is a 500GB 7200rpm SATA connected disk with would only be in the 70 to 100 IOPS range most likely. The conversion of a 50 GB image takes ca. 25 minutes after the initial image download into the cache. The issue cannot be reproduced with smaller images.

Increasing heartbeat_timeout_threshold to a higher value seems to help.
Workaround: heartbeat_timeout_threshold = 300

For debugging purposes, cinder-volume was moved to a compute node in order to separate services and remove some load from the controller.

Version-Release number of selected component (if applicable):
openstack-cinder-7.0.1-8.el7ost.noarch
python-cinder-7.0.1-8.el7ost.noarch
python-cinderclient-1.5.0-1.el7ost.noarch

How reproducible:


Steps to Reproduce:
1. cinder create 50 --display-name rhsostest --image-id 1174c7b3-0e17-4e57-b2a0-933fd9e6d9d2 --availability-zone nova
2.
3.

Additional info:

Analysis of packet captures and logs
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Analysis of packet captures - as you can see, the compute is Closing  the connection, the controller confirms with OK. Then, the controller sends 2 more heartbeats. As it receives no more heartbeat, it closes the connection (with a clear TCP tear down (FIN FIN/ACK ACK exchange)). 

~~~
[akaris@wks-akaris 01720643]$ tshark -r jrackctlr.pcap -nn -tud   amqp and tcp.port == 33556
8694 2016-10-19 17:38:46.387048 0.000000 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 76 133 Heartbeat 
12337 2016-10-19 17:39:01.387671 15.000623 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 80 133 Heartbeat 
17439 2016-10-19 17:39:19.537264 18.149593 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 6384 133 Basic.Deliver x=openstack rk=cinder-volume.hostgroup@lvmdriver Content-Header type=application/json Content-Body 
17445 2016-10-19 17:39:19.540093 0.002829 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 93 133 Basic.Ack 
17446 2016-10-19 17:39:19.540093 0.000000 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 93 133 [TCP Fast Retransmission] Basic.Ack 
17447 2016-10-19 17:39:19.540093 0.000000 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 89 133 [TCP Fast Retransmission] Basic.Ack 
32298 2016-10-19 17:40:16.390035 56.849942 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 76 133 Heartbeat 
47749 2016-10-19 17:41:16.392039 60.002004 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 76 133 Heartbeat 
53942 2016-10-19 17:41:39.899081 23.507042 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 80 133 Heartbeat 
54246 2016-10-19 17:41:40.919598 1.020517 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 91 133 Channel.Close reply= 
54252 2016-10-19 17:41:40.922046 0.002448 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 133 Channel.Close-Ok 
54253 2016-10-19 17:41:40.922054 0.000008 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 84 133 [TCP Fast Retransmission] Channel.Close-Ok 
54254 2016-10-19 17:41:40.922056 0.000002 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 84 133 [TCP Fast Retransmission] Channel.Close-Ok 
63456 2016-10-19 17:42:16.394029 35.471973 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 76 133 Heartbeat 
79161 2016-10-19 17:43:16.396034 60.002005 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 76 133 Heartbeat 
[akaris@wks-akaris 01720643]$ tshark -r jrackkvm.pcap -nn -tud   amqp and tcp.port == 33556
679 2016-10-19 17:38:46.387057 0.000000 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 Heartbeat 
1363 2016-10-19 17:39:01.387487 15.000430 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 76 15 Heartbeat 
2722 2016-10-19 17:39:19.537293 18.149806 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 6388 15 Basic.Deliver x=openstack rk=cinder-volume.hostgroup@lvmdriver Content-Header type=application/json Content-Body 
2728 2016-10-19 17:39:19.539986 0.002693 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 89 15 Basic.Ack 
2729 2016-10-19 17:39:19.539995 0.000009 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 93 15 [TCP Fast Retransmission] Basic.Ack 
2730 2016-10-19 17:39:19.539998 0.000003 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 93 15 [TCP Fast Retransmission] Basic.Ack 
5929 2016-10-19 17:40:16.390046 56.850048 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 Heartbeat 
9016 2016-10-19 17:41:16.392018 60.001972 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 Heartbeat 
10339 2016-10-19 17:41:39.898968 23.506950 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 76 15 Heartbeat 
10402 2016-10-19 17:41:40.919432 1.020464 ba:1a:0f:89:fb:37 →              192.168.1.12 → 192.168.1.13 33556 5672 AMQP 87 15 Channel.Close reply= 
10408 2016-10-19 17:41:40.922042 0.002610 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 84 15 Channel.Close-Ok 
10409 2016-10-19 17:41:40.922042 0.000000 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 84 15 [TCP Fast Retransmission] Channel.Close-Ok 
10410 2016-10-19 17:41:40.922042 0.000000 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 [TCP Fast Retransmission] Channel.Close-Ok 
12472 2016-10-19 17:42:16.393998 35.471956 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 Heartbeat 
15769 2016-10-19 17:43:16.396029 60.002031 c2:d2:13:15:4f:33 →              192.168.1.13 → 192.168.1.12 5672 33556 AMQP 80 15 Heartbeat 
~~~

This shows up as a heartbeat missed error in the compute's rabbitmq log. Althought the packet capture clearly shows that the *kernel* received heartbeats from the controller, the cinder process thinks that no heartbeats were received and hence tries a clean close operation of the connection. It then opens a new connection. Eventually, the image creation will finish, but highly delayed.
~~~
2016-10-19 17:39:19.854 13694 WARNING cinder.volume.flows.manager.create_volume [req-915f6480-1a40-469c-8a85-b031bcfa43c8 4786d4c961744796869010e4fe8e4703 5d29b3b8005046a9937246775f0220af - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-10-19 17:41:39.882 13694 INFO cinder.image.image_utils [req-915f6480-1a40-469c-8a85-b031bcfa43c8 4786d4c961744796869010e4fe8e4703 5d29b3b8005046a9937246775f0220af - - -] Image download 27338.00 MB at 195.24 MB/s
2016-10-19 17:41:39.899 13694 ERROR oslo.messaging._drivers.impl_rabbit [-] AMQP server on 192.168.1.13:5672 is unreachable: Too many heartbeats missed. Trying again in 1 seconds.
2016-10-19 17:41:39.931 13694 WARNING oslo.service.loopingcall [req-9d9715e1-3967-4442-bbfb-2fdb1a0a199c - - - - -] Function 'cinder.service.Service.report_state' run outlasted interval by 100.57 sec
2016-10-19 17:41:40.929 13694 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 192.168.1.13:5672
2016-10-19 17:41:41.154 13694 WARNING oslo.service.loopingcall [req-4349c42d-ad58-4eaf-8826-5db16061c17c - - - - -] Function 'cinder.service.Service.periodic_tasks' run outlasted interval by 51.78 sec
2016-10-19 17:44:55.063 13694 INFO cinder.image.image_utils [req-3c755f3c-223a-4457-9984-40e6baa62b51 4786d4c961744796869010e4fe8e4703 5d29b3b8005046a9937246775f0220af - - -] Converted 27338.00 MB image at 6.58 MB/s
~~~

Comment 1 Justin Rackliffe 2016-10-25 19:02:49 UTC

As a note the image will not complete if pacemaker is enabled as it will restart cinder-vol which during init sees the open download task and marks it ERROR.  If we put pcm in maint_mode than cinder would recover the connection and restart the download and qemu-img conversion process.  It is the conversion from the img to the LVM target that is the most time intense in our case even though I have two lower IOP devices.

This feels like a threading issue w cinder-vol where for a long running qemu-img conversion task it can block the processing of heartbeat and inadvertently force an unresponsive case.

Comment 6 Alan Bishop 2018-12-13 20:02:18 UTC

I'm deferring this, at least until LVM is supported in production.