[lkp] [f2fs] 15bec0ff5a: -7.5% fsmark.files_per_sec

From: kernel test robot
Date: Thu Oct 08 2015 - 01:44:03 EST

Next message: kernel test robot: "[lkp] [drm/core] 12188d6e3a: WARNING: CPU: 2 PID: 144 at drivers/gpu/drm/drm_drv.c:569 drm_dev_alloc+0x257/0x320 [drm]()"
Previous message: kernel test robot: "[lkp] [btrfs] 84f0ca2788: BUG: sleeping function called from invalid context at kernel/locking/rwsem.c:21"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

FYI, we noticed the below changes on

https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master
commit 15bec0ff5a9ba6d203178fa8772259df6207942a ("f2fs: do not skip dentry block writes")

=========================================================================================
tbox_group/testcase/rootfs/kconfig/compiler/cpufreq_governor/iterations/nr_threads/disk/fs/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/16MB/60G/NoSync/16d/256fpd

commit:
1583667acb21aba71a8ba16a5f1596bba1cdbbfa
15bec0ff5a9ba6d203178fa8772259df6207942a

1583667acb21aba7 15bec0ff5a9ba6d203178fa877
---------------- --------------------------
%stddev %change %stddev
\ | \
9.60 ± 0% -7.5% 8.88 ± 2% fsmark.files_per_sec
25828 ± 14% +43.3% 37001 ± 9% fsmark.time.involuntary_context_switches
346865 ± 1% +5.1% 364446 ± 2% fsmark.time.voluntary_context_switches
149762 ± 1% -10.8% 133532 ± 1% meminfo.Writeback
25828 ± 14% +43.3% 37001 ± 9% time.involuntary_context_switches
10567 ± 0% -1.4% 10423 ± 0% vmstat.system.in
35272 ± 1% +13.7% 40088 ± 2% softirqs.BLOCK
55788 ± 2% -9.2% 50649 ± 2% softirqs.RCU
86.40 ± 0% +2.9% 88.90 ± 0% turbostat.Avg_MHz
15.04 ± 4% +51.2% 22.74 ± 7% turbostat.CPU%c6
95420434 ± 2% +11.1% 1.06e+08 ± 3% cpuidle.C1-NHM.time
76306793 ± 3% -25.7% 56703791 ± 6% cpuidle.C1E-NHM.time
136043 ± 3% +10.9% 150901 ± 1% cpuidle.C6-NHM.usage
85.60 ± 40% +149.5% 213.60 ± 32% proc-vmstat.allocstall
761.80 ±114% +1601.0% 12958 ± 32% proc-vmstat.nr_vmscan_immediate_reclaim
37430 ± 1% -10.8% 33381 ± 1% proc-vmstat.nr_writeback
4375 ± 2% +45.5% 6367 ± 10% proc-vmstat.pgactivate
307.90 ±138% +4385.4% 13810 ± 25% proc-vmstat.pgrotated
11195 ± 43% +150.1% 27994 ± 34% proc-vmstat.pgsteal_direct_dma32
274804 ± 7% -13.2% 238436 ± 6% sched_debug.cfs_rq[1]:/.min_vruntime
2498 ± 9% +44.4% 3607 ± 5% sched_debug.cfs_rq[4]:/.exec_clock
2769 ± 7% +39.7% 3869 ± 16% sched_debug.cfs_rq[5]:/.exec_clock
2667 ± 12% +40.3% 3741 ± 6% sched_debug.cfs_rq[6]:/.exec_clock
2631 ± 9% +43.1% 3765 ± 7% sched_debug.cfs_rq[7]:/.exec_clock
-95.80 ±-32% +95.2% -187.00 ±-30% sched_debug.cpu#0.nr_uninterruptible
11444 ± 7% +57.4% 18012 ± 46% sched_debug.cpu#5.nr_load_updates
43.30 ± 29% +228.2% 142.10 ± 27% sched_debug.cpu#5.nr_uninterruptible
9204 ± 10% +3829.2% 361677 ±193% sched_debug.cpu#5.ttwu_local
0.00 ± -1% +Inf% 726873 ± 91% latency_stats.avg.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].f2fs_new_inode.[f2fs].f2fs_create.[f2fs].vfs_create
0.00 ± -1% +Inf% 957001 ± 34% latency_stats.avg.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs]
0.00 ± -1% +Inf% 600712 ±106% latency_stats.avg.get_request.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2fs].get_read_data_page.[f2fs].find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open
0.00 ± -1% +Inf% 60887 ± 77% latency_stats.avg.wait_iff_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_pages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[f2fs]
83681 ± 43% +128.1% 190851 ± 70% latency_stats.avg.wait_on_page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs].f2fs_write_begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_write
0.00 ± -1% +Inf% 339404 ±117% latency_stats.avg.wait_on_page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
0.00 ± -1% +Inf% 765971 ± 90% latency_stats.max.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].f2fs_new_inode.[f2fs].f2fs_create.[f2fs].vfs_create
0.00 ± -1% +Inf% 1376989 ± 27% latency_stats.max.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs]
0.00 ± -1% +Inf% 808830 ±126% latency_stats.max.get_request.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2fs].get_read_data_page.[f2fs].find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open
0.00 ± -1% +Inf% 60934 ± 77% latency_stats.max.wait_iff_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_pages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[f2fs]
113863 ±265% -76.8% 26423 ± 86% latency_stats.max.wait_on_page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f2fs].set_data_blkaddr.[f2fs].reserve_new_block.[f2fs].f2fs_reserve_block.[f2fs].get_new_data_page.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open
0.00 ± -1% +Inf% 646891 ±130% latency_stats.max.wait_on_page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
1804998 ± 87% +5901.9% 1.083e+08 ± 9% latency_stats.sum.call_rwsem_down_read_failed.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
337670 ± 90% +85.5% 626367 ±147% latency_stats.sum.call_rwsem_down_read_failed.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs].f2fs_write_begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_write
17619 ± 18% +761.1% 151720 ± 14% latency_stats.sum.call_rwsem_down_read_failed.get_node_info.[f2fs].new_node_page.[f2fs].new_inode_page.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open
800.10 ±125% +7429.5% 60243 ± 27% latency_stats.sum.call_rwsem_down_write_failed.get_node_info.[f2fs].new_node_page.[f2fs].new_inode_page.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open
18545 ± 17% +670.2% 142844 ± 16% latency_stats.sum.call_rwsem_down_write_failed.set_node_addr.[f2fs].new_node_page.[f2fs].new_inode_page.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open
0.00 ± -1% +Inf% 1001773 ± 98% latency_stats.sum.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].f2fs_new_inode.[f2fs].f2fs_create.[f2fs].vfs_create
0.00 ± -1% +Inf% 3896545 ± 63% latency_stats.sum.get_request.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2fs].f2fs_submit_merged_bio.[f2fs].ra_meta_pages.[f2fs].build_free_nids.[f2fs].alloc_nid.[f2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs]
0.00 ± -1% +Inf% 1037029 ±109% latency_stats.sum.get_request.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2fs].get_read_data_page.[f2fs].find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open
0.00 ± -1% +Inf% 1365444 ±172% latency_stats.sum.wait_iff_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_pages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[f2fs]
1.318e+08 ± 62% +1624.3% 2.272e+09 ± 9% latency_stats.sum.wait_on_page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath
0.00 ± -1% +Inf% 1314116 ±111% latency_stats.sum.wait_on_page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].lookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath

nhm4: Nehalem
Memory: 4G

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: 0293645856ec527639b5902f021fa5aeba93e305
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: f2fs
fs2:
fsmark:
filesize: 16MB
test_size: 60G
sync_method: NoSync
nr_directories: 16d
nr_files_per_directory: 256fpd
queue: cyclic
testbox: nhm4
tbox_group: nhm4
kconfig: x86_64-rhel
enqueue_time: 2015-09-28 12:38:00.849493513 +08:00
id: 4dbd5c61ad6c53fd8fec9aca15c24fca05b31ca7
user: lkp
compiler: gcc-4.9
head_commit: 0293645856ec527639b5902f021fa5aeba93e305
base_commit: 9ffecb10283508260936b96022d4ee43a7798b4c
branch: linux-next/master
kernel: "/pkg/linux/x86_64-rhel/gcc-4.9/0293645856ec527639b5902f021fa5aeba93e305/vmlinuz-4.3.0-rc3-next-20150929"
rootfs: debian-x86_64-2015-02-07.cgz
result_root: "/result/fsmark/performance-1x-32t-1HDD-f2fs-16MB-60G-NoSync-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/0293645856ec527639b5902f021fa5aeba93e305/0"
job_file: "/lkp/scheduled/nhm4/cyclic_fsmark-performance-1x-32t-1HDD-f2fs-16MB-60G-NoSync-16d-256fpd-x86_64-rhel-CYCLIC_HEAD-0293645856ec527639b5902f021fa5aeba93e305-20150928-126591-1upq9j6-0.yaml"
dequeue_time: 2015-09-30 12:10:43.216175540 +08:00
max_uptime: 1600.06
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-f2fs-16MB-60G-NoSync-16d-256fpd-x86_64-rhel-CYCLIC_HEAD-0293645856ec527639b5902f021fa5aeba93e305-20150928-126591-1upq9j6-0.yaml
- ARCH=x86_64
- kconfig=x86_64-rhel
- branch=linux-next/master
- commit=0293645856ec527639b5902f021fa5aeba93e305
- BOOT_IMAGE=/pkg/linux/x86_64-rhel/gcc-4.9/0293645856ec527639b5902f021fa5aeba93e305/vmlinuz-4.3.0-rc3-next-20150929
- max_uptime=1600
- RESULT_ROOT=/result/fsmark/performance-1x-32t-1HDD-f2fs-16MB-60G-NoSync-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/0293645856ec527639b5902f021fa5aeba93e305/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/0293645856ec527639b5902f021fa5aeba93e305/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: 26.94 25.17 13.00 1/156 7065
start_time: '1443586272'
end_time: '1443586753'
version: "/lkp/lkp/.src-20150930-113106"
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 f2fs /dev/sda1
mount -t f2fs /dev/sda1 /fs/sda1
./fs_mark -d /fs/sda1/1 -d /fs/sda1/2 -d /fs/sda1/3 -d /fs/sda1/4 -d /fs/sda1/5 -d /fs/sda1/6 -d /fs/sda1/7 -d /fs/sda1/8 -d /fs/sda1/9 -d /fs/sda1/10 -d /fs/sda1/11 -d /fs/sda1/12 -d /fs/sda1/13 -d /fs/sda1/14 -d /fs/sda1/15 -d /fs/sda1/16 -d /fs/sda1/17 -d /fs/sda1/18 -d /fs/sda1/19 -d /fs/sda1/20 -d /fs/sda1/21 -d /fs/sda1/22 -d /fs/sda1/23 -d /fs/sda1/24 -d /fs/sda1/25 -d /fs/sda1/26 -d /fs/sda1/27 -d /fs/sda1/28 -d /fs/sda1/29 -d /fs/sda1/30 -d /fs/sda1/31 -d /fs/sda1/32 -D 16 -N 256 -n 120 -L 1 -S 0 -s 16777216

Next message: kernel test robot: "[lkp] [drm/core] 12188d6e3a: WARNING: CPU: 2 PID: 144 at drivers/gpu/drm/drm_drv.c:569 drm_dev_alloc+0x257/0x320 [drm]()"
Previous message: kernel test robot: "[lkp] [btrfs] 84f0ca2788: BUG: sleeping function called from invalid context at kernel/locking/rwsem.c:21"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]