yahoo-eng-team team mailing list archive

[Belmiro Moreira <1916031@xxxxxxxxxxxxxxxxxx>]

Public bug reported:

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.

** Affects: nova
     Importance: Undecided
     Assignee: Belmiro Moreira (moreira-belmiro-email-lists)
         Status: New

** Changed in: nova
     Assignee: (unassigned) => Belmiro Moreira (moreira-belmiro-email-lists)

** Description changed:

- In a recent VM live migration I noticed that the migration time reported in 
+ 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 
+ 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).
+ 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.
+ This behavior can cause some confusion when operators are debugging
+ issues.
+ 
  In my opinion Nova should log the real migration time.

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1916031

Title:
  Wrong elapsed time logged during a live migration

Status in OpenStack Compute (nova):
  New

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1916031/+subscriptions