Avi Kivity wrote:
> David S. Ahern wrote:
>>> I haven't been able to reproduce this:
>>>
>>>
>>>> [EMAIL PROTECTED] root]# ps -elf | grep -E 'memuser|kscand'
>>>> 1 S root 7 1 1 75 0 - 0 schedu 10:07 ?
>>>> 00:00:26 [kscand]
>>>> 0 S root 1464 1 1 75 0 - 196986 schedu 10:20 pts/0
>>>> 00:00:21 ./memuser 768M 120 5 300
>>>> 0 S root 1465 1 0 75 0 - 98683 schedu 10:20 pts/0
>>>> 00:00:10 ./memuser 384M 300 10 600
>>>> 0 S root 2148 1293 0 75 0 - 922 pipe_w 10:48 pts/0
>>>> 00:00:00 grep -E memuser|kscand
>>>>
>>> The workload has been running for about half an hour, and kswapd cpu
>>> usage doesn't seem significant. This is a 2GB guest running with my
>>> patch ported to kvm.git HEAD. Guest is has 2G of memory.
>>>
>>>
>>
>> I'm running on the per-page-pte-tracking branch, and I am still seeing
>> it.
>> I doubt you want to sit and watch the screen for an hour, so install
>> sysstat if not already, change the sample rate to 1 minute
>> (/etc/cron.d/sysstat), let the server run for a few hours and then run
>> 'sar -u'. You'll see something like this:
>>
>> 10:12:11 AM LINUX RESTART
>>
>> 10:13:03 AM CPU %user %nice %system %iowait %idle
>> 10:14:01 AM all 0.08 0.00 2.08 0.35 97.49
>> 10:15:03 AM all 0.05 0.00 0.79 0.04 99.12
>> 10:15:59 AM all 0.15 0.00 1.52 0.06 98.27
>> 10:17:01 AM all 0.04 0.00 0.69 0.04 99.23
>> 10:17:59 AM all 0.01 0.00 0.39 0.00 99.60
>> 10:18:59 AM all 0.00 0.00 0.12 0.02 99.87
>> 10:20:02 AM all 0.18 0.00 14.62 0.09 85.10
>> 10:21:01 AM all 0.71 0.00 26.35 0.01 72.94
>> 10:22:02 AM all 0.67 0.00 10.61 0.00 88.72
>> 10:22:59 AM all 0.14 0.00 1.80 0.00 98.06
>> 10:24:03 AM all 0.13 0.00 0.50 0.00 99.37
>> 10:24:59 AM all 0.09 0.00 11.46 0.00 88.45
>> 10:26:03 AM all 0.16 0.00 0.69 0.03 99.12
>> 10:26:59 AM all 0.14 0.00 10.01 0.02 89.83
>> 10:28:03 AM all 0.57 0.00 2.20 0.03 97.20
>> Average: all 0.21 0.00 5.55 0.05 94.20
>>
>>
>> every one of those jumps in %system time directly correlates to kscand
>> activity. Without the memuser programs running the guest %system time
>> is <1%. The point of this silly memuser program is just to use high
>> memory -- let it age, then make it active again, sit idle, repeat. If
>> you run kvm_stat with -l in the host you'll see the jump in pte
>> writes/updates. An intern here added a timestamp to the kvm_stat
>> output for me which helps to directly correlate guest/host data.
>>
>>
>> I also ran my real guest on the branch. Performance at boot through
>> the first 15 minutes was much better, but I'm still seeing recurring
>> hits every 5 minutes when kscand kicks in. Here's the data from the
>> guest for the first one which happened after 15 minutes of uptime:
>>
>> active_anon_scan: HighMem, age 11, count[age] 24886 -> 5796, direct
>> 24845, dj 59
>>
>> active_anon_scan: HighMem, age 7, count[age] 47772 -> 21289, direct
>> 40868, dj 103
>>
>> active_anon_scan: HighMem, age 3, count[age] 91007 -> 329, direct
>> 45805, dj 1212
>>
>>
>
> We touched 90,000 ptes in 12 seconds. That's 8,000 ptes per second.
> Yet we see 180,000 page faults per second in the trace.
>
> Oh! Only 45K pages were direct, so the other 45K were shared, with
> perhaps many ptes. We shoud count ptes, not pages.
>
> Can you modify page_referenced() to count the numbers of ptes mapped (1
> for direct pages, nr_chains for indirect pages) and print the total
> deltas in active_anon_scan?
>
Here you go. I've shortened the line lengths to get them to squeeze into
80 columns:
anon_scan, all HighMem zone, 187,910 active pages at loop start:
count[12] 21462 -> 230, direct 20469, chains 3479, dj 58
count[11] 1338 -> 1162, direct 227, chains 26144, dj 59
count[8] 29397 -> 5410, direct 26115, chains 27617, dj 117
count[4] 35804 -> 25556, direct 31508, chains 82929, dj 256
count[3] 2738 -> 2207, direct 2680, chains 58, dj 7
count[0] 92580 -> 89509, direct 75024, chains 262834, dj 726
(age number is the index in [])
cache_scan, all HighMem zone, 48,298 active pages at loop start:
count[12] 3642 -> 2982, direct 499, chains 20022, dj 44
count[8] 11254 -> 11187, direct 7189, chains 9854, dj 37
count[4] 15709 -> 15702, direct 5071, chains 9388, dj 31
(with anon_cache_count bug fixed)
If you sum the direct pages and the chains count for each row, convert
dj into dt (divided by HZ = 100) you get:
( 20469 + 3479 ) / 0.58 = 41289
( 227 + 26144 ) / 0.59 = 44696
( 26115 + 27617 ) / 1.17 = 45924
( 31508 + 82929 ) / 2.56 = 44701
( 2680 + 58 ) / 0.07 = 39114
( 75024 + 262834 ) / 7.26 = 46536
( 499 + 20022 ) / 0.44 = 46638
( 7189 + 9854 ) / 0.37 = 46062
( 5071 + 9388 ) / 0.31 = 46641
For 4 pte writes per direct page or chain entry comes to ~187,000/sec
which is close to the total collected by kvm_stat (data width shrunk to
fit in e-mail; hope this is readable still):
|---------- mmu_ ----------|----- pf_ -----|
cache flood pde_z pte_u pte_w shado fixed guest
267 271 95 21455 21842 285 22840 165
66 88 0 12102 12224 88 12458 0
2042 2133 0 178146 180515 2133 188089 387
1053 1212 0 187067 188485 1212 193011 8
4771 4811 88 185129 190998 4825 207490 448
910 824 7 183066 184050 824 195836 12
707 785 0 176381 177300 785 180350 6
1167 1144 0 189618 191014 1144 195902 10
4238 4193 87 188381 193590 4206 207030 465
1448 1400 7 187786 189509 1400 198688 21
982 971 0 187880 189076 971 198405 2
1165 1208 0 190007 191503 1208 195746 13
1106 1146 0 189144 190550 1146 195143 0
4767 4788 96 185802 191704 4802 206362 477
1388 1431 0 187387 188991 1431 195115 3
584 551 0 77176 77802 551 84829 10
12 7 0 3601 3609 7 13497 4
243 153 91 31085 31333 167 35059 879
21 18 6 3130 3155 18 3827 2
21 4 1 4665 4670 4 6825 9
>> The kvm_stat data for this time period is attached due to line lengths.
>>
>>
>> Also, I forgot to mention this before, but there is a bug in the
>> kscand code in the RHEL3U8 kernel. When it scans the cache list it
>> uses the count from the anonymous list:
>>
>> if (need_active_cache_scan(zone)) {
>> for (age = MAX_AGE-1; age >= 0; age--) {
>> scan_active_list(zone, age,
>> &zone->active_cache_list[age],
>> zone->active_anon_count[age]);
>> ^^^^^^^^^^^^^^^^^
>> if (current->need_resched)
>> schedule();
>> }
>> }
>>
>> When the anonymous count is higher it is scanning the cache list
>> repeatedly. An example of that was captured here:
>>
>> active_cache_scan: HighMem, age 7, count[age] 222 -> 179, count anon
>> 111967, direct 626, dj 3
>>
>> count anon is active_anon_count[age] which at this moment was 111,967.
>> There were only 222 entries in the cache list, but the count value
>> passed to scan_active_list was 111,967. When the cache list has a lot
>> of direct pages, that causes a larger hit on kvm than needed. That
>> said, I have to live with the bug in the guest.
>>
>
> For debugging, can you fix it? It certainly has a large impact.
>
yes, I have run a few tests with it fixed to get a ballpark on the
impact. The fix is included in the number above.
> Perhaps it is fixed in an update kernel. There's a 2.4.21-50.EL in the
> centos 3.8 update repos.
>
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
