From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751445AbcBNHal (ORCPT ); Sun, 14 Feb 2016 02:30:41 -0500 Received: from mga02.intel.com ([134.134.136.20]:18904 "EHLO mga02.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751272AbcBNHaj (ORCPT ); Sun, 14 Feb 2016 02:30:39 -0500 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.22,444,1449561600"; d="yaml'?sh'?scan'208";a="884091309" From: kernel test robot Subject: [lkp] [f2fs] 974b5afbf1: +187.0% fsmark.time.voluntary_context_switches CC: lkp@01.org CC: LKML TO: Jaegeuk Kim Date: Sun, 14 Feb 2016 15:30:37 +0800 Message-ID: <87lh6nn3z6.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/jaegeuk/f2fs dev-test commit 974b5afbf16ecd3e01cefd5d52e3090b6d967693 ("f2fs: use writepages->loc= k for WB_SYNC_ALL") =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 compiler/disk/filesize/fs/iterations/kconfig/nr_directories/nr_files_per_di= rectory/nr_threads/rootfs/sync_method/tbox_group/test_size/testcase: gcc-4.9/1HDD/16MB/f2fs/1x/x86_64-rhel/16d/256fpd/32t/debian-x86_64-2015-0= 2-07.cgz/fsyncBeforeClose/nhm4/60G/fsmark commit:=20 ac247fd0403387a3f264b86b41cdc71543e66400 974b5afbf16ecd3e01cefd5d52e3090b6d967693 ac247fd0403387a3 974b5afbf16ecd3e01cefd5d52=20 ---------------- --------------------------=20 %stddev %change %stddev \ | \=20=20 40098 =B1 2% +25.7% 50389 =B1 3% fsmark.time.involuntary_c= ontext_switches 19.30 =B1 2% +18.1% 22.80 =B1 1% fsmark.time.percent_of_cp= u_this_job_got 97.36 =B1 1% +18.1% 115.00 =B1 1% fsmark.time.system_time 804635 =B1 1% +187.0% 2309592 =B1 5% fsmark.time.voluntary_con= text_switches 1904 =B1 1% -18.8% 1546 =B1 3% uptime.idle 38568 =B1 2% +19.0% 45897 =B1 3% softirqs.RCU 45610 =B1 1% +26.9% 57875 =B1 1% softirqs.SCHED 78751 =B1 1% +39.3% 109673 =B1 0% softirqs.TIMER 65587 =B1 0% +76.5% 115770 =B1 0% vmstat.memory.free 4605 =B1 1% +159.8% 11962 =B1 3% vmstat.system.cs 564.10 =B1 1% +75.7% 991.10 =B1 0% vmstat.system.in 65578 =B1 0% +76.3% 115584 =B1 0% meminfo.MemFree 69193 =B1 0% +46.4% 101331 =B1 2% meminfo.SReclaimable 79277 =B1 0% +53.9% 121991 =B1 0% meminfo.SUnreclaim 148470 =B1 0% +50.4% 223322 =B1 1% meminfo.Slab 1066 =B1 2% +45.8% 1554 =B1 1% time.file_system_inputs 40098 =B1 2% +25.7% 50389 =B1 3% time.involuntary_context_= switches 19.30 =B1 2% +18.1% 22.80 =B1 1% time.percent_of_cpu_this_= job_got 97.36 =B1 1% +18.1% 115.00 =B1 1% time.system_time 804635 =B1 1% +187.0% 2309592 =B1 5% time.voluntary_context_sw= itches 4.80 =B1 3% +240.9% 16.37 =B1 3% turbostat.%Busy 150.30 =B1 3% +259.0% 539.60 =B1 3% turbostat.Avg_MHz 10.10 =B1 2% +69.4% 17.11 =B1 2% turbostat.CPU%c1 24.51 =B1 2% +12.3% 27.54 =B1 2% turbostat.CPU%c3 60.59 =B1 0% -35.7% 38.99 =B1 2% turbostat.CPU%c6 56.00 =B1 1% +12.9% 63.20 =B1 1% turbostat.CoreTmp 1.042e+08 =B1 3% -32.6% 70243667 =B1 5% cpuidle.C1E-NHM.time 5.49e+08 =B1 2% +23.1% 6.76e+08 =B1 2% cpuidle.C3-NHM.time 155243 =B1 2% +22.3% 189817 =B1 3% cpuidle.C3-NHM.usage 3.052e+09 =B1 0% -17.6% 2.515e+09 =B1 1% cpuidle.C6-NHM.time 132307 =B1 2% +20.6% 159621 =B1 2% cpuidle.C6-NHM.usage 64832253 =B1 9% +626.5% 4.71e+08 =B1 4% cpuidle.POLL.time 95963 =B1 2% +987.2% 1043299 =B1 8% cpuidle.POLL.usage 582.20 =B1 0% +1e+05% 583505 =B1 7% slabinfo.f2fs_extent_node= .active_objs 7.20 =B1 5% +1.1e+05% 7994 =B1 7% slabinfo.f2fs_extent_node= .active_slabs 582.20 =B1 0% +1e+05% 583664 =B1 7% slabinfo.f2fs_extent_node= .num_objs 7.20 =B1 5% +1.1e+05% 7994 =B1 7% slabinfo.f2fs_extent_node= .num_slabs 10171 =B1 6% +22.6% 12471 =B1 10% slabinfo.free_nid.active_= objs 10194 =B1 6% +23.4% 12580 =B1 9% slabinfo.free_nid.num_objs 1834 =B1 1% +543.2% 11798 =B1 0% slabinfo.kmalloc-256.acti= ve_objs 78.70 =B1 6% +406.9% 398.90 =B1 1% slabinfo.kmalloc-256.acti= ve_slabs 2524 =B1 6% +403.5% 12710 =B1 1% slabinfo.kmalloc-256.num_= objs 78.70 =B1 6% +406.9% 398.90 =B1 1% slabinfo.kmalloc-256.num_= slabs 355.80 =B1 0% +2796.0% 10303 =B1 1% slabinfo.kmalloc-4096.act= ive_objs 55.00 =B1 1% +8795.8% 4892 =B1 3% slabinfo.kmalloc-4096.act= ive_slabs 378.60 =B1 0% +2639.0% 10369 =B1 1% slabinfo.kmalloc-4096.num= _objs 55.00 =B1 1% +8795.8% 4892 =B1 3% slabinfo.kmalloc-4096.num= _slabs 2929 =B1 11% +1926.0% 59360 =B1 5% proc-vmstat.allocstall 160.70 =B1 28% +461.8% 902.80 =B1 39% proc-vmstat.compact_isola= ted 116.60 =B1 21% +1575.8% 1954 =B1124% proc-vmstat.compact_migra= te_scanned 1657 =B1 10% +10214.9% 170917 =B1 14% proc-vmstat.kswapd_high_w= mark_hit_quickly 14489 =B1 3% +974.7% 155724 =B1 12% proc-vmstat.kswapd_low_wm= ark_hit_quickly 16393 =B1 0% +76.3% 28901 =B1 0% proc-vmstat.nr_free_pages 17297 =B1 0% +46.4% 25331 =B1 2% proc-vmstat.nr_slab_recla= imable 19818 =B1 0% +53.9% 30499 =B1 0% proc-vmstat.nr_slab_unrec= laimable 16253363 =B1 0% +21.1% 19685684 =B1 0% proc-vmstat.numa_hit 16253363 =B1 0% +21.1% 19685684 =B1 0% proc-vmstat.numa_local 16974 =B1 2% +1830.1% 327619 =B1 13% proc-vmstat.pageoutrun 16298906 =B1 0% +44.0% 23466530 =B1 0% proc-vmstat.pgalloc_dma32 15711596 =B1 0% +45.8% 22903686 =B1 0% proc-vmstat.pgfree 480139 =B1 8% +1593.6% 8131796 =B1 5% proc-vmstat.pgscan_direct= _dma32 14970914 =B1 0% -51.0% 7341759 =B1 5% proc-vmstat.pgscan_kswapd= _dma32 396381 =B1 11% +1928.7% 8041357 =B1 5% proc-vmstat.pgsteal_direc= t_dma32 14805624 =B1 0% -51.4% 7188819 =B1 5% proc-vmstat.pgsteal_kswap= d_dma32 207014 =B1 0% +6368.5% 13390822 =B1 1% proc-vmstat.slabs_scanned 0.00 =B1 -1% +Inf% 19563 =B1 50% latency_stats.avg.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_data_page.[f2fs].do_write_da= ta_page.[f2fs].f2fs_write_data_page.[f2fs].__f2fs_writepage.[f2fs].f2fs_wri= te_cache_pages.[f2fs].f2fs_write_data_pages.[f2fs].do_writepages.__filemap_= fdatawrite_range.filemap_write_and_wait_range.f2fs_sync_file.[f2fs] 0.00 =B1 -1% +Inf% 31033 =B1 94% latency_stats.avg.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_node_page.[f2fs].f2fs_write_= node_page.[f2fs].sync_node_pages.[f2fs].f2fs_sync_file.[f2fs].vfs_fsync_ran= ge.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath 43514 =B1179% -24.3% 32919 =B1 42% latency_stats.avg.call_rw= sem_down_write_failed.block_operations.[f2fs].write_checkpoint.[f2fs].f2fs_= sync_fs.[f2fs].f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.ent= ry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 39044 =B1 40% latency_stats.avg.call_rw= sem_down_write_failed.f2fs_submit_merged_bio.[f2fs].f2fs_write_data_pages.[= f2fs].do_writepages.__filemap_fdatawrite_range.filemap_write_and_wait_range= .f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_= fastpath 9117306 =B1127% -99.9% 10078 =B1263% latency_stats.avg.nfs_wai= t_on_request.nfs_updatepage.nfs_write_end.generic_perform_write.__generic_f= ile_write_iter.generic_file_write_iter.nfs_file_write.__vfs_write.vfs_write= .SyS_write.entry_SYSCALL_64_fastpath 33.75 =B1173% +1.9e+05% 62857 =B1114% latency_stats.avg.pipe_wr= ite.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 78722 =B1 14% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_kmem_pages_node.copy_process._do_fork.SyS_clone 0.00 =B1 -1% +Inf% 73283 =B1 1% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_wri= te_begin 0.00 =B1 -1% +Inf% 84609 =B1 12% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_meta_page.[f2f= s] 0.00 =B1 -1% +Inf% 75164 =B1 12% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.new_node_page.[f2fs] 0.00 =B1 -1% +Inf% 85332 =B1 1% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.new_slab.___slab_alloc.__slab_alloc 0.00 =B1 -1% +Inf% 65254 =B1 66% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.pte_alloc_one.__pte_alloc.handle_mm_fault 0.00 =B1 -1% +Inf% 75091 =B1 35% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.handle_mm_fault.__do_page_fault.do_page_fault 0.00 =B1 -1% +Inf% 64635 =B1 50% latency_stats.avg.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.wp_page_copy.do_wp_page.handle_mm_fault 57408 =B1 1% -93.3% 3824 =B1 10% latency_stats.avg.wait_on= _page_bit.__filemap_fdatawait_range.filemap_fdatawait_range.filemap_write_a= nd_wait_range.f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.entr= y_SYSCALL_64_fastpath 49060 =B1 2% +1508.8% 789275 =B1 10% latency_stats.hits.wait_o= n_page_bit.__filemap_fdatawait_range.filemap_fdatawait_range.filemap_write_= and_wait_range.f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.ent= ry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 129504 =B1 33% latency_stats.max.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_data_page.[f2fs].do_write_da= ta_page.[f2fs].f2fs_write_data_page.[f2fs].__f2fs_writepage.[f2fs].f2fs_wri= te_cache_pages.[f2fs].f2fs_write_data_pages.[f2fs].do_writepages.__filemap_= fdatawrite_range.filemap_write_and_wait_range.f2fs_sync_file.[f2fs] 0.00 =B1 -1% +Inf% 38782 =B1 81% latency_stats.max.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_node_page.[f2fs].f2fs_write_= node_page.[f2fs].sync_node_pages.[f2fs].f2fs_sync_file.[f2fs].vfs_fsync_ran= ge.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 86260 =B1 46% latency_stats.max.call_rw= sem_down_write_failed.f2fs_submit_merged_bio.[f2fs].f2fs_write_data_pages.[= f2fs].do_writepages.__filemap_fdatawrite_range.filemap_write_and_wait_range= .f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_= fastpath 13770 =B1 38% +2493.6% 357160 =B1 18% latency_stats.max.call_rw= sem_down_write_failed.f2fs_submit_page_mbio.[f2fs].do_write_page.[f2fs].wri= te_data_page.[f2fs].do_write_data_page.[f2fs].f2fs_write_data_page.[f2fs]._= _f2fs_writepage.[f2fs].f2fs_write_cache_pages.[f2fs].f2fs_write_data_pages.= [f2fs].do_writepages.__filemap_fdatawrite_range.filemap_write_and_wait_range 71537 =B1135% -90.4% 6880 =B1 17% latency_stats.max.call_rw= sem_down_write_failed.get_node_info.[f2fs].new_node_page.[f2fs].get_dnode_o= f_data.[f2fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs].f2fs_write_be= gin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_wri= te_iter.f2fs_file_write_iter.[f2fs].__vfs_write 15813502 =B1166% -99.9% 10078 =B1263% latency_stats.max.nfs_wai= t_on_request.nfs_updatepage.nfs_write_end.generic_perform_write.__generic_f= ile_write_iter.generic_file_write_iter.nfs_file_write.__vfs_write.vfs_write= .SyS_write.entry_SYSCALL_64_fastpath 33.75 =B1173% +2.2e+05% 73000 =B1113% latency_stats.max.pipe_wr= ite.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 97634 =B1 0% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_kmem_pages_node.copy_process._do_fork.SyS_clone 0.00 =B1 -1% +Inf% 99094 =B1 0% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_wri= te_begin 0.00 =B1 -1% +Inf% 97469 =B1 0% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_meta_page.[f2f= s] 0.00 =B1 -1% +Inf% 95084 =B1 5% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.new_node_page.[f2fs] 0.00 =B1 -1% +Inf% 98808 =B1 0% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.new_slab.___slab_alloc.__slab_alloc 0.00 =B1 -1% +Inf% 66744 =B1 65% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.pte_alloc_one.__pte_alloc.handle_mm_fault 0.00 =B1 -1% +Inf% 87727 =B1 33% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.handle_mm_fault.__do_page_fault.do_page_fault 0.00 =B1 -1% +Inf% 69586 =B1 50% latency_stats.max.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.wp_page_copy.do_wp_page.handle_mm_fault 20738812 =B1 27% -87.5% 2591032 =B1122% latency_stats.sum.alloc_n= id.[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.vfs_wr= ite.SyS_write 0.00 =B1 -1% +Inf% 423935 =B1 53% latency_stats.sum.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_data_page.[f2fs].do_write_da= ta_page.[f2fs].f2fs_write_data_page.[f2fs].__f2fs_writepage.[f2fs].f2fs_wri= te_cache_pages.[f2fs].f2fs_write_data_pages.[f2fs].do_writepages.__filemap_= fdatawrite_range.filemap_write_and_wait_range.f2fs_sync_file.[f2fs] 0.00 =B1 -1% +Inf% 51307 =B1 98% latency_stats.sum.allocat= e_data_block.[f2fs].do_write_page.[f2fs].write_node_page.[f2fs].f2fs_write_= node_page.[f2fs].sync_node_pages.[f2fs].f2fs_sync_file.[f2fs].vfs_fsync_ran= ge.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath 1.391e+08 =B1 38% +329.4% 5.974e+08 =B1 19% latency_stats.sum.balance= _dirty_pages.balance_dirty_pages_ratelimited.generic_perform_write.__generi= c_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs= _write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 188844 =B1 44% latency_stats.sum.call_rw= sem_down_write_failed.f2fs_submit_merged_bio.[f2fs].f2fs_write_data_pages.[= f2fs].do_writepages.__filemap_fdatawrite_range.filemap_write_and_wait_range= .f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_= fastpath 13770 =B1 38% +4.1e+05% 56903822 =B1 3% latency_stats.sum.call_rw= sem_down_write_failed.f2fs_submit_page_mbio.[f2fs].do_write_page.[f2fs].wri= te_data_page.[f2fs].do_write_data_page.[f2fs].f2fs_write_data_page.[f2fs]._= _f2fs_writepage.[f2fs].f2fs_write_cache_pages.[f2fs].f2fs_write_data_pages.= [f2fs].do_writepages.__filemap_fdatawrite_range.filemap_write_and_wait_range 0.00 =B1 -1% +Inf% 190702 =B1103% latency_stats.sum.call_rw= sem_down_write_failed.get_node_info.[f2fs].read_node_page.[f2fs].__get_node= _page.[f2fs].get_node_page.[f2fs].get_dnode_of_data.[f2fs].get_read_data_pa= ge.[f2fs].find_data_page.[f2fs].f2fs_find_entry.[f2fs].f2fs_lookup.[f2fs].l= ookup_real.path_openat 33143824 =B1 9% -84.9% 5019833 =B1 18% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].f2fs_submit_merged_bio.[f2fs].sync_node_pages.[f2fs].f2fs_sync_file.[f2f= s].vfs_fsync_range.do_fsync.SyS_fsync.entry_SYSCALL_64_fastpath 2913424 =B1 31% -71.7% 823962 =B1 30% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.__submit_merged_bio.[f2f= s].f2fs_submit_page_mbio.[f2fs].do_write_page.[f2fs].write_node_page.[f2fs]= .f2fs_write_node_page.[f2fs].sync_node_pages.[f2fs].f2fs_sync_file.[f2fs].v= fs_fsync_range 356283 =B1145% -54.1% 163527 =B1 96% latency_stats.sum.get_req= uest.blk_queue_bio.generic_make_request.submit_bio.submit_bio_wait.f2fs_iss= ue_flush.[f2fs].f2fs_sync_file.[f2fs].vfs_fsync_range.do_fsync.SyS_fsync.en= try_SYSCALL_64_fastpath 20099124 =B1162% -99.9% 10078 =B1263% latency_stats.sum.nfs_wai= t_on_request.nfs_updatepage.nfs_write_end.generic_perform_write.__generic_f= ile_write_iter.generic_file_write_iter.nfs_file_write.__vfs_write.vfs_write= .SyS_write.entry_SYSCALL_64_fastpath 33.75 =B1173% +2.2e+05% 73005 =B1113% latency_stats.sum.pipe_wr= ite.__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath 0.00 =B1 -1% +Inf% 615502 =B1 53% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_kmem_pages_node.copy_process._do_fork.SyS_clone 0.00 =B1 -1% +Inf% 98280568 =B1 12% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_cache_page_wri= te_begin 0.00 =B1 -1% +Inf% 301619 =B1 56% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.grab_meta_page.[f2f= s] 0.00 =B1 -1% +Inf% 481793 =B1 63% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.__page_cache_alloc.pagecache_get_page.new_node_page.[f2fs] 0.00 =B1 -1% +Inf% 26057234 =B1 5% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.new_slab.___slab_alloc.__slab_alloc 0.00 =B1 -1% +Inf% 101284 =B1 93% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_current.pte_alloc_one.__pte_alloc.handle_mm_fault 0.00 =B1 -1% +Inf% 333615 =B1 52% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.handle_mm_fault.__do_page_fault.do_page_fault 0.00 =B1 -1% +Inf% 138162 =B1 93% latency_stats.sum.wait_if= f_congested.shrink_inactive_list.shrink_zone_memcg.shrink_zone.do_try_to_fr= ee_pages.try_to_free_pages.__alloc_pages_slowpath.__alloc_pages_nodemask.al= loc_pages_vma.wp_page_copy.do_wp_page.handle_mm_fault 13154 =B1 1% +23.4% 16233 =B1 6% sched_debug.cfs_rq:/.exec= _clock.0 8553 =B1 0% +54.7% 13230 =B1 6% sched_debug.cfs_rq:/.exec= _clock.1 8198 =B1 1% +51.5% 12425 =B1 1% sched_debug.cfs_rq:/.exec= _clock.2 8134 =B1 1% +51.6% 12333 =B1 1% sched_debug.cfs_rq:/.exec= _clock.3 6757 =B1 1% +23.1% 8318 =B1 2% sched_debug.cfs_rq:/.exec= _clock.4 6611 =B1 1% +28.2% 8477 =B1 2% sched_debug.cfs_rq:/.exec= _clock.5 6746 =B1 2% +23.9% 8357 =B1 2% sched_debug.cfs_rq:/.exec= _clock.6 6753 =B1 2% +24.8% 8425 =B1 1% sched_debug.cfs_rq:/.exec= _clock.7 8113 =B1 0% +35.3% 10975 =B1 1% sched_debug.cfs_rq:/.exec= _clock.avg 13154 =B1 1% +24.5% 16373 =B1 4% sched_debug.cfs_rq:/.exec= _clock.max 6542 =B1 1% +24.7% 8158 =B1 1% sched_debug.cfs_rq:/.exec= _clock.min 2058 =B1 4% +41.6% 2913 =B1 5% sched_debug.cfs_rq:/.exec= _clock.stddev 72862 =B1 1% +11.4% 81181 =B1 3% sched_debug.cfs_rq:/.min_= vruntime.5 5374 =B1 3% -28.0% 3867 =B1 16% sched_debug.cfs_rq:/.min_= vruntime.stddev -15402 =B1 -7% -52.8% -7264 =B1-35% sched_debug.cfs_rq:/.spre= ad0.4 -16718 =B1 -6% -61.4% -6457 =B1-62% sched_debug.cfs_rq:/.spre= ad0.5 -15098 =B1 -7% -63.1% -5565 =B1-67% sched_debug.cfs_rq:/.spre= ad0.7 -11694 =B1 -4% -50.9% -5743 =B1-55% sched_debug.cfs_rq:/.spre= ad0.avg -17636 =B1 -4% -34.4% -11575 =B1-32% sched_debug.cfs_rq:/.spre= ad0.min 5375 =B1 3% -28.0% 3867 =B1 16% sched_debug.cfs_rq:/.spre= ad0.stddev 676391 =B1 8% -47.7% 353495 =B1 32% sched_debug.cpu.avg_idle.= min 108056 =B1 15% +92.1% 207595 =B1 16% sched_debug.cpu.avg_idle.= stddev 45103 =B1 2% +21.1% 54620 =B1 3% sched_debug.cpu.nr_load_u= pdates.0 18846 =B1 4% +70.1% 32053 =B1 4% sched_debug.cpu.nr_load_u= pdates.1 17706 =B1 5% +52.2% 26944 =B1 3% sched_debug.cpu.nr_load_u= pdates.2 17047 =B1 2% +56.1% 26602 =B1 3% sched_debug.cpu.nr_load_u= pdates.3 10781 =B1 2% +25.4% 13521 =B1 2% sched_debug.cpu.nr_load_u= pdates.4 11231 =B1 2% +25.5% 14091 =B1 3% sched_debug.cpu.nr_load_u= pdates.5 10556 =B1 1% +26.0% 13300 =B1 2% sched_debug.cpu.nr_load_u= pdates.6 10601 =B1 2% +27.7% 13541 =B1 3% sched_debug.cpu.nr_load_u= pdates.7 17734 =B1 1% +37.2% 24335 =B1 1% sched_debug.cpu.nr_load_u= pdates.avg 45103 =B1 2% +21.2% 54662 =B1 3% sched_debug.cpu.nr_load_u= pdates.max 10419 =B1 1% +26.4% 13166 =B1 1% sched_debug.cpu.nr_load_u= pdates.min 10889 =B1 3% +24.3% 13541 =B1 3% sched_debug.cpu.nr_load_u= pdates.stddev 230386 =B1 11% +42.9% 329109 =B1 8% sched_debug.cpu.nr_switch= es.0 202377 =B1 8% +251.4% 711088 =B1 4% sched_debug.cpu.nr_switch= es.1 171137 =B1 19% +180.6% 480135 =B1 8% sched_debug.cpu.nr_switch= es.2 203086 =B1 18% +117.9% 442482 =B1 6% sched_debug.cpu.nr_switch= es.3 83980 =B1 6% +109.3% 175809 =B1 14% sched_debug.cpu.nr_switch= es.4 89866 =B1 11% +75.8% 158005 =B1 7% sched_debug.cpu.nr_switch= es.5 83814 =B1 10% +88.5% 158008 =B1 10% sched_debug.cpu.nr_switch= es.6 85831 =B1 14% +78.4% 153106 =B1 13% sched_debug.cpu.nr_switch= es.7 143810 =B1 1% +126.7% 325968 =B1 3% sched_debug.cpu.nr_switch= es.avg 250243 =B1 5% +184.3% 711514 =B1 4% sched_debug.cpu.nr_switch= es.max 76332 =B1 3% +87.6% 143189 =B1 8% sched_debug.cpu.nr_switch= es.min 65017 =B1 6% +198.8% 194260 =B1 5% sched_debug.cpu.nr_switch= es.stddev 203.80 =B1 36% +113.9% 436.00 =B1 9% sched_debug.cpu.nr_uninte= rruptible.4 271442 =B1 9% +36.5% 370389 =B1 7% sched_debug.cpu.sched_cou= nt.0 202559 =B1 8% +251.6% 712283 =B1 4% sched_debug.cpu.sched_cou= nt.1 171330 =B1 19% +180.8% 481155 =B1 8% sched_debug.cpu.sched_cou= nt.2 203293 =B1 18% +118.1% 443428 =B1 6% sched_debug.cpu.sched_cou= nt.3 84236 =B1 6% +110.5% 177352 =B1 14% sched_debug.cpu.sched_cou= nt.4 90110 =B1 11% +77.1% 159606 =B1 7% sched_debug.cpu.sched_cou= nt.5 84044 =B1 10% +89.9% 159621 =B1 10% sched_debug.cpu.sched_cou= nt.6 86056 =B1 14% +79.6% 154524 =B1 13% sched_debug.cpu.sched_cou= nt.7 149134 =B1 1% +122.8% 332295 =B1 3% sched_debug.cpu.sched_cou= nt.avg 277382 =B1 7% +158.6% 717324 =B1 4% sched_debug.cpu.sched_cou= nt.max 76562 =B1 3% +89.1% 144747 =B1 8% sched_debug.cpu.sched_cou= nt.min 73405 =B1 6% +167.7% 196494 =B1 5% sched_debug.cpu.sched_cou= nt.stddev 93022 =B1 14% +46.7% 136420 =B1 10% sched_debug.cpu.sched_goi= dle.0 80762 =B1 10% +310.6% 331612 =B1 4% sched_debug.cpu.sched_goi= dle.1 65323 =B1 24% +230.1% 215622 =B1 9% sched_debug.cpu.sched_goi= dle.2 81365 =B1 22% +142.9% 197613 =B1 7% sched_debug.cpu.sched_goi= dle.3 24975 =B1 10% +175.0% 68669 =B1 17% sched_debug.cpu.sched_goi= dle.4 28091 =B1 18% +113.2% 59878 =B1 9% sched_debug.cpu.sched_goi= dle.5 25071 =B1 17% +139.1% 59944 =B1 12% sched_debug.cpu.sched_goi= dle.6 25926 =B1 22% +122.1% 57579 =B1 17% sched_debug.cpu.sched_goi= dle.7 53067 =B1 1% +165.5% 140918 =B1 4% sched_debug.cpu.sched_goi= dle.avg 103919 =B1 6% +219.2% 331734 =B1 4% sched_debug.cpu.sched_goi= dle.max 21303 =B1 5% +146.7% 52553 =B1 10% sched_debug.cpu.sched_goi= dle.min 30666 =B1 6% +209.8% 95012 =B1 5% sched_debug.cpu.sched_goi= dle.stddev 114436 =B1 5% +504.9% 692179 =B1 7% sched_debug.cpu.ttwu_coun= t.0 85402 =B1 9% +51.2% 129168 =B1 8% sched_debug.cpu.ttwu_coun= t.1 97257 =B1 16% +34.8% 131088 =B1 10% sched_debug.cpu.ttwu_coun= t.2 77150 =B1 10% +62.7% 125500 =B1 8% sched_debug.cpu.ttwu_coun= t.3 87047 =B1 1% +107.1% 180272 =B1 3% sched_debug.cpu.ttwu_coun= t.avg 125384 =B1 6% +452.1% 692194 =B1 7% sched_debug.cpu.ttwu_coun= t.max 57245 =B1 8% +22.4% 70061 =B1 8% sched_debug.cpu.ttwu_coun= t.min 22286 =B1 16% +775.5% 195117 =B1 8% sched_debug.cpu.ttwu_coun= t.stddev 65970 =B1 1% +25.1% 82512 =B1 3% sched_debug.cpu.ttwu_loca= l.0 36267 =B1 2% +19.0% 43155 =B1 6% sched_debug.cpu.ttwu_loca= l.1 36396 =B1 3% +17.8% 42878 =B1 8% sched_debug.cpu.ttwu_loca= l.2 36182 =B1 3% +15.9% 41920 =B1 5% sched_debug.cpu.ttwu_loca= l.3 34843 =B1 0% +14.8% 39990 =B1 3% sched_debug.cpu.ttwu_loca= l.avg 65970 =B1 1% +25.1% 82533 =B1 3% sched_debug.cpu.ttwu_loca= l.max 12737 =B1 2% +38.6% 17657 =B1 4% sched_debug.cpu.ttwu_loca= l.stddev nhm4: Nehalem Memory: 4G fsmark.time.system_time 120 ++-------------------------------------------------------------------= -+ | O = | 115 ++ OOOO O O O = | | O O OOO O O O = | | OO OO OO OO O O O O O O = | 110 +OO O O OO O O O O O = | O O O O = | 105 ++ = | | * = | 100 ++ :: *. * = | |**.*: **.** **. ** * ** .* * * **.** : ** * * *. = *| * * * * * * *** + * * + * : ** : :.* ***.* ** *= * 95 ++ * * * * +: * = | | * = | 90 ++-------------------------------------------------------------------= -+ fsmark.time.voluntary_context_switches 3e+06 ++---------------------------------------------------------------= -+ |O O O = | | O O OO O O O = | 2.5e+06 O+O OO O OO O O O O OO O O = | | O O O O OO O OO O OOO O O = | | O O O O O = | 2e+06 ++ = | | = | 1.5e+06 ++ = | | = | | = | 1e+06 ++ = | ****.*******.********.*******.*******.*******.********.*******.**= ** | = | 500000 ++---------------------------------------------------------------= -+ 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: default-watchdogs: oom-killer: watchdog: commit: 974b5afbf16ecd3e01cefd5d52e3090b6d967693 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: fsyncBeforeClose nr_directories: 16d nr_files_per_directory: 256fpd queue: bisect testbox: nhm4 tbox_group: nhm4 kconfig: x86_64-rhel enqueue_time: 2016-02-10 15:11:15.543683635 +08:00 compiler: gcc-4.9 rootfs: debian-x86_64-2015-02-07.cgz id: f4fa0b2b0d60f3cbc15108e26ade977e01dedf0a user: lkp head_commit: c06a2a7722d2e55368aabf0ca1ed44092a57a9ed base_commit: 388f7b1d6e8ca06762e2454d28d6c3c55ad0fe95 branch: linux-next/master result_root: "/result/fsmark/1x-32t-1HDD-f2fs-16MB-60G-fsyncBeforeClose-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/974b5afbf16ecd3e01cefd5d52e3090b6d967693/0" job_file: "/lkp/scheduled/nhm4/bisect_fsmark-1x-32t-1HDD-f2fs-16MB-60G-fsyncBeforeClose-16d-256fpd-debian-x86_64-2015-02-07.cgz-x86_64-rhel-974b5afbf16ecd3e01cefd5d52e3090b6d967693-20160210-69915-wscxbo-0.yaml" max_uptime: 1636.8999999999999 initrd: "/osimage/debian/debian-x86_64-2015-02-07.cgz" bootloader_append: - root=/dev/ram0 - user=lkp - job=/lkp/scheduled/nhm4/bisect_fsmark-1x-32t-1HDD-f2fs-16MB-60G-fsyncBeforeClose-16d-256fpd-debian-x86_64-2015-02-07.cgz-x86_64-rhel-974b5afbf16ecd3e01cefd5d52e3090b6d967693-20160210-69915-wscxbo-0.yaml - ARCH=x86_64 - kconfig=x86_64-rhel - branch=linux-next/master - commit=974b5afbf16ecd3e01cefd5d52e3090b6d967693 - BOOT_IMAGE=/pkg/linux/x86_64-rhel/gcc-4.9/974b5afbf16ecd3e01cefd5d52e3090b6d967693/vmlinuz-4.5.0-rc2-00261-g974b5af - max_uptime=1636 - RESULT_ROOT=/result/fsmark/1x-32t-1HDD-f2fs-16MB-60G-fsyncBeforeClose-16d-256fpd/nhm4/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/974b5afbf16ecd3e01cefd5d52e3090b6d967693/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/974b5afbf16ecd3e01cefd5d52e3090b6d967693/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/974b5afbf16ecd3e01cefd5d52e3090b6d967693/linux-headers.cgz" repeat_to: 5 kernel: "/pkg/linux/x86_64-rhel/gcc-4.9/974b5afbf16ecd3e01cefd5d52e3090b6d967693/vmlinuz-4.5.0-rc2-00261-g974b5af" dequeue_time: 2016-02-10 16:31:50.889688281 +08:00 job_state: finished loadavg: 32.16 26.33 13.46 1/156 7259 start_time: '1455093140' end_time: '1455093636' version: "/lkp/lkp/.src-20160210-100108" --=-=-= Content-Type: application/x-sh Content-Disposition: attachment; filename=reproduce.sh Content-Transfer-Encoding: base64 MjAxNi0wMi0xMCAxNjozMjoxNiBta2ZzIC10IGYyZnMgL2Rldi9zZGExCjIwMTYtMDItMTAgMTY6 MzI6MTggbW91bnQgLXQgZjJmcyAvZGV2L3NkYTEgL2ZzL3NkYTEKMjAxNi0wMi0xMCAxNjozMjoy MCAuL2ZzX21hcmsgLWQgL2ZzL3NkYTEvMSAtZCAvZnMvc2RhMS8yIC1kIC9mcy9zZGExLzMgLWQg L2ZzL3NkYTEvNCAtZCAvZnMvc2RhMS81IC1kIC9mcy9zZGExLzYgLWQgL2ZzL3NkYTEvNyAtZCAv ZnMvc2RhMS84IC1kIC9mcy9zZGExLzkgLWQgL2ZzL3NkYTEvMTAgLWQgL2ZzL3NkYTEvMTEgLWQg L2ZzL3NkYTEvMTIgLWQgL2ZzL3NkYTEvMTMgLWQgL2ZzL3NkYTEvMTQgLWQgL2ZzL3NkYTEvMTUg LWQgL2ZzL3NkYTEvMTYgLWQgL2ZzL3NkYTEvMTcgLWQgL2ZzL3NkYTEvMTggLWQgL2ZzL3NkYTEv MTkgLWQgL2ZzL3NkYTEvMjAgLWQgL2ZzL3NkYTEvMjEgLWQgL2ZzL3NkYTEvMjIgLWQgL2ZzL3Nk YTEvMjMgLWQgL2ZzL3NkYTEvMjQgLWQgL2ZzL3NkYTEvMjUgLWQgL2ZzL3NkYTEvMjYgLWQgL2Zz L3NkYTEvMjcgLWQgL2ZzL3NkYTEvMjggLWQgL2ZzL3NkYTEvMjkgLWQgL2ZzL3NkYTEvMzAgLWQg L2ZzL3NkYTEvMzEgLWQgL2ZzL3NkYTEvMzIgLUQgMTYgLU4gMjU2IC1uIDEyMCAtTCAxIC1TIDEg LXMgMTY3NzcyMTYK --=-=-=--