Wrong elapsed time logged during a live migration

[Belmiro Moreira]

In a recent VM live migration I noticed that the migration time reported in
the logs was not consistent with the actual time that it was taking:

```
2021-01-15 09:51:07.41 43553 INFO nova.virt.libvirt.driver [ ] Migration running for 0 secs, memory 100% remaining; (bytes processed=0, remaining=0, total=0)
2021-01-15 09:52:37.740 43553 DEBUG nova.virt.libvirt.driver [ ] Migration running for 5 secs, memory 100% remaining; (bytes processed=0, remaining=0, total=0)
2021-01-15 09:53:34.574 43553 DEBUG nova.virt.libvirt.driver [ ] Migration running for 10 secs, memory 100% remaining; (bytes processed=0, remaining=0, total=0)
2021-01-15 09:54:21.186 43553 DEBUG nova.virt.libvirt.driver [ ] Migration running for 15 secs, memory 100% remaining; (bytes processed=0, remaining=0, total=0)
(...)
```

This is because Nova doesn’t log the actual time that is taking. It cycles
to check the migration job status every 500ms and it logs the number of cycles/2.

Nova assumes that libvirt calls will report immediately, which was not the case. (In this particular example the compute node had issues and libvirt calls were taking a few seconds).

This behavior can cause some confusion when operators are debugging issues.

In my opinion Nova should log the real migration time.

[Balazs Gibizer (balazs-gibizer)]

Being fixed in https://review.opendev.org/c/openstack/nova/+/776428

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 23.0.0.0rc1 release candidate.