RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1523036 - "virsh domjobinfo --completed" prints "Expected downtime" instead of "Total downtime"
Summary: "virsh domjobinfo --completed" prints "Expected downtime" instead of "Total d...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: libvirt
Version: 7.5
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Jiri Denemark
QA Contact: Yanqiu Zhang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-12-07 04:07 UTC by Fangge Jin
Modified: 2018-04-10 11:03 UTC (History)
7 users (show)

Fixed In Version: libvirt-3.9.0-8.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-10 11:02:08 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
libvirtd log (34.90 KB, application/x-bzip)
2017-12-07 04:07 UTC, Fangge Jin 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2018:0704 0 None None None 2018-04-10 11:03:43 UTC

Description Fangge Jin 2017-12-07 04:07:07 UTC 
Created attachment 1364005 [details]
libvirtd log

Description of problem:
"virsh domjobinfo --completed" prints "Expected downtime" instead of "Total downtime"

Version-Release number of selected component:
libvirt-3.9.0-5.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Start a guest
2. Do managedsave or other async job(for example: save, dump, snapshot, migration)
   # virsh managedsave rhel7

   Domain rhel7 state saved by libvirt

3. Check the completed job info:
# virsh domjobinfo rhel7 --completed
Job type:         Unbounded   
Operation:        Save        
Time elapsed:     559          ms
Data processed:   707.478 MiB
Data remaining:   0.000 B
Data total:       1.126 GiB
Memory processed: 707.478 MiB
Memory remaining: 0.000 B
Memory total:     1.126 GiB
Memory bandwidth: 1.275 GiB/s
Dirty rate:       0            pages/s
Page size:        4096         bytes
Iteration:        3           
Constant pages:   114614      
Normal pages:     180510      
Normal data:      705.117 MiB
Expected downtime: 553          ms
Setup time:       6            ms

Actual results:
In the output of "virsh domjobinfo --completed":
1) The "Job type" is unbounded.
2) "Expected downtime" is printed

Expected results:
1) The "Job type" should be completed.
2) "Total downtime" should be printed, not "Expected downtime"
Comment 2 Fangge Jin 2017-12-08 02:36:58 UTC 
Additional info:
During managedsave, after "migration" is completed and before managedsave is completed, "virsh domjobinfo" returns "Job type: Completed".


# while true; do date; virsh domjobinfo rhel7; done
......
Fri Dec  8 10:16:18 CST 2017
Job type:         Unbounded   
Operation:        Save        
Time elapsed:     2109         ms
Data processed:   901.944 MiB
Data remaining:   0.000 B
Data total:       1.126 GiB
Memory processed: 901.944 MiB
Memory remaining: 0.000 B
Memory total:     1.126 GiB
Memory bandwidth: 452.502 MiB/s
Dirty rate:       0            pages/s
Page size:        4096         bytes
Iteration:        3           
Constant pages:   64947       
Normal pages:     230305      
Normal data:      899.629 MiB
Expected downtime: 1031         ms
Setup time:       11           ms

Fri Dec  8 10:16:19 CST 2017
Job type:         Completed   

Fri Dec  8 10:16:19 CST 2017
Job type:         Completed   

Fri Dec  8 10:16:19 CST 2017
Job type:         Completed   
......



libvirtd log:

