Hide Forgot
Description of problem: glance with image APIv2 shows the following warning message when using RBD as a backend ~~~ 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal ~~~ All uploads with APIv2 then resize the image. This does not happen with APIv1. Version-Release number of selected component (if applicable): OSP 8, latest packages How reproducible: all the time Steps to Reproduce: 1. create raw image without sparse sectors (option -S 0): ~~~ sudo /usr/bin/qemu-img convert -f qcow2 -O raw -S 0 rhel-guest-image-7.2-20160302.0.x86_64.qcow2 rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw ~~~ 2. run the following 2 commands: ~~~ stack@undercloud-1 disks]$ date && time glance --os-image-api-version 1 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7 --container-format bare --disk-format raw; date && time glance --os-image-api-version 2 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw ~~~ ~~~ [stack@undercloud-1 disks]$ date && time glance --os-image-api-version 2 image-create --progress --visibility public --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw ~~~ 3. compare log output Actual results: API v1: /var/log/glance/api.log ~~~ 2016-09-06 21:51:41.714 12327 DEBUG glance.registry.client.v1.client [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registry request PUT /im ages/ce5163c9-d919-47f1-bdaf-a010026a85b3 HTTP 200 request id req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:128 2016-09-06 21:51:41.715 12327 DEBUG glance.api.v1.images [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Uploading image data for image ce516 3c9-d919-47f1-bdaf-a010026a85b3 to rbd store _upload /usr/lib/python2.7/site-packages/glance/api/v1/images.py:650 2016-09-06 21:51:41.754 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image ce5163c9-d919-47 f1-bdaf-a010026a85b3 with order 23 and size 10737418240 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:51:41.807 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add / usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:51:42.090 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ API v2 ~~~ 2016-09-06 21:58:17.414 12327 DEBUG glance_store.capabilities [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 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:98 2016-09-06 21:58:17.415 12327 DEBUG glance_store.driver [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:95 2016-09-06 21:58:17.415 12327 DEBUG glance_store.location [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x714bf50>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90 2016-09-06 21:58:17.451 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image 6d13a228-1b77-4815-abdd-21e8c977fe47 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:58:17.451 12327 WARNING glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal 2016-09-06 21:58:17.509 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.513 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:58:17.799 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.802 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ Expected results: v2 should not need to resize Additional info: 1) create raw image without sparse sectors (option -S 0): ~~~ sudo /usr/bin/qemu-img convert -f qcow2 -O raw -S 0 rhel-guest-image-7.2-20160302.0.x86_64.qcow2 rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw ~~~ I am not sure if this is necessary or not. However, I wanted to be sure that the apparent size and occupied space really are the same prior to this test. Compare this to the other war image, which was created without the -S 0 option. ~~~ [stack@undercloud-1 disks]$ du -sh * 11G rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw 470M rhel-guest-image-7.2-20160302.0.x86_64.qcow2 1.4G rhel-guest-image-7.2-20160302.0.x86_64.raw ~~~ I am running this on a lab system, so the `time` command isn't really the best reference ... however, the logs reveal that a switch between glance API version 1 and 2 makes a difference. Keep in mind that `date` returns EDT vs UTC in logs (4 hours difference): ### --os-image-api-version 1 ### ~~~ stack@undercloud-1 disks]$ date && time glance --os-image-api-version 1 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7 --container-format bare --disk-format raw; date && time glance --os-image-api-version 2 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw Tue Sep 6 17:51:41 EDT 2016 [=============================>] 100% +------------------+--------------------------------------+ | Property | Value | +------------------+--------------------------------------+ | checksum | 62f33fb78ed23539b0871d1ab8c86725 | | container_format | bare | | created_at | 2016-09-06T21:51:41.000000 | | deleted | False | | deleted_at | None | | disk_format | raw | | id | ce5163c9-d919-47f1-bdaf-a010026a85b3 | | is_public | True | | min_disk | 0 | | min_ram | 0 | | name | rhel7 | | owner | 5d2edea478ec4bdba74b6bd5e108fe3d | | protected | False | | size | 10737418240 | | status | active | | updated_at | 2016-09-06T21:57:49.000000 | | virtual_size | None | +------------------+--------------------------------------+ real 6m8.575s user 0m3.949s sys 0m6.812s ~~~ /var/log/glance/api.log ~~~ 2016-09-06 21:51:41.714 12327 DEBUG glance.registry.client.v1.client [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registry request PUT /im ages/ce5163c9-d919-47f1-bdaf-a010026a85b3 HTTP 200 request id req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:128 2016-09-06 21:51:41.715 12327 DEBUG glance.api.v1.images [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Uploading image data for image ce516 3c9-d919-47f1-bdaf-a010026a85b3 to rbd store _upload /usr/lib/python2.7/site-packages/glance/api/v1/images.py:650 2016-09-06 21:51:41.754 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image ce5163c9-d919-47 f1-bdaf-a010026a85b3 with order 23 and size 10737418240 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:51:41.807 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add / usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:51:42.090 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ ### --os-image-api-version 2 ### ~~~ [stack@undercloud-1 disks]$ date && time glance --os-image-api-version 2 image-create --progress --visibility public --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format rawTue Sep 6 17:58:16 EDT 2016 [=============================>] 100% +------------------+----------------------------------------------------------------------------------+ | Property | Value | +------------------+----------------------------------------------------------------------------------+ | checksum | 62f33fb78ed23539b0871d1ab8c86725 | | container_format | bare | | created_at | 2016-09-06T21:58:17Z | | direct_url | rbd://25ca4074-6996-11e6-9f65-5254004c20ce/images/6d13a228-1b77-4815-abdd- | | | 21e8c977fe47/snap | | disk_format | raw | | id | 6d13a228-1b77-4815-abdd-21e8c977fe47 | | min_disk | 0 | | min_ram | 0 | | name | rhel7b | | owner | 5d2edea478ec4bdba74b6bd5e108fe3d | | protected | False | | size | 10737418240 | | status | active | | tags | [] | | updated_at | 2016-09-06T22:05:04Z | | virtual_size | None | | visibility | public | +------------------+----------------------------------------------------------------------------------+ real 6m48.313s user 0m4.106s sys 0m6.186s ~~~ ~~~ 2016-09-06 21:58:17.414 12327 DEBUG glance_store.capabilities [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 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:98 2016-09-06 21:58:17.415 12327 DEBUG glance_store.driver [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:95 2016-09-06 21:58:17.415 12327 DEBUG glance_store.location [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x714bf50>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90 2016-09-06 21:58:17.451 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image 6d13a228-1b77-4815-abdd-21e8c977fe47 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:58:17.451 12327 WARNING glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal 2016-09-06 21:58:17.509 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.513 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:58:17.799 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.802 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ All of the above is related to this commit: https://review.openstack.org/gitweb?p=openstack/glance.git;a=commitdiff;h=1414c3fa8e12604a35e2c299dcac13830a419aaf However, I do not know (yet) why API version 2 does not send the actual size along with the image and why a resize is necessary with API version 2.
Hello, This is partly related .. some performance measurements: with APIv2 and ceph: # glance --os-image-url http://svl-fab1-aos-mgmt-01.cisco.com:9292 image-create --name rhel-raw-test --disk-format=raw --container-format=bare --file /var/lib/nova/instances/rhel-guest-image-7.2-20151102.0.x86_64.cisco-20160512.raw --progress --visibility public >> with image_store=rbd I aborted above after 2hours and upload at 51% image ID 98f7cb97-4eae-4926-abef-e024b4605116 ============================================================ with APIv1 and ceph: ~~~ glance --os-image-api-version 1 --os-image-url http://svl-fab1-aos-mgmt-01.cisco.com:9292 image-create --name rhel-raw-test --disk-format=raw --container-format=bare --file /var/lib/nova/instances/rhel-guest-image-7.2-20151102.0.x86_64.cisco-20160512.raw --progress --is-public true ~~~ After 5 minutes was only at 2% upload progress. ============================================================ with APIv2 and file: ~~~ # glance --os-image-url http://svl-fab1-aos-mgmt-01.cisco.com:9292 image-create --name rhel-raw-test --disk-format=raw --container-format=bare --file /var/lib/nova/instances/rhel-guest-image-7.2-20151102.0.x86_64.cisco-20160512.raw --progress --visibility public >> with image_store=file above completed in around 1 minute, image id ba2a9206-d642-4c6f-9db4-2c811c04ece1 ~~~ ============================================================ direct import into RBD: If we rbd import 10GB image from the glance endpoint directly it completes in ~1 minute.
Please be aware that this here is about upload performance with glance api v1 only. Glance API v1 does not seem to have the resize issue. However, performance still isn't satisfying (see my last post). ====================================================================== This is with glance api v1: /var/log/glance/api.log ~~~ 2016-09-06 21:51:41.714 12327 DEBUG glance.registry.client.v1.client [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registry request PUT /im ages/ce5163c9-d919-47f1-bdaf-a010026a85b3 HTTP 200 request id req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:128 2016-09-06 21:51:41.715 12327 DEBUG glance.api.v1.images [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Uploading image data for image ce516 3c9-d919-47f1-bdaf-a010026a85b3 to rbd store _upload /usr/lib/python2.7/site-packages/glance/api/v1/images.py:650 2016-09-06 21:51:41.754 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image ce5163c9-d919-47 f1-bdaf-a010026a85b3 with order 23 and size 10737418240 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:51:41.807 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add / usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:51:42.090 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ What I see so far is that writes from glance RBD driver to Ceph seem to be very slow. This is a glance apiv1 call, so the resize issue is _not_ there. /var/log/glance/api.log ~~~ 2016-09-08 15:19:12.081 6498 DEBUG glance_store._drivers.rbd [req-6ed8e72d-35a2-4ec8-8bb8-2bf59253661c 02a92e33f5c142888304e22b54ba88d2 884ef5fe230a43d9a58bd9ea551b82fe - - -] writing chunk at offset 142606336 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-08 15:19:12.116 6498 DEBUG glance_store._drivers.rbd [req-6ed8e72d-35a2-4ec8-8bb8-2bf59253661c 02a92e33f5c142888304e22b54ba88d2 884ef5fe230a43d9a58bd9ea551b82fe - - -] writing chunk at offset 144703488 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 ~~~ Compare that to a glance apiv2 call with the resize issue API v2 ~~~ 2016-09-06 21:58:17.414 12327 DEBUG glance_store.capabilities [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 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:98 2016-09-06 21:58:17.415 12327 DEBUG glance_store.driver [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:95 2016-09-06 21:58:17.415 12327 DEBUG glance_store.location [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x714bf50>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90 2016-09-06 21:58:17.451 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image 6d13a228-1b77-4815-abdd-21e8c977fe47 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407 2016-09-06 21:58:17.451 12327 WARNING glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal 2016-09-06 21:58:17.509 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.513 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 2016-09-06 21:58:17.799 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436 2016-09-06 21:58:17.802 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439 (...) ~~~ Getting back to our glance API v1 call - this can't be right for 2MB chunks! Have a look at the timestamps, it sometimes takes tens of seconds until the next batch is uploaded ~~~ [akaris@collab-shell glance]$ grep req-6ed8e72d-35a2-4ec8-8bb8-2bf59253661c api.log | grep chunk | awk '{print $2}' | tr '\n' ' ' 15:14:44.826 15:14:52.303 15:14:52.349 15:14:52.389 15:14:52.422 15:14:52.451 15:14:52.484 15:14:59.571 15:15:21.989 15:15:22.028 15:15:24.082 15:15:24.119 15:15:24.952 15:15:24.987 15:15:25.021 15:15:34.312 15:15:42.403 15:15:42.442 15:15:47.535 15:15:47.569 15:15:47.797 15:15:47.828 15:15:51.888 15:16:02.393 15:16:13.235 15:16:14.475 15:16:14.503 15:16:14.533 15:16:14.563 15:16:14.593 15:16:40.815 15:16:40.853 15:16:40.894 15:16:47.864 15:16:47.944 15:16:54.622 15:16:54.653 15:16:54.686 15:16:54.722 15:16:54.756 15:16:56.202 15:16:56.233 15:16:56.263 15:17:09.228 15:17:09.262 15:17:09.512 15:17:09.546 15:17:09.576 15:17:33.224 15:17:47.777 15:17:50.225 15:17:50.267 15:17:50.297 15:17:50.326 15:18:18.704 15:18:18.787 15:18:28.348 15:18:28.387 15:18:28.417 15:18:28.446 15:18:28.473 15:18:33.738 15:18:33.776 15:18:33.805 15:18:33.835 15:18:33.863 15:18:33.896 15:18:59.318 15:19:12.081 15:19:12.116 15:19:12.146 15:19:12.189 15:19:19.869 15:19:19.900 15:19:19.930 15:19:19.967 15:19:19.996 15:19:20.025 15:19:35.400 15:19:54.459 15:19:58.918 15:19:58.949 [akaris@collab-shell glance]$ ~~~ In either case, for apiv1 and apiv2, the same glance_store driver is being used. /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py ~~~ try: with rbd.Image(ioctx, image_name) as image: bytes_written = 0 offset = 0 chunks = utils.chunkreadable(image_file, self.WRITE_CHUNKSIZE) for chunk in chunks: # If the image size provided is zero we need to do # a resize for the amount we are writing. This will # be slower so setting a higher chunk size may # speed things up a bit. if image_size == 0: chunk_length = len(chunk) length = offset + chunk_length bytes_written += chunk_length LOG.debug(_("resizing image to %s KiB") % (length / units.Ki)) image.resize(length) LOG.debug(_("writing chunk at offset %s") % (offset)) offset += image.write(chunk, offset) checksum.update(chunk) if loc.snapshot: image.create_snap(loc.snapshot) image.protect_snap(loc.snapshot) ~~~ Note that no resize is taking place with API v1 (see above log outputs, and compare that to the LOG.debug line in `if image_size == 0` condition. If the upload to ceph is still slow, then because ... ~~~ with rbd.Image(ioctx, image_name) as image: (...) image.write(chunk, offset) ~~~ ... is slow. rbd is being imported at the head of /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py ~~~ """Storage backend for RBD (RADOS (Reliable Autonomic Distributed Object Store) Block Device)""" from __future__ import absolute_import from __future__ import with_statement import contextlib import hashlib import logging import math from oslo_config import cfg from oslo_utils import units import six from six.moves import urllib from glance_store import capabilities from glance_store.common import utils from glance_store import driver from glance_store import exceptions from glance_store import i18n from glance_store.i18n import _ from glance_store import location try: import rados import rbd except ImportError: rados = None rbd = None DEFAULT_POOL = 'images' ~~~ Some pdb to find out where that's coming from: ~~~ [root@overcloud-controller-0 glance_store]# pwd /usr/lib/python2.7/site-packages/glance_store [root@overcloud-controller-0 glance_store]# python -m pdb _drivers/rbd.py > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(17)<module>() -> (RADOS (Reliable Autonomic Distributed Object Store) Block Device)""" (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(18)<module>() -> from __future__ import absolute_import (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(19)<module>() -> from __future__ import with_statement (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(21)<module>() -> import contextlib (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(22)<module>() -> import hashlib (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(23)<module>() -> import logging (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(24)<module>() -> import math (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(26)<module>() -> from oslo_config import cfg (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(27)<module>() -> from oslo_utils import units (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(28)<module>() -> import six (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(29)<module>() -> from six.moves import urllib (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(31)<module>() -> from glance_store import capabilities (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(32)<module>() -> from glance_store.common import utils (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(33)<module>() -> from glance_store import driver (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(34)<module>() -> from glance_store import exceptions (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(35)<module>() -> from glance_store import i18n (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(36)<module>() -> from glance_store.i18n import _ (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(37)<module>() -> from glance_store import location (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(39)<module>() -> try: (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(40)<module>() -> import rados (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/six.py(180)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/six.py(181)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/six.py(183)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/six.py(183)find_module()->None -> return None (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(175)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(176)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module()->None -> return None (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/rados.py(5)<module>() -> """ (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(5)<module>() -> """ (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(6)<module>() -> from ctypes import CDLL, c_char_p, c_size_t, c_void_p, c_char, c_int, c_long, \ (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(9)<module>() -> from ctypes.util import find_library (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(10)<module>() -> import ctypes (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(11)<module>() -> import errno (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(12)<module>() -> import threading (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(13)<module>() -> import time (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(14)<module>() -> from datetime import datetime (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/six.py(180)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/six.py(181)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/six.py(183)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/six.py(183)find_module()->None -> return None (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(175)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(176)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module()->None -> return None (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(16)<module>() -> ANONYMOUS_AUID = 0xffffffffffffffff (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(17)<module>() -> ADMIN_AUID = 0 (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(18)<module>() -> LIBRADOS_ALL_NSPACES = '\001' (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(20)<module>() -> LIBRADOS_OP_FLAG_FADVISE_RANDOM = 0x4 (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(21)<module>() -> LIBRADOS_OP_FLAG_FADVISE_SEQUENTIAL = 0x8 (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(22)<module>() -> LIBRADOS_OP_FLAG_FADVISE_WILLNEED = 0x10 (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(23)<module>() -> LIBRADOS_OP_FLAG_FADVISE_DONTNEED = 0x20 (Pdb) s > /usr/lib/python2.7/site-packages/rados.py(24)<module>() -> LIBRADOS_OP_FLAG_FADVISE_NOCACHE = 0x40 (Pdb) u > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(40)<module>() -> import rados (Pdb) n > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(41)<module>() -> import rbd (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/six.py(180)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/six.py(181)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/six.py(183)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/six.py(183)find_module()->None -> return None (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(175)find_module() -> def find_module(self, fullname, path=None): (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(176)find_module() -> if fullname in self.known_modules: (Pdb) s > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module() -> return None (Pdb) s --Return-- > /usr/lib/python2.7/site-packages/eventlet/support/six.py(178)find_module()->None -> return None (Pdb) s --Call-- > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(17)<module>() -> (RADOS (Reliable Autonomic Distributed Object Store) Block Device)""" (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(17)<module>() -> (RADOS (Reliable Autonomic Distributed Object Store) Block Device)""" (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(18)<module>() -> from __future__ import absolute_import (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(19)<module>() -> from __future__ import with_statement (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(21)<module>() -> import contextlib (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(22)<module>() -> import hashlib (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(23)<module>() -> import logging (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(24)<module>() -> import math (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(26)<module>() -> from oslo_config import cfg (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(27)<module>() -> from oslo_utils import units (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(28)<module>() -> import six (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(29)<module>() -> from six.moves import urllib (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(31)<module>() -> from glance_store import capabilities (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(32)<module>() -> from glance_store.common import utils (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(33)<module>() -> from glance_store import driver (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(34)<module>() -> from glance_store import exceptions (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(35)<module>() -> from glance_store import i18n (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(36)<module>() -> from glance_store.i18n import _ (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(37)<module>() -> from glance_store import location (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(39)<module>() -> try: (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(40)<module>() -> import rados (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(41)<module>() -> import rbd (Pdb) s > /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py(46)<module>() -> DEFAULT_POOL = 'images' ~~~ (although I'm too stupid to use pdb, so I don't realy know where it's from .. but I'm guessing ;-) ) The code is in site-packages/rbd.py ~~~ 323 class Image(object): 324 """ 325 This class represents an RBD image. It is used to perform I/O on 326 the image and interact with snapshots. 327 328 **Note**: Any method of this class may raise :class:`ImageNotFound` 329 if the image has been deleted. 330 """ 331 332 def __init__(self, ioctx, name, snapshot=None, read_only=False): (...) 377 def __enter__(self): 378 return self (...) 766 def write(self, data, offset, fadvise_flags=0): 767 """ 768 Write data to the image. Raises :class:`InvalidArgument` if 769 part of the write would fall outside the image. 770 771 :param data: the data to be written 772 :type data: str 773 :param offset: where to start writing data 774 :type offset: int 775 :param fadvise_flags: fadvise flags for this write 776 :type fadvise_flags: int 777 :returns: int - the number of bytes written 778 :raises: :class:`IncompleteWriteError`, :class:`LogicError`, 779 :class:`InvalidArgument`, :class:`IOError` 780 """ 781 if not isinstance(data, str): 782 raise TypeError('data must be a string') 783 length = len(data) 784 if fadvise_flags == 0: 785 ret = self.librbd.rbd_write(self.image, c_uint64(offset), 786 c_size_t(length), c_char_p(data)) 787 else: 788 ret = self.librbd.rbd_write2(self.image, c_uint64(offset), 789 c_size_t(length), c_char_p(data), c_int(fadvise_flags)) 790 791 if ret == length: 792 return ret 793 elif ret < 0: 794 raise make_ex(ret, "error writing to %s" % (self.name,)) 795 elif ret < length: 796 raise IncompleteWriteError("Wrote only %ld out of %ld bytes" % (ret, length)) 797 else: 798 raise LogicError("logic error: rbd_write(%s) \ 799 returned %d, but %d was the maximum number of bytes it could have \ 800 written." % (self.name, ret, length)) (...) ~~~ `write()` calls `librbd.rbd_write` --- which makes this entirely (?) and RBD / ceph issue. Maybe something is wrong with librbd? Or glance misuses the library. In any case, I don't think that the glance code is at fault here when it comes to the performance issue with APIv1 (!).
OK, so Flavio and I have been talking about this, and I think I have a patch for this bug. I could not really confirm this issue because, well, devstack is broken (again). I will try and get a test system up on Monday. In the meantime, could you report this upstream and give us the link to Launchpad? I don't think there is anything private in your logs. I will then try to fix the issue upstream, do the downstream ports and push a new package :)
Hi Cyril, I will do so. I guess we are talking about the APIv2 resize bug, and not the speed issue, correct? In any case, sorting that out would at least help and show the customer that we are getting some progress here. I'll let you know once I created the upstream bug.
https://bugs.launchpad.net/glance/+bug/1627147
This bug https://bugs.launchpad.net/python-glanceclient/+bug/1220197 contains a reference to this review https://review.openstack.org/#/c/44859/ . The patch has been merged and is available in OSP8, it seems. I wonder if this is the patch we are looking for.
This is quite an old bug, I'm closing it. Feel free to reopen if needed.
Closed as wontfix, nothing for QE to test/automate. Also clearing needinfo