Re: performance with guests running 2.4 kernels (specifically RHEL3)

["David S. Ahern" <daahern@cisco.com>]

I added tracers to kvm_mmu_page_fault() that include collecting tsc cycles:

1. before vcpu->arch.mmu.page_fault()
2. after vcpu->arch.mmu.page_fault()
3. after mmu_topup_memory_caches()
4. after emulate_instruction()

So the delta in the trace reports show:
- cycles required for arch.mmu.page_fault (tracer 2)
- cycles required for mmu_topup_memory_caches(tracer 3)
- cycles required for emulate_instruction() (tracer 4)

I captured trace data for ~5-seconds during one of the usual events (again this
time it was due to kscand in the guest). I ran the formatted trace data through
an awk script to summarize:

    TSC cycles      tracer2   tracer3   tracer4
      0 -  10,000:   295067    213251    115873
 10,001 -  25,000:     7682      1004     98336
 25,001 -  50,000:      201        15        36
 50,001 - 100,000:   100655         0        10
        > 100,000:      117         0        15

This means vcpu->arch.mmu.page_fault() was called 403,722 times in the roughyl
5-second interval: 295,067 times it took < 10,000 cycles, but 100,772 times it
took longer than 50,000 cycles. The page_fault function getting run is
paging64_page_fault.

mmu_topup_memory_caches() and emulate_instruction() were both run 214,270 times,
most of them relatively quickly.

Note: I bumped the scheduling priority of the qemu threads to RR 1 so that few
host processes could interrupt it.

david


Avi Kivity wrote:
> David S. Ahern wrote:
>> I added the traces and captured data over another apparent lockup of
>> the guest.
>> This seems to be representative of the sequence (pid/vcpu removed).
>>
>> (+4776)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c016127c ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db4 ]
>> (+3632)  VMENTRY
>> (+4552)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c016104a ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x0000000b, virt = 0x00000000
>> fffb61c8 ]
>> (+   54928)  VMENTRY
>>   
> 
> Can you oprofile the host to see where the 54K cycles are spent?
> 
>> (+4568)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c01610e7 ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db4 ]
>> (+   0)  PTE_WRITE      [ gpa = 0x00000000 00009db4 gpte = 0x00000000
>> 41c5d363 ]
>> (+8432)  VMENTRY
>> (+3936)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c01610ee ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db0 ]
>> (+   0)  PTE_WRITE      [ gpa = 0x00000000 00009db0 gpte = 0x00000000
>> 00000000 ]
>> (+   13832)  VMENTRY
>>
>>
>> (+5768)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c016127c ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db4 ]
>> (+3712)  VMENTRY
>> (+4576)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c016104a ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x0000000b, virt = 0x00000000
>> fffb61d0 ]
>> (+   0)  PTE_WRITE      [ gpa = 0x00000000 3d5981d0 gpte = 0x00000000
>> 3d55d047 ]
>>   
> 
> This indeed has the accessed bit clear.
> 
>> (+   65216)  VMENTRY
>> (+4232)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c01610e7 ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db4 ]
>> (+   0)  PTE_WRITE      [ gpa = 0x00000000 00009db4 gpte = 0x00000000
>> 3d598363 ]
>>   
> 
> This has the accessed bit set and the user bit clear, and the pte
> pointing at the previous pte_write gpa.  Looks like a kmap_atomic().
> 
>> (+8640)  VMENTRY
>> (+3936)  VMEXIT         [ exitcode = 0x00000000, rip = 0x00000000
>> c01610ee ]
>> (+   0)  PAGE_FAULT     [ errorcode = 0x00000003, virt = 0x00000000
>> c0009db0 ]
>> (+   0)  PTE_WRITE      [ gpa = 0x00000000 00009db0 gpte = 0x00000000
>> 00000000 ]
>> (+   14160)  VMENTRY
>>
>> I can forward a more complete time snippet if you'd like. vcpu0 +
>> corresponding
>> vcpu1 files have 85000 total lines and compressed the files total ~500k.
>>
>> I did not see the FLOODED trace come out during this sample though I
>> did bump
>> the count from 3 to 4 as you suggested.
>>
>>
>>   
> 
> Bumping the count was supposed to remove the flooding...
> 
>> Correlating rip addresses to the 2.4 kernel:
>>
>> c0160d00-c0161290 = page_referenced
>>
>> It looks like the event is kscand running through the pages. I
>> suspected this
>> some time ago, and tried tweaking the kscand_work_percent sysctl
>> variable. It
>> appeared to lower the peak of the spikes, but maybe I imagined it. I
>> believe
>> lowering that value makes kscand wake up more often but do less work
>> (page
>> scanning) each time it is awakened.
>>
>>   
> 
> What does 'top' in the guest show (perhaps sorted by total cpu time
> rather than instantaneous usage)?
> 
> What host kernel are you running?  How many host cpus?
> 

-------------------------------------------------------------------------
This SF.net email is sponsored by the 2008 JavaOne(SM) Conference 
Don't miss this year's exciting event. There's still time to save $100. 
Use priority code J8TL2D2. 
http://ad.doubleclick.net/clk;198757673;13503038;p?http://java.sun.com/javaone