2017-12-08 02:16:17.276+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"stop","id":"libvirt-25"}
2017-12-08 02:16:17.338+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699377, "microseconds": 337802}, "event": "STOP"}
2017-12-08 02:16:17.338+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {}, "id": "libvirt-25"}
2017-12-08 02:16:17.384+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-26"}
2017-12-08 02:16:17.386+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {}, "id": "libvirt-26"}
2017-12-08 02:16:17.386+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-27"}
2017-12-08 02:16:17.387+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {}, "id": "libvirt-27"}
2017-12-08 02:16:17.388+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-28"}
2017-12-08 02:16:17.389+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699377, "microseconds": 389075}, "event": "MIGRATION", "data": {"status": "setup"}}
2017-12-08 02:16:17.389+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {}, "id": "libvirt-28"}
2017-12-08 02:16:17.400+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699377, "microseconds": 400042}, "event": "MIGRATION_PASS", "data": {"pass": 1}}
2017-12-08 02:16:17.400+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699377, "microseconds": 400086}, "event": "MIGRATION", "data": {"status": "active"}}
2017-12-08 02:16:18.351+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699378, "microseconds": 351290}, "event": "MIGRATION_PASS", "data": {"pass": 2}}
2017-12-08 02:16:18.352+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699378, "microseconds": 351962}, "event": "MIGRATION_PASS", "data": {"pass": 3}}
2017-12-08 02:16:19.383+0000: 16141: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7ff8b0000fb0 event={"timestamp": {"seconds": 1512699379, "microseconds": 383094}, "event": "MIGRATION", "data": {"status": "completed"}}
2017-12-08 02:16:19.384+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"query-migrate","id":"libvirt-59"}
2017-12-08 02:16:19.385+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {"status": "completed", "setup-time": 11, "downtime": 1031, "total-time": 1994, "ram": {"total": 1209352192, "postcopy-requests": 0, "dirty-sync-count": 3, "page-size": 4096, "remaining": 0, "mbps": 3795.863029, "transferred": 945756604, "duplicate": 64947, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 943329280, "normal": 230305}}, "id": "libvirt-59"}
2017-12-08 02:16:19.386+0000: 16221: info : qemuMonitorSend:1064 : QEMU_MONITOR_SEND_MSG: mon=0x7ff8b0000fb0 msg={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-60"}
2017-12-08 02:16:19.387+0000: 16141: info : qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7ff8b0000fb0 reply={"return": {}, "id": "libvirt-60"}
Comment 3 Jiri Denemark 2018-01-11 17:42:18 UTC 
This is caused by wrong type store in the completed job info. It's set to UNBOUNDED while it should be COMPLETED.

Broken by:

commit 3f2d6d829eb8de0348fcbd58d654b29d5c5bebc2
Refs: v3.7.0-29-g3f2d6d829e
Author:     Nikolay Shirokovskiy <nshirokovskiy>
AuthorDate: Fri Sep 1 09:49:31 2017 +0300
Commit:     Jiri Denemark <jdenemar>
CommitDate: Thu Sep 7 12:52:36 2017 +0200

    qemu: migration: don't expose incomplete job as complete

    In case of real migration (not migrating to file on save, dump etc)
    migration info is not complete at time qemu finishes migration
    in normal (non postcopy) mode. We need to update disks stats,
    downtime info etc. Thus let's not expose this job status as
    completed.

    To archive this let's set status to 'qemu completed' after
    qemu reports migration is finished. It is not visible as complete
    job to clients. Cookie code on confirm phase will finally turn
    job into completed. As we don't need more things to do when
    migrating to file status is set to 'completed' as before
    in this case.

    Signed-off-by: Jiri Denemark <jdenemar>
Comment 5 Jiri Denemark 2018-01-11 21:50:21 UTC 
Patch sent upstream for review: https://www.redhat.com/archives/libvir-list/2018-January/msg00392.html
Comment 6 Jiri Denemark 2018-01-12 10:50:45 UTC 
Fixed upstream by

commit e8784e7868d44a2ce796b376cf78f0f6c61c114a
Refs: v3.10.0-183-ge8784e7868
Author:     Jiri Denemark <jdenemar>
AuthorDate: Thu Jan 11 20:47:50 2018 +0100
Commit:     Jiri Denemark <jdenemar>
CommitDate: Fri Jan 12 10:45:31 2018 +0100

    qemu: Fix type of a completed job

    Libvirt 3.7.0 and earlier libvirt reported a migration job as completed
    immediately after QEMU finished sending migration data at which point
    migration was not really complete yet. Commit v3.7.0-29-g3f2d6d829e
    fixed this, but caused a regression in reporting statistics for
    completed jobs which started reporting the job as still running. This
    happened because the completed job statistics including the job status
    are copied from the running job before we finally mark it as completed.

    Let's make sure QEMU_DOMAIN_JOB_STATUS_COMPLETED is always set in the
    completed job info even when the job has not finished yet.

    https://bugzilla.redhat.com/show_bug.cgi?id=1523036

    Signed-off-by: Jiri Denemark <jdenemar>
    Reviewed-by: Pavel Hrdina <phrdina>
Comment 9 yafu 2018-01-31 03:28:43 UTC 
Reproduced with libvirt-3.9.0-5.el7.x86_64.

Verified pass with libvirt-3.9.0-9.el7.x86_64.
Test steps：
1.Start a guest;

2.Do managedsave:
#virsh managedsave iommu1
Domain iommu1 state saved by libvirt

3.Check the completed job info:
# virsh domjobinfo iommu1 --completed
Job type:         ***Completed***   
Operation:        Save        
Time elapsed:     1007         ms
Data processed:   794.056 MiB
Data remaining:   0.000 B
Data total:       4.171 GiB
Memory processed: 794.056 MiB
Memory remaining: 0.000 B
Memory total:     4.171 GiB
Memory bandwidth: 798.506 MiB/s
Dirty rate:       0            pages/s
Page size:        4096         bytes
Iteration:        3           
Constant pages:   892407      
Normal pages:     200925      
Normal data:      784.863 MiB
***Total downtime***:   1002         ms
Setup time:       19           ms

4.Also test dump/snapshot/migrate, all work well.
Comment 13 errata-xmlrpc 2018-04-10 11:02:08 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2018:0704
Note You need to log in before you can comment on or make changes to this bug.