Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 07/04/2017 10:16 AM, Martin Schwidefsky wrote:
> On Tue, 4 Jul 2017 09:48:11 +0200
> Christian Borntraeger  wrote:
> 
>> On 07/03/2017 09:07 PM, Dr. David Alan Gilbert wrote:
>>> * Michael S. Tsirkin (m...@redhat.com) wrote:  
 On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:  
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:  
>> On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
>>  
 Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
 RAM_SAVE_FLAG_COMPRESS
 then try changing ram_handle_compressed to always do the memset.  
>>>
>>> FWIW, changing ram_handle_compressed to always memset makes the problem 
>>> go away.  
>>
>> It is still running fine now with the "always memset change"  
>
> Did we ever nail down a fix for this; as I remember Andrea said
> we shouldn't need to do that memset, but we came to the conclusion
> it was something specific to how s390 protection keys worked.
>
> Dave  

 No we didn't. Let's merge that for now, with a comment that
 we don't really understand what's going on?  
>>>
>>> Hmm no, I don't really want to change the !s390 behaviour, especially
>>> since it causes allocation that we otherwise avoid and Andrea's
>>> reply tothe original post pointed out it's not necessary.  
>>
>>
>> Since storage keys are per physical page we must not have shared pages.
>> Therefore in s390_enable_skey we already do a break_ksm (via ksm_madvise),
>> in other words we already allocate pages on the keyless->keyed switch.
>>
>> So why not do the same for zero pages - instead of invalidating the page
>> table entry, lets just do a proper COW.
>>
>> Something like this maybe (Andrea, Martin any better way to do that?)
>>
>>
>> diff --git a/arch/s390/mm/gmap.c b/arch/s390/mm/gmap.c
>> index 4fb3d3c..11475c7 100644
>> --- a/arch/s390/mm/gmap.c
>> +++ b/arch/s390/mm/gmap.c
>> @@ -2149,13 +2149,18 @@ EXPORT_SYMBOL_GPL(s390_enable_sie);
>>  static int __s390_enable_skey(pte_t *pte, unsigned long addr,
>>   unsigned long next, struct mm_walk *walk)
>>  {
>> +   struct page *page;
>> /*
>> -* Remove all zero page mappings,
>> +* Remove all zero page mappings with a COW
>>  * after establishing a policy to forbid zero page mappings
>>  * following faults for that page will get fresh anonymous pages
>>  */
>> -   if (is_zero_pfn(pte_pfn(*pte)))
>> -   ptep_xchg_direct(walk->mm, addr, pte, __pte(_PAGE_INVALID));
>> +   if (is_zero_pfn(pte_pfn(*pte))) {
>> +   if (get_user_pages(addr, 1, FOLL_WRITE, , NULL) == 1)
>> +   put_page(page);
>> +   else
>> +   return -ENOMEM;
>> +   }
>> /* Clear storage key */
>> ptep_zap_key(walk->mm, addr, pte);
>> return 0;
> 
> I do not quite get the problem here. The zero-page mappings are always
> marked as _PAGE_SPECIAL. These should be safe to replace with an empty
> pte. We do mark all VMAs as unmergeable prior to the page table walk
> that replaces all zero-page mappings. What is the get_user_pages() call
> supposed to do?
> 


After talking to Martin, we decided that it might be a good trial to simply
not use the empty zero page at all for KVM guests. Something like this


diff --git a/arch/s390/include/asm/pgtable.h b/arch/s390/include/asm/pgtable.h
index 57057fb..65ab11d 100644
--- a/arch/s390/include/asm/pgtable.h
+++ b/arch/s390/include/asm/pgtable.h
@@ -505,7 +505,7 @@ static inline int mm_alloc_pgste(struct mm_struct *mm)
  * In the case that a guest uses storage keys
  * faults should no longer be backed by zero pages
  */
-#define mm_forbids_zeropage mm_use_skey
+#define mm_forbids_zeropage mm_has_pgste
 static inline int mm_use_skey(struct mm_struct *mm)
 {
 #ifdef CONFIG_PGSTE
diff --git a/arch/s390/mm/gmap.c b/arch/s390/mm/gmap.c
index 4fb3d3c..88f502a 100644
--- a/arch/s390/mm/gmap.c
+++ b/arch/s390/mm/gmap.c
@@ -2149,13 +2149,6 @@ EXPORT_SYMBOL_GPL(s390_enable_sie);
 static int __s390_enable_skey(pte_t *pte, unsigned long addr,
  unsigned long next, struct mm_walk *walk)
 {
-   /*
-* Remove all zero page mappings,
-* after establishing a policy to forbid zero page mappings
-* following faults for that page will get fresh anonymous pages
-*/
-   if (is_zero_pfn(pte_pfn(*pte)))
-   ptep_xchg_direct(walk->mm, addr, pte, __pte(_PAGE_INVALID));
/* Clear storage key */
ptep_zap_key(walk->mm, addr, pte);
return 0;



seems to do the trick. Will have a look what that means for the memory usage for
the usual cases.

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Martin Schwidefsky]

On Tue, 4 Jul 2017 09:48:11 +0200
Christian Borntraeger  wrote:

> On 07/03/2017 09:07 PM, Dr. David Alan Gilbert wrote:
> > * Michael S. Tsirkin (m...@redhat.com) wrote:  
> >> On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:  
> >>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:  
>  On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
>   
> >> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
> >> RAM_SAVE_FLAG_COMPRESS
> >> then try changing ram_handle_compressed to always do the memset.  
> >
> > FWIW, changing ram_handle_compressed to always memset makes the problem 
> > go away.  
> 
>  It is still running fine now with the "always memset change"  
> >>>
> >>> Did we ever nail down a fix for this; as I remember Andrea said
> >>> we shouldn't need to do that memset, but we came to the conclusion
> >>> it was something specific to how s390 protection keys worked.
> >>>
> >>> Dave  
> >>
> >> No we didn't. Let's merge that for now, with a comment that
> >> we don't really understand what's going on?  
> > 
> > Hmm no, I don't really want to change the !s390 behaviour, especially
> > since it causes allocation that we otherwise avoid and Andrea's
> > reply tothe original post pointed out it's not necessary.  
> 
> 
> Since storage keys are per physical page we must not have shared pages.
> Therefore in s390_enable_skey we already do a break_ksm (via ksm_madvise),
> in other words we already allocate pages on the keyless->keyed switch.
> 
> So why not do the same for zero pages - instead of invalidating the page
> table entry, lets just do a proper COW.
> 
> Something like this maybe (Andrea, Martin any better way to do that?)
> 
> 
> diff --git a/arch/s390/mm/gmap.c b/arch/s390/mm/gmap.c
> index 4fb3d3c..11475c7 100644
> --- a/arch/s390/mm/gmap.c
> +++ b/arch/s390/mm/gmap.c
> @@ -2149,13 +2149,18 @@ EXPORT_SYMBOL_GPL(s390_enable_sie);
>  static int __s390_enable_skey(pte_t *pte, unsigned long addr,
>   unsigned long next, struct mm_walk *walk)
>  {
> +   struct page *page;
> /*
> -* Remove all zero page mappings,
> +* Remove all zero page mappings with a COW
>  * after establishing a policy to forbid zero page mappings
>  * following faults for that page will get fresh anonymous pages
>  */
> -   if (is_zero_pfn(pte_pfn(*pte)))
> -   ptep_xchg_direct(walk->mm, addr, pte, __pte(_PAGE_INVALID));
> +   if (is_zero_pfn(pte_pfn(*pte))) {
> +   if (get_user_pages(addr, 1, FOLL_WRITE, , NULL) == 1)
> +   put_page(page);
> +   else
> +   return -ENOMEM;
> +   }
> /* Clear storage key */
> ptep_zap_key(walk->mm, addr, pte);
> return 0;

I do not quite get the problem here. The zero-page mappings are always
marked as _PAGE_SPECIAL. These should be safe to replace with an empty
pte. We do mark all VMAs as unmergeable prior to the page table walk
that replaces all zero-page mappings. What is the get_user_pages() call
supposed to do?

-- 
blue skies,
   Martin.

"Reality continues to ruin my life." - Calvin.

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 07/04/2017 10:16 AM, Martin Schwidefsky wrote:
> On Tue, 4 Jul 2017 09:48:11 +0200
> Christian Borntraeger  wrote:
> 
>> On 07/03/2017 09:07 PM, Dr. David Alan Gilbert wrote:
>>> * Michael S. Tsirkin (m...@redhat.com) wrote:  
 On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:  
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:  
>> On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
>>  
 Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
 RAM_SAVE_FLAG_COMPRESS
 then try changing ram_handle_compressed to always do the memset.  
>>>
>>> FWIW, changing ram_handle_compressed to always memset makes the problem 
>>> go away.  
>>
>> It is still running fine now with the "always memset change"  
>
> Did we ever nail down a fix for this; as I remember Andrea said
> we shouldn't need to do that memset, but we came to the conclusion
> it was something specific to how s390 protection keys worked.
>
> Dave  

 No we didn't. Let's merge that for now, with a comment that
 we don't really understand what's going on?  
>>>
>>> Hmm no, I don't really want to change the !s390 behaviour, especially
>>> since it causes allocation that we otherwise avoid and Andrea's
>>> reply tothe original post pointed out it's not necessary.  
>>
>>
>> Since storage keys are per physical page we must not have shared pages.
>> Therefore in s390_enable_skey we already do a break_ksm (via ksm_madvise),
>> in other words we already allocate pages on the keyless->keyed switch.
>>
>> So why not do the same for zero pages - instead of invalidating the page
>> table entry, lets just do a proper COW.
>>
>> Something like this maybe (Andrea, Martin any better way to do that?)
>>
>>
>> diff --git a/arch/s390/mm/gmap.c b/arch/s390/mm/gmap.c
>> index 4fb3d3c..11475c7 100644
>> --- a/arch/s390/mm/gmap.c
>> +++ b/arch/s390/mm/gmap.c
>> @@ -2149,13 +2149,18 @@ EXPORT_SYMBOL_GPL(s390_enable_sie);
>>  static int __s390_enable_skey(pte_t *pte, unsigned long addr,
>>   unsigned long next, struct mm_walk *walk)yy
>>  {
>> +   struct page *page;
>> /*
>> -* Remove all zero page mappings,
>> +* Remove all zero page mappings with a COW
>>  * after establishing a policy to forbid zero page mappings
>>  * following faults for that page will get fresh anonymous pages
>>  */
>> -   if (is_zero_pfn(pte_pfn(*pte)))
>> -   ptep_xchg_direct(walk->mm, addr, pte, __pte(_PAGE_INVALID));
>> +   if (is_zero_pfn(pte_pfn(*pte))) {
>> +   if (get_user_pages(addr, 1, FOLL_WRITE, , NULL) == 1)
>> +   put_page(page);
>> +   else
>> +   return -ENOMEM;
>> +   }
>> /* Clear storage key */
>> ptep_zap_key(walk->mm, addr, pte);
>> return 0;
> 
> I do not quite get the problem here. The zero-page mappings are always
> marked as _PAGE_SPECIAL. These should be safe to replace with an empty
> pte. We do mark all VMAs as unmergeable prior to the page table walk
> that replaces all zero-page mappings. What is the get_user_pages() call
> supposed to do?

the problem is that postcopy migration will do a read on the target system
for zero pages (to fault in zero pages).
The logic in postcopy then relies on this page never ever delivering a 
userfault again.

If we now enable keys on the target host, we will break the zero pages with
an empty PTE (lazy faulting).
With an empty pte we will get a userfault for this if this page is accesses
again on the target. Now postcopy "knows" that this page was already transferred
and bascially ignores this fault. Since postcopy will never resolve this
userfault the guest will hang.

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 07/03/2017 09:07 PM, Dr. David Alan Gilbert wrote:
> * Michael S. Tsirkin (m...@redhat.com) wrote:
>> On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 On 04/26/2017 01:45 PM, Christian Borntraeger wrote:

>> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
>> RAM_SAVE_FLAG_COMPRESS
>> then try changing ram_handle_compressed to always do the memset.
>
> FWIW, changing ram_handle_compressed to always memset makes the problem 
> go away.

 It is still running fine now with the "always memset change"
>>>
>>> Did we ever nail down a fix for this; as I remember Andrea said
>>> we shouldn't need to do that memset, but we came to the conclusion
>>> it was something specific to how s390 protection keys worked.
>>>
>>> Dave
>>
>> No we didn't. Let's merge that for now, with a comment that
>> we don't really understand what's going on?
> 
> Hmm no, I don't really want to change the !s390 behaviour, especially
> since it causes allocation that we otherwise avoid and Andrea's
> reply tothe original post pointed out it's not necessary.


Since storage keys are per physical page we must not have shared pages.
Therefore in s390_enable_skey we already do a break_ksm (via ksm_madvise),
in other words we already allocate pages on the keyless->keyed switch.

So why not do the same for zero pages - instead of invalidating the page
table entry, lets just do a proper COW.

Something like this maybe (Andrea, Martin any better way to do that?)


diff --git a/arch/s390/mm/gmap.c b/arch/s390/mm/gmap.c
index 4fb3d3c..11475c7 100644
--- a/arch/s390/mm/gmap.c
+++ b/arch/s390/mm/gmap.c
@@ -2149,13 +2149,18 @@ EXPORT_SYMBOL_GPL(s390_enable_sie);
 static int __s390_enable_skey(pte_t *pte, unsigned long addr,
  unsigned long next, struct mm_walk *walk)
 {
+   struct page *page;
/*
-* Remove all zero page mappings,
+* Remove all zero page mappings with a COW
 * after establishing a policy to forbid zero page mappings
 * following faults for that page will get fresh anonymous pages
 */
-   if (is_zero_pfn(pte_pfn(*pte)))
-   ptep_xchg_direct(walk->mm, addr, pte, __pte(_PAGE_INVALID));
+   if (is_zero_pfn(pte_pfn(*pte))) {
+   if (get_user_pages(addr, 1, FOLL_WRITE, , NULL) == 1)
+   put_page(page);
+   else
+   return -ENOMEM;
+   }
/* Clear storage key */
ptep_zap_key(walk->mm, addr, pte);
return 0;

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Michael S. Tsirkin (m...@redhat.com) wrote:
> On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:
> > * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> > > On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
> > > 
> > > >> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
> > > >> RAM_SAVE_FLAG_COMPRESS
> > > >> then try changing ram_handle_compressed to always do the memset.
> > > > 
> > > > FWIW, changing ram_handle_compressed to always memset makes the problem 
> > > > go away.
> > > 
> > > It is still running fine now with the "always memset change"
> > 
> > Did we ever nail down a fix for this; as I remember Andrea said
> > we shouldn't need to do that memset, but we came to the conclusion
> > it was something specific to how s390 protection keys worked.
> > 
> > Dave
> 
> No we didn't. Let's merge that for now, with a comment that
> we don't really understand what's going on?

Hmm no, I don't really want to change the !s390 behaviour, especially
since it causes allocation that we otherwise avoid and Andrea's
reply tothe original post pointed out it's not necessary.

Dave

> > --
> > Dr. David Alan Gilbert / dgilb...@redhat.com / Manchester, UK
--
Dr. David Alan Gilbert / dgilb...@redhat.com / Manchester, UK

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Michael S. Tsirkin]

On Fri, Jun 30, 2017 at 05:31:39PM +0100, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> > On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
> > 
> > >> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
> > >> RAM_SAVE_FLAG_COMPRESS
> > >> then try changing ram_handle_compressed to always do the memset.
> > > 
> > > FWIW, changing ram_handle_compressed to always memset makes the problem 
> > > go away.
> > 
> > It is still running fine now with the "always memset change"
> 
> Did we ever nail down a fix for this; as I remember Andrea said
> we shouldn't need to do that memset, but we came to the conclusion
> it was something specific to how s390 protection keys worked.
> 
> Dave

No we didn't. Let's merge that for now, with a comment that
we don't really understand what's going on?

> --
> Dr. David Alan Gilbert / dgilb...@redhat.com / Manchester, UK

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 06/30/2017 06:31 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
>>
 Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
 RAM_SAVE_FLAG_COMPRESS
 then try changing ram_handle_compressed to always do the memset.
>>>
>>> FWIW, changing ram_handle_compressed to always memset makes the problem go 
>>> away.
>>
>> It is still running fine now with the "always memset change"
> 
> Did we ever nail down a fix for this; as I remember Andrea said
> we shouldn't need to do that memset, but we came to the conclusion
> it was something specific to how s390 protection keys worked.

It was specific to s390. Newer Linuxes do not use the storage keys,
so we enable them lazily. If a guest goes from keyless to keyed, the
kernel will mark the VM to no longer use the zero page and the  walk all
pages of that guests and zaps the empty_zero page from the page table.
All normal code will then fault in a cow copy of the zero page on the
next access. 
The postcopy logic now at least reads all zero pages to prevent faults
on these addresses. If a running guest switches to key-mode afterwards
(but during postcopy) then we might get a fault for a zero page.

Still not sure about the best solution. (see  s390_enable_skey in 
arch/s390/mm/gmap.c)

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> On 04/26/2017 01:45 PM, Christian Borntraeger wrote:
> 
> >> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
> >> RAM_SAVE_FLAG_COMPRESS
> >> then try changing ram_handle_compressed to always do the memset.
> > 
> > FWIW, changing ram_handle_compressed to always memset makes the problem go 
> > away.
> 
> It is still running fine now with the "always memset change"

Did we ever nail down a fix for this; as I remember Andrea said
we shouldn't need to do that memset, but we came to the conclusion
it was something specific to how s390 protection keys worked.

Dave

--
Dr. David Alan Gilbert / dgilb...@redhat.com / Manchester, UK

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/26/2017 01:45 PM, Christian Borntraeger wrote:

>> Hmm, I have a theory, if the flags field has bit 1 set, i.e. 
>> RAM_SAVE_FLAG_COMPRESS
>> then try changing ram_handle_compressed to always do the memset.
> 
> FWIW, changing ram_handle_compressed to always memset makes the problem go 
> away.

It is still running fine now with the "always memset change"

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/26/2017 01:01 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 09:12 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 David, Juan,

 I can trigger a hang of postcopy migration (when I do it early) so
 that both sides are in paused state. Looks like one thread is still
 loading vmstates for virtio and this load accesses guest memory and
 triggers a userfault.
>>>
>>> It's perfectly legal for the destination to cause a userfault as it
>>> loads the virtio queue - the virtio queue should be being loaded by
>>> the main thread from the buffer while the 'listening' thread is
>>> waiting for the incoming page data.
>>>
>>> Can you turn on the following tracing please: destination: 
>>> postcopy_ram_fault_thread_request postcopy_place_page 
>>> postcopy_place_page_zero
>>>
>>> source: migrate_handle_rp_req_pages ram_save_queue_pages
>>>
>>> You should see: virtio does the access userfault generates a fault 
>>> postcopy_ram_fault_thread_request sends the request to the source
>>>
>>> the source sees migrate_handle_rp_req_pages queues it with
>>> ram_save_queue_pages
>>>
>>> the destination sees the page arrive and postcopy_place_page or
>>> postcopy_place_page_zero
>>>
>>> some of that might disappear if the page was already on it's way.
>>
>>
>> the last event on the source are
>> [..]
>> 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
>> 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
>
> How do you see those on the source???

 It was the previous migrate (I did it in a loop forth and back)
 The problem happens on the migrate back.
>>>
>>> OK, good.
>>>
>
>> 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 
>> 41d9000 len 1000
>> 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 
>> len: 100
>>
>
> Is that a typo? I'm expecting those two 'len' fields to be the same?

 Yes, its a cut'n' paste "miss the last byte"
>>>
>>> Good.
>>>
>>> Ok, before digging further, is this a new bug or does it happen on older
>>> QEMU?  Have you got a rune to reproduce it on x86?
>>>

>
>> On the target a see lots of
>>
>> 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
>> 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
>> 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
>> 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
>> 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
>> 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
>>
>> So we have about 2 seconds of traffic going on after that request,
>> I assume its precopy related.
>>
>> Looking back on the target history there was
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
>>
>> In fact it seems to be the first and only request:
>>
>> # cat /tmp/test0.trace | grep -v postcopy_place_page
>>
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
>
> OK, does the HVA there correspond to the address that your virtio device 
> is blocking on?

 yes it is the same page.


> (or at least the start of the page)
> Do you see a postcopy_place_page with a host= the same HVA ?

 no
>>>
>>> Hmm, that's bad.
>>> The flow is:
>>> Precopy
>>>(a) Send pages
>>> Switch to postcopy
>>>(b) Send discards for pages that have been changed after
>>>(a)
>>> Postcopy
>>>(c) Keep sending pages until we run out
>>>(d) But send pages we're asked for first
>>>
>>>  (d) might be ignored if the source thinks the page was already sent or not 
>>> dirty.
>>>
>>> So we need to figure out:
>>>   1) If the source sent the pages during (a)
>>>   2) If the source discarded it during (b)
>>>   3) If it sent it again any time in c/d
>>>   4) If it ignored the request from d
>>>
>>>
>>> So please turn on the traces:
>>> get_queued_page_not_dirtyshould help with (4)
>>> get_queued_page  should help with (4)
>>> ram_discard_rangeshould help with (2)
>>> loadvm_postcopy_ram_handle_discard   should help with (2)
>>> qemu_savevm_send_postcopy_ram_discardshould help with (2)
>>>

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/26/2017 01:01 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 09:12 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 David, Juan,

 I can trigger a hang of postcopy migration (when I do it early) so
 that both sides are in paused state. Looks like one thread is still
 loading vmstates for virtio and this load accesses guest memory and
 triggers a userfault.
