Liberty :cinder issue comes when trying to create multiple instances at the same time

[vloiseau]

This is a issue with Orange using Red Hat Openstack platform with CDOT :

The process I used is like this: on the OpenStack dashboard I select “Launch instance”, I select to create a new volume for the instance, select the source image to be used (rhel qcow2 image of ~500MB), select instance count x and deploy (instance.jpeg attached)

The problem comes when I try to create more than 4~5 instances, because the instance creation process fails, giving an error on the block mapping device (“Error: Failed to perform requested operation on instance "qwe-2", the instance has an error status: Please try again later [Error: Build of instance b4f0e9a4-1da1-433c-9fc7-20a65d47fd99 aborted: Block Device Mapping is Invalid.].”)

Looking on the volumes and the instance tabs at the same time, I noticed that the instance creation process times out before the volumes are created. I attached error.jpeg with a snapshot of the instance and the volumes tab at the same moment. As you can see, the volumes are still under construction when the error appears on the instance tab. After ~1 minute all volumes are created successfully, but the instances are already in error so the volumes created after the moment of the picture I sent, are not mapped to any instance.

Also, I attached the log of cinder for the operation above.

I noticed here the download operation (download source image of ~500 MB is done at ~200+ MB/s), but the multiplication operation (use the image to put it on all 6 volumes) is done at ~2.4 MB/s.

Is this speed very low or not? Also, I imagine the convert operation is internal (not through the network, but locally on the device).

