Re: [LKP] [SUNRPC] c4a7ca77494: +6.0% fsmark.time.involuntary_context_switches, no primary result change
From: Trond Myklebust
Date: Sun Feb 15 2015 - 13:02:35 EST
Hi guys,
On Sun, Feb 15, 2015 at 2:57 AM, Huang Ying <ying.huang@xxxxxxxxx> wrote:
> FYI, we noticed the below changes on
>
> commit c4a7ca774949960064dac11b326908f28407e8c3 ("SUNRPC: Allow waiting on memory allocation")
>
>
> testbox/testcase/testparams: nhm4/fsmark/performance-1x-32t-1HDD-f2fs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd
>
> 127b21b89f9d8ba0 c4a7ca774949960064dac11b32
> ---------------- --------------------------
> %stddev %change %stddev
> \ | \
> 52524 Â 0% +6.0% 55672 Â 0% fsmark.time.involuntary_context_switches
> 436 Â 14% +54.9% 676 Â 20% sched_debug.cfs_rq[0]:/.tg_load_contrib
> 433 Â 15% +54.7% 670 Â 21% sched_debug.cfs_rq[0]:/.blocked_load_avg
> 8348 Â 7% +27.0% 10602 Â 9% sched_debug.cfs_rq[0]:/.min_vruntime
> 190081 Â 13% +32.7% 252269 Â 13% sched_debug.cpu#0.sched_goidle
> 205783 Â 12% +30.2% 267903 Â 13% sched_debug.cpu#0.ttwu_local
> 464065 Â 11% +26.6% 587524 Â 12% sched_debug.cpu#0.nr_switches
> 464278 Â 11% +26.6% 587734 Â 12% sched_debug.cpu#0.sched_count
> 15807 Â 11% +19.6% 18910 Â 12% sched_debug.cpu#4.nr_load_updates
> 300041 Â 8% +20.3% 360969 Â 10% sched_debug.cpu#0.ttwu_count
> 1863 Â 9% +18.1% 2201 Â 10% sched_debug.cfs_rq[4]:/.exec_clock
>
> testbox/testcase/testparams: nhm4/fsmark/performance-1x-32t-1HDD-btrfs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd
>
> 127b21b89f9d8ba0 c4a7ca774949960064dac11b32
> ---------------- --------------------------
> fail:runs %reproduction fail:runs
> | | |
> 52184 Â 0% +5.6% 55122 Â 0% fsmark.time.involuntary_context_switches
> 557 Â 19% +21.5% 677 Â 9% sched_debug.cfs_rq[5]:/.blocked_load_avg
> 217 Â 19% -42.9% 124 Â 21% sched_debug.cfs_rq[2]:/.load
> 45852 Â 14% -39.4% 27773 Â 24% sched_debug.cpu#7.ttwu_local
> 457 Â 18% +50.1% 686 Â 20% sched_debug.cfs_rq[0]:/.tg_load_contrib
> 455 Â 18% +46.7% 668 Â 19% sched_debug.cfs_rq[0]:/.blocked_load_avg
> 66605 Â 10% -26.7% 48826 Â 14% sched_debug.cpu#7.sched_goidle
> 78249 Â 9% -22.5% 60678 Â 11% sched_debug.cpu#7.ttwu_count
> 153506 Â 9% -22.7% 118649 Â 12% sched_debug.cpu#7.nr_switches
> 153613 Â 9% -22.7% 118755 Â 12% sched_debug.cpu#7.sched_count
> 15806 Â 6% +19.2% 18833 Â 18% sched_debug.cpu#4.nr_load_updates
> 2171 Â 5% +15.6% 2510 Â 13% sched_debug.cfs_rq[4]:/.exec_clock
> 9924 Â 11% -27.0% 7244 Â 25% sched_debug.cfs_rq[3]:/.min_vruntime
> 3156 Â 4% -13.4% 2734 Â 8% sched_debug.cfs_rq[7]:/.min_vruntime
>
> testbox/testcase/testparams: nhm4/fsmark/performance-1x-32t-1HDD-ext4-nfsv4-9B-400M-fsyncBeforeClose-16d-256fpd
>
> 127b21b89f9d8ba0 c4a7ca774949960064dac11b32
> ---------------- --------------------------
> 104802 Â 0% +7.7% 112883 Â 0% fsmark.time.involuntary_context_switches
> 471755 Â 0% -1.3% 465592 Â 0% fsmark.time.voluntary_context_switches
> 1977 Â 36% +90.8% 3771 Â 8% sched_debug.cpu#4.curr->pid
> 2 Â 34% +80.0% 4 Â 24% sched_debug.cpu#6.cpu_load[1]
> 4 Â 33% +83.3% 8 Â 31% sched_debug.cpu#6.cpu_load[0]
> 193 Â 17% +48.0% 286 Â 19% sched_debug.cfs_rq[2]:/.blocked_load_avg
> 196 Â 17% +47.5% 290 Â 19% sched_debug.cfs_rq[2]:/.tg_load_contrib
> 96 Â 18% +40.6% 135 Â 11% sched_debug.cfs_rq[7]:/.load
> 97 Â 18% +38.5% 135 Â 11% sched_debug.cpu#7.load
> 2274 Â 7% -16.5% 1898 Â 3% proc-vmstat.pgalloc_dma
> 319 Â 6% -29.7% 224 Â 24% sched_debug.cfs_rq[1]:/.tg_load_contrib
> 314 Â 5% -29.4% 222 Â 25% sched_debug.cfs_rq[1]:/.blocked_load_avg
> 621 Â 10% +41.9% 881 Â 37% sched_debug.cfs_rq[4]:/.avg->runnable_avg_sum
>
> nhm4: Nehalem
> Memory: 4G
>
>
>
>
> fsmark.time.involuntary_context_switches
>
> 114000 ++-----------------------------------------------------------------+
> 113000 O+ O O O O O O O O O O O O O O O O O |
> | O O O O O
> 112000 ++ |
> 111000 ++ |
> | |
> 110000 ++ |
> 109000 ++ |
> 108000 ++ |
> | |
> 107000 ++ |
> 106000 ++ |
> | |
> 105000 *+.*..*..*..*..*..*..*..*..*..*...*..*..*..*..*..*..*..* |
> 104000 ++-----------------------------------------------------------------+
>
>
> [*] bisect-good sample
> [O] bisect-bad sample
>
> To reproduce:
>
> apt-get install ruby
> git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
> cd lkp-tests
> bin/setup-local job.yaml # the job file attached in this email
> bin/run-local job.yaml
So this is on a loopback NFS setup (i.e. the server resides on the
same node as the client, which just mounts from the loopback IP
address 127.0.0.1)?
That's a fairly quirky setup as far as memory management goes. In low
memory situations, you have very a nasty feedback mechanism whereby
the NFS server ends up pushing the client to write back more data,
increasing the memory pressure on the NFS server, etc.
It is quite possible that allowing the NFS client to block more
aggressively in low memory situations could worsen that feedback
mechanism, however that's not our main target platform; we actively
discourage people from using loopback NFS in production systems.
Is there any way you could confirm this performance change using a
remote NFS server instead of the loopback NFS?
Cheers
Trond
--
Trond Myklebust
Linux NFS client maintainer, PrimaryData
trond.myklebust@xxxxxxxxxxxxxxx
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/