>>>
>>> It's perfectly legal for the destination to cause a userfault as it
>>> loads the virtio queue - the virtio queue should be being loaded by
>>> the main thread from the buffer while the 'listening' thread is
>>> waiting for the incoming page data.
>>>
>>> Can you turn on the following tracing please: destination: 
>>> postcopy_ram_fault_thread_request postcopy_place_page 
>>> postcopy_place_page_zero
>>>
>>> source: migrate_handle_rp_req_pages ram_save_queue_pages
>>>
>>> You should see: virtio does the access userfault generates a fault 
>>> postcopy_ram_fault_thread_request sends the request to the source
>>>
>>> the source sees migrate_handle_rp_req_pages queues it with
>>> ram_save_queue_pages
>>>
>>> the destination sees the page arrive and postcopy_place_page or
>>> postcopy_place_page_zero
>>>
>>> some of that might disappear if the page was already on it's way.
>>
>>
>> the last event on the source are
>> [..]
>> 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
>> 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
>
> How do you see those on the source???

 It was the previous migrate (I did it in a loop forth and back)
 The problem happens on the migrate back.
>>>
>>> OK, good.
>>>
>
>> 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 
>> 41d9000 len 1000
>> 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 
>> len: 100
>>
>
> Is that a typo? I'm expecting those two 'len' fields to be the same?

 Yes, its a cut'n' paste "miss the last byte"
