[lkp-robot] [workqueue] 5c0338c687: blogbench.write_score -21.2% regression

From: kernel test robot
Date: Thu Jan 04 2018 - 00:58:08 EST


Greeting,

FYI, we noticed a -21.2% regression of blogbench.write_score due to commit:


commit: 5c0338c68706be53b3dc472e4308961c36e4ece1 ("workqueue: restore WQ_UNBOUND/max_active==1 to be ordered")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

in testcase: blogbench
on test machine: 16 threads Intel(R) Xeon(R) CPU D-1541 @ 2.10GHz with 8G memory
with following parameters:

disk: 1SSD
fs: btrfs
cpufreq_governor: performance

test-description: Blogbench is a portable filesystem benchmark that tries to reproduce the load of a real-world busy file server.
test-url: https://www.pureftpd.org/project/blogbench


Details are as below:
-------------------------------------------------------------------------------------------------->


To reproduce:

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp run job.yaml

=========================================================================================
compiler/cpufreq_governor/disk/fs/kconfig/rootfs/tbox_group/testcase:
gcc-6/performance/1SSD/btrfs/x86_64-rhel-7.2/debian-x86_64-2016-08-31.cgz/lkp-bdw-de1/blogbench

commit:
74cbd96bc2 ("Merge tag 'md/4.13-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/shli/md")
5c0338c687 ("workqueue: restore WQ_UNBOUND/max_active==1 to be ordered")

