Re: [Xen-devel] Live migration hanging for a CPU intensive task

[Anthony Liguori <aliguori@xxxxxxxxxx>]

Andres Lagar Cavilla wrote:
> Hi all,
> I'm doing a few experiments with live migration in an emulated WAN 
> environment. Under heavy CPU pressure, the live migration algorithm 
> stalls before inititating the last non-live iteration. The suspend 
> calls hangs indefinitely (at least until I get tired of waiting...)
> Below find xend.log for two cases on which this happened. Log messages 
> include VM creation and the aborted attempt to migrate. Mem size is 512MB
> You'll note that for many iterations more pages get dirtied than the 
> ones pushed through to the migration target.
If this is the case, wouldn't you expect that migration could never 
complete?  If the VM is dirty more pages than it transmit, the algorithm 
will not converge.  Is there something else going on here?
Regards,

Anthony Liguori

> This is due to the heavy processing going on and the restricted 
> network conditions (100Mbps, 33 ms RTT). If I run the same test in a 
> Gigabit LAN, migration finishes succesfully.
> After suspend begins, the VM becomes unresponsive, as expected. 
> However, xm top indicates a steady CPU utilization of 99%
> I would appreciate if someone with insight on the migration/suspend 
> code can give me a hint. In principle, I need to add more debugging 
> messages to the suspend code. I'm thinking that given the length of 
> the migration and the rate of page dirtying, the shadow page tables 
> get "overloaded" (whatever that might be) and that causes weirdness 
> while suspending. But that's just a wild conjecture.
> Thanks indeed for any feedback
> Andres
>
> xend.log -----------------------------
>
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:177) 
> XendDomainInfo.create(['vm', ['name', 'xenbox'], ['memory', '512'], 
> ['vcpus', '4'], ['image', ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']]], ['device', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]], ['device', 
> ['vif', ['mac', '00:a0:24:60:31:67']]]])
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:282) 
> parseConfig: config is ['vm', ['name', 'xenbox'], ['memory', '512'], 
> ['vcpus', '4'], ['image', ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']]], ['device', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]], ['device', 
> ['vif', ['mac', '00:a0:24:60:31:67']]]]
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:376) 
> parseConfig: result is {'ssidref': None, 'uuid': None, 'on_crash': 
> None, 'on_reboot': None, 'image': ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']], 'on_poweroff': None, 'cpus': 
> None, 'name': 'xenbox', 'backend': [], 'vcpus': 4, 'cpu_weight': None, 
> 'vcpu_avail': None, 'memory': 512, 'device': [('vbd', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]), ('vif', 
> ['vif', ['mac', '00:a0:24:60:31:67']])], 'bootloader': None, 'cpu': 
> None, 'maxmem': None}
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:1130) 
> XendDomainInfo.construct: None 0
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:1162) 
> XendDomainInfo.initDomain: 31 1.0
> [2006-04-12 15:55:08 xend] DEBUG (balloon:84) Balloon: free 1025; need 
> 513; done.
> [2006-04-12 15:55:08 xend] INFO (image:133) buildDomain os=linux 
> dom=31 vcpus=4
> [2006-04-12 15:55:08 xend] DEBUG (image:171) dom            = 31
> [2006-04-12 15:55:08 xend] DEBUG (image:172) image          = 
> /boot/vmlinuz-2.6.12.6-xenU
> [2006-04-12 15:55:08 xend] DEBUG (image:173) store_evtchn   = 1
> [2006-04-12 15:55:08 xend] DEBUG (image:174) console_evtchn = 2
> [2006-04-12 15:55:08 xend] DEBUG (image:175) cmdline        =  
> ip=:1.2.3.4::::eth0:dhcp root=/dev/sda1 ro 4
> [2006-04-12 15:55:08 xend] DEBUG (image:176) ramdisk        = 
> [2006-04-12 15:55:08 xend] DEBUG (image:177) vcpus          = 4
> [2006-04-12 15:55:08 xend] DEBUG (DevController:103) DevController: 
> writing {'virtual-device': '2049', 'backend-id': '0', 'state': '1', 
> 'backend': '/local/domain/0/backend/vbd/31/2049'} to 
> /local/domain/31/device/vbd/2049.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:105) DevController: 
> writing {'domain': 'xenbox', 'frontend': 
> '/local/domain/31/device/vbd/2049', 'dev': 'sda1', 'state': '1', 
> 'params': 'hdk', 'mode': 'w', 'frontend-id': '31', 'type': 'phy'} to 
> /local/domain/0/backend/vbd/31/2049.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:103) DevController: 
> writing {'backend-id': '0', 'mac': '00:a0:24:60:31:67', 'handle': '0', 
> 'state': '1', 'backend': '/local/domain/0/backend/vif/31/0'} to 
> /local/domain/31/device/vif/0.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:105) DevController: 
> writing {'mac': '00:a0:24:60:31:67', 'state': '1', 'handle': '0', 
> 'script': '/etc/xen/scripts/vif-bridge', 'frontend-id': '31', 
> 'domain': 'xenbox', 'frontend': '/local/domain/31/device/vif/0'} to 
> /local/domain/0/backend/vif/31/0.
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:663) 
> Storing VM details: {'ssidref': '0', 'uuid': 
> '78c48e6b-4d9c-5478-15f2-5aa295db9cde', 'on_reboot': 'restart', 
> 'start_time': '1144871708.44', 'on_poweroff': 'destroy', 'name': 
> 'xenbox', 'vcpus': '4', 'vcpu_avail': '15', 'memory': '512', 
> 'on_crash': 'restart', 'image': "(linux (kernel 
> /boot/vmlinuz-2.6.12.6-xenU) (ip :1.2.3.4::::eth0:dhcp) (root 
> '/dev/sda1 ro') (args 4))", 'maxmem': '512'}
> [2006-04-12 15:55:08 xend.XendDomainInfo] DEBUG (XendDomainInfo:688) 
> Storing domain details: {'console/ring-ref': '50152', 'console/port': 
> '2', 'cpu/3/availability': 'online', 'name': 'xenbox', 
> 'console/limit': '1048576', 'cpu/2/availability': 'online', 'vm': 
> '/vm/78c48e6b-4d9c-5478-15f2-5aa295db9cde', 'domid': '31', 
> 'cpu/0/availability': 'online', 'memory/target': '524288', 
> 'store/ring-ref': '443869', 'cpu/1/availability': 'online', 
> 'store/port': '1'}
> [2006-04-12 15:55:08 xend] DEBUG (DevController:132) Waiting for 
> devices vif.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:138) Waiting for 0.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vif/31/0/hotplug-status.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vif/31/0/hotplug-status.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:417) 
> hotplugStatusCallback 1.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:132) Waiting for 
> devices usb.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:132) Waiting for 
> devices vbd.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:138) Waiting for 2049.
> [2006-04-12 15:55:08 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vbd/31/2049/hotplug-status.
> [2006-04-12 15:55:09 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vbd/31/2049/hotplug-status.
> [2006-04-12 15:55:09 xend] DEBUG (DevController:417) 
> hotplugStatusCallback 1.
> [2006-04-12 15:55:09 xend] DEBUG (DevController:132) Waiting for 
> devices pci.
> [2006-04-12 15:55:09 xend] DEBUG (DevController:132) Waiting for 
> devices ioports.
> [2006-04-12 15:55:09 xend] DEBUG (DevController:132) Waiting for 
> devices vtpm.
> [2006-04-12 15:55:09 xend] INFO (XendDomain:360) Domain xenbox (31) 
> unpaused.
> [2006-04-12 15:56:09 xend] DEBUG (XendCheckpoint:80) [xc_save]: 
> /usr/lib/xen/bin/xc_save 11 17 31 0 0 1
> [2006-04-12 15:56:09 xend] ERROR (XendCheckpoint:227) Had 0 
> unexplained entries in p2m table
> [2006-04-12 15:57:10 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 1   0%  6% 11% 16% 21%PT Race: 
> [10000000,904] pte=bdc063, mfn=00000bdc
> [2006-04-12 15:57:10 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,905] pte=bdd063, mfn=00000bdd
> [2006-04-12 15:57:10 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,906] pte=bde063, mfn=00000bde
> [2006-04-12 15:57:10 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,907] pte=bdf063, mfn=00000bdf
> [2006-04-12 15:57:10 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,908] pte=bd9063, mfn=00000bd9
> [2006-04-12 15:59:44 xend] ERROR 
> (XendCheckpoint:227)  26% 31% 36% 41% 46% 51% 
> 56% 61% 66% 71% 76% 81% 86% 92% 97%
> 1: sent 98834, skipped 32238, delta 215040ms, dom0 6%, target 22%, 
> sent 15Mb/s, dirtied 6Mb/s 39757 pages
> [2006-04-12 16:00:17 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: 
> iter 2   0%  5% 13% 18% 23% 28% 33% 43% 
> 48% 75%
> 2: sent 15081, skipped 24676, delta 32749ms, dom0 6%, target 23%, sent 
> 15Mb/s, dirtied 37Mb/s 37093 pages
> [2006-04-12 16:00:17 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 3   0%netbuf race: iter 3, pfn 401. mfn ffffffff
> [2006-04-12 16:00:19 xend] ERROR (XendCheckpoint:227) netbuf race: 
> iter 3, pfn 5760. mfn ffffffff
> [2006-04-12 16:00:49 xend] ERROR 
> (XendCheckpoint:227)   5% 17% 26% 31% 36% 41% 
> 48% 54% 78%
> 3: sent 14415, skipped 22676, delta 31370ms, dom0 6%, target 23%, sent 
> 15Mb/s, dirtied 38Mb/s 37102 pages
> [2006-04-12 16:00:49 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 4   0%netbuf race: iter 4, pfn 32b8. mfn ffffffff
> [2006-04-12 16:01:24 xend] ERROR 
> (XendCheckpoint:227)   5% 16% 24% 33% 38% 44% 
> 49% 54% 63% 96%
> 4: sent 16474, skipped 20627, delta 35812ms, dom0 6%, target 23%, sent 
> 15Mb/s, dirtied 31Mb/s 34655 pages
> [2006-04-12 16:01:24 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 5   0%netbuf race: iter 5, pfn 36a0. mfn ffffffff
> [2006-04-12 16:01:27 xend] ERROR (XendCheckpoint:227) netbuf race: 
> iter 5, pfn 5760. mfn ffffffff
> [2006-04-12 16:01:40 xend] ERROR 
> (XendCheckpoint:227)   6% 16% 21%netbuf race: iter 5, pfn 
> 3b52. mfn ffffffff
> [2006-04-12 16:01:44 xend] ERROR (XendCheckpoint:227)  29%netbuf 
> race: iter 5, pfn 327f. mfn ffffffff
> [2006-04-12 16:01:51 xend] ERROR (XendCheckpoint:227)  34%netbuf 
> race: iter 5, pfn 34cd. mfn ffffffff
> [2006-04-12 16:02:00 xend] ERROR (XendCheckpoint:227)  40% 
> 46%netbuf race: iter 5, pfn 390a. mfn ffffffff
> [2006-04-12 16:02:33 xend] ERROR 
> (XendCheckpoint:227)  52% 57% 62% 67% 75% 81% 
> 87% 92%netbuf race: iter 5, pfn 2df0. mfn ffffffff
> [2006-04-12 16:02:33 xend] ERROR (XendCheckpoint:227) netbuf race: 
> iter 5, pfn 2df1. mfn ffffffff
> [2006-04-12 16:02:38 xend] ERROR (XendCheckpoint:227)  99%
> 5: sent 33877, skipped 770, delta 73629ms, dom0 5%, target 31%, sent 
> 15Mb/s, dirtied 0Mb/s 816 pages
> [2006-04-12 16:02:40 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 6   0%
> 6: sent 816, skipped 0, delta 1783ms, dom0 6%, target 31%, sent 
> 14Mb/s, dirtied 1Mb/s 94 pages
> [2006-04-12 16:02:40 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 7   0%
> 7: sent 94, skipped 0, delta 169ms, dom0 7%, target 28%, sent 18Mb/s, 
> dirtied 11Mb/s 59 pages
> [2006-04-12 16:02:40 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 8   0%
> 8: sent 59, skipped 0, delta 128ms, dom0 7%, target 28%, sent 15Mb/s, 
> dirtied 6Mb/s 25 pages
> [2006-04-12 16:02:40 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 9   0%
> 9: sent 25, skipped 0, Start last iteration
> [2006-04-12 16:02:40 xend] DEBUG (XendCheckpoint:200) suspend
> [2006-04-12 16:02:40 xend] DEBUG (XendCheckpoint:83) In 
> saveInputHandler suspend
> [2006-04-12 16:02:40 xend] DEBUG (XendCheckpoint:85) Suspending 31 ...
> --> After 7 minutes I kill the thing <---
> [2006-04-12 16:09:36 xend.XendDomainInfo] DEBUG (XendDomainInfo:1272) 
> XendDomainInfo.destroy: domid=31
> [2006-04-12 16:09:36 xend.XendDomainInfo] DEBUG (XendDomainInfo:1280) 
> XendDomainInfo.destroyDomain(31)
> [2006-04-12 16:09:36 xend] INFO (XendCheckpoint:88) Domain 31 suspended.
> [2006-04-12 16:09:36 xend] ERROR (XendCheckpoint:99) Save failed on 
> domain xenbox (31).
> Traceback (most recent call last):
>  File "/usr/lib/python/xen/xend/XendCheckpoint.py", line 93, in save
>    forkHelper(cmd, fd, saveInputHandler, False)
>  File "/usr/lib/python/xen/xend/XendCheckpoint.py", line 206, in 
> forkHelper
>    raise XendError('Error reading from child process for %s: %s' %
> XendError: Error reading from child process for 
> ['/usr/lib/xen/bin/xc_save', '11', '17', '31', '0', '0', '1']: [Errno 
> 32] Broken pipe
> ----> Another try <-----
> [2006-04-12 16:35:44 xend.XendDomainInfo] DEBUG (XendDomainInfo:177) 
> XendDomainInfo.create(['vm', ['name', 'xenbox'], ['memory', '512'], 
> ['vcpus', '4'], ['image', ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']]], ['device', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]], ['device', 
> ['vif', ['mac', '00:a0:24:60:31:67']]]])
> [2006-04-12 16:35:44 xend.XendDomainInfo] DEBUG (XendDomainInfo:282) 
> parseConfig: config is ['vm', ['name', 'xenbox'], ['memory', '512'], 
> ['vcpus', '4'], ['image', ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']]], ['device', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]], ['device', 
> ['vif', ['mac', '00:a0:24:60:31:67']]]]
> [2006-04-12 16:35:44 xend.XendDomainInfo] DEBUG (XendDomainInfo:376) 
> parseConfig: result is {'ssidref': None, 'uuid': None, 'on_crash': 
> None, 'on_reboot': None, 'image': ['linux', ['kernel', 
> '/boot/vmlinuz-2.6.12.6-xenU'], ['ip', ':1.2.3.4::::eth0:dhcp'], 
> ['root', '/dev/sda1 ro'], ['args', '4']], 'on_poweroff': None, 'cpus': 
> None, 'name': 'xenbox', 'backend': [], 'vcpus': 4, 'cpu_weight': None, 
> 'vcpu_avail': None, 'memory': 512, 'device': [('vbd', ['vbd', 
> ['uname', 'phy:hdk'], ['dev', 'sda1'], ['mode', 'w']]), ('vif', 
> ['vif', ['mac', '00:a0:24:60:31:67']])], 'bootloader': None, 'cpu': 
> None, 'maxmem': None}
> [2006-04-12 16:35:44 xend.XendDomainInfo] DEBUG (XendDomainInfo:1130) 
> XendDomainInfo.construct: None 0
> [2006-04-12 16:35:44 xend.XendDomainInfo] DEBUG (XendDomainInfo:1162) 
> XendDomainInfo.initDomain: 32 1.0
> [2006-04-12 16:35:44 xend] DEBUG (balloon:84) Balloon: free 1025; need 
> 513; done.
> [2006-04-12 16:35:44 xend] INFO (image:133) buildDomain os=linux 
> dom=32 vcpus=4
> [2006-04-12 16:35:44 xend] DEBUG (image:171) dom            = 32
> [2006-04-12 16:35:44 xend] DEBUG (image:172) image          = 
> /boot/vmlinuz-2.6.12.6-xenU
> [2006-04-12 16:35:44 xend] DEBUG (image:173) store_evtchn   = 1
> [2006-04-12 16:35:44 xend] DEBUG (image:174) console_evtchn = 2
> [2006-04-12 16:35:44 xend] DEBUG (image:175) cmdline        =  
> ip=:1.2.3.4::::eth0:dhcp root=/dev/sda1 ro 4
> [2006-04-12 16:35:44 xend] DEBUG (image:176) ramdisk        = 
> [2006-04-12 16:35:44 xend] DEBUG (image:177) vcpus          = 4
> [2006-04-12 16:35:45 xend] DEBUG (DevController:103) DevController: 
> writing {'virtual-device': '2049', 'backend-id': '0', 'state': '1', 
> 'backend': '/local/domain/0/backend/vbd/32/2049'} to 
> /local/domain/32/device/vbd/2049.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:105) DevController: 
> writing {'domain': 'xenbox', 'frontend': 
> '/local/domain/32/device/vbd/2049', 'dev': 'sda1', 'state': '1', 
> 'params': 'hdk', 'mode': 'w', 'frontend-id': '32', 'type': 'phy'} to 
> /local/domain/0/backend/vbd/32/2049.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:103) DevController: 
> writing {'backend-id': '0', 'mac': '00:a0:24:60:31:67', 'handle': '0', 
> 'state': '1', 'backend': '/local/domain/0/backend/vif/32/0'} to 
> /local/domain/32/device/vif/0.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:105) DevController: 
> writing {'mac': '00:a0:24:60:31:67', 'state': '1', 'handle': '0', 
> 'script': '/etc/xen/scripts/vif-bridge', 'frontend-id': '32', 
> 'domain': 'xenbox', 'frontend': '/local/domain/32/device/vif/0'} to 
> /local/domain/0/backend/vif/32/0.
> [2006-04-12 16:35:45 xend.XendDomainInfo] DEBUG (XendDomainInfo:663) 
> Storing VM details: {'ssidref': '0', 'uuid': 
> 'd21e4e32-4f12-3fe7-bddc-2fab6cd9c60d', 'on_reboot': 'restart', 
> 'start_time': '1144874145.05', 'on_poweroff': 'destroy', 'name': 
> 'xenbox', 'vcpus': '4', 'vcpu_avail': '15', 'memory': '512', 
> 'on_crash': 'restart', 'image': "(linux (kernel 
> /boot/vmlinuz-2.6.12.6-xenU) (ip :1.2.3.4::::eth0:dhcp) (root 
> '/dev/sda1 ro') (args 4))", 'maxmem': '512'}
> [2006-04-12 16:35:45 xend.XendDomainInfo] DEBUG (XendDomainInfo:688) 
> Storing domain details: {'console/ring-ref': '441914', 'console/port': 
> '2', 'cpu/3/availability': 'online', 'name': 'xenbox', 
> 'console/limit': '1048576', 'cpu/2/availability': 'online', 'vm': 
> '/vm/d21e4e32-4f12-3fe7-bddc-2fab6cd9c60d', 'domid': '32', 
> 'cpu/0/availability': 'online', 'memory/target': '524288', 
> 'store/ring-ref': '23533', 'cpu/1/availability': 'online', 
> 'store/port': '1'}
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices vif.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:138) Waiting for 0.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vif/32/0/hotplug-status.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:417) 
> hotplugStatusCallback 1.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices usb.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices vbd.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:138) Waiting for 2049.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vbd/32/2049/hotplug-status.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:403) 
> hotplugStatusCallback /local/domain/0/backend/vbd/32/2049/hotplug-status.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:417) 
> hotplugStatusCallback 1.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices pci.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices ioports.
> [2006-04-12 16:35:45 xend] DEBUG (DevController:132) Waiting for 
> devices vtpm.
> [2006-04-12 16:35:45 xend] INFO (XendDomain:360) Domain xenbox (32) 
> unpaused.
> [2006-04-12 16:36:46 xend] DEBUG (XendCheckpoint:80) [xc_save]: 
> /usr/lib/xen/bin/xc_save 11 17 32 0 0 1
> [2006-04-12 16:36:46 xend] ERROR (XendCheckpoint:227) Had 0 
> unexplained entries in p2m table
> [2006-04-12 16:37:36 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 1   0%  5% 10% 15% 21%PT Race: 
> [10000000,904] pte=bdc063, mfn=00000bdc
> [2006-04-12 16:37:36 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,905] pte=bdd063, mfn=00000bdd
> [2006-04-12 16:37:36 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,906] pte=bde063, mfn=00000bde
> [2006-04-12 16:37:36 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,907] pte=bdf063, mfn=00000bdf
> [2006-04-12 16:37:36 xend] ERROR (XendCheckpoint:227) PT Race: 
> [10000000,908] pte=bd9063, mfn=00000bd9
> [2006-04-12 16:39:50 xend] ERROR 
> (XendCheckpoint:227)  26% 31% 36% 41% 46% 51% 
> 56% 61% 66% 71% 76% 81% 86% 92% 97%
> 1: sent 101026, skipped 30046, delta 184259ms, dom0 7%, target 22%, 
> sent 17Mb/s, dirtied 7Mb/s 39422 pages
> [2006-04-12 16:39:54 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 2   0%netbuf race: iter 2, pfn 6638. mfn ffffffff
> [2006-04-12 16:40:22 xend] ERROR 
> (XendCheckpoint:227)   5% 10% 17% 25% 30% 38% 
> 44% 51% 70% 97%
> 2: sent 17510, skipped 21911, delta 31895ms, dom0 7%, target 22%, sent 
> 17Mb/s, dirtied 37Mb/s 36685 pages
> [2006-04-12 16:40:26 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 3   0%netbuf race: iter 3, pfn 6638. mfn ffffffff
> [2006-04-12 16:40:54 xend] ERROR 
> (XendCheckpoint:227)   5% 13% 20% 25% 31% 36% 
> 41% 47% 52% 59% 72% 86%
> 3: sent 17601, skipped 19083, delta 32029ms, dom0 7%, target 22%, sent 
> 18Mb/s, dirtied 37Mb/s 36597 pages
> [2006-04-12 16:40:58 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 4   0%netbuf race: iter 4, pfn 6638. mfn ffffffff
> [2006-04-12 16:41:28 xend] ERROR 
> (XendCheckpoint:227)   5% 15% 23% 32% 41% 46% 
> 52% 57% 69% 77% 93%
> 4: sent 18460, skipped 18136, delta 33650ms, dom0 7%, target 22%, sent 
> 17Mb/s, dirtied 35Mb/s 36693 pages
> [2006-04-12 16:41:31 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 5   0%netbuf race: iter 5, pfn 6638. mfn ffffffff
> [2006-04-12 16:42:00 xend] ERROR 
> (XendCheckpoint:227)   6% 13% 18% 27% 32% 37% 
> 42% 48% 53% 67% 76% 85% 94%
> 5: sent 17853, skipped 18839, delta 32543ms, dom0 7%, target 22%, sent 
> 17Mb/s, dirtied 26Mb/s 26304 pages
> [2006-04-12 16:42:02 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 6   0%netbuf race: iter 6, pfn 6638. mfn ffffffff
> [2006-04-12 16:42:18 xend] ERROR 
> (XendCheckpoint:227)   9% 19% 27% 38% 51% 67% 
> 78% 90%
> 6: sent 9973, skipped 16330, delta 18135ms, dom0 7%, target 22%, sent 
> 18Mb/s, dirtied 52Mb/s 28903 pages
> [2006-04-12 16:42:22 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 7   0%netbuf race: iter 7, pfn 6638. mfn ffffffff
> [2006-04-12 16:42:40 xend] ERROR 
> (XendCheckpoint:227)   9% 18% 25% 32% 37% 44% 
> 51% 74%
> 7: sent 11736, skipped 17166, delta 21407ms, dom0 7%, target 22%, sent 
> 17Mb/s, dirtied 52Mb/s 34244 pages
> [2006-04-12 16:42:43 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 8   0%netbuf race: iter 8, pfn 6638. mfn ffffffff
> [2006-04-12 16:43:08 xend] ERROR 
> (XendCheckpoint:227)   5% 13% 19% 26% 32% 38% 
> 44%netbuf race: iter 8, pfn 173c3. mfn ffffffff
> [2006-04-12 16:43:10 xend] ERROR (XendCheckpoint:227) netbuf race: 
> iter 8, pfn 1651. mfn ffffffff
> [2006-04-12 16:43:21 xend] ERROR 
> (XendCheckpoint:227)  50% 55% 65%netbuf race: iter 8, pfn 
> 395b. mfn ffffffff
> [2006-04-12 16:43:23 xend] ERROR (XendCheckpoint:227) netbuf race: 
> iter 8, pfn 18e15. mfn ffffffff
> [2006-04-12 16:43:28 xend] ERROR (XendCheckpoint:227)  74%netbuf 
> race: iter 8, pfn 1f197. mfn ffffffff
> [2006-04-12 16:43:36 xend] ERROR (XendCheckpoint:227)  80% 
> 86%netbuf race: iter 8, pfn 475e. mfn ffffffff
> [2006-04-12 16:43:39 xend] ERROR (XendCheckpoint:227)  92%netbuf 
> race: iter 8, pfn 1c7d6. mfn ffffffff
> [2006-04-12 16:43:42 xend] ERROR (XendCheckpoint:227)  98%
> 8: sent 34027, skipped 209, delta 61914ms, dom0 6%, target 23%, sent 
> 18Mb/s, dirtied 0Mb/s 232 pages
> [2006-04-12 16:43:42 xend] ERROR (XendCheckpoint:227) Saving memory 
> pages: iter 9   0%
> 9: sent 232, skipped 0, Start last iteration
> [2006-04-12 16:43:42 xend] DEBUG (XendCheckpoint:200) suspend
> [2006-04-12 16:43:42 xend] DEBUG (XendCheckpoint:83) In 
> saveInputHandler suspend
> [2006-04-12 16:43:42 xend] DEBUG (XendCheckpoint:85) Suspending 32 ...
> [2006-04-12 16:47:28 xend.XendDomainInfo] DEBUG (XendDomainInfo:1272) 
> XendDomainInfo.destroy: domid=32
> [2006-04-12 16:47:28 xend.XendDomainInfo] DEBUG (XendDomainInfo:1280) 
> XendDomainInfo.destroyDomain(32)
> [2006-04-12 16:47:28 xend] INFO (XendCheckpoint:88) Domain 32 suspended.
> [2006-04-12 16:47:28 xend] ERROR (XendCheckpoint:99) Save failed on 
> domain xenbox (32).
> Traceback (most recent call last):
>  File "/usr/lib/python/xen/xend/XendCheckpoint.py", line 93, in save
>    forkHelper(cmd, fd, saveInputHandler, False)
>  File "/usr/lib/python/xen/xend/XendCheckpoint.py", line 206, in 
> forkHelper
>    raise XendError('Error reading from child process for %s: %s' %
>
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@xxxxxxxxxxxxxxxxxxx
> http://lists.xensource.com/xen-devel

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel