lkml.org 
[lkml]   [2015]   [Sep]   [9]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Subject[lkp] [sched/preempt] fe32d3cd5e: -5.0% fsmark.files_per_sec
Date
FYI, we noticed the below changes on

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit fe32d3cd5e8eb0f82e459763374aa80797023403 ("sched/preempt: Fix cond_resched_lock() and cond_resched_softirq()")


=========================================================================================
tbox_group/testcase/rootfs/kconfig/compiler/cpufreq_governor/iterations/nr_threads/disk/fs/fs2/filesize/test_size/sync_method/nr_directories/nr_files_per_directory:
nhm4/fsmark/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/performance/1x/32t/1HDD/f2fs/nfsv4/5K/400M/fsyncBeforeClose/16d/256fpd

commit:
c56dadf39761a6157239cac39e3988998c994f98
fe32d3cd5e8eb0f82e459763374aa80797023403

c56dadf39761a615 fe32d3cd5e8eb0f82e45976337
---------------- --------------------------
%stddev %change %stddev
\ | \
24905032 ± 2% -23.3% 19104197 ± 2% fsmark.app_overhead
128.00 ± 0% -5.0% 121.60 ± 0% fsmark.files_per_sec
640.73 ± 0% +5.6% 676.69 ± 0% fsmark.time.elapsed_time
640.73 ± 0% +5.6% 676.69 ± 0% fsmark.time.elapsed_time.max
88485 ± 0% +14.6% 101386 ± 0% fsmark.time.involuntary_context_switches
374807 ± 0% -2.8% 364148 ± 0% fsmark.time.voluntary_context_switches
88485 ± 0% +14.6% 101386 ± 0% time.involuntary_context_switches
18539 ± 1% -11.8% 16345 ± 1% slabinfo.kmalloc-128.active_objs
19786 ± 1% -10.7% 17675 ± 1% slabinfo.kmalloc-128.num_objs
4.23e+08 ± 1% +19.2% 5.042e+08 ± 3% cpuidle.C1-NHM.time
84188847 ± 1% +22.9% 1.034e+08 ± 1% cpuidle.C1E-NHM.time
85925 ± 0% +21.8% 104644 ± 0% cpuidle.C1E-NHM.usage
1.81 ± 0% -5.4% 1.71 ± 0% turbostat.%Busy
53.00 ± 0% -5.7% 50.00 ± 0% turbostat.Avg_MHz
19.57 ± 1% +11.1% 21.73 ± 2% turbostat.CPU%c1
1589 ± 0% -5.0% 1510 ± 0% vmstat.io.bo
22835 ± 0% -3.8% 21965 ± 0% vmstat.system.cs
7892 ± 0% -5.7% 7445 ± 0% vmstat.system.in
75995 ± 0% +10.1% 83680 ± 0% latency_stats.avg.rpc_wait_bit_killable.__rpc_wait_for_completion_task.nfs4_run_open_task.[nfsv4]._nfs4_open_and_get_state.[nfsv4].nfs4_do_open.[nfsv4].nfs4_atomic_open.[nfsv4].nfs_atomic_open.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
370488 ± 65% -48.0% 192671 ± 8% latency_stats.max.wait_on_page_bit.filemap_fdatawait_range.filemap_write_and_wait_range.nfs4_file_fsync.[nfsv4].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath
1353699 ± 0% +4.2% 1410361 ± 0% latency_stats.sum.do_wait.SyS_wait4.entry_SYSCALL_64_fastpath
2451859 ± 1% +4.4% 2559496 ± 0% latency_stats.sum.pipe_wait.pipe_read.__vfs_read.vfs_read.SyS_read.entry_SYSCALL_64_fastpath
18995177 ± 4% -26.9% 13876200 ± 1% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_execute.rpc_run_task.nfs4_call_sync_sequence.[nfsv4]._nfs4_proc_lookup.[nfsv4].nfs4_proc_lookup_common.[nfsv4].nfs4_proc_lookup.[nfsv4].nfs_lookup_revalidate.nfs4_lookup_revalidate.lookup_dcache.__lookup_hash
5.941e+09 ± 0% +2.9% 6.116e+09 ± 0% latency_stats.sum.rpc_wait_bit_killable.__rpc_wait_for_completion_task.nfs4_do_close.[nfsv4].__nfs4_close.[nfsv4].nfs4_close_sync.[nfsv4].nfs4_close_context.[nfsv4].__put_nfs_open_context.nfs_release.nfs_file_release.__fput.____fput.task_work_run
6.257e+09 ± 0% +10.1% 6.89e+09 ± 0% latency_stats.sum.rpc_wait_bit_killable.__rpc_wait_for_completion_task.nfs4_run_open_task.[nfsv4]._nfs4_open_and_get_state.[nfsv4].nfs4_do_open.[nfsv4].nfs4_atomic_open.[nfsv4].nfs_atomic_open.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
4.633e+09 ± 0% +6.9% 4.951e+09 ± 0% latency_stats.sum.wait_on_page_bit.filemap_fdatawait_range.filemap_write_and_wait_range.nfs4_file_fsync.[nfsv4].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath
429.00 ± 10% -10.5% 384.00 ± 6% sched_debug.cfs_rq[0]:/.tg->runnable_avg
430.75 ± 10% -10.6% 385.25 ± 6% sched_debug.cfs_rq[1]:/.tg->runnable_avg
15.50 ± 5% +21.0% 18.75 ± 4% sched_debug.cfs_rq[2]:/.nr_spread_over
431.50 ± 10% -10.2% 387.50 ± 6% sched_debug.cfs_rq[2]:/.tg->runnable_avg
437.75 ± 10% -10.1% 393.75 ± 7% sched_debug.cfs_rq[4]:/.tg->runnable_avg
441.00 ± 9% -10.3% 395.75 ± 6% sched_debug.cfs_rq[5]:/.tg->runnable_avg
442.75 ± 9% -10.2% 397.75 ± 6% sched_debug.cfs_rq[6]:/.tg->runnable_avg
1888 ± 41% -55.4% 843.00 ± 39% sched_debug.cfs_rq[7]:/.blocked_load_avg
443.50 ± 9% -9.3% 402.25 ± 6% sched_debug.cfs_rq[7]:/.tg->runnable_avg
1916 ± 41% -54.9% 865.25 ± 39% sched_debug.cfs_rq[7]:/.tg_load_contrib
320180 ± 0% +9.7% 351102 ± 0% sched_debug.cpu#0.clock
320180 ± 0% +9.7% 351102 ± 0% sched_debug.cpu#0.clock_task
46298 ± 11% +20.5% 55770 ± 16% sched_debug.cpu#0.nr_load_updates
-3942 ± -2% -7.1% -3663 ± -1% sched_debug.cpu#0.nr_uninterruptible
320181 ± 0% +9.7% 351102 ± 0% sched_debug.cpu#1.clock
320181 ± 0% +9.7% 351102 ± 0% sched_debug.cpu#1.clock_task
320181 ± 0% +9.7% 351104 ± 0% sched_debug.cpu#2.clock
320181 ± 0% +9.7% 351104 ± 0% sched_debug.cpu#2.clock_task
418.25 ± 7% +35.0% 564.50 ± 0% sched_debug.cpu#2.nr_uninterruptible
320180 ± 0% +9.7% 351103 ± 0% sched_debug.cpu#3.clock
320180 ± 0% +9.7% 351103 ± 0% sched_debug.cpu#3.clock_task
43361 ± 0% +28.5% 55731 ± 21% sched_debug.cpu#3.nr_load_updates
503.00 ± 5% +16.1% 583.75 ± 3% sched_debug.cpu#3.nr_uninterruptible
60027 ± 0% +997.9% 659006 ±155% sched_debug.cpu#3.ttwu_local
320179 ± 0% +9.7% 351103 ± 0% sched_debug.cpu#4.clock
320179 ± 0% +9.7% 351103 ± 0% sched_debug.cpu#4.clock_task
3.50 ± 95% +135.7% 8.25 ± 51% sched_debug.cpu#4.cpu_load[2]
1090 ± 2% +13.7% 1239 ± 2% sched_debug.cpu#4.nr_uninterruptible
320178 ± 0% +9.7% 351087 ± 0% sched_debug.cpu#5.clock
320178 ± 0% +9.7% 351087 ± 0% sched_debug.cpu#5.clock_task
547.50 ± 3% -45.8% 296.75 ± 4% sched_debug.cpu#5.nr_uninterruptible
320178 ± 0% +9.7% 351105 ± 0% sched_debug.cpu#6.clock
320178 ± 0% +9.7% 351105 ± 0% sched_debug.cpu#6.clock_task
542.75 ± 2% -46.0% 293.25 ± 13% sched_debug.cpu#6.nr_uninterruptible
320182 ± 0% +9.7% 351104 ± 0% sched_debug.cpu#7.clock
320182 ± 0% +9.7% 351104 ± 0% sched_debug.cpu#7.clock_task
495.75 ± 3% -39.0% 302.50 ± 6% sched_debug.cpu#7.nr_uninterruptible
320182 ± 0% +9.7% 351105 ± 0% sched_debug.cpu_clk
320014 ± 0% +9.7% 350935 ± 0% sched_debug.ktime
320182 ± 0% +9.7% 351105 ± 0% sched_debug.sched_clk