74cbd96bc2e00f5d 5c0338c68706be53b3dc472e43
---------------- --------------------------
%stddev %change %stddev
\ | \
3974 -21.2% 3131 ± 4% blogbench.write_score
1608428 ± 2% +9.7% 1764811 ± 6% blogbench.read_score
1.043e+08 -58.0% 43770754 ± 19% blogbench.time.file_system_inputs
33045282 -23.0% 25456502 ± 4% blogbench.time.file_system_outputs
1889747 -51.2% 922952 blogbench.time.involuntary_context_switches
1066 -9.1% 969.60 ± 4% blogbench.time.percent_of_cpu_this_job_got
3058 -9.6% 2764 ± 4% blogbench.time.system_time
20367518 ± 2% -58.2% 8523363 ± 17% blogbench.time.voluntary_context_switches
56387 ± 6% -9.4% 51101 ± 2% interrupts.CAL:Function_call_interrupts
599681 ± 2% -42.0% 347640 ± 14% softirqs.SCHED
21.79 ± 3% +6.4 28.17 ± 10% mpstat.cpu.iowait%
0.02 ± 22% +0.2 0.23 ± 15% mpstat.cpu.soft%
3.08 ± 5% +0.6 3.72 ± 6% mpstat.cpu.usr%
63227 ± 3% +13.0% 71434 ± 6% meminfo.CmaFree
1915913 ± 4% -25.3% 1431623 ± 4% meminfo.Inactive
1897786 ± 4% -25.5% 1413549 ± 4% meminfo.Inactive(file)
1269568 ± 4% +27.1% 1613730 ± 9% meminfo.MemFree
8434 ± 5% -55.9% 3719 ± 18% iostat.sda.r/s
168471 ± 5% -56.9% 72537 ± 19% iostat.sda.rkB/s
10.68 ± 8% -37.2% 6.70 ± 11% iostat.sda.rrqm/s
732.25 ± 5% -30.4% 509.76 ± 2% iostat.sda.w/s
1748 ± 4% -18.2% 1429 ± 5% iostat.sda.wrqm/s
8.165e+08 ± 2% -20.7% 6.477e+08 ± 14% cpuidle.C1.time
26339770 ± 2% -59.2% 10742045 ± 18% cpuidle.C1.usage
1.775e+08 ± 6% +236.0% 5.962e+08 ± 6% cpuidle.C1E.time
607354 ± 4% +51.8% 921820 ± 9% cpuidle.C1E.usage
134897 ± 25% -38.6% 82860 ± 15% cpuidle.C3.usage
518720 ± 2% -60.1% 207069 ± 19% cpuidle.POLL.usage
168530 ± 5% -56.9% 72617 ± 19% vmstat.io.bi
57048 ± 5% -22.2% 44397 ± 4% vmstat.io.bo
429.10 ± 5% +21.2% 520.20 ± 8% vmstat.memory.buff
1289089 ± 4% +26.6% 1631377 ± 8% vmstat.memory.free
40.40 ± 4% -17.6% 33.30 ± 11% vmstat.procs.b
207214 ± 5% -34.2% 136272 ± 9% vmstat.system.cs
27043 ± 2% -26.6% 19840 ± 3% vmstat.system.in
216066 ± 3% +12.8% 243680 ± 2% slabinfo.btrfs_delayed_node.active_objs
11273 ± 4% -27.3% 8194 ± 3% slabinfo.btrfs_extent_buffer.active_objs
11710 ± 4% -26.2% 8636 ± 3% slabinfo.btrfs_extent_buffer.num_objs
5056 ± 3% -12.2% 4441 ± 6% slabinfo.btrfs_ordered_extent.active_objs
5187 ± 3% -11.9% 4568 ± 6% slabinfo.btrfs_ordered_extent.num_objs
19452 ± 10% +66.7% 32428 ± 8% slabinfo.kmalloc-256.active_objs
624.40 ± 9% +65.7% 1034 ± 8% slabinfo.kmalloc-256.active_slabs
19996 ± 9% +65.7% 33129 ± 8% slabinfo.kmalloc-256.num_objs
624.40 ± 9% +65.7% 1034 ± 8% slabinfo.kmalloc-256.num_slabs
6.933e+11 -7.8% 6.395e+11 ± 2% perf-stat.branch-instructions
0.62 -0.1 0.47 ± 4% perf-stat.branch-miss-rate%
4.329e+09 -30.0% 3.032e+09 ± 2% perf-stat.branch-misses
64545297 ± 2% -35.9% 41378261 ± 9% perf-stat.context-switches
9.103e+12 -8.0% 8.376e+12 ± 3% perf-stat.cpu-cycles
6729558 ± 3% -72.4% 1858286 ± 17% perf-stat.cpu-migrations
26.24 ± 5% +23.6 49.83 ± 9% perf-stat.iTLB-load-miss-rate%
4.122e+08 ± 7% +26.5% 5.214e+08 ± 5% perf-stat.iTLB-load-misses
1.157e+09 ± 2% -54.2% 5.302e+08 ± 14% perf-stat.iTLB-loads
8459 ± 7% -24.3% 6399 ± 5% perf-stat.instructions-per-iTLB-miss
0.38 +4.4% 0.40 perf-stat.ipc
319949 ± 5% -3.9% 307528 perf-stat.minor-faults
319952 ± 5% -3.9% 307494 perf-stat.page-faults
84255382 ± 9% -95.6% 3708415 ± 83% proc-vmstat.compact_daemon_free_scanned
1829109 ± 18% -97.6% 44241 ± 93% proc-vmstat.compact_daemon_migrate_scanned
1059 ± 11% -92.8% 75.90 ±100% proc-vmstat.compact_daemon_wake
84255382 ± 9% -95.6% 3708415 ± 83% proc-vmstat.compact_free_scanned
781008 ± 21% -98.8% 9090 ± 89% proc-vmstat.compact_isolated
1829109 ± 18% -97.6% 44241 ± 93% proc-vmstat.compact_migrate_scanned
179.80 ± 9% -40.8% 106.50 ± 16% proc-vmstat.kswapd_high_wmark_hit_quickly
22499 ± 62% -100.0% 5.50 ±125% proc-vmstat.kswapd_inodesteal
4237 ± 8% -83.2% 710.60 ± 28% proc-vmstat.kswapd_low_wmark_hit_quickly
4539912 -24.2% 3441760 ± 4% proc-vmstat.nr_dirtied
316909 ± 4% +27.1% 402889 ± 9% proc-vmstat.nr_free_pages
474932 ± 4% -25.5% 353600 ± 4% proc-vmstat.nr_inactive_file
207449 ± 14% -54.1% 95277 ± 24% proc-vmstat.nr_vmscan_immediate_reclaim
4442638 -24.2% 3366510 ± 4% proc-vmstat.nr_written
474994 ± 4% -25.5% 353713 ± 4% proc-vmstat.nr_zone_inactive_file
20945924 -35.0% 13606065 ± 7% proc-vmstat.numa_hit
20945924 -35.0% 13606065 ± 7% proc-vmstat.numa_local
4632 ± 7% -75.8% 1119 ± 18% proc-vmstat.pageoutrun
26805123 ± 2% -35.6% 17261359 ± 6% proc-vmstat.pgactivate
6702031 -15.2% 5684286 ± 4% proc-vmstat.pgalloc_dma32
17277542 -27.9% 12464886 ± 4% proc-vmstat.pgalloc_normal
31715903 ± 2% -39.0% 19354510 ± 8% proc-vmstat.pgdeactivate
22331249 -26.4% 16425277 ± 5% proc-vmstat.pgfree
62247 ± 8% -94.5% 3437 ± 76% proc-vmstat.pgmigrate_success
52404647 -58.0% 22020215 ± 19% proc-vmstat.pgpgin
17745601 -24.2% 13447782 ± 4% proc-vmstat.pgpgout
31724465 ± 2% -39.0% 19363354 ± 8% proc-vmstat.pgrefill
229386 ± 12% -48.0% 119203 ± 28% proc-vmstat.pgrotated
16121910 -54.1% 7392371 ± 17% proc-vmstat.pgscan_kswapd
15714718 -54.8% 7109527 ± 17% proc-vmstat.pgsteal_kswapd
8744243 -55.3% 3910348 ± 18% proc-vmstat.slabs_scanned
1941347 ± 11% -75.0% 485169 ± 26% proc-vmstat.workingset_activate
3087977 ± 13% -76.7% 718263 ± 28% proc-vmstat.workingset_refault


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,
Xiaolong
---

#! jobs/blogbench-1ssd.yaml
suite: blogbench
testcase: blogbench
category: benchmark
disk: 1SSD
fs: btrfs
blogbench:
job_origin: "/lkp/lkp/.src-20170721-133542/allot/cyclic:linux-devel:devel-hourly/lkp-bdw-de1/blogbench-1ssd.yaml"

#! queue options
queue: bisect
testbox: lkp-bdw-de1
tbox_group: lkp-bdw-de1
submit_id: 5973470b0b9a93631584a7d0
job_file: "/lkp/scheduled/lkp-bdw-de1/blogbench-1SSD-btrfs-performance-debian-x86_64-2016-08-31.cgz-5c0338c68706be53b3dc472e4308961c36e4ece1-20170722-25365-6b8zgb-0.yaml"
id: d3e7da0613559b94d7a99eb30e80352859bdd7bc

#! hosts/lkp-bdw-de1
model: Broadwell-DE
nr_cpu: 16
memory: 8G
ssd_partitions: "/dev/disk/by-id/ata-INTEL_SSDSC2BB480G6_BTWA6075012T480FGN"
swap_partitions:
rootfs_partition:
kernel_cmdline: console=ttyS1,115200 console=tty0
brand: Intel(R) Xeon(R) CPU D-1541 @ 2.10GHz

#! include/category/benchmark
kmsg:
iostat:
heartbeat:
vmstat:
numa-numastat:
numa-vmstat:
numa-meminfo:
proc-vmstat:
proc-stat:
meminfo:
slabinfo:
interrupts:
lock_stat:
latency_stats:
softirqs:
bdi_dev_mapping:
diskstats:
nfsstat:
cpuidle:
cpufreq-stats:
turbostat:
sched_debug:
perf-stat:
mpstat:
perf-profile:

#! include/category/ALL
cpufreq_governor: performance

#! include/disk/nr_ssd
need_kconfig:
- CONFIG_BLK_DEV_SD
- CONFIG_SCSI
- CONFIG_BLOCK=y
- CONFIG_SATA_AHCI
- CONFIG_SATA_AHCI_PLATFORM
- CONFIG_ATA
- CONFIG_PCI=y
- CONFIG_BTRFS_FS

#! include/queue/cyclic
commit: 5c0338c68706be53b3dc472e4308961c36e4ece1

#! include/fs/btrfs

#! default params
kconfig: x86_64-rhel-7.2
compiler: gcc-6
rootfs: debian-x86_64-2016-08-31.cgz
enqueue_time: 2017-07-22 20:37:33.211024853 +08:00
_id: 5973470b0b9a93631584a7d0
_rt: "/result/blogbench/1SSD-btrfs-performance/lkp-bdw-de1/debian-x86_64-2016-08-31.cgz/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1"