2016-09-02 12:00:53.517 84402 INFO cinder.image.image_utils [req-7836475d-4fcf-4efa-8396-878686fbe678 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 293.51 MB/s

2016-09-02 12:00:55.046 84402 INFO cinder.image.image_utils [req-4cc4db12-78c5-4656-ad80-372c73518cc7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 149.71 MB/s

2016-09-02 12:00:56.856 84402 INFO cinder.image.image_utils [req-4394c7a9-907f-4c48-82e4-da00433a207c eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 286.39 MB/s

2016-09-02 12:00:58.685 84402 INFO cinder.image.image_utils [req-3bcecb94-b1a8-4026-a1a6-7313be730903 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 290.32 MB/s

2016-09-02 12:01:00.157 84402 INFO cinder.image.image_utils [req-af147fe1-e7fe-4c45-9863-de70805931f2 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 152.89 MB/s

2016-09-02 12:01:01.832 84402 INFO cinder.image.image_utils [req-e8b516ec-6f62-4db1-a614-79ece6f7cda5 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 149.98 MB/s

2016-09-02 12:03:21.251 84402 INFO cinder.image.image_utils [req-3313c5c7-605a-4b9d-9d36-0c494fe19626 - - - - -] Converted 469.00 MB image at 3.47 MB/s

2016-09-02 12:03:31.504 84402 INFO cinder.image.image_utils [req-e9ef809b-78b1-40b8-a888-3f595d4f51c9 - - - - -] Converted 469.00 MB image at 3.25 MB/s

2016-09-02 12:03:51.924 84402 INFO cinder.image.image_utils [req-cc36495a-9ce3-4486-a01c-cda0035f4160 - - - - -] Converted 469.00 MB image at 2.93 MB/s

2016-09-02 12:04:17.428 84402 INFO cinder.image.image_utils [req-7de67d38-89ac-4827-8143-0b9bd566683b - - - - -] Converted 469.00 MB image at 2.47 MB/s

2016-09-02 12:04:22.938 84402 INFO cinder.image.image_utils [req-4e81f96b-c6bc-4111-907b-6dfd4e81335e - - - - -] Converted 469.00 MB image at 2.46 MB/s

2016-09-02 12:04:37.320 84402 INFO cinder.image.image_utils [req-96b8ef90-bc60-4ec4-a623-713f8498dbc5 - - - - -] Converted 469.00 MB image at 2.28 MB/s

Also, if I try the same test using a smaller image (~12 MB), I can have it successfully for 10 instances.

One quick and dirty workaround would be to change the timeout timers on the OpenStack side, but as far as I read on Red Hat support portal, this is likely to create other issues and they don’t recommend nor support it.

Could you please help?

Thank you,

[vloiseau]

cinder log content

2016-09-02 12:00:21.870 84402 INFO cinder.volume.drivers.netapp.dataontap.ssc_cmode [-] Successfully completed stale refresh job for server: 172.20.2.1 and vserver openstack
2016-09-02 12:00:51.909 84402 INFO cinder.volume.flows.manager.create_volume [req-4cc4db12-78c5-4656-ad80-372c73518cc7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume c7946bae-7783-4586-aec7-a0f3f01b71d7: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-c7946bae-7783-4586-aec7-a0f3f01b71d7', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x6726810>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x54a1a90>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x54a1a90>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:51.912 84402 WARNING cinder.context [req-4cc4db12-78c5-4656-ad80-372c73518cc7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:51.912 84402 WARNING cinder.volume.flows.manager.create_volume [req-4cc4db12-78c5-4656-ad80-372c73518cc7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:00:51.916 84402 INFO cinder.volume.flows.manager.create_volume [req-7836475d-4fcf-4efa-8396-878686fbe678 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume dcbbbe23-939c-4b91-9369-3cccc7f83707: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-dcbbbe23-939c-4b91-9369-3cccc7f83707', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x58a1b10>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x56c8450>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x56c8450>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:51.917 84402 WARNING cinder.context [req-7836475d-4fcf-4efa-8396-878686fbe678 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:51.918 84402 WARNING cinder.volume.flows.manager.create_volume [req-7836475d-4fcf-4efa-8396-878686fbe678 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:00:53.517 84402 INFO cinder.image.image_utils [req-7836475d-4fcf-4efa-8396-878686fbe678 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 293.51 MB/s
2016-09-02 12:00:55.046 84402 INFO cinder.image.image_utils [req-4cc4db12-78c5-4656-ad80-372c73518cc7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 149.71 MB/s
2016-09-02 12:00:55.213 84402 INFO cinder.volume.flows.manager.create_volume [req-4394c7a9-907f-4c48-82e4-da00433a207c eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume 79e7bca9-3a93-43e1-bdcd-bd58feebe27a: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-79e7bca9-3a93-43e1-bdcd-bd58feebe27a', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x4e7c4d0>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x5d1b850>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x5d1b850>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:55.215 84402 WARNING cinder.context [req-4394c7a9-907f-4c48-82e4-da00433a207c eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:55.216 84402 WARNING cinder.volume.flows.manager.create_volume [req-4394c7a9-907f-4c48-82e4-da00433a207c eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:00:56.856 84402 INFO cinder.image.image_utils [req-4394c7a9-907f-4c48-82e4-da00433a207c eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 286.39 MB/s
2016-09-02 12:00:57.067 84402 INFO cinder.volume.flows.manager.create_volume [req-3bcecb94-b1a8-4026-a1a6-7313be730903 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume ef46b777-b0bb-4519-ac0a-e34b5ace2115: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-ef46b777-b0bb-4519-ac0a-e34b5ace2115', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x5044b10>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x5493a90>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x5493a90>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:57.068 84402 WARNING cinder.context [req-3bcecb94-b1a8-4026-a1a6-7313be730903 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:57.068 84402 WARNING cinder.volume.flows.manager.create_volume [req-3bcecb94-b1a8-4026-a1a6-7313be730903 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:00:57.087 84402 INFO cinder.volume.flows.manager.create_volume [req-af147fe1-e7fe-4c45-9863-de70805931f2 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume 27499780-3533-4c37-96db-77b0687849f7: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-27499780-3533-4c37-96db-77b0687849f7', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x6438a50>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x4e5b050>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x4e5b050>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:57.088 84402 WARNING cinder.context [req-af147fe1-e7fe-4c45-9863-de70805931f2 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:57.088 84402 WARNING cinder.volume.flows.manager.create_volume [req-af147fe1-e7fe-4c45-9863-de70805931f2 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:00:58.685 84402 INFO cinder.image.image_utils [req-3bcecb94-b1a8-4026-a1a6-7313be730903 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 290.32 MB/s
2016-09-02 12:00:58.701 84402 INFO cinder.volume.flows.manager.create_volume [req-e8b516ec-6f62-4db1-a614-79ece6f7cda5 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Volume 978d8dd7-bc15-471d-bc09-8b366be3b45c: being created as image with specification: {'status': u'creating', 'image_location': (u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', None), 'volume_size': 40, 'volume_name': u'volume-978d8dd7-bc15-471d-bc09-8b366be3b45c', 'image_id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', 'image_service': <cinder.image.glance.GlanceImageService object at 0x57da550>, 'image_meta': {u'status': u'active', u'virtual_size': None, u'name': u'dasd', u'tags': [], u'container_format': u'bare', u'created_at': datetime.datetime(2016, 9, 1, 15, 14, 42, tzinfo=<iso8601.iso8601.Utc object at 0x6a10690>), u'disk_format': u'qcow2', u'updated_at': datetime.datetime(2016, 9, 1, 15, 15, 10, tzinfo=<iso8601.iso8601.Utc object at 0x6a10690>), u'visibility': u'public', 'properties': {u'architecture': u'amd64'}, u'owner': u'269b206ff5fb4ed3854bd145e6d0419c', u'protected': False, u'id': u'4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'file': u'/v2/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27/file', u'checksum': u'5907366ad7abe80c63d2936b92dec704', u'min_disk': 0, u'direct_url': u'file:///var/lib/glance/images/4a8a51a0-62c1-422a-9e1c-f863c9272d27', u'min_ram': 0, u'size': 492692992}}
2016-09-02 12:00:58.702 84402 WARNING cinder.context [req-e8b516ec-6f62-4db1-a614-79ece6f7cda5 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get internal tenant context: Missing required config parameters.
2016-09-02 12:00:58.703 84402 WARNING cinder.volume.flows.manager.create_volume [req-e8b516ec-6f62-4db1-a614-79ece6f7cda5 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Unable to get Cinder internal context, will not use image-volume cache.
2016-09-02 12:01:00.157 84402 INFO cinder.image.image_utils [req-af147fe1-e7fe-4c45-9863-de70805931f2 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 152.89 MB/s
2016-09-02 12:01:01.832 84402 INFO cinder.image.image_utils [req-e8b516ec-6f62-4db1-a614-79ece6f7cda5 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Image download 469.00 MB at 149.98 MB/s
2016-09-02 12:01:04.505 84402 WARNING os_brick.initiator.connector [req-3313c5c7-605a-4b9d-9d36-0c494fe19626 - - - - -] ISCSI volume not yet found at: ['/dev/disk/by-path/ip-172.20.1.1:3260-iscsi-iqn.1992-08.com.netapp:sn.396f317c229111e6b15700a09891b627:vs.5-lun-1']. Will rescan & retry.  Try number: 0.
2016-09-02 12:01:05.718 84402 WARNING os_brick.initiator.connector [req-7de67d38-89ac-4827-8143-0b9bd566683b - - - - -] ISCSI volume not yet found at: ['/dev/disk/by-path/ip-172.20.1.1:3260-iscsi-iqn.1992-08.com.netapp:sn.396f317c229111e6b15700a09891b627:vs.5-lun-2']. Will rescan & retry.  Try number: 0.
2016-09-02 12:01:10.106 84402 WARNING os_brick.initiator.connector [req-cc36495a-9ce3-4486-a01c-cda0035f4160 - - - - -] ISCSI volume not yet found at: ['/dev/disk/by-path/ip-172.20.1.1:3260-iscsi-iqn.1992-08.com.netapp:sn.396f317c229111e6b15700a09891b627:vs.5-lun-4']. Will rescan & retry.  Try number: 0.
2016-09-02 12:01:20.299 84402 INFO cinder.volume.drivers.netapp.dataontap.ssc_cmode [-] Running stale ssc refresh job for server: 172.20.2.1 and vserver openstack
2016-09-02 12:01:30.074 84402 INFO cinder.volume.drivers.netapp.dataontap.ssc_cmode [-] Successfully completed stale refresh job for server: 172.20.2.1 and vserver openstack
2016-09-02 12:03:21.251 84402 INFO cinder.image.image_utils [req-3313c5c7-605a-4b9d-9d36-0c494fe19626 - - - - -] Converted 469.00 MB image at 3.47 MB/s
2016-09-02 12:03:22.473 84402 INFO cinder.volume.flows.manager.create_volume [req-3313c5c7-605a-4b9d-9d36-0c494fe19626 - - - - -] Volume volume-dcbbbe23-939c-4b91-9369-3cccc7f83707 (dcbbbe23-939c-4b91-9369-3cccc7f83707): created successfully
2016-09-02 12:03:22.477 84402 INFO cinder.volume.manager [req-3313c5c7-605a-4b9d-9d36-0c494fe19626 - - - - -] Created volume successfully.
2016-09-02 12:03:26.515 84402 INFO cinder.volume.manager [req-322bd16d-c1c0-49e3-887c-351fcbd16486 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Initialize volume connection completed successfully.
2016-09-02 12:03:27.281 84402 INFO cinder.volume.manager [req-992a3f7b-912d-4d98-890c-cba8fb4a94f9 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Attach volume completed successfully.
2016-09-02 12:03:31.504 84402 INFO cinder.image.image_utils [req-e9ef809b-78b1-40b8-a888-3f595d4f51c9 - - - - -] Converted 469.00 MB image at 3.25 MB/s
2016-09-02 12:03:32.773 84402 INFO cinder.volume.flows.manager.create_volume [req-e9ef809b-78b1-40b8-a888-3f595d4f51c9 - - - - -] Volume volume-79e7bca9-3a93-43e1-bdcd-bd58feebe27a (79e7bca9-3a93-43e1-bdcd-bd58feebe27a): created successfully
2016-09-02 12:03:32.778 84402 INFO cinder.volume.manager [req-e9ef809b-78b1-40b8-a888-3f595d4f51c9 - - - - -] Created volume successfully.
2016-09-02 12:03:37.031 84402 INFO cinder.volume.manager [req-486fa4b8-b245-406f-a1cf-fa81ce22f9a4 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Initialize volume connection completed successfully.
2016-09-02 12:03:37.784 84402 INFO cinder.volume.manager [req-ba79e8a7-b562-4581-aff1-4215e87c80ac eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Attach volume completed successfully.
2016-09-02 12:03:51.924 84402 INFO cinder.image.image_utils [req-cc36495a-9ce3-4486-a01c-cda0035f4160 - - - - -] Converted 469.00 MB image at 2.93 MB/s
2016-09-02 12:03:53.410 84402 INFO cinder.volume.flows.manager.create_volume [req-cc36495a-9ce3-4486-a01c-cda0035f4160 - - - - -] Volume volume-27499780-3533-4c37-96db-77b0687849f7 (27499780-3533-4c37-96db-77b0687849f7): created successfully
2016-09-02 12:03:53.415 84402 INFO cinder.volume.manager [req-cc36495a-9ce3-4486-a01c-cda0035f4160 - - - - -] Created volume successfully.
2016-09-02 12:03:56.003 84402 INFO cinder.volume.manager [req-b553a646-632b-4e6b-b71e-e5bdb2772744 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Initialize volume connection completed successfully.
2016-09-02 12:03:56.897 84402 INFO cinder.volume.manager [req-f3c085fd-ab1a-42ab-a201-1b9bac4c3ad7 eb794bb7de3e41f4aaa2dddaa22e4b42 269b206ff5fb4ed3854bd145e6d0419c - - -] Attach volume completed successfully.
2016-09-02 12:04:17.428 84402 INFO cinder.image.image_utils [req-7de67d38-89ac-4827-8143-0b9bd566683b - - - - -] Converted 469.00 MB image at 2.47 MB/s
2016-09-02 12:04:18.680 84402 INFO cinder.volume.flows.manager.create_volume [req-7de67d38-89ac-4827-8143-0b9bd566683b - - - - -] Volume volume-c7946bae-7783-4586-aec7-a0f3f01b71d7 (c7946bae-7783-4586-aec7-a0f3f01b71d7): created successfully
2016-09-02 12:04:18.685 84402 INFO cinder.volume.manager [req-7de67d38-89ac-4827-8143-0b9bd566683b - - - - -] Created volume successfully.
2016-09-02 12:04:22.938 84402 INFO cinder.image.image_utils [req-4e81f96b-c6bc-4111-907b-6dfd4e81335e - - - - -] Converted 469.00 MB image at 2.46 MB/s
2016-09-02 12:04:24.219 84402 INFO cinder.volume.flows.manager.create_volume [req-4e81f96b-c6bc-4111-907b-6dfd4e81335e - - - - -] Volume volume-ef46b777-b0bb-4519-ac0a-e34b5ace2115 (ef46b777-b0bb-4519-ac0a-e34b5ace2115): created successfully
2016-09-02 12:04:24.224 84402 INFO cinder.volume.manager [req-4e81f96b-c6bc-4111-907b-6dfd4e81335e - - - - -] Created volume successfully.
2016-09-02 12:04:37.320 84402 INFO cinder.image.image_utils [req-96b8ef90-bc60-4ec4-a623-713f8498dbc5 - - - - -] Converted 469.00 MB image at 2.28 MB/s
2016-09-02 12:04:38.214 84402 INFO cinder.volume.flows.manager.create_volume [req-96b8ef90-bc60-4ec4-a623-713f8498dbc5 - - - - -] Volume volume-978d8dd7-bc15-471d-bc09-8b366be3b45c (978d8dd7-bc15-471d-bc09-8b366be3b45c): created successfully
2016-09-02 12:04:38.217 84402 INFO cinder.volume.manager [req-96b8ef90-bc60-4ec4-a623-713f8498dbc5 - - - - -] Created volume successfully.

[Bishoy · Accepted solution]

FYI,

We have figured out that it's an issue with the platform overall write sizing. the test required ~500MB per second and this platform is not optimized for suck workload. 

NFS caching could be an option instead of using ISCSI for cinder by NetApp driver.