Loading...

Type: Bug
Resolution: Unresolved
Priority: Undefined
Fix Version/s: rhos-18.0.z
Affects Version/s: None
Component/s: openstack-nova
Labels:
None

Story Points:
2
Blocked:
False
Blocked Reason:

Hide

None

Show
None
Ready:
False
Docs Approval:
?
AssignedTeam:
rhos-workloads-compute
Regression:
None
Intelligence Requested:
Market:
PX Impact Score:

Severity:
Moderate

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

This is a copy of upstream bug https://bugs.launchpad.net/nova/+bug/2091138

tl;dr The live migration monitoring thread writes migration stats to the database every 5 seconds and if the live migration runs for a sufficiently long time, the message queue can become overwhelmed culminating in a MessagingTimeout raised from the RPC.

This issue was discovered during investigation of a downstream bug [1] where a live migration was dirtying memory faster than the transfer and the live migration failed in nova-compute with a MessagingTimeout, for example:

Live migration failed.: oslo_messaging.exceptions.MessagingTimeout: Timed out waiting for a reply to message ID 389a868aba184d1a9956337bca78a569
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 425, in get
    return self._queues[msg_id].get(block=True, timeout=timeout)
  File "/usr/lib/python3.6/site-packages/eventlet/queue.py", line 322, in get
    return waiter.wait()
  File "/usr/lib/python3.6/site-packages/eventlet/queue.py", line 141, in wait
    return get_hub().switch()
  File "/usr/lib/python3.6/site-packages/eventlet/hubs/hub.py", line 298, in switch
    return self.greenlet.switch()
queue.Empty

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/nova/compute/manager.py", line 7466, in _do_live_migration
    block_migration, migrate_data)
  File "/usr/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 8858, in live_migration
    migrate_data)
  File "/usr/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 9382, in _live_migration
    finish_event, disk_paths)
  File "/usr/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 9256, in _live_migration_monitor
    info, remaining)
  File "/usr/lib/python3.6/site-packages/nova/virt/libvirt/migration.py", line 557, in save_stats
    migration.save()
  File "/usr/lib/python3.6/site-packages/oslo_versionedobjects/base.py", line 210, in wrapper
    ctxt, self, fn.__name__, args, kwargs)
  File "/usr/lib/python3.6/site-packages/nova/conductor/rpcapi.py", line 246, in object_action
    objmethod=objmethod, args=args, kwargs=kwargs)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 181, in call
    transport_options=self.transport_options)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/transport.py", line 129, in _send
    transport_options=transport_options)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 674, in send
    transport_options=transport_options)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 662, in _send
    call_monitor_timeout)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 551, in wait
    message = self.waiters.get(msg_id, timeout=timeout)
  File "/usr/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 429, in get
    'to message ID %s' % msg_id)
oslo_messaging.exceptions.MessagingTimeout: Timed out waiting for a reply to message ID 389a868aba184d1a9956337bca78a569

The bug reporter was able to reproduce the problem in a lab environment and after we tracked things down to the live migration monitoring thread database writes as the possible culprit, he was able to run some tests [2][3] experimenting with changing the database write interval to be less frequent (once every 30 seconds for example) and the MessagingTimeout stopped occurring.

Note that the live migration still had other issues due to dirtying memory faster than the transfer and not having live_migration_timeout_action set to force_complete but with the slower database write interval there we no MessagingTimeout errors from the message queue and the migration failed as expected due to the live migration itself timing out as it was not able to get ahead of the memory dirtying.

My thought about how to address this is to make the interval for the database writes in the live migration monitoring thread configurable, so that operators can control and tune it to their deployment environments.

[1] https://bugzilla.redhat.com/show_bug.cgi?id=2312196
[2] https://bugzilla.redhat.com/show_bug.cgi?id=2312196#c23
[3] https://bugzilla.redhat.com/show_bug.cgi?id=2312196#c24