#! schedule options
user: lkp
head_commit: dd5e317b37c687cf696b54b1148559ec09682d18
base_commit: 5771a8c08880cdca3bfb4a3fc6d309d6bba20877
branch: linux-devel/devel-hourly-2017072207
result_root: "/result/blogbench/1SSD-btrfs-performance/lkp-bdw-de1/debian-x86_64-2016-08-31.cgz/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1/0"
LKP_SERVER: inn
max_uptime: 3232.98
initrd: "/osimage/debian/debian-x86_64-2016-08-31.cgz"
bootloader_append:
- root=/dev/ram0
- user=lkp
- job=/lkp/scheduled/lkp-bdw-de1/blogbench-1SSD-btrfs-performance-debian-x86_64-2016-08-31.cgz-5c0338c68706be53b3dc472e4308961c36e4ece1-20170722-25365-6b8zgb-0.yaml
- ARCH=x86_64
- kconfig=x86_64-rhel-7.2
- branch=linux-devel/devel-hourly-2017072207
- commit=5c0338c68706be53b3dc472e4308961c36e4ece1
- BOOT_IMAGE=/pkg/linux/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1/vmlinuz-4.13.0-rc1-00060-g5c0338c
- console=ttyS1,115200 console=tty0
- max_uptime=3232
- RESULT_ROOT=/result/blogbench/1SSD-btrfs-performance/lkp-bdw-de1/debian-x86_64-2016-08-31.cgz/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1/0
- LKP_SERVER=inn
- debug
- apic=debug
- sysrq_always_enabled
- rcupdate.rcu_cpu_stall_timeout=100
- net.ifnames=0
- printk.devkmsg=on
- panic=-1
- softlockup_panic=1
- nmi_watchdog=panic
- oops=panic
- load_ramdisk=2
- prompt_ramdisk=0
- drbd.minor_count=8
- earlyprintk=ttyS1,115200
- systemd.log_level=err
- console=ttyS1,115200
- console=tty0
- rw
lkp_initrd: "/lkp/lkp/lkp-x86_64.cgz"
modules_initrd: "/pkg/linux/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1/modules.cgz"
bm_initrd: "/osimage/deps/debian-x86_64-2016-08-31.cgz/lkp_2017-05-01.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/rsync-rootfs_2016-11-15.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/run-ipconfig_2016-11-15.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/fs_2016-11-15.cgz,/osimage/pkg/debian-x86_64-2016-08-31.cgz/blogbench-x86_64_2016-09-01.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/iostat_2016-11-15.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/turbostat_2016-11-15.cgz,/osimage/pkg/debian-x86_64-2016-08-31.cgz/turbostat-x86_64-d5256b2_2017-06-20.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/perf_2017-07-07.cgz,/osimage/pkg/debian-x86_64-2016-08-31.cgz/perf-x86_64-af3c8d98508d_2017-07-10.cgz,/osimage/deps/debian-x86_64-2016-08-31.cgz/hw_2016-11-15.cgz"
site: inn

#! /lkp/lkp/.src-20170721-133542/include/site/inn
LKP_CGI_PORT: 80
LKP_CIFS_PORT: 139
oom-killer:
watchdog:

#! runtime status
repeat_to: 5

#! user overrides
kernel: "/pkg/linux/x86_64-rhel-7.2/gcc-6/5c0338c68706be53b3dc472e4308961c36e4ece1/vmlinuz-4.13.0-rc1-00060-g5c0338c"
dequeue_time: 2017-07-22 20:42:28.496576889 +08:00
job_state: finished
loadavg: '130.02'
dmsetup remove_all
wipefs -a --force /dev/sda
mkfs -t btrfs /dev/sda
mkdir -p /fs/sda
mount -t btrfs /dev/sda /fs/sda

for cpu_dir in /sys/devices/system/cpu/cpu[0-9]*
do
online_file="$cpu_dir"/online
[ -f "$online_file" ] && [ "$(cat "$online_file")" -eq 0 ] && continue

file="$cpu_dir"/cpufreq/scaling_governor
[ -f "$file" ] && echo "$scaling_governor" > "$file"
done

./blogbench -d /fs/sda