Bug 1265902
Summary: | Guest OS paused after migration | ||
---|---|---|---|
Product: | Red Hat Enterprise Linux 7 | Reporter: | Fangge Jin <fjin> |
Component: | libvirt | Assignee: | Jiri Denemark <jdenemar> |
Status: | CLOSED ERRATA | QA Contact: | Virtualization Bugs <virt-bugs> |
Severity: | medium | Docs Contact: | |
Priority: | unspecified | ||
Version: | 7.2 | CC: | dgilbert, dyuan, fjin, huding, jdenemar, juzhang, knoel, lmiksik, mzhan, pezhang, quintela, rbalakri, virt-maint, zpeng |
Target Milestone: | rc | Keywords: | Regression |
Target Release: | --- | ||
Hardware: | x86_64 | ||
OS: | Linux | ||
Whiteboard: | |||
Fixed In Version: | libvirt-1.2.17-13.el7 | Doc Type: | Bug Fix |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2015-11-19 06:55:18 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: | |||
Bug Depends On: | 1271145 | ||
Bug Blocks: | |||
Attachments: |
Description
Fangge Jin
2015-09-24 06:55:40 UTC
I'm sorry but that the guest machine type should be "pc-i440fx-rhel7.2.0" in step1. Would you mind sharing libvirtd debug logs and qemu log from the destination host? Created attachment 1078524 [details]
libvirtd log from target
Created attachment 1078525 [details]
qemu log from target
Looking at libvirtd.log, something weird happened in QEMU as {"execute":"cont","id":"libvirt-102"} returned success ({"return": {}, "id": "libvirt-102"}) but we didn't get any RESUME event. Hi Do you have qemu.log from target? My (wild) guess is that libvirt is not waiting until the migration has finished on destitanion. It should wait for "complete" event on both source and destination before issuing the "cont" command. So Juan's wild guess is actually correct. Apparently QEMU doesn't actually start the CPUs after "cont" when migration is not complete yet or something like that. In any case, the bug is confirmed to be in libvirt as one can see what happened in the debug log from the destination host: ... 2015-09-30 02:05:38.239+0000: 5216: debug : qemuMonitorJSONCommandWithFd:291 : Send command '{"execute":"cont","id":"libvirt-102"}' for write with FD -1 ... 2015-09-30 02:05:38.314+0000: 5211: info : qemuMonitorJSONIOProcessLine:201 : QEMU_MONITOR_RECV_EVENT: mon=0x7f74440194c0 event={"timestamp": {"seconds": 1443578738, "microseconds": 314085}, "event": "MIGRATION", "data": {"status": "completed"}} In other words, we call "cont" 64ms before the destination QEMU considers migration to be finished. We really need to start waiting for a completed MIGRATION event on destination too. I wasn't able to reproduce the weired state of the domain, but by looking at the logs, it's apparently pretty easy to hit this race and call "cont" before migration actually completes. And I was able to reliably hit that even with --live. Note: I was using peer-to-peer (--p2p) migration to make transition from the source libvirtd to the destination libvirtd faster. So after some more tries, I was able to reproduce the weired state too. If migration completes after we call "cont" but before QEMU processes this command, the domain will remain running, but if QEMU manages to process the "cont" command before finishing migration, we will think the domain is running but it will actually be still paused. One can distinguish these two cases in the libvirtd logs: 1) migration finished before processing "cont" 2015-10-02 13:30:58.820+0000: 1430623: debug : qemuMonitorJSONCommandWithFd:291 : Send command '{"execute":"cont","id":"libvirt-99"}' for write with FD -1 2015-10-02 13:30:58.828+0000: 1430618: info : qemuMonitorJSONIOProcessLine:201 : QEMU_MONITOR_RECV_EVENT: mon=0x7f90c000e410 event={"timestamp": {"seconds": 1443792658, "microseconds": 828065}, "event": "MIGRATION", "data": {"status": "completed"}} 2015-10-02 13:30:58.829+0000: 1430618: info : qemuMonitorJSONIOProcessLine:201 : QEMU_MONITOR_RECV_EVENT: mon=0x7f90c000e410 event={"timestamp": {"seconds": 1443792658, "microseconds": 828896}, "event": "RESUME"} 2015-10-02 13:30:58.830+0000: 1430618: info : qemuMonitorJSONIOProcessLine:206 : QEMU_MONITOR_RECV_REPLY: mon=0x7f90c000e410 reply={"return": {}, "id": "libvirt-99"} 2) "cont" was processed before migration finished: 2015-10-02 13:21:08.997+0000: 1430622: debug : qemuMonitorJSONCommandWithFd:291 : Send command '{"execute":"cont","id":"libvirt-99"}' for write with FD -1 2015-10-02 13:21:08.999+0000: 1430618: info : qemuMonitorJSONIOProcessLine:206 : QEMU_MONITOR_RECV_REPLY: mon=0x7f90d0006470 reply={"return": {}, "id": "libvirt-99"} 2015-10-02 13:21:09.007+0000: 1430618: info : qemuMonitorJSONIOProcessLine:201 : QEMU_MONITOR_RECV_EVENT: mon=0x7f90d0006470 event={"timestamp": {"seconds": 1443792069, "microseconds": 6818}, "event": "MIGRATION", "data": {"status": "completed"}} Patches sent upstream for review: https://www.redhat.com/archives/libvir-list/2015-October/msg00123.html While this bug was originally filed for non-live migration, it's possible to hit the race even with live migration. After playing even more with this on RHEL with qemu-kvm-rhev, the behavior really depends on machine type. With older machine types QEMU actually resumes guest CPUs once migration finishes even though "cont" was earlier. For pc-i440fx-rhel7.2.0 machine type early "cont" is just ignored and guest CPUs stay paused. (In reply to Jiri Denemark from comment #17) > After playing even more with this on RHEL with qemu-kvm-rhev, the behavior > really depends on machine type. With older machine types QEMU actually > resumes guest CPUs once migration finishes even though "cont" was earlier. > For pc-i440fx-rhel7.2.0 machine type early "cont" is just ignored and guest > CPUs stay paused. That doesn't surprise me - the new global state thing is only enabled on the newer machine types. Fixed upstream by v1.2.20-37-gd27c66d..v1.2.20-41-gbe5347b: commit d27c66dbaae33d9b463eab8a8a2b0ad8cebff06a Author: Jiri Denemark <jdenemar> Date: Thu Oct 1 21:39:35 2015 +0200 qemu: Always update migration times on destination Even if we are migrating a domain with VIR_MIGRATE_PAUSED flag set, we should still update the total time of the migration. Updating downtime doesn't hurt either, even though we don't actually start guest CPUs. Signed-off-by: Jiri Denemark <jdenemar> commit b106c8b910ec49f1018146dd82b0f93833a66600 Author: Jiri Denemark <jdenemar> Date: Thu Oct 1 21:54:38 2015 +0200 qemu: Copy completed migration stats only on success The destination host gets detailed statistics about the current migration form the source host via migration cookie and copies them to the domain object so that they can be queried using virDomainGetJobStats. However, we should only copy statistics to the domain object when migration finished successfully. Signed-off-by: Jiri Denemark <jdenemar> commit 2af983f4c42e8f0af95fe1eb464e14ba52bb1145 Author: Jiri Denemark <jdenemar> Date: Mon Oct 5 14:36:15 2015 +0200 qemu: Introduce flags in qemuMigrationCompleted The function already has two bool parameters and we will need to add a new one. Let's switch to flags to make the callers readable. Signed-off-by: Jiri Denemark <jdenemar> commit 829c62b7a5268a639116bc1cea51d1c6598f4bf4 Author: Jiri Denemark <jdenemar> Date: Mon Oct 5 14:32:58 2015 +0200 qemu: Make updating stats in qemuMigrationCheckJobStatus optional With new QEMU which supports migration events, qemuMigrationCheckJobStatus needs to explicitly query QEMU for migration statistics once migration is completed to make sure the caller sees up-to-date statistics with both old and new QEMU. However, some callers are not interested in the statistics at all and once we start waiting for a completed migration on the destination host too, checking the statistics would even fail. Let's push the decision whether to update the statistics or not to the caller. Signed-off-by: Jiri Denemark <jdenemar> commit be5347bb7223cab0a9f0713ed9c4bf5738a7e0ea Author: Jiri Denemark <jdenemar> Date: Fri Oct 2 12:08:26 2015 +0200 qemu: Wait until destination QEMU consumes all migration data Even though QEMU on the source host reports completed migration and thus we move to the Finish phase, QEMU on the destination host may still be processing migration data. Thus before we can start guest CPUs on the destination, we have to wait for a completed migration event. https://bugzilla.redhat.com/show_bug.cgi?id=1265902 Signed-off-by: Jiri Denemark <jdenemar> Created attachment 1081180 [details] libvirt log from source host for comment 22 I tested with the following builds, the results are same as before(comment1), please have a look. Logs are attached. libvirt-1.2.17-13.el7.x86_64 qemu-kvm-rhev-2.3.0-29.el7.x86_64 Created attachment 1081181 [details] libvirt log from target host for comment 23 Created attachment 1081182 [details] qemu log from source host for comment 23 Created attachment 1081183 [details] qemu log from target host for comment 23 And my guest paused unexpectedly when I test managedsave, the behaviour is similar, I don't know if it's related to this bug. And it's not 100% reproducible. What I did generally is: How reproducible: < 10% Versions: libvirt-1.2.17-13.el7.x86_64 Steps: 1.Prepare a running guest. 2.Restart service libvirt-guests. 3.Check the state of guest: # virsh list Id Name State ---------------------------------------------------- 2 rhel7.2 running But actually, try to do some operation in the guest, the guest OS is not responding. 4.Then I use "virsh suspend rhel7.2" and "virsh resume rhel7.2", the guest can respond again. Created attachment 1081191 [details] libvirtd log for comment 27 (In reply to JinFangge from comment #23) > I tested with the following builds, the results are same as > before(comment1), please have a look. Logs are attached. > > libvirt-1.2.17-13.el7.x86_64 > qemu-kvm-rhev-2.3.0-29.el7.x86_64 Hmm, looking at the logs this seems to be slightly different and it's actually a proof that libvirt works correctly: 2015-10-09 03:42:35.895+0000: 29236: debug : qemuMigrationFinish:5719 : Waiting for migration to complete ... 2015-10-09 03:42:35.898+0000: 29233: info : qemuMonitorJSONIOProcessLine:201 : QEMU_MONITOR_RECV_EVENT: mon=0x7f80e00066c0 event={"timestamp": {"seconds": 1444362155, "microseconds": 898448}, "event": "MIGRATION", "data": {"status": "completed"}} ... 2015-10-09 03:42:35.899+0000: 29236: info : qemuMonitorSend:1033 : QEMU_MONITOR_SEND_MSG: mon=0x7f80e00066c0 msg={"execute":"cont","id":"libvirt-14"} ... 2015-10-09 03:42:35.899+0000: 29233: info : qemuMonitorJSONIOProcessLine:206 : QEMU_MONITOR_RECV_REPLY: mon=0x7f80e00066c0 reply={"return": {}, "id": "libvirt-14"} That is, we properly wait for a migration completed event before calling "cont". However, even though QEMU said "cont" was executed successfully, it never sent any RESUME event and it apparently completely ignored the request to start guest CPUs. Please, file a bug for qemu-kvm-rhev? (In reply to JinFangge from comment #27) > And my guest paused unexpectedly when I test managedsave, the behaviour is > similar, I don't know if it's related to this bug. And it's not 100% > reproducible. I suspect this is similar to comment 23. Once we know what's the bug in QEMU causing this we will know if we need to open a new libvirt bug or not. (In reply to Jiri Denemark from comment #29) > (In reply to JinFangge from comment #23) > > I tested with the following builds, the results are same as > > before(comment1), please have a look. Logs are attached. > > > > libvirt-1.2.17-13.el7.x86_64 > > qemu-kvm-rhev-2.3.0-29.el7.x86_64 > > Hmm, looking at the logs this seems to be slightly different and it's > actually a proof that libvirt works correctly: > > 2015-10-09 03:42:35.895+0000: 29236: debug : qemuMigrationFinish:5719 : > Waiting > for migration to complete > ... > 2015-10-09 03:42:35.898+0000: 29233: info : qemuMonitorJSONIOProcessLine:201 > : > QEMU_MONITOR_RECV_EVENT: mon=0x7f80e00066c0 event={"timestamp": > {"seconds": > 1444362155, "microseconds": 898448}, "event": "MIGRATION", "data": > {"status": > "completed"}} > ... > 2015-10-09 03:42:35.899+0000: 29236: info : qemuMonitorSend:1033 : > QEMU_MONITOR_SEND_MSG: mon=0x7f80e00066c0 > msg={"execute":"cont","id":"libvirt-14"} > ... > 2015-10-09 03:42:35.899+0000: 29233: info : qemuMonitorJSONIOProcessLine:206 > : > QEMU_MONITOR_RECV_REPLY: mon=0x7f80e00066c0 reply={"return": {}, "id": > "libvirt-14"} > > That is, we properly wait for a migration completed event before calling > "cont". However, even though QEMU said "cont" was executed successfully, it > never sent any RESUME event and it apparently completely ignored the request > to start guest CPUs. Please, file a bug for qemu-kvm-rhev? Created new bug for qemu-kvm-rhev: Bug 1271145 - Guest OS paused after migration. (In reply to JinFangge from comment #27) > And my guest paused unexpectedly when I test managedsave, the behaviour is > similar, I don't know if it's related to this bug. And it's not 100% > reproducible. So it appears we will need a patch for libvirt to fix this code path (in addition to the QEMU fix from bug 1271145). Could you file a new bug for that (since I can't reproduce the bug). (In reply to Jiri Denemark from comment #32) > (In reply to JinFangge from comment #27) > > And my guest paused unexpectedly when I test managedsave, the behaviour is > > similar, I don't know if it's related to this bug. And it's not 100% > > reproducible. > > So it appears we will need a patch for libvirt to fix this code path (in > addition to the QEMU fix from bug 1271145). Could you file a new bug for > that (since I can't reproduce the bug). I also can't reproduce it now after trying many times(with the qemu version without patch in bug 1271145), I will create bug if I meet this issue next time. Verify on build: libvirt-1.2.17-13.el7.x86_64 qemu-kvm-rhev-2.3.0-31.el7.x86_64 Steps are same as comment 0, guest works well after migration: # virsh migrate rhel7.2 qemu+ssh://10.66.5.20/system --verbose root.5.20's password: Migration: [100 %] Get the domjobinfo on source: (during migration) # virsh domjobinfo rhel7.2 Job type: Unbounded Time elapsed: 3139 ms Data processed: 272.340 MiB Data remaining: 771.773 MiB Data total: 1.102 GiB Memory processed: 272.340 MiB Memory remaining: 771.773 MiB Memory total: 1.102 GiB Memory bandwidth: 107.645 MiB/s Constant pages: 21870 Normal pages: 69535 Normal data: 271.621 MiB Expected downtime: 300 ms Setup time: 20 ms (after migration) # virsh domjobinfo rhel7.2 --completed Job type: Completed Time elapsed: 9546 ms Time elapsed w/o network: 9535 ms Data processed: 944.201 MiB Data remaining: 0.000 B Data total: 1.102 GiB Memory processed: 944.201 MiB Memory remaining: 0.000 B Memory total: 1.102 GiB Memory bandwidth: 105.563 MiB/s Constant pages: 47843 Normal pages: 241139 Normal data: 941.949 MiB Total downtime: 9035 ms Downtime w/o network: 9024 ms Setup time: 20 ms Get domjobinfo on target: (during migration) # virsh domjobinfo rhel7.2 (virsh hangs until migration finished) Job type: None (after migration) # virsh domjobinfo rhel7.2 --completed Job type: Completed Time elapsed: 9546 ms Time elapsed w/o network: 9535 ms Data processed: 944.201 MiB Data remaining: 0.000 B Data total: 1.102 GiB Memory processed: 944.201 MiB Memory remaining: 0.000 B Memory total: 1.102 GiB Memory bandwidth: 105.563 MiB/s Constant pages: 47843 Normal pages: 241139 Normal data: 941.949 MiB Total downtime: 9035 ms Downtime w/o network: 9024 ms Setup time: 20 ms According to comment 34, the problem in this bug has been fixed correctly. So move to verified. 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://rhn.redhat.com/errata/RHBA-2015-2202.html *** Bug 1340976 has been marked as a duplicate of this bug. *** |