=========================================================================================
tbox_group/testcase/rootfs/kconfig/compiler/cpufreq_governor/iterations/nr_threads/disk/fs/fs2/filesize/test_size/sync_method/nr_directories/nr_files_per_directory:
nhm4/fsmark/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/performance/1x/32t/1HDD/xfs/nfsv4/8K/400M/fsyncBeforeClose/16d/256fpd

commit:
c56dadf39761a6157239cac39e3988998c994f98
fe32d3cd5e8eb0f82e459763374aa80797023403

c56dadf39761a615 fe32d3cd5e8eb0f82e45976337
---------------- --------------------------
fail:runs %reproduction fail:runs
| | |
2:4 -50% :4 kmsg.Spurious_LAPIC_timer_interrupt_on_cpu
%stddev %change %stddev
\ | \
5006474 ± 0% +8.3% 5423397 ± 1% fsmark.app_overhead
55958 ± 0% +8.2% 60571 ± 0% fsmark.time.involuntary_context_switches
229728 ± 0% -1.8% 225635 ± 0% fsmark.time.voluntary_context_switches
2156965 ± 0% +15.7% 2495398 ± 0% latency_stats.sum.rpc_wait_bit_killable.__rpc_execute.rpc_execute.rpc_run_task.nfs4_call_sync_sequence.[nfsv4]._nfs4_proc_lookup.[nfsv4].nfs4_proc_lookup_common.[nfsv4].nfs4_proc_lookup.[nfsv4].nfs_lookup_revalidate.nfs4_lookup_revalidate.lookup_dcache.__lookup_hash
2481 ± 2% +10.1% 2731 ± 2% slabinfo.kmalloc-256.num_objs
5226 ± 8% -8.5% 4783 ± 4% slabinfo.vm_area_struct.active_objs
2584 ± 6% -21.8% 2021 ± 8% sched_debug.cfs_rq[2]:/.min_vruntime
-1883 ±-12% +38.9% -2614 ± -8% sched_debug.cfs_rq[2]:/.spread0
7666 ±165% -100.0% 0.00 ± -1% sched_debug.cfs_rq[4]:/.load
229.25 ±110% -100.0% 0.00 ± -1% sched_debug.cfs_rq[4]:/.runnable_load_avg
-2331 ± -9% +17.2% -2731 ± -6% sched_debug.cfs_rq[4]:/.spread0
437.25 ± 61% -100.0% 0.00 ± -1% sched_debug.cfs_rq[4]:/.utilization_load_avg
2091 ± 7% +22.3% 2558 ± 8% sched_debug.cfs_rq[5]:/.min_vruntime
-2376 ± -6% -12.6% -2077 ± -8% sched_debug.cfs_rq[5]:/.spread0
1537704 ± 96% -93.1% 105402 ± 33% sched_debug.cpu#7.nr_switches
1537765 ± 96% -93.1% 105462 ± 33% sched_debug.cpu#7.sched_count
756633 ± 98% -94.6% 41165 ± 43% sched_debug.cpu#7.sched_goidle


nhm4: Nehalem
Memory: 4G




fsmark.time.involuntary_context_switches

65000 ++------------------------------------------------------------------+
64000 ++ O |
O O O O O O O O O O O O O O O |
63000 ++ O |
62000 ++ |
| |
61000 ++ O O O O O
60000 ++ O O O |
59000 ++ |
| |
58000 ++ |
57000 ++ |
*..*.. .*. .*.. .* |
56000 ++ *. *..*. *..*..*.*..*..*..*..*..* |
55000 ++------------------------------------------------------------------+


fsmark.time.voluntary_context_switches

231000 ++-----------------------------------------------------------------+
| .*.. |
230000 ++ .*.*..*.. .* .*.*.. .* |
*..*. *..*. *.. .*. *..*. |
229000 ++ *. |
| |
228000 ++ |
| |
227000 ++ |
O |
226000 ++ O O |
| O O O O O O O O O O O O O O O
225000 ++ O O O O O O O |
| |
224000 ++-----------------------------------------------------------------+


[*] bisect-good sample
[O] bisect-bad sample

To reproduce:

git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp run job.yaml


Disclaimer:
Results have been estimated based on internal Intel analysis and are provided
for informational purposes only. Any difference in system hardware or software
design or configuration may affect actual performance.


Thanks,
Ying Huang
---
LKP_SERVER: inn
LKP_CGI_PORT: 80
LKP_CIFS_PORT: 139
testcase: fsmark
default-monitors:
wait: activate-monitor
kmsg:
uptime:
iostat:
vmstat:
numa-numastat:
numa-vmstat:
numa-meminfo:
proc-vmstat:
proc-stat:
interval: 10
meminfo:
slabinfo:
interrupts:
lock_stat:
latency_stats:
softirqs:
bdi_dev_mapping:
diskstats:
nfsstat:
cpuidle:
cpufreq-stats:
turbostat:
pmeter:
sched_debug:
interval: 60
cpufreq_governor: performance
default-watchdogs:
oom-killer:
watchdog:
commit: 9cfcc658da9693f65e7224e8329e40ada2f3c699
model: Nehalem
nr_cpu: 8
memory: 4G
hdd_partitions: "/dev/disk/by-id/ata-WDC_WD1003FBYZ-010FB0_WD-WCAW36812041-part1"
swap_partitions: "/dev/disk/by-id/ata-WDC_WD1003FBYZ-010FB0_WD-WCAW36812041-part2"
rootfs_partition: "/dev/disk/by-id/ata-WDC_WD1003FBYZ-010FB0_WD-WCAW36812041-part3"
netconsole_port: 6649
category: benchmark
iterations: 1x
nr_threads: 32t
disk: 1HDD
fs: xfs
fs2: nfsv4
fsmark:
filesize: 8K
test_size: 400M
sync_method: fsyncBeforeClose
nr_directories: 16d
nr_files_per_directory: 256fpd
queue: cyclic
testbox: nhm4
tbox_group: nhm4
kconfig: x86_64-rhel
enqueue_time: 2015-09-05 22:01:12.417466845 +08:00
id: 6cafd078675b335a6d47e6ddc8daebd0059f0c88
user: lkp
compiler: gcc-4.9
head_commit: 9cfcc658da9693f65e7224e8329e40ada2f3c699
base_commit: bf59e6623a3a92a2bf428f2d6592c81aae6317e1
branch: linus/master
kernel: "/pkg/linux/x86_64-rhel/gcc-4.9/9cfcc658da9693f65e7224e8329e40ada2f3c699/vmlinuz-4.2.0-09628-g9cfcc65"
rootfs: debian-x86_64-2015-02-07.cgz
result_root: "/result/fsmark/performance-1x-32t-1HDD-xfs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/9cfcc658da9693f65e7224e8329e40ada2f3c699/0"
job_file: "/lkp/scheduled/nhm4/cyclic_fsmark-performance-1x-32t-1HDD-xfs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd-x86_64-rhel-CYCLIC_HEAD-9cfcc658da9693f65e7224e8329e40ada2f3c699-20150905-98956-61twsm-0.yaml"
dequeue_time: 2015-09-07 03:13:57.049455437 +08:00
max_uptime: 917.1600000000001
initrd: "/osimage/debian/debian-x86_64-2015-02-07.cgz"
bootloader_append:
- root=/dev/ram0
- user=lkp
- job=/lkp/scheduled/nhm4/cyclic_fsmark-performance-1x-32t-1HDD-xfs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd-x86_64-rhel-CYCLIC_HEAD-9cfcc658da9693f65e7224e8329e40ada2f3c699-20150905-98956-61twsm-0.yaml
- ARCH=x86_64
- kconfig=x86_64-rhel
- branch=linus/master
- commit=9cfcc658da9693f65e7224e8329e40ada2f3c699
- BOOT_IMAGE=/pkg/linux/x86_64-rhel/gcc-4.9/9cfcc658da9693f65e7224e8329e40ada2f3c699/vmlinuz-4.2.0-09628-g9cfcc65
- max_uptime=917
- RESULT_ROOT=/result/fsmark/performance-1x-32t-1HDD-xfs-nfsv4-8K-400M-fsyncBeforeClose-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/9cfcc658da9693f65e7224e8329e40ada2f3c699/0
- LKP_SERVER=inn
- |-
libata.force=1.5Gbps

earlyprintk=ttyS0,115200 systemd.log_level=err
debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100
panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0
console=ttyS0,115200 console=tty0 vga=normal

rw
lkp_initrd: "/lkp/lkp/lkp-x86_64.cgz"
modules_initrd: "/pkg/linux/x86_64-rhel/gcc-4.9/9cfcc658da9693f65e7224e8329e40ada2f3c699/modules.cgz"
bm_initrd: "/osimage/deps/debian-x86_64-2015-02-07.cgz/lkp.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/run-ipconfig.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/turbostat.cgz,/lkp/benchmarks/turbostat.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/fs.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/fs2.cgz,/lkp/benchmarks/fsmark.cgz"
job_state: finished
loadavg: 27.12 11.13 4.14 1/187 2699
start_time: '1441566896'
end_time: '1441567023'
version: "/lkp/lkp/.src-20150906-205656"
echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu1/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu2/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu3/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu4/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu5/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu6/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu7/cpufreq/scaling_governor
mkfs -t xfs /dev/sda1
mount -t xfs -o nobarrier,inode64 /dev/sda1 /fs/sda1
/etc/init.d/rpcbind start
/etc/init.d/nfs-common start
/etc/init.d/nfs-kernel-server start
mount -t nfs -o vers=4 localhost:/fs/sda1 /nfs/sda1
./fs_mark -d /nfs/sda1/1 -d /nfs/sda1/2 -d /nfs/sda1/3 -d /nfs/sda1/4 -d /nfs/sda1/5 -d /nfs/sda1/6 -d /nfs/sda1/7 -d /nfs/sda1/8 -d /nfs/sda1/9 -d /nfs/sda1/10 -d /nfs/sda1/11 -d /nfs/sda1/12 -d /nfs/sda1/13 -d /nfs/sda1/14 -d /nfs/sda1/15 -d /nfs/sda1/16 -d /nfs/sda1/17 -d /nfs/sda1/18 -d /nfs/sda1/19 -d /nfs/sda1/20 -d /nfs/sda1/21 -d /nfs/sda1/22 -d /nfs/sda1/23 -d /nfs/sda1/24 -d /nfs/sda1/25 -d /nfs/sda1/26 -d /nfs/sda1/27 -d /nfs/sda1/28 -d /nfs/sda1/29 -d /nfs/sda1/30 -d /nfs/sda1/31 -d /nfs/sda1/32 -D 16 -N 256 -n 1600 -L 1 -S 1 -s 8192
\
 
 \ /
  Last update: 2015-09-10 04:21    [W:0.363 / U:0.512 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site