Cinder hangs while deleting 500 volumes (MOS 9.0 build 150)

[Ivan Lozgachev]

Environment:

MOS 9.0 build 150
1 Controller node, 2 Compute nodes, 3 Ceph nodes

Steps to reproduce:
Write python script to generate and then delete volumes using this code

def wait_for_volume_status(self, cinder, volume_id, status):
  while True:
    volume = cinder.volumes.get(volume_id)
    if status == volume.status:
      break
    else:
      time.sleep(3)

def generate_volumes(self):
  for i in range(0, 500):
    volume = cinder.volumes.create(size=1, name="horizon_load_test_volume")
    self.wait_for_volume_status(cinder, volume.id, "available")
    self.created_volumes.append({"id": volume.id})

def cleanup_volumes(self):
  for volume in self.created_volumes:
    cinder.volumes.delete(volume["id"])

Expected result:
  Cinder deleted all volumes after some time

Actual result:
  Cinder deleted several volumes and then stopped do that
  All volumes are in "deleting" state forever

From logs:
2016-04-29 07:35:39.320 9801 INFO cinder.volume.manager [req-736428d1-698e-49b5-99e5-a95c11ee619d cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:35:39.475 9801 INFO cinder.volume.manager [req-c40db947-e00d-4ea9-ada9-6b0b59df0837 cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:35:39.875 9801 INFO cinder.volume.manager [req-8d8ddd04-36a2-4041-8250-afabcd4d920b cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:35:40.269 9801 INFO cinder.volume.manager [req-03176723-f14f-42a0-a433-d17567dc25da cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:36:31.519 9801 WARNING cinder.db.sqlalchemy.api [req-8fa06fd8-4335-4157-9509-86711ddfb770 cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deadlock detected when running 'reservation_commit': Retrying...
2016-04-29 07:36:38.544 9801 INFO cinder.volume.manager [req-94ddc5d0-8599-4b2d-ad46-d73d5afefb44 cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:36:38.587 9801 INFO cinder.volume.manager [req-2d4ac2ea-d673-418e-9b43-1b18d3da27fc cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.
2016-04-29 07:36:46.351 9801 INFO cinder.volume.manager [req-8fa06fd8-4335-4157-9509-86711ddfb770 cd761c068199487898fa1d7b9edb1cff 47b4db36d1584adebec7031623356dd9 - - -] Deleted volume successfully.

After that nothing happens for 30 minutes.

See attached cinder and ceph logs collected from Controller node

[Ivan Lozgachev (ilozgachev)]

Conroller node restart fixes this problem. "nova volume-list" shows empty list after restart.

[Ivan Kolodyazhny (e0ne)]

Ivan, please provide more details for this bug: diagnostic snapshot, atop logs, etc. I can't reproduce this issue on my env.

BTW, 500 volumes deletion at the same time: is it real customer use case? If not, I think that we can change priority to medium

[Ivan Kolodyazhny (e0ne)]

Also, please specify controller's specification: how many CPUs and memory are there?