From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751501AbbJHFn7 (ORCPT ); Thu, 8 Oct 2015 01:43:59 -0400 Received: from mga09.intel.com ([134.134.136.24]:56157 "EHLO mga09.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751020AbbJHFn6 (ORCPT ); Thu, 8 Oct 2015 01:43:58 -0400 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.17,653,1437462000"; d="yaml'?scan'208";a="822020976" From: kernel test robot Subject: [lkp] [f2fs] 15bec0ff5a: -7.5% fsmark.files_per_sec CC: lkp@01.org CC: LKML TO: Jaegeuk Kim Date: Thu, 08 Oct 2015 13:43:55 +0800 Message-ID: <87lhbdx6ck.fsf@yhuang-dev.intel.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.5 (gnu/linux) MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org --=-=-= Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: quoted-printable 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") =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D 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:=20 1583667acb21aba71a8ba16a5f1596bba1cdbbfa 15bec0ff5a9ba6d203178fa8772259df6207942a 1583667acb21aba7 15bec0ff5a9ba6d203178fa877=20 ---------------- --------------------------=20 %stddev %change %stddev \ | \=20=20 9.60 =B1 0% -7.5% 8.88 =B1 2% fsmark.files_per_sec 25828 =B1 14% +43.3% 37001 =B1 9% fsmark.time.involuntary_c= ontext_switches 346865 =B1 1% +5.1% 364446 =B1 2% fsmark.time.voluntary_con= text_switches 149762 =B1 1% -10.8% 133532 =B1 1% meminfo.Writeback 25828 =B1 14% +43.3% 37001 =B1 9% time.involuntary_context_= switches 10567 =B1 0% -1.4% 10423 =B1 0% vmstat.system.in 35272 =B1 1% +13.7% 40088 =B1 2% softirqs.BLOCK 55788 =B1 2% -9.2% 50649 =B1 2% softirqs.RCU 86.40 =B1 0% +2.9% 88.90 =B1 0% turbostat.Avg_MHz 15.04 =B1 4% +51.2% 22.74 =B1 7% turbostat.CPU%c6 95420434 =B1 2% +11.1% 1.06e+08 =B1 3% cpuidle.C1-NHM.time 76306793 =B1 3% -25.7% 56703791 =B1 6% cpuidle.C1E-NHM.time 136043 =B1 3% +10.9% 150901 =B1 1% cpuidle.C6-NHM.usage 85.60 =B1 40% +149.5% 213.60 =B1 32% proc-vmstat.allocstall 761.80 =B1114% +1601.0% 12958 =B1 32% proc-vmstat.nr_vmscan_imm= ediate_reclaim 37430 =B1 1% -10.8% 33381 =B1 1% proc-vmstat.nr_writeback 4375 =B1 2% +45.5% 6367 =B1 10% proc-vmstat.pgactivate 307.90 =B1138% +4385.4% 13810 =B1 25% proc-vmstat.pgrotated 11195 =B1 43% +150.1% 27994 =B1 34% proc-vmstat.pgsteal_direc= t_dma32 274804 =B1 7% -13.2% 238436 =B1 6% sched_debug.cfs_rq[1]:/.m= in_vruntime 2498 =B1 9% +44.4% 3607 =B1 5% sched_debug.cfs_rq[4]:/.e= xec_clock 2769 =B1 7% +39.7% 3869 =B1 16% sched_debug.cfs_rq[5]:/.e= xec_clock 2667 =B1 12% +40.3% 3741 =B1 6% sched_debug.cfs_rq[6]:/.e= xec_clock 2631 =B1 9% +43.1% 3765 =B1 7% sched_debug.cfs_rq[7]:/.e= xec_clock -95.80 =B1-32% +95.2% -187.00 =B1-30% sched_debug.cpu#0.nr_unin= terruptible 11444 =B1 7% +57.4% 18012 =B1 46% sched_debug.cpu#5.nr_load= _updates 43.30 =B1 29% +228.2% 142.10 =B1 27% sched_debug.cpu#5.nr_unin= terruptible 9204 =B1 10% +3829.2% 361677 =B1193% sched_debug.cpu#5.ttwu_lo= cal 0.00 =B1 -1% +Inf% 726873 =B1 91% latency_stats.avg.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 957001 =B1 34% latency_stats.avg.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 600712 =B1106% latency_stats.avg.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2= fs].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 =B1 -1% +Inf% 60887 =B1 77% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_p= ages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_ca= che_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[= f2fs] 83681 =B1 43% +128.1% 190851 =B1 70% latency_stats.avg.wait_on= _page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f= 2fs].get_dnode_of_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2f= s].f2fs_write_begin.[f2fs].generic_perform_write.__generic_file_write_iter.= generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_write 0.00 =B1 -1% +Inf% 339404 =B1117% latency_stats.avg.wait_on= _page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].l= ookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_f= astpath 0.00 =B1 -1% +Inf% 765971 =B1 90% latency_stats.max.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 1376989 =B1 27% latency_stats.max.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 808830 =B1126% latency_stats.max.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2= fs].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 =B1 -1% +Inf% 60934 =B1 77% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_p= ages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_ca= che_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[= f2fs] 113863 =B1265% -76.8% 26423 =B1 86% latency_stats.max.wait_on= _page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f= 2fs].set_data_blkaddr.[f2fs].reserve_new_block.[f2fs].f2fs_reserve_block.[f= 2fs].get_new_data_page.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs= _create.path_openat.do_filp_open 0.00 =B1 -1% +Inf% 646891 =B1130% latency_stats.max.wait_on= _page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].l= ookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_f= astpath 1804998 =B1 87% +5901.9% 1.083e+08 =B1 9% latency_stats.sum.call_rw= sem_down_read_failed.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_w= riteback.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_o= penat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath 337670 =B1 90% +85.5% 626367 =B1147% latency_stats.sum.call_rw= sem_down_read_failed.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_w= riteback.[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 =B1 18% +761.1% 151720 =B1 14% latency_stats.sum.call_rw= sem_down_read_failed.get_node_info.[f2fs].new_node_page.[f2fs].new_inode_pa= ge.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2= fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open 800.10 =B1125% +7429.5% 60243 =B1 27% latency_stats.sum.call_rw= sem_down_write_failed.get_node_info.[f2fs].new_node_page.[f2fs].new_inode_p= age.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f= 2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open 18545 =B1 17% +670.2% 142844 =B1 16% latency_stats.sum.call_rw= sem_down_write_failed.set_node_addr.[f2fs].new_node_page.[f2fs].new_inode_p= age.[f2fs].init_inode_metadata.[f2fs].__f2fs_add_link.[f2fs].f2fs_create.[f= 2fs].vfs_create.path_openat.do_filp_open.do_sys_open.SyS_open 0.00 =B1 -1% +Inf% 1001773 =B1 98% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 3896545 =B1 63% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].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 =B1 -1% +Inf% 1037029 =B1109% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.f2fs_submit_page_bio.[f2= fs].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 =B1 -1% +Inf% 1365444 =B1172% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_lruvec.shrink_zone.do_try_to_free_p= ages.try_to_free_pages.__alloc_pages_nodemask.alloc_pages_current.__page_ca= che_alloc.pagecache_get_page.grab_cache_page_write_begin.f2fs_write_begin.[= f2fs] 1.318e+08 =B1 62% +1624.3% 2.272e+09 =B1 9% latency_stats.sum.wait_on= _page_bit.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait_on_page_writeback.[f= 2fs].__f2fs_add_link.[f2fs].f2fs_create.[f2fs].vfs_create.path_openat.do_fi= lp_open.do_sys_open.SyS_open.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 1314116 =B1111% latency_stats.sum.wait_on= _page_bit.find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].l= ookup_real.path_openat.do_filp_open.do_sys_open.SyS_open.entry_SYSCALL_64_f= astpath nhm4: Nehalem Memory: 4G To reproduce: git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tes= ts.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 provid= ed for informational purposes only. Any difference in system hardware or softw= are design or configuration may affect actual performance. Thanks, Ying Huang --=-=-= Content-Type: text/plain; charset=ascii Content-Disposition: attachment; filename=job.yaml --- 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" --=-=-= Content-Type: text/plain; charset=ascii Content-Disposition: attachment; filename=reproduce 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 --=-=-=--