[lkp] [kernel/fs] d57d611505: +54.7% turbostat.%Busy

From: kernel test robot
Date: Tue Feb 23 2016 - 03:26:19 EST

Next message: Chunhao Lin: "[PATCH net v3] r8169:fix "rtl_counters_cond == 1 (loop: 1000, delay: 10)" log spam."
Previous message: Minchan Kim: "Re: [RFC][PATCH v2 3/3] mm/zsmalloc: increase ZS_MAX_PAGES_PER_ZSPAGE"
Next in thread: Stephane Gasparini: "Re: [lkp] [kernel/fs] d57d611505: +54.7% turbostat.%Busy"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

FYI, we noticed the below changes on

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit d57d611505d911c6f9f81cd9bd6dbd293d66dd9f ("kernel/fs: fix I/O wait not accounted for RW O_DSYNC")

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

commit:
09954bad448791ef01202351d437abdd9497a804
d57d611505d911c6f9f81cd9bd6dbd293d66dd9f

09954bad448791ef d57d611505d911c6f9f81cd9bd
---------------- --------------------------
%stddev %change %stddev
\ | \
14760 ± 1% +6.3% 15695 ± 1% fsmark.time.involuntary_context_switches
46.00 ± 0% -8.2% 42.25 ± 1% fsmark.time.percent_of_cpu_this_job_got
26151 ±116% -71.3% 7498 ± 23% latency_stats.sum.call_rwsem_down_read_failed.f2fs_mkdir.[f2fs].vfs_mkdir.SyS_mkdir.entry_SYSCALL_64_fastpath
7418 ± 23% -27.7% 5361 ± 3% numa-vmstat.node0.nr_slab_unreclaimable
1.47 ± 1% -9.9% 1.33 ± 0% time.user_time
1447 ± 4% -29.0% 1028 ± 7% uptime.idle
7.75 ± 19% +206.5% 23.75 ± 1% vmstat.procs.b
29675 ± 23% -27.7% 21447 ± 3% numa-meminfo.node0.SUnreclaim
83099 ± 8% -11.5% 73568 ± 1% numa-meminfo.node0.Slab
11.91 ± 1% +54.7% 18.43 ± 1% turbostat.%Busy
358.00 ± 1% +60.0% 572.75 ± 1% turbostat.Avg_MHz
21.54 ± 0% -17.4% 17.79 ± 1% turbostat.CPU%c1
24.78 ± 3% +41.1% 34.98 ± 1% turbostat.CPU%c3
41.76 ± 1% -31.0% 28.81 ± 1% turbostat.CPU%c6
8.53 ± 5% -25.6% 6.34 ± 10% turbostat.Pkg%pc3
66312232 ± 0% -68.5% 20910669 ± 4% cpuidle.C1-NHM.time
46386272 ± 2% -20.5% 36884085 ± 5% cpuidle.C1E-NHM.time
2.79e+08 ± 2% +51.5% 4.226e+08 ± 0% cpuidle.C3-NHM.time
254315 ± 2% +25.1% 318250 ± 2% cpuidle.C3-NHM.usage
7.585e+08 ± 1% -22.2% 5.901e+08 ± 1% cpuidle.C6-NHM.time
415414 ± 1% -38.1% 257115 ± 1% cpuidle.C6-NHM.usage
1.135e+08 ± 1% +77.8% 2.017e+08 ± 2% cpuidle.POLL.time
102777 ± 1% +36.0% 139811 ± 1% cpuidle.POLL.usage
2011 ± 25% -27.1% 1467 ± 2% sched_debug.cfs_rq:/.exec_clock.2
1820 ± 3% -12.2% 1597 ± 7% sched_debug.cfs_rq:/.exec_clock.4
4297 ± 6% +78.1% 7653 ± 54% sched_debug.cfs_rq:/.min_vruntime.12
4803 ± 18% -16.1% 4028 ± 21% sched_debug.cfs_rq:/.min_vruntime.8
3763 ± 4% -17.0% 3124 ± 7% sched_debug.cfs_rq:/.min_vruntime.9
3408 ± 4% -14.9% 2900 ± 2% sched_debug.cfs_rq:/.min_vruntime.min
4.75 ± 54% -73.7% 1.25 ±173% sched_debug.cfs_rq:/.nr_spread_over.2
1.99 ± 16% +25.5% 2.50 ± 9% sched_debug.cfs_rq:/.nr_spread_over.stddev
-4362 ±-25% -92.7% -318.24 ±-1304% sched_debug.cfs_rq:/.spread0.12
200.25 ± 47% -48.8% 102.50 ± 22% sched_debug.cfs_rq:/.util_avg.7
187.75 ± 64% -77.2% 42.75 ± 56% sched_debug.cfs_rq:/.util_avg.8
1.41 ± 31% +37.0% 1.93 ± 12% sched_debug.cpu.clock.stddev
1.41 ± 31% +37.0% 1.93 ± 12% sched_debug.cpu.clock_task.stddev
1.63 ± 67% -53.9% 0.75 ± 38% sched_debug.cpu.cpu_load[4].stddev
33822 ± 16% -17.2% 28018 ± 4% sched_debug.cpu.nr_switches.13
36824 ± 3% +12.9% 41569 ± 4% sched_debug.cpu.nr_switches.14
33117 ± 7% -11.1% 29438 ± 5% sched_debug.cpu.nr_switches.15
57634 ± 3% +8.8% 62716 ± 3% sched_debug.cpu.nr_switches.4
1723 ± 7% -11.3% 1527 ± 5% sched_debug.cpu.nr_uninterruptible.10
1378 ± 6% -8.7% 1258 ± 5% sched_debug.cpu.nr_uninterruptible.15
1232 ± 10% +25.3% 1543 ± 3% sched_debug.cpu.nr_uninterruptible.8
34660 ± 13% -19.1% 28034 ± 4% sched_debug.cpu.sched_count.13
37545 ± 2% +18.9% 44629 ± 7% sched_debug.cpu.sched_count.14
34003 ± 9% -13.4% 29456 ± 5% sched_debug.cpu.sched_count.15
62715 ± 6% +9.5% 68642 ± 7% sched_debug.cpu.sched_count.2
14091 ± 19% -20.4% 11212 ± 5% sched_debug.cpu.sched_goidle.13
14175 ± 3% +15.4% 16354 ± 6% sched_debug.cpu.sched_goidle.14
13465 ± 9% -12.5% 11782 ± 6% sched_debug.cpu.sched_goidle.15
24646 ± 3% +9.4% 26968 ± 4% sched_debug.cpu.sched_goidle.4
15258 ± 6% -22.8% 11773 ± 4% sched_debug.cpu.ttwu_count.11
15765 ± 5% +48.1% 23355 ± 15% sched_debug.cpu.ttwu_count.12
16869 ± 3% -26.1% 12461 ± 4% sched_debug.cpu.ttwu_count.13
3142 ± 5% +13.0% 3551 ± 8% sched_debug.cpu.ttwu_local.13

