Bug 1677054

Summary: Creating images from cinder volumes with ceph backend is very inefficient
Product: Red Hat OpenStack Reporter: Matt Flusche <mflusche>
Component: openstack-glanceAssignee: Mridula Joshi <mrjoshi>
Status: CLOSED MIGRATED QA Contact: msava
Severity: medium Docs Contact: Tana <tberry>
Priority: high    
Version: 13.0 (Queens)CC: akekane, cyril, eglynn, gcharot, jschluet, msava, udesale, vimartin
Target Milestone: AlphaKeywords: FutureFeature, Triaged
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2023-11-07 00:45:37 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:
Embargoed:
Bug Depends On: 2013665    
Bug Blocks:    

Description Matt Flusche 2019-02-13 21:50:15 UTC
Description of problem:
In a pretty typical OSP deployment with ceph storage, when creating an image from a cinder volume the operation currently involves cinder volume downloading the image from ceph and then uploading to glance and back into ceph.  Overall this is a very slow operation.

- Is there way to configure glance and/or cinder to use snapshots in ceph to eliminate the transfers? similar to how cinder or nova can use a snapshot from a glance image to create volumes.

- Is there a way to limit the concurrent image creation operations for this heavy weight process?

Version-Release number of selected component (if applicable):
OSP 13 current

How reproducible:
100%

Steps to Reproduce:
1. create image from volume
$ openstack image create --volume 4e7ae6db-e364-47c4-b711-2ee66ab367ea test1
+---------------------+--------------------------------------+
| Field               | Value                                |
+---------------------+--------------------------------------+
| container_format    | bare                                 |
| disk_format         | raw                                  |
| display_description | None                                 |
| id                  | 4e7ae6db-e364-47c4-b711-2ee66ab367ea |
| image_id            | 428c8bd8-7f6b-451e-b5a7-bb31236ce1dd |
| image_name          | test1                                |
| protected           | False                                |
| size                | 10                                   |
| status              | uploading                            |
| updated_at          | 2019-02-13T21:24:47.000000           |
| visibility          | shared                               |
| volume_type         | None                                 |
+---------------------+--------------------------------------+

2. Observe the debug logs for cinder volume and glance api.

From /var/log/containers/cinder/cinder-volume.log showing image download, conversion, and upload to glance, this took about 3.5 minutes on a 10GB volume.

