RE: [lkp] [f2fs] b9d777b85f: No primary result change, +18023.3% latency_stats.sum.call_rwsem_down_read_failed.f2fs_write_begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_write.vfs_writ

[Chao Yu]

Hi,

> -----Original Message-----
> From: kernel test robot [mailto:ying.huang@xxxxxxxxxxxxxxx]
> Sent: Thursday, January 14, 2016 10:53 AM
> To: Jaegeuk Kim
> Cc: lkp@xxxxxx; LKML; Chao Yu
> Subject: [lkp] [f2fs] b9d777b85f: No primary result change, +18023.3%
> latency_stats.sum.call_rwsem_down_read_failed.f2fs_write_begin.[f2fs].generic_perform_writ
> e.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_writ
> e.vfs_write.Sy
> 
> FYI, we noticed the below changes on
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/jaegeuk/f2fs dev-test
> commit b9d777b85ff1ff79a1173190317b25bebc404ab4 ("f2fs: check inline_data flag at converting
> time")
> 
> 
> =========================================================================================
> compiler/disk/filesize/fs/iterations/kconfig/nr_directories/nr_files_per_directory/nr_thre
> ads/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-02-07.cgz/NoSync/n
> hm4/60G/fsmark
> 
> commit:
>   74fd8d9927ef08db30a85f131a124152aeba66c7
>   b9d777b85ff1ff79a1173190317b25bebc404ab4
> 
> 74fd8d9927ef08db b9d777b85ff1ff79a117319031
> ---------------- --------------------------
>          %stddev     %change         %stddev
>              \          |                \
>      10.00 ±  0%     -10.0%       9.00 ±  0%  fsmark.time.percent_of_cpu_this_job_got
>      10.00 ±  0%     -10.0%       9.00 ±  0%  time.percent_of_cpu_this_job_got
>       2.35 ±  0%      -3.7%       2.26 ±  0%  turbostat.%Busy
>      67.30 ±  0%      -4.5%      64.30 ±  0%  turbostat.Avg_MHz
>       2116 ±  1%     -98.7%      27.20 ±110%  proc-vmstat.kswapd_inodesteal
>     191431 ±  0%     +18.2%     226316 ±  0%  proc-vmstat.slabs_scanned
>      56566 ±  0%     +21.3%      68612 ±  0%  proc-vmstat.workingset_nodereclaim
>    1176917 ±  2%    -100.0%       0.00 ± -1%
> latency_stats.avg.call_rwsem_down_read_failed.f2fs_convert_inline_inode.[f2fs].f2fs_write_
> begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_
> file_write_iter.[f2fs].__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
>      62312 ± 55%   +1577.8%    1045503 ± 11%
> latency_stats.avg.call_rwsem_down_read_failed.f2fs_write_begin.[f2fs].generic_perform_writ
> e.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_writ
> e.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
>      11969 ±  8%    -100.0%       0.00 ± -1%
> latency_stats.hits.call_rwsem_down_read_failed.get_node_info.[f2fs].read_node_page.[f2fs].
> get_node_page.[f2fs].f2fs_convert_inline_inode.[f2fs].f2fs_write_begin.[f2fs].generic_perf
> orm_write.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__
> vfs_write.vfs_write
>    1773702 ±  7%    -100.0%       0.00 ± -1%
> latency_stats.max.call_rwsem_down_read_failed.f2fs_convert_inline_inode.[f2fs].f2fs_write_
> begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_
> file_write_iter.[f2fs].__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
>  3.041e+08 ±  2%    -100.0%       0.00 ± -1%

Thanks for your report!

Looks like sum of latency caused by f2fs_lock_op was transferred from
f2fs_convert_inline_inode into f2fs_write_begin.

f2fs_convert_inline_inode:
3.041e+08 ±  2%    -100.0%       0.00 ± -1%
f2fs_write_begin
1743538 ± 56%  +18023.3%   3.16e+08 ±  3%

Thanks,

> latency_stats.sum.call_rwsem_down_read_failed.f2fs_convert_inline_inode.[f2fs].f2fs_write_
> begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_file_write_iter.f2fs_
> file_write_iter.[f2fs].__vfs_write.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
>     163413 ±112%    +165.9%     434477 ±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_bloc
> k.[f2fs].f2fs_write_begin.[f2fs].generic_perform_write.__generic_file_write_iter.generic_f
> ile_write_iter.f2fs_file_write_iter.[f2fs].__vfs_write
>     788095 ±164%     -60.4%     312194 ±122%
> latency_stats.sum.call_rwsem_down_read_failed.f2fs_wait_on_page_writeback.[f2fs].f2fs_wait
> _on_page_writeback.[f2fs].update_inode.[f2fs].sync_inode_page.[f2fs].reserve_new_block.[f2
> fs].f2fs_reserve_block.[f2fs].f2fs_get_block.[f2fs].f2fs_write_begin.[f2fs].generic_perfor
> m_write.__generic_file_write_iter.generic_file_write_iter
>    1743538 ± 56%  +18023.3%   3.16e+08 ±  3%
> latency_stats.sum.call_rwsem_down_read_failed.f2fs_write_begin.[f2fs].generic_perform_writ
> e.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__vfs_writ
> e.vfs_write.SyS_write.entry_SYSCALL_64_fastpath
>    1677147 ±  9%    -100.0%       0.00 ± -1%
> latency_stats.sum.call_rwsem_down_read_failed.get_node_info.[f2fs].read_node_page.[f2fs].g
> et_node_page.[f2fs].f2fs_convert_inline_inode.[f2fs].f2fs_write_begin.[f2fs].generic_perfo
> rm_write.__generic_file_write_iter.generic_file_write_iter.f2fs_file_write_iter.[f2fs].__v
> fs_write.vfs_write
> 
> 
> 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