>>>
>>> Good.
>>>
>>> Ok, before digging further, is this a new bug or does it happen on older
>>> QEMU?  Have you got a rune to reproduce it on x86?
>>>

>
>> On the target a see lots of
>>
>> 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
>> 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
>> 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
>> 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
>> 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
>> 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
>>
>> So we have about 2 seconds of traffic going on after that request,
>> I assume its precopy related.
>>
>> Looking back on the target history there was
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
>>
>> In fact it seems to be the first and only request:
>>
>> # cat /tmp/test0.trace | grep -v postcopy_place_page
>>
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
>
> OK, does the HVA there correspond to the address that your virtio device 
> is blocking on?

 yes it is the same page.


> (or at least the start of the page)
> Do you see a postcopy_place_page with a host= the same HVA ?

 no
>>>
>>> Hmm, that's bad.
>>> The flow is:
>>> Precopy
>>>(a) Send pages
>>> Switch to postcopy
>>>(b) Send discards for pages that have been changed after
>>>(a)
>>> Postcopy
>>>(c) Keep sending pages until we run out
>>>(d) But send pages we're asked for first
>>>
>>>  (d) might be ignored if the source thinks the page was already sent or not 
>>> dirty.
>>>
>>> So we need to figure out:
>>>   1) If the source sent the pages during (a)
>>>   2) If the source discarded it during (b)
>>>   3) If it sent it again any time in c/d
>>>   4) If it ignored the request from d
>>>
>>>
>>> So please turn on the traces:
>>> get_queued_page_not_dirtyshould help with (4)
>>> get_queued_page  should help with (4)
>>> ram_discard_rangeshould help with (2)
>>> loadvm_postcopy_ram_handle_discard   should help with (2)
>>> qemu_savevm_send_postcopy_ram_discardshould help with (2)
>>>

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> On 04/24/2017 09:12 PM, Dr. David Alan Gilbert wrote:
> > * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> >> On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
> >>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>  On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> > * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> >> David, Juan,
> >>
> >> I can trigger a hang of postcopy migration (when I do it early) so
> >> that both sides are in paused state. Looks like one thread is still
> >> loading vmstates for virtio and this load accesses guest memory and
> >> triggers a userfault.
> >
> > It's perfectly legal for the destination to cause a userfault as it
> > loads the virtio queue - the virtio queue should be being loaded by
> > the main thread from the buffer while the 'listening' thread is
> > waiting for the incoming page data.
> >
> > Can you turn on the following tracing please: destination: 
> > postcopy_ram_fault_thread_request postcopy_place_page 
> > postcopy_place_page_zero
> >
> > source: migrate_handle_rp_req_pages ram_save_queue_pages
> >
> > You should see: virtio does the access userfault generates a fault 
> > postcopy_ram_fault_thread_request sends the request to the source
> >
> > the source sees migrate_handle_rp_req_pages queues it with
> > ram_save_queue_pages
> >
> > the destination sees the page arrive and postcopy_place_page or
> > postcopy_place_page_zero
> >
> > some of that might disappear if the page was already on it's way.
> 
> 
>  the last event on the source are
>  [..]
>  58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
>  58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
> >>>
> >>> How do you see those on the source???
> >>
> >> It was the previous migrate (I did it in a loop forth and back)
> >> The problem happens on the migrate back.
> > 
> > OK, good.
> > 
> >>>
>  58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 
>  41d9000 len 1000
>  58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 
>  len: 100
> 
> >>>
> >>> Is that a typo? I'm expecting those two 'len' fields to be the same?
> >>
> >> Yes, its a cut'n' paste "miss the last byte"
> > 
> > Good.
> > 
> > Ok, before digging further, is this a new bug or does it happen on older
> > QEMU?  Have you got a rune to reproduce it on x86?
> > 
> >>
> >>>
>  On the target a see lots of
> 
>  39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
>  39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
>  39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
>  39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
>  39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
>  39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
> 
>  So we have about 2 seconds of traffic going on after that request,
>  I assume its precopy related.
> 
>  Looking back on the target history there was
>  39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>  HVA=3ff618d9000 rb=s390.ram offset=41d9000
> 
>  In fact it seems to be the first and only request:
> 
>  # cat /tmp/test0.trace | grep -v postcopy_place_page
> 
>  39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>  HVA=3ff618d9000 rb=s390.ram offset=41d9000
> >>>
> >>> OK, does the HVA there correspond to the address that your virtio device 
> >>> is blocking on?
> >>
> >> yes it is the same page.
> >>
> >>
> >>> (or at least the start of the page)
> >>> Do you see a postcopy_place_page with a host= the same HVA ?
> >>
> >> no
> > 
> > Hmm, that's bad.
> > The flow is:
> > Precopy
> >(a) Send pages
> > Switch to postcopy
> >(b) Send discards for pages that have been changed after
> >(a)
> > Postcopy
> >(c) Keep sending pages until we run out
> >(d) But send pages we're asked for first
> > 
> >  (d) might be ignored if the source thinks the page was already sent or not 
> > dirty.
> > 
> > So we need to figure out:
> >   1) If the source sent the pages during (a)
> >   2) If the source discarded it during (b)
> >   3) If it sent it again any time in c/d
> >   4) If it ignored the request from d
> > 
> > 
> > So please turn on the traces:
> > get_queued_page_not_dirtyshould help with (4)
> > get_queued_page  should help with (4)
> > ram_discard_rangeshould help with (2)
> > loadvm_postcopy_ram_handle_discard   should help with (2)
> > qemu_savevm_send_postcopy_ram_discardshould help with (2)
> > 
> > add near the top of ram_save_page in ram.c:

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/26/2017 11:59 AM, Christian Borntraeger wrote:

> source:
> 28863@1493200554.418978:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419047:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419056:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419064:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419071:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419077:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419083:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419088:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419094:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419100:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419106:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419112:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419117:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419123:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419130:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419138:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419145:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419151:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419156:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419163:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419169:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419174:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419179:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419184:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419189:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
> 28863@1493200554.419208:qemu_savevm_send_postcopy_ram_discard s390.ram: 9d
> 28863@1493200554.818195:migrate_handle_rp_req_pages in s390.ram at 3c6b000 
> len 1000
> 28863@1493200554.818208:ram_save_queue_pages s390.ram: start: 3c6b000 len: 
> 1000
> 28863@1493200554.818469:get_queued_page_not_dirty s390.ram/3c6b000 
> ram_addr=3c6b000 (sent=0)
> 
> I also get 
> ram_save_page: s390.ram:3c6b000

looks like this one happens before the discards.

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/24/2017 09:12 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> David, Juan,
>>
>> I can trigger a hang of postcopy migration (when I do it early) so
>> that both sides are in paused state. Looks like one thread is still
>> loading vmstates for virtio and this load accesses guest memory and
>> triggers a userfault.
>
> It's perfectly legal for the destination to cause a userfault as it
> loads the virtio queue - the virtio queue should be being loaded by
> the main thread from the buffer while the 'listening' thread is
> waiting for the incoming page data.
>
> Can you turn on the following tracing please: destination: 
> postcopy_ram_fault_thread_request postcopy_place_page 
> postcopy_place_page_zero
>
> source: migrate_handle_rp_req_pages ram_save_queue_pages
>
> You should see: virtio does the access userfault generates a fault 
> postcopy_ram_fault_thread_request sends the request to the source
>
> the source sees migrate_handle_rp_req_pages queues it with
> ram_save_queue_pages
>
> the destination sees the page arrive and postcopy_place_page or
> postcopy_place_page_zero
>
> some of that might disappear if the page was already on it's way.


 the last event on the source are
 [..]
 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
>>>
>>> How do you see those on the source???
>>
>> It was the previous migrate (I did it in a loop forth and back)
>> The problem happens on the migrate back.
> 
> OK, good.
> 
>>>
 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 
 len 1000
 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 
 100

>>>
>>> Is that a typo? I'm expecting those two 'len' fields to be the same?
>>
>> Yes, its a cut'n' paste "miss the last byte"
> 
> Good.
> 
> Ok, before digging further, is this a new bug or does it happen on older
> QEMU?  Have you got a rune to reproduce it on x86?
> 
>>
>>>
 On the target a see lots of

 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000

 So we have about 2 seconds of traffic going on after that request,
 I assume its precopy related.

 Looking back on the target history there was
 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
 HVA=3ff618d9000 rb=s390.ram offset=41d9000

 In fact it seems to be the first and only request:

 # cat /tmp/test0.trace | grep -v postcopy_place_page

 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
 HVA=3ff618d9000 rb=s390.ram offset=41d9000
>>>
>>> OK, does the HVA there correspond to the address that your virtio device is 
>>> blocking on?
>>
>> yes it is the same page.
>>
>>
>>> (or at least the start of the page)
>>> Do you see a postcopy_place_page with a host= the same HVA ?
>>
>> no
> 
> Hmm, that's bad.
> The flow is:
> Precopy
>(a) Send pages
> Switch to postcopy
>(b) Send discards for pages that have been changed after
>(a)
> Postcopy
>(c) Keep sending pages until we run out
>(d) But send pages we're asked for first
> 
>  (d) might be ignored if the source thinks the page was already sent or not 
> dirty.
> 
> So we need to figure out:
>   1) If the source sent the pages during (a)
>   2) If the source discarded it during (b)
>   3) If it sent it again any time in c/d
>   4) If it ignored the request from d
> 
> 
> So please turn on the traces:
> get_queued_page_not_dirtyshould help with (4)
> get_queued_page  should help with (4)
> ram_discard_rangeshould help with (2)
> loadvm_postcopy_ram_handle_discard   should help with (2)
> qemu_savevm_send_postcopy_ram_discardshould help with (2)
> 
> add near the top of ram_save_page in ram.c:
>   fprintf(stderr, "%s: %s:%zx\n", __func__, block->idstr, (size_t)offset);
> 
>should help with 1, 3


source:
28863@1493200554.418978:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d
28863@1493200554.419047:qemu_savevm_send_postcopy_ram_discard s390.ram: 12d

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/24/2017 09:12 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> David, Juan,
>>
>> I can trigger a hang of postcopy migration (when I do it early) so
>> that both sides are in paused state. Looks like one thread is still
>> loading vmstates for virtio and this load accesses guest memory and
>> triggers a userfault.
>
> It's perfectly legal for the destination to cause a userfault as it
> loads the virtio queue - the virtio queue should be being loaded by
> the main thread from the buffer while the 'listening' thread is
> waiting for the incoming page data.
>
> Can you turn on the following tracing please: destination: 
> postcopy_ram_fault_thread_request postcopy_place_page 
> postcopy_place_page_zero
>
> source: migrate_handle_rp_req_pages ram_save_queue_pages
>
> You should see: virtio does the access userfault generates a fault 
> postcopy_ram_fault_thread_request sends the request to the source
>
> the source sees migrate_handle_rp_req_pages queues it with
> ram_save_queue_pages
>
> the destination sees the page arrive and postcopy_place_page or
> postcopy_place_page_zero
>
> some of that might disappear if the page was already on it's way.


 the last event on the source are
 [..]
 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
>>>
>>> How do you see those on the source???
>>
>> It was the previous migrate (I did it in a loop forth and back)
>> The problem happens on the migrate back.
> 
> OK, good.
> 
>>>
 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 
 len 1000
 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 
 100

>>>
>>> Is that a typo? I'm expecting those two 'len' fields to be the same?
>>
>> Yes, its a cut'n' paste "miss the last byte"
> 
> Good.
> 
> Ok, before digging further, is this a new bug or does it happen on older
> QEMU?  Have you got a rune to reproduce it on x86?

No x86 yet. It also seems to happen with 2.8 but only between two specific
machines (and one of those is down for maintenance right now).
Will do the experiments as soon as it  is back up.



>>
>>>
 On the target a see lots of

 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000

 So we have about 2 seconds of traffic going on after that request,
 I assume its precopy related.

 Looking back on the target history there was
 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
 HVA=3ff618d9000 rb=s390.ram offset=41d9000

 In fact it seems to be the first and only request:

 # cat /tmp/test0.trace | grep -v postcopy_place_page

 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
 HVA=3ff618d9000 rb=s390.ram offset=41d9000