lkp-ne04: Nehalem-EP
Memory: 12G

uptime.idle

1600 ++-------------------------------------------------------------------+
| .*. *. |
1500 *+**.** * **.*.**.* *.**.**.*.**.* *.**.*.**.**.*.**.**.*.* **.*
1400 ++ : : : : :+ |
| :: :: * |
1300 ++ * * |
| |
1200 ++ |
| |
1100 O+OO OO O O OO O OO OO O O OO O |
1000 ++ |
| |
900 ++ O O |
| |
800 ++-------------------------------------------------------------------+

cpuidle.POLL.time

2.2e+08 ++---------------O--O----O----------------------------------------+
O O O O O |
2e+08 ++O O O O O O O O |
| O OO O O |
| |
1.8e+08 ++ |
| |
1.6e+08 ++ |
| |
1.4e+08 ++ |
| |
| |
1.2e+08 ++ .* .* *. .*.**. .**. *.**. *.* *. *.**.**.**.|
*.**.** * *. : **. * ** **.* *.* *.* * *
1e+08 ++------------*-----*---------------------------------------------+

cpuidle.C1-NHM.time

8e+07 ++------------------------------------------------------------------+
| |
7e+07 ++ .* *. .* .* *. *. .* *.* |
| *. *.**.*. .**.*. * *.* * *. *.* *.* * *. * *. .* *.**.*
6e+07 *+* * ** * * * * |
| |
5e+07 ++ |
| |
4e+07 ++ |
| |
3e+07 ++ |
| O O |
2e+07 O+OO OO OO O OO O OO OO OO O O |
| |
1e+07 ++------------------------------------------------------------------+

cpuidle.C3-NHM.time

4.4e+08 ++------------O---------------------------------------------------+
| OO O O O O O O |
4.2e+08 O+ O O O O O O |
4e+08 ++ O O O O O |
| |
3.8e+08 ++ |
3.6e+08 ++ |
| |
3.4e+08 ++ |
3.2e+08 ++ |
| * |
3e+08 ++ +: ** *.* .* |
2.8e+08 *+ *. *. *. * :.* + + .* .**. .* :.* .*.* * *.**.* .* .*
| * * * * * * * * ** * * *.* * *.** |
2.6e+08 ++----------------------------------------------------------------+

cpuidle.C6-NHM.time

8e+08 ++----------*-----------------------------------------------------+
| * .* .* + .* |
|.* + * * ** *. *.*. *. *.**.**.**. *. .**.**.**. *.**. *.* |
7.5e+08 *+ * * * * * * * * *.*
| |
| |
7e+08 ++ |
| |
6.5e+08 ++ |
| |
O |
6e+08 ++ O OO O O O O O O |
| O OO O O O O O O |
| O O |
5.5e+08 ++----------------------------------------------------------------+

cpuidle.C6-NHM.usage

440000 ++-----------------------------------------------------------------+
420000 ++ *. *. *. .*. * .* .* .*.* .* |
|.* .**.**. : *.* * **.** * + *.**.*.** * :.** : .** *.*
400000 *+ * * * * *.** |
380000 ++ |
| |
360000 ++ |
340000 ++ |
320000 ++ |
| |
300000 ++ |
280000 ++ |
| O O O O O |
260000 O+ O OO OO O O OO O O OO O O |
240000 ++-----------------------------------------------------------------+

turbostat.Avg_MHz

650 ++--------------------------------------------------------------------+
| |
600 O+ OO O O O O |
| O O OO O O OO OO O |
550 ++ O O O |
| |
500 ++ |
| |
450 ++ |
| |
400 ++ |
| *.*.* .**. .**.*. .**. .* .**. *.|
350 *+**.*.**.**.*. *.*.* .* *.* **.* ** *.**.* * *.* *
| * * |
300 ++--------------------------------------------------------------------+

turbostat._Busy

20 ++---------------------------------------------------------------------+
19 O+ O O O O |
| O O OO O O O O O OO |
18 ++OO O O O |
17 ++ |
| |
16 ++ |
15 ++ |
14 ++ |
| |
13 ++ |
12 ++ .* .**.*.* .*.**. *.*.**. .**.* .*.**.*.**.*.**.|
*.**.*.**.* *. .**.* .* * *.* * * *
11 ++ * * |
10 ++---------------------------------------------------------------------+

turbostat.CPU_c1

23 ++---------------------------------------------------------------------+
| * * *. |
22 ++ * +: : *. .* *. : *. * * *. |
| *. *. .* : * : : * :+ * .*.: * + + *. *.*.* .*.* *.**.*
21 *+* *.* * : : *.* * * * * * * |
| *.* |
20 ++ |
| |
19 ++ |
| |
18 ++ O OO O O O O O |
| OO O O O O O O O |
17 O+ O O O |
| |
16 ++---------------------------------------------------------------------+

turbostat.CPU_c3

38 ++---------------------------------------------------------------------+
| O |
36 ++OO O O O O |
34 ++ O O O O O OO O |
O O O |
32 ++ O O O |
| |
30 ++ |
| |
28 ++ * |
26 ++ : : *.* *.* * .*
*. *. .* .*. : : *. : : *. .**. + : *. *.*. :+ .* .*. *. * |
24 ++* * * ** * * : : * *.** :+ * **.* * * * *.* |
| * * |
22 ++---------------------------------------------------------------------+

turbostat.CPU_c6

44 ++---*-------*---------------------------------------------------------+
|.* + + *.*.* + .**. *. *. .** * .*. *.* *. .*.* |
42 *+ * * * **.*.* + * * + .**. + * * :.*.* *.** *.|
40 ++ * * * * *
| |
38 ++ |
36 ++ |
| |
34 ++ |
32 ++ |
O O O |
30 ++ O O O OO O O O |
28 ++OO O O O O O O |
| O O |
26 ++---------------------------------------------------------------------+

vmstat.procs.b

30 ++---------------------------------------------------------------------+
| |
| O |
25 O+O O O O OO O O O O O |
| O O O O O O O O |
| |
20 ++ |
| |
15 ++ |
| |
| |
10 ++* *.* .* .* *.*. *. .* .**.*. * |
|+ :.*. .* .* *.* * + *. .* * * :.*. * **. .**. + :.*
* * **.* :.* * * * * * * * |
5 ++-----------*---------------------------------------------------------+

[*] 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:
heartbeat:
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: d57d611505d911c6f9f81cd9bd6dbd293d66dd9f
model: Nehalem-EP
memory: 12G
hdd_partitions: "/dev/disk/by-id/ata-ST3500514NS_9WJ03EBA-part3"
swap_partitions: "/dev/disk/by-id/ata-ST3120026AS_5MS07HA2-part2"
rootfs_partition: "/dev/disk/by-id/ata-ST3500514NS_9WJ03EBA-part1"
category: benchmark
iterations: 1x
nr_threads: 32t
disk: 1HDD
fs: f2fs
fs2:
fsmark:
filesize: 9B
test_size: 400M
sync_method: fsyncBeforeClose
nr_directories: 16d
nr_files_per_directory: 256fpd
queue: bisect
testbox: lkp-ne04
tbox_group: lkp-ne04
kconfig: x86_64-rhel
enqueue_time: 2016-02-22 10:58:09.364797751 +08:00
compiler: gcc-4.9
rootfs: debian-x86_64-2015-02-07.cgz
id: 6d2662afc93143f862f189ea98b1c462b2ff6215
user: lkp
head_commit: cb0ddba856afd26f4aa32ca286e798fae835c5d4
base_commit: 81f70ba233d5f660e1ea5fe23260ee323af5d53a
branch: linux-devel/devel-hourly-2016022201
result_root: "/result/fsmark/performance-1x-32t-1HDD-f2fs-9B-400M-fsyncBeforeClose-16d-256fpd/lkp-ne04/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/0"
job_file: "/lkp/scheduled/lkp-ne04/bisect_fsmark-performance-1x-32t-1HDD-f2fs-9B-400M-fsyncBeforeClose-16d-256fpd-debian-x86_64-2015-02-07.cgz-x86_64-rhel-d57d611505d911c6f9f81cd9bd6dbd293d66dd9f-20160222-22073-1mh810r-0.yaml"
nr_cpu: "$(nproc)"
max_uptime: 839.1400000000001
initrd: "/osimage/debian/debian-x86_64-2015-02-07.cgz"
bootloader_append:
- root=/dev/ram0
- user=lkp
- job=/lkp/scheduled/lkp-ne04/bisect_fsmark-performance-1x-32t-1HDD-f2fs-9B-400M-fsyncBeforeClose-16d-256fpd-debian-x86_64-2015-02-07.cgz-x86_64-rhel-d57d611505d911c6f9f81cd9bd6dbd293d66dd9f-20160222-22073-1mh810r-0.yaml
- ARCH=x86_64
- kconfig=x86_64-rhel
- branch=linux-devel/devel-hourly-2016022201
- commit=d57d611505d911c6f9f81cd9bd6dbd293d66dd9f
- BOOT_IMAGE=/pkg/linux/x86_64-rhel/gcc-4.9/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/vmlinuz-4.5.0-rc1-00192-gd57d611
- max_uptime=839
- RESULT_ROOT=/result/fsmark/performance-1x-32t-1HDD-f2fs-9B-400M-fsyncBeforeClose-16d-256fpd/lkp-ne04/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/0
- LKP_SERVER=inn
- |2-

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/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/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"
linux_headers_initrd: "/pkg/linux/x86_64-rhel/gcc-4.9/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/linux-headers.cgz"
repeat_to: 2
kernel: "/pkg/linux/x86_64-rhel/gcc-4.9/d57d611505d911c6f9f81cd9bd6dbd293d66dd9f/vmlinuz-4.5.0-rc1-00192-gd57d611"
dequeue_time: 2016-02-22 11:07:01.622256068 +08:00
job_state: finished
loadavg: 23.23 7.48 2.63 2/257 3180
start_time: '1456110470'
end_time: '1456110550'
version: "/lkp/lkp/.src-20160222-105838"

Attachment: reproduce.sh
Description: Bourne shell script

Next message: Chunhao Lin: "[PATCH net v3] r8169:fix "rtl_counters_cond == 1 (loop: 1000, delay: 10)" log spam."
Previous message: Minchan Kim: "Re: [RFC][PATCH v2 3/3] mm/zsmalloc: increase ZS_MAX_PAGES_PER_ZSPAGE"
Next in thread: Stephane Gasparini: "Re: [lkp] [kernel/fs] d57d611505: +54.7% turbostat.%Busy"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]