[lkp] [sched/preempt] fe32d3cd5e: -5.0% fsmark.files_per_sec

[kernel test robot]

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