>>>
>>> OK, does the HVA there correspond to the address that your virtio device is 
>>> blocking on?
>>
>> yes it is the same page.
>>
>>
>>> (or at least the start of the page)
>>> Do you see a postcopy_place_page with a host= the same HVA ?
>>
>> no
> 
> Hmm, that's bad.
> The flow is:
> Precopy
>(a) Send pages
> Switch to postcopy
>(b) Send discards for pages that have been changed after
>(a)
> Postcopy
>(c) Keep sending pages until we run out
>(d) But send pages we're asked for first
> 
>  (d) might be ignored if the source thinks the page was already sent or not 
> dirty.
> 
> So we need to figure out:
>   1) If the source sent the pages during (a)
>   2) If the source discarded it during (b)
>   3) If it sent it again any time in c/d
>   4) If it ignored the request from d
> 
> 
> So please turn on the traces:
> get_queued_page_not_dirtyshould help with (4)
> get_queued_page  should help with (4)
> ram_discard_rangeshould help with (2)
> loadvm_postcopy_ram_handle_discard   should help with (2)
> qemu_savevm_send_postcopy_ram_discardshould help with (2)
> 
> add near the top of ram_save_page in ram.c:
>   fprintf(stderr, "%s: %s:%zx\n", __func__, block->idstr, (size_t)offset);
> 
>should help with 1, 3
> 
> So lets see 

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
> > * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> >> On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> >>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>  David, Juan,
> 
>  I can trigger a hang of postcopy migration (when I do it early) so
>  that both sides are in paused state. Looks like one thread is still
>  loading vmstates for virtio and this load accesses guest memory and
>  triggers a userfault.
> >>>
> >>> It's perfectly legal for the destination to cause a userfault as it
> >>> loads the virtio queue - the virtio queue should be being loaded by
> >>> the main thread from the buffer while the 'listening' thread is
> >>> waiting for the incoming page data.
> >>>
> >>> Can you turn on the following tracing please: destination: 
> >>> postcopy_ram_fault_thread_request postcopy_place_page 
> >>> postcopy_place_page_zero
> >>>
> >>> source: migrate_handle_rp_req_pages ram_save_queue_pages
> >>>
> >>> You should see: virtio does the access userfault generates a fault 
> >>> postcopy_ram_fault_thread_request sends the request to the source
> >>>
> >>> the source sees migrate_handle_rp_req_pages queues it with
> >>> ram_save_queue_pages
> >>>
> >>> the destination sees the page arrive and postcopy_place_page or
> >>> postcopy_place_page_zero
> >>>
> >>> some of that might disappear if the page was already on it's way.
> >>
> >>
> >> the last event on the source are
> >> [..]
> >> 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
> >> 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
> > 
> > How do you see those on the source???
> 
> It was the previous migrate (I did it in a loop forth and back)
> The problem happens on the migrate back.

OK, good.

> > 
> >> 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 
> >> len 1000
> >> 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 
> >> 100
> >>
> > 
> > Is that a typo? I'm expecting those two 'len' fields to be the same?
> 
> Yes, its a cut'n' paste "miss the last byte"

Good.

Ok, before digging further, is this a new bug or does it happen on older
QEMU?  Have you got a rune to reproduce it on x86?

> 
> > 
> >> On the target a see lots of
> >>
> >> 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
> >> 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
> >> 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
> >> 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
> >> 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
> >> 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
> >>
> >> So we have about 2 seconds of traffic going on after that request,
> >> I assume its precopy related.
> >>
> >> Looking back on the target history there was
> >> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
> >> HVA=3ff618d9000 rb=s390.ram offset=41d9000
> >>
> >> In fact it seems to be the first and only request:
> >>
> >> # cat /tmp/test0.trace | grep -v postcopy_place_page
> >>
> >> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
> >> HVA=3ff618d9000 rb=s390.ram offset=41d9000
> > 
> > OK, does the HVA there correspond to the address that your virtio device is 
> > blocking on?
> 
> yes it is the same page.
> 
> 
> > (or at least the start of the page)
> > Do you see a postcopy_place_page with a host= the same HVA ?
> 
> no

Hmm, that's bad.
The flow is:
Precopy
   (a) Send pages
Switch to postcopy
   (b) Send discards for pages that have been changed after
   (a)
Postcopy
   (c) Keep sending pages until we run out
   (d) But send pages we're asked for first

 (d) might be ignored if the source thinks the page was already sent or not 
dirty.

So we need to figure out:
  1) If the source sent the pages during (a)
  2) If the source discarded it during (b)
  3) If it sent it again any time in c/d
  4) If it ignored the request from d


So please turn on the traces:
get_queued_page_not_dirtyshould help with (4)
get_queued_page  should help with (4)
ram_discard_rangeshould help with (2)
loadvm_postcopy_ram_handle_discard   should help with (2)
qemu_savevm_send_postcopy_ram_discardshould help with (2)

add near the top of ram_save_page in ram.c:
  fprintf(stderr, "%s: %s:%zx\n", __func__, block->idstr, (size_t)offset);

   should help with 1, 3

So lets see if your page ever gets sent in ram_save_page, and does it get
discarded prior to it hitting the point where it hangs but after the page
arrived?
Another (slimmer) possibility is the number of dirties paged is wrong
so the source thinks it has finished too soon - but we'll only look at
that if all the above doesn't help.

Dave

> > 
> 

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/24/2017 04:35 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
>>> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
 David, Juan,

 I can trigger a hang of postcopy migration (when I do it early) so
 that both sides are in paused state. Looks like one thread is still
 loading vmstates for virtio and this load accesses guest memory and
 triggers a userfault.
>>>
>>> It's perfectly legal for the destination to cause a userfault as it
>>> loads the virtio queue - the virtio queue should be being loaded by
>>> the main thread from the buffer while the 'listening' thread is
>>> waiting for the incoming page data.
>>>
>>> Can you turn on the following tracing please: destination: 
>>> postcopy_ram_fault_thread_request postcopy_place_page 
>>> postcopy_place_page_zero
>>>
>>> source: migrate_handle_rp_req_pages ram_save_queue_pages
>>>
>>> You should see: virtio does the access userfault generates a fault 
>>> postcopy_ram_fault_thread_request sends the request to the source
>>>
>>> the source sees migrate_handle_rp_req_pages queues it with
>>> ram_save_queue_pages
>>>
>>> the destination sees the page arrive and postcopy_place_page or
>>> postcopy_place_page_zero
>>>
>>> some of that might disappear if the page was already on it's way.
>>
>>
>> the last event on the source are
>> [..]
>> 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
>> 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
> 
> How do you see those on the source???

It was the previous migrate (I did it in a loop forth and back)
The problem happens on the migrate back.
> 
>> 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 
>> len 1000
>> 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 
>> 100
>>
> 
> Is that a typo? I'm expecting those two 'len' fields to be the same?

Yes, its a cut'n' paste "miss the last byte"


> 
>> On the target a see lots of
>>
>> 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
>> 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
>> 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
>> 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
>> 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
>> 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
>>
>> So we have about 2 seconds of traffic going on after that request,
>> I assume its precopy related.
>>
>> Looking back on the target history there was
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
>>
>> In fact it seems to be the first and only request:
>>
>> # cat /tmp/test0.trace | grep -v postcopy_place_page
>>
>> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
>> HVA=3ff618d9000 rb=s390.ram offset=41d9000
> 
> OK, does the HVA there correspond to the address that your virtio device is 
> blocking on?

yes it is the same page.


> (or at least the start of the page)
> Do you see a postcopy_place_page with a host= the same HVA ?

no

> 
> From the source backtrace, I think the source thinks it's sent everything
> and is waiting for the return-path-thread to close.
> 
> Dave
> 
>>>
>>> Dave
>>>
 Thread 1 (Thread 0x3ffa2f45f00 (LWP 21122)): #0  0x01017130
 in lduw_he_p (ptr=0x3ff498d9002) at
 /root/qemu/include/qemu/bswap.h:317 < according to the host
 kernel this threads hangs in handle_userfault. #1
 0x01017342 in lduw_le_p (ptr=0x3ff498d9002) at
 /root/qemu/include/qemu/bswap.h:359 #2  0x01025840 in
 address_space_lduw_internal_cached (cache=0x283491d0, addr=2,
 attrs=..., result=0x0, endian=DEVICE_LITTLE_ENDIAN) at
 /root/qemu/memory_ldst.inc.c:284 #3  0x010259a6 in
 address_space_lduw_le_cached (cache=0x283491d0, addr=2, attrs=...,
 result=0x0) at /root/qemu/memory_ldst.inc.c:315 #4
 0x01025ad6 in lduw_le_phys_cached (cache=0x283491d0,
 addr=2) at /root/qemu/memory_ldst.inc.c:334 #5  0x01116c10
 in virtio_lduw_phys_cached (vdev=0x28275090, cache=0x283491d0,
 pa=2) at /root/qemu/include/hw/virtio/virtio-access.h:166 #6
 0x01117940 in vring_used_idx (vq=0x3ffa2e1c090) at
 /root/qemu/hw/virtio/virtio.c:263 #7  0x0111daea in
 virtio_load (vdev=0x28275090, f=0x28353600, version_id=2) at
 /root/qemu/hw/virtio/virtio.c:2168 #8  0x0111d0cc in
 virtio_device_get (f=0x28353600, opaque=0x28275090, size=0,
 field=0x16adf38 <__compound_literal.0>) at
 /root/qemu/hw/virtio/virtio.c:1975 #9  0x012a7f50 in
 vmstate_load_state (f=0x28353600, vmsd=0x14db480
 , opaque=0x28275090, version_id=2) at
 /root/qemu/migration/vmstate.c:128 #10 0x010cbc08 in
 vmstate_load (f=0x28353600, se=0x28279e60, version_id=2) 

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> > * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> >> David, Juan,
> >> 
> >> I can trigger a hang of postcopy migration (when I do it early) so
> >> that both sides are in paused state. Looks like one thread is still
> >> loading vmstates for virtio and this load accesses guest memory and
> >> triggers a userfault.
> > 
> > It's perfectly legal for the destination to cause a userfault as it
> > loads the virtio queue - the virtio queue should be being loaded by
> > the main thread from the buffer while the 'listening' thread is
> > waiting for the incoming page data.
> > 
> > Can you turn on the following tracing please: destination: 
> > postcopy_ram_fault_thread_request postcopy_place_page 
> > postcopy_place_page_zero
> > 
> > source: migrate_handle_rp_req_pages ram_save_queue_pages
> > 
> > You should see: virtio does the access userfault generates a fault 
> > postcopy_ram_fault_thread_request sends the request to the source
> > 
> > the source sees migrate_handle_rp_req_pages queues it with
> > ram_save_queue_pages
> > 
> > the destination sees the page arrive and postcopy_place_page or
> > postcopy_place_page_zero
> > 
> > some of that might disappear if the page was already on it's way.
> 
> 
> the last event on the source are
> [..]
> 58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
> 58412@1493037953.747992:postcopy_place_page host=0x3ff92247000

How do you see those on the source???

> 58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 
> len 1000
> 58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 100
> 

Is that a typo? I'm expecting those two 'len' fields to be the same?

> On the target a see lots of
> 
> 39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
> 39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
> 39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
> 39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
> 39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
> 39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000
> 
> So we have about 2 seconds of traffic going on after that request,
> I assume its precopy related.
> 
> Looking back on the target history there was
> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
> HVA=3ff618d9000 rb=s390.ram offset=41d9000
> 
> In fact it seems to be the first and only request:
> 
> # cat /tmp/test0.trace | grep -v postcopy_place_page
> 
> 39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
> HVA=3ff618d9000 rb=s390.ram offset=41d9000

OK, does the HVA there correspond to the address that your virtio device is 
blocking on?
(or at least the start of the page)
Do you see a postcopy_place_page with a host= the same HVA ?

From the source backtrace, I think the source thinks it's sent everything
and is waiting for the return-path-thread to close.

Dave

> > 
> > Dave
> > 
> >> Thread 1 (Thread 0x3ffa2f45f00 (LWP 21122)): #0  0x01017130
> >> in lduw_he_p (ptr=0x3ff498d9002) at
> >> /root/qemu/include/qemu/bswap.h:317 < according to the host
> >> kernel this threads hangs in handle_userfault. #1
> >> 0x01017342 in lduw_le_p (ptr=0x3ff498d9002) at
> >> /root/qemu/include/qemu/bswap.h:359 #2  0x01025840 in
> >> address_space_lduw_internal_cached (cache=0x283491d0, addr=2,
> >> attrs=..., result=0x0, endian=DEVICE_LITTLE_ENDIAN) at
> >> /root/qemu/memory_ldst.inc.c:284 #3  0x010259a6 in
> >> address_space_lduw_le_cached (cache=0x283491d0, addr=2, attrs=...,
> >> result=0x0) at /root/qemu/memory_ldst.inc.c:315 #4
> >> 0x01025ad6 in lduw_le_phys_cached (cache=0x283491d0,
> >> addr=2) at /root/qemu/memory_ldst.inc.c:334 #5  0x01116c10
> >> in virtio_lduw_phys_cached (vdev=0x28275090, cache=0x283491d0,
> >> pa=2) at /root/qemu/include/hw/virtio/virtio-access.h:166 #6
> >> 0x01117940 in vring_used_idx (vq=0x3ffa2e1c090) at
> >> /root/qemu/hw/virtio/virtio.c:263 #7  0x0111daea in
> >> virtio_load (vdev=0x28275090, f=0x28353600, version_id=2) at
> >> /root/qemu/hw/virtio/virtio.c:2168 #8  0x0111d0cc in
> >> virtio_device_get (f=0x28353600, opaque=0x28275090, size=0,
> >> field=0x16adf38 <__compound_literal.0>) at
> >> /root/qemu/hw/virtio/virtio.c:1975 #9  0x012a7f50 in
> >> vmstate_load_state (f=0x28353600, vmsd=0x14db480
> >> , opaque=0x28275090, version_id=2) at
> >> /root/qemu/migration/vmstate.c:128 #10 0x010cbc08 in
> >> vmstate_load (f=0x28353600, se=0x28279e60, version_id=2) at
> >> /root/qemu/migration/savevm.c:732 #11 0x010ced6e in
> >> qemu_loadvm_section_start_full (f=0x28353600, mis=0x17169a8
> >> ) at /root/qemu/migration/savevm.c:1890 #12
> >> 0x010cf00c in qemu_loadvm_state_main (f=0x28353600,
> >> mis=0x17169a8 ) at 

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:

FWIW, the sending side calltrace looks like:

> 
Thread 8 (Thread 0x3ff509aa910 (LWP 58594)):
#0  0x03ff9d588ca4 in pthread_join () from target:/lib64/libpthread.so.0
#1  0x01493d4a in qemu_thread_join (thread=0x16c7e78 
) at /root/qemu/util/qemu-thread-posix.c:504
#2  0x012a0d0e in await_return_path_close_on_source (ms=0x16c7da0 
) at /root/qemu/migration/migration.c:1641
#3  0x012a1312 in migration_completion (s=0x16c7da0 
, current_active_state=5, old_vm_running=0x3ff509a7789, 
start_time=0x3ff509a7790)
at /root/qemu/migration/migration.c:1860
#4  0x012a17b2 in migration_thread (opaque=0x16c7da0 
) at /root/qemu/migration/migration.c:1987
#5  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#6  0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 7 (Thread 0x3ff4bfff910 (LWP 58593)):
#0  0x03ff9d5915b6 in recvmsg () from target:/lib64/libpthread.so.0
#1  0x0141771a in qio_channel_socket_readv (ioc=0xc9986b0, 
iov=0x3ff4bffc170, niov=1, fds=0x0, nfds=0x0, errp=0x0) at 
/root/qemu/io/channel-socket.c:476
#2  0x01411668 in qio_channel_readv_full (ioc=0xc9986b0, 
iov=0x3ff4bffc170, niov=1, fds=0x0, nfds=0x0, errp=0x0) at 
/root/qemu/io/channel.c:64
#3  0x0141190a in qio_channel_read (ioc=0xc9986b0, buf=0xca23888 "", 
buflen=32768, errp=0x0) at /root/qemu/io/channel.c:112
#4  0x012ad384 in channel_get_buffer (opaque=0xc9986b0, buf=0xca23888 
"", pos=49, size=32768) at /root/qemu/migration/qemu-file-channel.c:78
#5  0x012abb64 in qemu_fill_buffer (f=0xca23850) at 
/root/qemu/migration/qemu-file.c:295
#6  0x012ac7b2 in qemu_peek_byte (f=0xca23850, offset=0) at 
/root/qemu/migration/qemu-file.c:555
#7  0x012ac82e in qemu_get_byte (f=0xca23850) at 
/root/qemu/migration/qemu-file.c:568
#8  0x012acbfa in qemu_get_be16 (f=0xca23850) at 
/root/qemu/migration/qemu-file.c:640
#9  0x012a0756 in source_return_path_thread (opaque=0x16c7da0 
) at /root/qemu/migration/migration.c:1512
#10 0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#11 0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 6 (Thread 0x3ff511aa910 (LWP 58454)):
#0  0x03ff9d58d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
target:/lib64/libpthread.so.0
#1  0x01492fce in qemu_cond_wait (cond=0xc9ca238, mutex=0xc9ca210) at 
/root/qemu/util/qemu-thread-posix.c:133
#2  0x010c6080 in do_data_decompress (opaque=0xc9ca208) at 
/root/qemu/migration/ram.c:2277
#3  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#4  0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 5 (Thread 0x3ff519aa910 (LWP 58453)):
#0  0x03ff9d58d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
target:/lib64/libpthread.so.0
#1  0x01492fce in qemu_cond_wait (cond=0xc9ca1c0, mutex=0xc9ca198) at 
/root/qemu/util/qemu-thread-posix.c:133
#2  0x010c6080 in do_data_decompress (opaque=0xc9ca190) at 
/root/qemu/migration/ram.c:2277
#3  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#4  0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 4 (Thread 0x3ff98807910 (LWP 58440)):
#0  0x03ff9d58d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
target:/lib64/libpthread.so.0
#1  0x01492fce in qemu_cond_wait (cond=0xc9e6930, mutex=0x17116b0 
) at /root/qemu/util/qemu-thread-posix.c:133
#2  0x0107720e in qemu_kvm_wait_io_event (cpu=0xc9a87d0) at 
/root/qemu/cpus.c:1085
#3  0x010773aa in qemu_kvm_cpu_thread_fn (arg=0xc9a87d0) at 
/root/qemu/cpus.c:1123
#4  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#5  0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 3 (Thread 0x3ff99d7f910 (LWP 58437)):
#0  0x03ff9d47d832 in ppoll () from target:/lib64/libc.so.6
#1  0x0148b2fa in qemu_poll_ns (fds=0x3ff940008c0, nfds=1, timeout=-1) 
at /root/qemu/util/qemu-timer.c:322
#2  0x0148f6d2 in aio_poll (ctx=0xc9473c0, blocking=true) at 
/root/qemu/util/aio-posix.c:622
#3  0x011a7b5e in iothread_run (opaque=0xc947230) at 
/root/qemu/iothread.c:59
#4  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#5  0x03ff9d48a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 2 (Thread 0x3ff9a57f910 (LWP 58434)):
#0  0x03ff9d484336 in syscall () from target:/lib64/libc.so.6
---Type  to continue, or q  to quit---
#1  0x01493636 in qemu_futex_wait (f=0x1b2b9dc , 
val=4294967295) at /root/qemu/include/qemu/futex.h:26
#2  0x01493838 in qemu_event_wait (ev=0x1b2b9dc ) 
at /root/qemu/util/qemu-thread-posix.c:399
#3  0x014b40a8 in call_rcu_thread (opaque=0x0) at 
/root/qemu/util/rcu.c:249
#4  0x03ff9d587bc4 in start_thread () from target:/lib64/libpthread.so.0
#5  

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

On 04/24/2017 12:53 PM, Dr. David Alan Gilbert wrote:
> * Christian Borntraeger (borntrae...@de.ibm.com) wrote:
>> David, Juan,
>> 
>> I can trigger a hang of postcopy migration (when I do it early) so
>> that both sides are in paused state. Looks like one thread is still
>> loading vmstates for virtio and this load accesses guest memory and
>> triggers a userfault.
> 
> It's perfectly legal for the destination to cause a userfault as it
> loads the virtio queue - the virtio queue should be being loaded by
> the main thread from the buffer while the 'listening' thread is
> waiting for the incoming page data.
> 
> Can you turn on the following tracing please: destination: 
> postcopy_ram_fault_thread_request postcopy_place_page 
> postcopy_place_page_zero
> 
> source: migrate_handle_rp_req_pages ram_save_queue_pages
> 
> You should see: virtio does the access userfault generates a fault 
> postcopy_ram_fault_thread_request sends the request to the source
> 
> the source sees migrate_handle_rp_req_pages queues it with
> ram_save_queue_pages
> 
> the destination sees the page arrive and postcopy_place_page or
> postcopy_place_page_zero
> 
> some of that might disappear if the page was already on it's way.


the last event on the source are
[..]
58412@1493037953.747988:postcopy_place_page host=0x3ff92246000
58412@1493037953.747992:postcopy_place_page host=0x3ff92247000
58412@1493037956.804210:migrate_handle_rp_req_pages in s390.ram at 41d9000 len 
1000
58412@1493037956.804216:ram_save_queue_pages s390.ram: start: 41d9000 len: 100


On the target a see lots of

39741@1493037958.833710:postcopy_place_page_zero host=0x3ff9befa000
39741@1493037958.833716:postcopy_place_page host=0x3ff9befb000
39741@1493037958.833759:postcopy_place_page host=0x3ff9befc000
39741@1493037958.833818:postcopy_place_page host=0x3ff9befd000
39741@1493037958.833819:postcopy_place_page_zero host=0x3ff9befe000
39741@1493037958.833822:postcopy_place_page host=0x3ff9beff000

So we have about 2 seconds of traffic going on after that request,
I assume its precopy related.

Looking back on the target history there was
39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
HVA=3ff618d9000 rb=s390.ram offset=41d9000

In fact it seems to be the first and only request:

# cat /tmp/test0.trace | grep -v postcopy_place_page

39741@1493037956.804337:postcopy_ram_fault_thread_request Request for 
HVA=3ff618d9000 rb=s390.ram offset=41d9000

> 
> Dave
> 
>> Thread 1 (Thread 0x3ffa2f45f00 (LWP 21122)): #0  0x01017130
>> in lduw_he_p (ptr=0x3ff498d9002) at
>> /root/qemu/include/qemu/bswap.h:317 < according to the host
>> kernel this threads hangs in handle_userfault. #1
>> 0x01017342 in lduw_le_p (ptr=0x3ff498d9002) at
>> /root/qemu/include/qemu/bswap.h:359 #2  0x01025840 in
>> address_space_lduw_internal_cached (cache=0x283491d0, addr=2,
>> attrs=..., result=0x0, endian=DEVICE_LITTLE_ENDIAN) at
>> /root/qemu/memory_ldst.inc.c:284 #3  0x010259a6 in
>> address_space_lduw_le_cached (cache=0x283491d0, addr=2, attrs=...,
>> result=0x0) at /root/qemu/memory_ldst.inc.c:315 #4
>> 0x01025ad6 in lduw_le_phys_cached (cache=0x283491d0,
>> addr=2) at /root/qemu/memory_ldst.inc.c:334 #5  0x01116c10
>> in virtio_lduw_phys_cached (vdev=0x28275090, cache=0x283491d0,
>> pa=2) at /root/qemu/include/hw/virtio/virtio-access.h:166 #6
>> 0x01117940 in vring_used_idx (vq=0x3ffa2e1c090) at
>> /root/qemu/hw/virtio/virtio.c:263 #7  0x0111daea in
>> virtio_load (vdev=0x28275090, f=0x28353600, version_id=2) at
>> /root/qemu/hw/virtio/virtio.c:2168 #8  0x0111d0cc in
>> virtio_device_get (f=0x28353600, opaque=0x28275090, size=0,
>> field=0x16adf38 <__compound_literal.0>) at
>> /root/qemu/hw/virtio/virtio.c:1975 #9  0x012a7f50 in
>> vmstate_load_state (f=0x28353600, vmsd=0x14db480
>> , opaque=0x28275090, version_id=2) at
>> /root/qemu/migration/vmstate.c:128 #10 0x010cbc08 in
>> vmstate_load (f=0x28353600, se=0x28279e60, version_id=2) at
>> /root/qemu/migration/savevm.c:732 #11 0x010ced6e in
>> qemu_loadvm_section_start_full (f=0x28353600, mis=0x17169a8
>> ) at /root/qemu/migration/savevm.c:1890 #12
>> 0x010cf00c in qemu_loadvm_state_main (f=0x28353600,
>> mis=0x17169a8 ) at /root/qemu/migration/savevm.c:1947 
>> #13 0x010ce5bc in loadvm_handle_cmd_packaged (mis=0x17169a8
>> ) at /root/qemu/migration/savevm.c:1707 #14
>> 0x010ce87e in loadvm_process_command (f=0x282c7d20) at
>> /root/qemu/migration/savevm.c:1770 #15 0x010cf056 in
>> qemu_loadvm_state_main (f=0x282c7d20, mis=0x17169a8 )
>> at /root/qemu/migration/savevm.c:1960 #16 0x010cf2b6 in
>> qemu_loadvm_state (f=0x282c7d20) at
>> /root/qemu/migration/savevm.c:2020 #17 0x0129d234 in
>> process_incoming_migration_co (opaque=0x282c7d20) at
>> /root/qemu/migration/migration.c:404 #18 0x014b6ca2 in
>> coroutine_trampoline (i0=0, i1=674533168) at
>> 

Re: [Qemu-devel] postcopy migration hangs while loading virtio state

[Dr. David Alan Gilbert]

* Christian Borntraeger (borntrae...@de.ibm.com) wrote:
> David, Juan,
> 
> I can trigger a hang of postcopy migration (when I do it early) so that
> both sides are in paused state. Looks like one thread is still loading
> vmstates for virtio and this load accesses guest memory and triggers
> a userfault. 

It's perfectly legal for the destination to cause a userfault as it loads the
virtio queue - the virtio queue should be being loaded by the main thread
from the buffer while the 'listening' thread is waiting for the incoming
page data.

Can you turn on the following tracing please:
  destination:
postcopy_ram_fault_thread_request
postcopy_place_page
postcopy_place_page_zero

  source:
migrate_handle_rp_req_pages
ram_save_queue_pages

You should see:
virtio does the access
userfault generates a fault
postcopy_ram_fault_thread_request sends the request to the source

the source sees migrate_handle_rp_req_pages
queues it with ram_save_queue_pages

the destination sees the page arrive and
postcopy_place_page or postcopy_place_page_zero

some of that might disappear if the page was already on it's way.

Dave

