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