2019-02-13 15:33:34.038 31 DEBUG oslo_concurrency.processutils [req-e85ab7a0-bff9-48e3-b96e-ed34a3286b4b 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Running cmd (subprocess): rbd export --pool volumes volume-4e7ae6db-e364-47c4-b711-2ee66ab367ea /var/lib/cinder/conversion/volume-4e7ae6db-e364-47c4-b711-2ee66ab367ea-428c8bd8-7f6b-451e-b5a7-bb31236ce1dd --id openstack --cluster ceph --conf /etc/ceph/ceph.conf execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372
2019-02-13 15:33:54.329 31 DEBUG oslo_concurrency.processutils [req-e85ab7a0-bff9-48e3-b96e-ed34a3286b4b 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] CMD "rbd export --pool volumes volume-4e7ae6db-e364-47c4-b711-2ee66ab367ea /var/lib/cinder/conversion/volume-4e7ae6db-e364-47c4-b711-2ee66ab367ea-428c8bd8-7f6b-451e-b5a7-bb31236ce1dd --id openstack --cluster ceph --conf /etc/ceph/ceph.conf" returned: 0 in 20.291s execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409
2019-02-13 15:33:54.330 31 DEBUG cinder.image.image_utils [req-e85ab7a0-bff9-48e3-b96e-ed34a3286b4b 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] 428c8bd8-7f6b-451e-b5a7-bb31236ce1dd was raw, no need to convert to raw upload_volume /usr/lib/python2.7/site-packages/cinder/image/image_utils.py:522
2019-02-13 15:37:03.716 31 DEBUG cinder.volume.manager [req-e85ab7a0-bff9-48e3-b96e-ed34a3286b4b 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Uploaded volume to glance image-id: 428c8bd8-7f6b-451e-b5a7-bb31236ce1dd. copy_volume_to_image /usr/lib/python2.7/site-packages/cinder/volume/manager.py:1579
2019-02-13 15:37:03.775 31 INFO cinder.volume.manager [req-e85ab7a0-bff9-48e3-b96e-ed34a3286b4b 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Copy volume to image completed successfully.


From /var/log/containers/glance/api.log we see the upload back to rbd and slow image resize operations.

2019-02-13 15:33:54.444 24 DEBUG oslo_policy._cache_handler [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Reloading cached file /etc/glance/policy.json read_cached_file /usr/lib/python2.7/site-packages/oslo_policy/_cache_handler.py:40
2019-02-13 15:33:54.446 24 DEBUG oslo_policy.policy [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Reloaded policy file: /etc/glance/policy.json _load_policy_file /usr/lib/python2.7/site-packages/oslo_policy/policy.py:761
2019-02-13 15:33:55.047 24 DEBUG glance_store.backend [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Attempting to import store rbd _load_store /usr/lib/python2.7/site-packages/glance_store/backend.py:231
2019-02-13 15:33:55.048 24 DEBUG glance_store.capabilities [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Store glance_store._drivers.rbd.Store doesn't support updating dynamic storage capabilities. Please overwrite 'update_capabilities' method of the store to implement updating logics if needed. update_capabilities /usr/lib/python2.7/site-packages/glance_store/capabilities.py:97
2019-02-13 15:33:55.049 24 DEBUG glance_store.driver [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:89
2019-02-13 15:33:55.049 24 DEBUG glance_store.location [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x7fb5b1c08450>, 'store_entry': 'rbd'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:88
2019-02-13 15:33:55.129 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] creating image 428c8bd8-7f6b-451e-b5a7-bb31236ce1dd with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:461
2019-02-13 15:33:55.135 24 WARNING glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal
2019-02-13 15:33:55.276 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:490
2019-02-13 15:33:55.307 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:493
2019-02-13 15:33:55.422 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:490
2019-02-13 15:33:55.434 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:493
2019-02-13 15:33:55.552 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] resizing image to 24576 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:490
2019-02-13 15:33:55.560 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] writing chunk at offset 16777216 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:493
2019-02-13 15:33:55.668 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] resizing image to 32768 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:490

[...snip...]

2019-02-13 15:37:02.673 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] writing chunk at offset 10720641024 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:493
2019-02-13 15:37:02.736 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] resizing image to 10485760 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:490
2019-02-13 15:37:02.743 24 DEBUG glance_store._drivers.rbd [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] writing chunk at offset 10729029632 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:493
2019-02-13 15:37:03.102 24 DEBUG glance_store.backend [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Attempting to import store rbd _load_store /usr/lib/python2.7/site-packages/glance_store/backend.py:231
2019-02-13 15:37:03.103 24 DEBUG glance_store.capabilities [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Store glance_store._drivers.rbd.Store doesn't support updating dynamic storage capabilities. Please overwrite 'update_capabilities' method of the store to implement updating logics if needed. update_capabilities /usr/lib/python2.7/site-packages/glance_store/capabilities.py:97
2019-02-13 15:37:03.104 24 DEBUG glance_store.driver [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:89
2019-02-13 15:37:03.104 24 DEBUG glance_store.location [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x7fb5b1b401d0>, 'store_entry': 'rbd'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:88
2019-02-13 15:37:03.105 24 DEBUG glance_store.backend [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Skipping store.set_acls... not implemented. set_acls /usr/lib/python2.7/site-packages/glance_store/backend.py:471
2019-02-13 15:37:03.107 24 INFO eventlet.wsgi.server [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] 192.168.200.145 - - [13/Feb/2019 15:37:03] "PUT /v2/images/428c8bd8-7f6b-451e-b5a7-bb31236ce1dd/file HTTP/1.1" 204 189 188.762379
2019-02-13 15:37:03.113 24 DEBUG glance.api.middleware.version_negotiation [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Determining version of request: GET /v2/images/428c8bd8-7f6b-451e-b5a7-bb31236ce1dd Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:45
2019-02-13 15:37:03.113 24 DEBUG glance.api.middleware.version_negotiation [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Using url versioning process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:57
2019-02-13 15:37:03.114 24 DEBUG glance.api.middleware.version_negotiation [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] Matched version: v2 process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:69
2019-02-13 15:37:03.114 24 DEBUG glance.api.middleware.version_negotiation [req-d9770a64-b524-4c61-9403-4dddd42f16ed 259b8178527f4e92aff5979079551b0e 3edf39d145354bff87e6741f7e4b764f - default default] new path /v2/images/428c8bd8-7f6b-451e-b5a7-bb31236ce1dd process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:70

Comment 1 Cyril Roelandt 2019-03-06 16:26:50 UTC
I think we will need to target this at a future OSP release.

Comment 6 Gregory Charot 2022-05-12 16:35:11 UTC
Removing from OSP18.0 as this feature requires cinder BZ#2013665 which depends on keystone service role that is not planned for Zed. Once the keystone feature is merged we can retarget this RFE.