> Thread 1 (Thread 0x3ffa2f45f00 (LWP 21122)):
> #0  0x01017130 in lduw_he_p (ptr=0x3ff498d9002) at 
> /root/qemu/include/qemu/bswap.h:317
>   < according to the host kernel this threads hangs in 
> handle_userfault.
> #1  0x01017342 in lduw_le_p (ptr=0x3ff498d9002) at 
> /root/qemu/include/qemu/bswap.h:359
> #2  0x01025840 in address_space_lduw_internal_cached 
> (cache=0x283491d0, addr=2, attrs=..., result=0x0, 
> endian=DEVICE_LITTLE_ENDIAN) at /root/qemu/memory_ldst.inc.c:284
> #3  0x010259a6 in address_space_lduw_le_cached (cache=0x283491d0, 
> addr=2, attrs=..., result=0x0) at /root/qemu/memory_ldst.inc.c:315
> #4  0x01025ad6 in lduw_le_phys_cached (cache=0x283491d0, addr=2) at 
> /root/qemu/memory_ldst.inc.c:334
> #5  0x01116c10 in virtio_lduw_phys_cached (vdev=0x28275090, 
> cache=0x283491d0, pa=2) at /root/qemu/include/hw/virtio/virtio-access.h:166
> #6  0x01117940 in vring_used_idx (vq=0x3ffa2e1c090) at 
> /root/qemu/hw/virtio/virtio.c:263
> #7  0x0111daea in virtio_load (vdev=0x28275090, f=0x28353600, 
> version_id=2) at /root/qemu/hw/virtio/virtio.c:2168
> #8  0x0111d0cc in virtio_device_get (f=0x28353600, opaque=0x28275090, 
> size=0, field=0x16adf38 <__compound_literal.0>) at 
> /root/qemu/hw/virtio/virtio.c:1975
> #9  0x012a7f50 in vmstate_load_state (f=0x28353600, vmsd=0x14db480 
> , opaque=0x28275090, version_id=2) at 
> /root/qemu/migration/vmstate.c:128
> #10 0x010cbc08 in vmstate_load (f=0x28353600, se=0x28279e60, 
> version_id=2) at /root/qemu/migration/savevm.c:732
> #11 0x010ced6e in qemu_loadvm_section_start_full (f=0x28353600, 
> mis=0x17169a8 ) at /root/qemu/migration/savevm.c:1890
> #12 0x010cf00c in qemu_loadvm_state_main (f=0x28353600, mis=0x17169a8 
> ) at /root/qemu/migration/savevm.c:1947
> #13 0x010ce5bc in loadvm_handle_cmd_packaged (mis=0x17169a8 
> ) at /root/qemu/migration/savevm.c:1707
> #14 0x010ce87e in loadvm_process_command (f=0x282c7d20) at 
> /root/qemu/migration/savevm.c:1770
> #15 0x010cf056 in qemu_loadvm_state_main (f=0x282c7d20, mis=0x17169a8 
> ) at /root/qemu/migration/savevm.c:1960
> #16 0x010cf2b6 in qemu_loadvm_state (f=0x282c7d20) at 
> /root/qemu/migration/savevm.c:2020
> #17 0x0129d234 in process_incoming_migration_co (opaque=0x282c7d20) 
> at /root/qemu/migration/migration.c:404
> #18 0x014b6ca2 in coroutine_trampoline (i0=0, i1=674533168) at 
> /root/qemu/util/coroutine-ucontext.c:79
> #19 0x03ff8de530ea in __makecontext_ret () from target:/lib64/libc.so.6
> 
> Thread 8 (Thread 0x3ff40b38910 (LWP 21165)):
> #0  0x03ff8df04336 in syscall () from target:/lib64/libc.so.6
> #1  0x014933ce in qemu_futex_wait (f=0x17169b0 , 
> val=4294967295) at /root/qemu/include/qemu/futex.h:26
> #2  0x014935d0 in qemu_event_wait (ev=0x17169b0 ) at 
> /root/qemu/util/qemu-thread-posix.c:399
> #3  0x010ce094 in postcopy_ram_listen_thread (opaque=0x282c7d20) at 
> /root/qemu/migration/savevm.c:1532
> #4  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
> #5  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6
> 
> Thread 7 (Thread 0x3ff41338910 (LWP 21164)):
> #0  0x03ff8defd72c in ?? () from target:/lib64/libc.so.6
> #1  0x012af920 in postcopy_ram_fault_thread (opaque=0x17169a8 
> ) at /root/qemu/migration/postcopy-ram.c:437
> #2  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
> #3  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6
> 
> Thread 6 (Thread 0x3ff41b38910 (LWP 21163)):
> #0  0x03ff8e00d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
> target:/lib64/libpthread.so.0
> #1  

[Qemu-devel] postcopy migration hangs while loading virtio state

[Christian Borntraeger]

David, Juan,

I can trigger a hang of postcopy migration (when I do it early) so that
both sides are in paused state. Looks like one thread is still loading
vmstates for virtio and this load accesses guest memory and triggers
a userfault. 

Thread 1 (Thread 0x3ffa2f45f00 (LWP 21122)):
#0  0x01017130 in lduw_he_p (ptr=0x3ff498d9002) at 
/root/qemu/include/qemu/bswap.h:317
< according to the host kernel this threads hangs in 
handle_userfault.
#1  0x01017342 in lduw_le_p (ptr=0x3ff498d9002) at 
/root/qemu/include/qemu/bswap.h:359
#2  0x01025840 in address_space_lduw_internal_cached (cache=0x283491d0, 
addr=2, attrs=..., result=0x0, endian=DEVICE_LITTLE_ENDIAN) at 
/root/qemu/memory_ldst.inc.c:284
#3  0x010259a6 in address_space_lduw_le_cached (cache=0x283491d0, 
addr=2, attrs=..., result=0x0) at /root/qemu/memory_ldst.inc.c:315
#4  0x01025ad6 in lduw_le_phys_cached (cache=0x283491d0, addr=2) at 
/root/qemu/memory_ldst.inc.c:334
#5  0x01116c10 in virtio_lduw_phys_cached (vdev=0x28275090, 
cache=0x283491d0, pa=2) at /root/qemu/include/hw/virtio/virtio-access.h:166
#6  0x01117940 in vring_used_idx (vq=0x3ffa2e1c090) at 
/root/qemu/hw/virtio/virtio.c:263
#7  0x0111daea in virtio_load (vdev=0x28275090, f=0x28353600, 
version_id=2) at /root/qemu/hw/virtio/virtio.c:2168
#8  0x0111d0cc in virtio_device_get (f=0x28353600, opaque=0x28275090, 
size=0, field=0x16adf38 <__compound_literal.0>) at 
/root/qemu/hw/virtio/virtio.c:1975
#9  0x012a7f50 in vmstate_load_state (f=0x28353600, vmsd=0x14db480 
, opaque=0x28275090, version_id=2) at 
/root/qemu/migration/vmstate.c:128
#10 0x010cbc08 in vmstate_load (f=0x28353600, se=0x28279e60, 
version_id=2) at /root/qemu/migration/savevm.c:732
#11 0x010ced6e in qemu_loadvm_section_start_full (f=0x28353600, 
mis=0x17169a8 ) at /root/qemu/migration/savevm.c:1890
#12 0x010cf00c in qemu_loadvm_state_main (f=0x28353600, mis=0x17169a8 
) at /root/qemu/migration/savevm.c:1947
#13 0x010ce5bc in loadvm_handle_cmd_packaged (mis=0x17169a8 
) at /root/qemu/migration/savevm.c:1707
#14 0x010ce87e in loadvm_process_command (f=0x282c7d20) at 
/root/qemu/migration/savevm.c:1770
#15 0x010cf056 in qemu_loadvm_state_main (f=0x282c7d20, mis=0x17169a8 
) at /root/qemu/migration/savevm.c:1960
#16 0x010cf2b6 in qemu_loadvm_state (f=0x282c7d20) at 
/root/qemu/migration/savevm.c:2020
#17 0x0129d234 in process_incoming_migration_co (opaque=0x282c7d20) at 
/root/qemu/migration/migration.c:404
#18 0x014b6ca2 in coroutine_trampoline (i0=0, i1=674533168) at 
/root/qemu/util/coroutine-ucontext.c:79
#19 0x03ff8de530ea in __makecontext_ret () from target:/lib64/libc.so.6

Thread 8 (Thread 0x3ff40b38910 (LWP 21165)):
#0  0x03ff8df04336 in syscall () from target:/lib64/libc.so.6
#1  0x014933ce in qemu_futex_wait (f=0x17169b0 , 
val=4294967295) at /root/qemu/include/qemu/futex.h:26
#2  0x014935d0 in qemu_event_wait (ev=0x17169b0 ) at 
/root/qemu/util/qemu-thread-posix.c:399
#3  0x010ce094 in postcopy_ram_listen_thread (opaque=0x282c7d20) at 
/root/qemu/migration/savevm.c:1532
#4  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
#5  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 7 (Thread 0x3ff41338910 (LWP 21164)):
#0  0x03ff8defd72c in ?? () from target:/lib64/libc.so.6
#1  0x012af920 in postcopy_ram_fault_thread (opaque=0x17169a8 
) at /root/qemu/migration/postcopy-ram.c:437
#2  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
#3  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 6 (Thread 0x3ff41b38910 (LWP 21163)):
#0  0x03ff8e00d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
target:/lib64/libpthread.so.0
#1  0x01492d66 in qemu_cond_wait (cond=0x28302408, mutex=0x283023e0) at 
/root/qemu/util/qemu-thread-posix.c:133
#2  0x010c6080 in do_data_decompress (opaque=0x283023d8) at 
/root/qemu/migration/ram.c:2277
#3  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
#4  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 5 (Thread 0x3ff42338910 (LWP 21162)):
#0  0x03ff8e00d450 in pthread_cond_wait@@GLIBC_2.3.2 () from 
target:/lib64/libpthread.so.0
#1  0x01492d66 in qemu_cond_wait (cond=0x28302390, mutex=0x28302368) at 
/root/qemu/util/qemu-thread-posix.c:133
#2  0x010c6080 in do_data_decompress (opaque=0x28302360) at 
/root/qemu/migration/ram.c:2277
#3  0x03ff8e007bc4 in start_thread () from target:/lib64/libpthread.so.0
#4  0x03ff8df0a9f2 in thread_start () from target:/lib64/libc.so.6

Thread 4 (Thread 0x3ff89287910 (LWP 21148)):
#0  0x03ff8e010abc in __lll_lock_wait () from target:/lib64/libpthread.so.0
#1  0x03ff8e00bcb6 in __pthread_mutex_cond_lock () from