I ran into same RBD scaling issue during cinder ceph scaling test. This is the profiling I have done by using yappi. profile function: delete_volume ================================= Clock type: WALL Ordered by: ttot, desc name ncall tsub ttot tavg /usr/lib/python2.6/site-packages/rbd.py:279 RBD.remove 1 9.150229 9.150295 9.150295 /usr/lib/python2.6/site-packages/rbd.py:329 Image.__init__ 2 0.221957 0.389255 0.194627 /usr/lib64/python2.6/ctypes/util.py:208 find_library 4 0.000103 0.362277 0.090569 /usr/lib64/python2.6/ctypes/util.py:184 _findSoname_ldconfig 4 0.000841 0.362174 0.090543 /usr/lib/python2.6/site-packages/rbd.py:124 load_librbd 3 0.000106 0.276124 0.092041 __builtin__. 4 0.238940 0.238940 0.059735 ..2.6/site-packages/cinder/volume/drivers/rbd.py:297 RBDDriver._connect_to_rados 1 0.000058 0.222258 0.222258 /usr/lib/python2.6/site-packages/rados.py:196 Rados.__init__ 1 0.000413 0.221959 0.221959 /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:580 Session._ewait 1 0.000000 0.164918 0.164918 ../lib/python2.6/site-packages/qpid/messaging/endpoints.py:218 Connection._ewait 1 0.000000 0.164918 0.164918 ..r/lib/python2.6/site-packages/qpid/messaging/endpoints.py:197 Connection._wait 1 0.000009 0.164918 0.164918 /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:815 Sender._ewait 1 0.000000 0.164918 0.164918 /usr/lib/python2.6/site-packages/qpid/concurrency.py:46 Waiter.wait 1 0.000012 0.164909 0.164909 /usr/lib/python2.6/site-packages/qpid/concurrency.py:88 Condition.wait 2/1 0.000065 0.164817 0.082408 /usr/lib/python2.6/site-packages/qpid/compat.py:51 PipeWaiter.wait 2/1 0.024622 0.164742 0.082371 /usr/lib/python2.6/site-packages/rados.py:146 run_in_thread 6/3 0.000029 0.130822 0.021804 /usr/lib64/python2.6/threading.py:463 RadosThread.start 6/4 0.000017 0.123475 0.020579 /usr/lib64/python2.6/threading.py:391 _Event.wait 6/4 0.000000 0.121649 0.020275 ../site-packages/cinder/volume/drivers/rbd.py:543 RBDDriver._delete_backup_snaps 1 0.000106 0.116343 0.116343 /usr/lib64/python2.6/re.py:139 search 4 0.000118 0.113237 0.028309 __builtin__.search 4 0.109828 0.109828 0.027457 /usr/lib/python2.6/site-packages/cinder/service.py:241 Service.report_state 1 0.000026 0.109518 0.109518 /usr/lib/python2.6/site-packages/rbd.py:143 RBD.__init__ 1 0.000017 0.108991 0.108991 /usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py:117 wrapper 4/2 0.000027 0.108968 0.027242 /usr/lib/python2.6/site-packages/eventlet/hubs/timer.py:51 Timer.__call__ 18 0.000327 0.108744 0.006041 __builtin__. 40 0.000546 0.108584 0.002715 /usr/lib/python2.6/site-packages/eventlet/green/thread.py:23 __thread_body 6 0.000040 0.108038 0.018006 /usr/lib64/python2.6/threading.py:490 RadosThread.__bootstrap 6 0.000037 0.107998 0.018000 /usr/lib64/python2.6/threading.py:513 RadosThread.__bootstrap_inner 6 0.000305 0.107961 0.017993 /usr/lib/python2.6/site-packages/rados.py:140 RadosThread.run 6 0.104043 0.104043 0.017340 /usr/lib/python2.6/site-packages/eventlet/hubs/hub.py:327 Hub.fire_timers 12 0.000492 0.093392 0.007783 /usr/lib64/python2.6/site-packages/ibm_db_dbi.py:1316 Cursor.execute 5 0.000127 0.079162 0.015832 /usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py:253 _service_get 2 0.000089 0.074228 0.037114 /usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py:2141 Query.first 2 0.000076 0.072145 0.036073 ..r/lib64/python2.6/site-packages/sqlalchemy/orm/query.py:2004 Query.__getitem__ 2 0.000105 0.072069 0.036034 /usr/lib/python2.6/site-packages/cinder/db/api.py:131 service_update 1 0.000013 0.065131 0.065131 /usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py:366 service_update 1 0.000025 0.065102 0.065102 /usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py:2222 Query.__iter__ 2 0.000089 0.064455 0.032227 ..hon2.6/site-packages/sqlalchemy/orm/query.py:2236 Query._execute_and_instances 2 0.000191 0.063481 0.031740 ..ib64/python2.6/site-packages/sqlalchemy/engine/base.py:1385 Connection.execute 3 0.000030 0.057261 0.019087 ..site-packages/sqlalchemy/engine/base.py:1549 Connection._execute_clauseelement 3 0.000210 0.057231 0.019077 /usr/lib/python2.6/site-packages/rados.py:411 Rados.connect 1 0.000029 0.056991 0.056991 ..on2.6/site-packages/sqlalchemy/engine/base.py:1635 Connection._execute_context 3 0.000128 0.053990 0.017997 ..ib/python2.6/site-packages/ibm_db_sa/ibm_db.py:99 DB2Dialect_ibm_db.do_execute 3 0.000013 0.050828 0.016943 /usr/lib/python2.6/site-packages/rados.py:280 Rados.conf_read_file 1 0.000036 0.047981 0.047981 /usr/lib/python2.6/site-packages/cinder/db/api.py:87 service_get 1 0.000010 0.043877 0.043877 /usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py:267 service_get 1 0.000005 0.043845 0.043845 /usr/lib64/python2.6/site-packages/ibm_db_dbi.py:1225 Cursor._execute_helper 5 0.000116 0.043386 0.008677 ibm_db.execute 5 0.043238 0.043238 0.008648 /usr/lib64/python2.6/site-packages/ibm_db_dbi.py:1207 Cursor._set_cursor_helper 5 0.000099 0.035018 0.007004 ibm_db.num_fields 8 0.034917 0.034917 0.004365 ..4/python2.6/site-packages/sqlalchemy/event.py:371 _ListenerCollection.__call__ 4 0.000179 0.030411 0.007603 ..n2.6/site-packages/sqlalchemy/orm/query.py:2229 Query._connection_from_session 2 0.000016 0.029329 0.014664 ../python2.6/site-packages/sqlalchemy/orm/session.py:723 SessionMaker.connection 2 0.000022 0.029313 0.014656 ../site-packages/sqlalchemy/orm/session.py:779 SessionMaker._connection_for_bind 2 0.000024 0.029252 0.014626 ..thon2.6/site-packages/sqlalchemy/engine/base.py:2473 Engine.contextual_connect 2 0.000028 0.029042 0.014521 /usr/lib64/python2.6/site-packages/sqlalchemy/pool.py:227 QueuePool.connect 2 0.000033 0.029009 0.014505 ..lib64/python2.6/site-packages/sqlalchemy/pool.py:460 _ConnectionFairy.checkout 2 0.000044 0.028687 0.014343 ..e-packages/cinder/openstack/common/db/sqlalchemy/session.py:528 _ping_listener 2 0.000083 0.028473 0.014236 ..on2.6/site-packages/cinder/openstack/common/db/sqlalchemy/session.py:467 _wrap 6 0.000017 0.025402 0.004234 ../site-packages/cinder/openstack/common/db/sqlalchemy/models.py:37 Service.save 1 0.000015 0.025111 0.025111 :2 Driver.readable 2 0.000046 0.025091 0.012545 ..ckages/cinder/openstack/common/db/sqlalchemy/session.py:649 SessionMaker.flush 4 0.000030 0.024946 0.006236 ..ib64/python2.6/site-packages/sqlalchemy/orm/session.py:1684 SessionMaker.flush 4 0.000063 0.024916 0.006229 ..b64/python2.6/site-packages/sqlalchemy/orm/session.py:1727 SessionMaker._flush 1 0.000059 0.024810 0.024810 ..ython2.6/site-packages/sqlalchemy/orm/unitofwork.py:309 UOWTransaction.execute 1 0.000035 0.024382 0.024382 ..python2.6/site-packages/sqlalchemy/orm/unitofwork.py:472 SaveUpdateAll.execute 1 0.000021 0.024093 0.024093 /usr/lib64/python2.6/site-packages/sqlalchemy/orm/persistence.py:25 save_obj 1 0.000067 0.024072 0.024072 ..hon2.6/site-packages/sqlalchemy/orm/persistence.py:451 _emit_update_statements 1 0.000062 0.023501 0.023501 /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:405 Driver.readable 2 0.000379 0.023178 0.011589 /usr/lib/python2.6/site-packages/rbd.py:384 Image.close 4 0.021953 0.021992 0.005498 /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:635 Engine.write 2 0.002601 0.019320 0.009660 /usr/lib/python2.6/site-packages/eventlet/greenthread.py:15 sleep 3 0.000136 0.016468 0.005489 /usr/lib64/python2.6/threading.py:230 _Condition.wait 6 0.000405 0.015457 0.002576 ..2.6/site-packages/cinder/volume/drivers/rbd.py:316 RBDDriver._get_backup_snaps 1 0.001074 0.015362 0.015362 ..packages/sqlalchemy/orm/session.py:288 SessionTransaction._connection_for_bind 4/2 0.000114 0.015286 0.003821 /usr/lib/python2.6/site-packages/cinder/backup/drivers/ceph.py:43 1 0.010790 0.011888 0.011888 /usr/lib/python2.6/site-packages/qpid/ops.py:82 SessionAttached.dispatch 6 0.000091 0.011059 0.001843 ../lib64/python2.6/site-packages/sqlalchemy/engine/base.py:1347 Connection.close 2 0.000013 0.010932 0.005466 /usr/lib64/python2.6/site-packages/sqlalchemy/pool.py:509 _ConnectionFairy.close 2 0.000060 0.010919 0.005459 /usr/lib/python2.6/site-packages/qpid/datatypes.py:234 RangedSet.add 6 0.000027 0.010586 0.001764 /usr/lib/python2.6/site-packages/qpid/datatypes.py:220 RangedSet.add_range 6 0.000046 0.010520 0.001753 ..ython2.6/site-packages/qpid/messaging/driver.py:802 Engine.do_execution_result 2 0.000012 0.010335 0.005167 /usr/lib/python2.6/site-packages/qpid/datatypes.py:193 Range.span 2 0.010028 0.010109 0.005054 ..r/lib64/python2.6/site-packages/sqlalchemy/pool.py:514 _ConnectionFairy._close 2 0.000027 0.009472 0.004736 /usr/lib64/python2.6/site-packages/sqlalchemy/pool.py:352 _finalize_fairy 2 0.000060 0.009445 0.004723 /usr/lib/python2.6/site-packages/eventlet/hubs/hub.py:171 Hub.switch 17 0.009117 0.009423 0.000554 ..ython2.6/site-packages/sqlalchemy/orm/session.py:358 SessionTransaction.commit 3 0.000036 0.009407 0.003136 ..hon2.6/site-packages/sqlalchemy/orm/session.py:442 SessionTransaction.__exit__ 2 0.000011 0.009378 0.004689 posix.popen 4 0.008957 0.008957 0.002239 /usr/lib/python2.6/site-packages/eventlet/semaphore.py:60 Semaphore.acquire 131 0.000390 0.007533 0.000058 /usr/lib64/python2.6/site-packages/ibm_db_dbi.py:710 Connection.rollback 2 0.000011 0.007499 0.003749 ibm_db.rollback 2 0.007488 0.007488 0.003744 /usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py:2291 Query.instances 4 0.000229 0.007445 0.001861 ..python2.6/site-packages/sqlalchemy/orm/session.py:424 SessionTransaction.close 3 0.000029 0.005754 0.001918 ..64/python2.6/site-packages/sqlalchemy/engine/base.py:3200 ResultProxy.fetchall 2 0.000012 0.005582 0.002791 /usr/lib/python2.6/site-packages/rados.py:135 RadosThread.__init__ 6 0.000067 0.005382 0.000897 /usr/lib64/python2.6/threading.py:426 RadosThread.__init__ 6 0.002656 0.005315 0.000886 ..lib64/python2.6/site-packages/sqlalchemy/engine/base.py:3021 ResultProxy.close 3 0.000012 0.005303 0.001768 ..python2.6/site-packages/oslo/messaging/openstack/common/jsonutils.py:163 dumps 2 0.000016 0.005130 0.002565 /usr/lib64/python2.6/json/__init__.py:184 dumps 2 0.004081 0.005114 0.002557 ..ib/python2.6/site-packages/oslo/messaging/_drivers/common.py:458 serialize_msg 1 0.000011 0.004851 0.004851 /usr/lib/python2.6/site-packages/qpid/framing.py:258 OpDecoder.write 2 0.000114 0.004115 0.002057 /usr/lib64/python2.6/ctypes/__init__.py:337 CDLL.__init__ 4 0.000553 0.003937 0.000984 /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:565 Session._wakeup 1 0.000011 0.003776 0.003776 ..lib/python2.6/site-packages/qpid/messaging/endpoints.py:200 Connection._wakeup 1 0.000088 0.003765 0.003765 ..... The result is sorted by ttol. You can see the most significant part is /usr/lib/python2.6/site-packages/rbd.py:279 RBD.remove 1 9.150229 9.150295 9.150295 Both ttol and tsub are the same 9.1 seconds. That is the blockage in the librbd::remove from rbd library, which is a blocking call. If the volume size increases and cinder API load concurrency increases, the timing curve jump up dramatically. Since it is not a call eventlet can monkey patch, it blocks the whole cinder volume process from running(since librbd doesn't handle GIL either). There are two solutions here per discussion with ceph folks: 1. make librbd::remove async, which it is something they are looking into. But no immediate solution yet. 2. call rbd command from a child process via subprocess and remove the volume. There is one thing I want to clarify here. Originally, i was planning to fork a child process and make Rados connection and invoke the RBD from there , but it doesn't work, which ended up with EPERM error. This is a known limitation from librbd and this is the issue referenced at http://tracker.ceph.com/issues/4185. The mentioned workaround by using multiprocessing manager doesn't work either due to the eventlet monkey_patch. This pretty much left with only choice to fork and execute the rbd rm command directly to remove the volume. I would propose to use this rbd cli approach to handle the RBD volume delete for now before ceph community figure out the async RBD remove way. Btw, queue that mentioned above may not fix the issue since as long as RBD python binding is used, the process that has the queue that processing RBD.remove will be blocked and no greenthreads will be runnable. And you cannot fork a child process to call RBD/RADOS due to the known librados limitation.