Skip to contentSkip to conversation

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

lkp Chao Yu 1 participant 1 message Jan 14, 2016

lore
Share & tools
lore

Chao Yu

author
#0 lore raw

Hi,

Quoted 48 lines

-----Original Message-----
From: kernel test robot [mailto:ying.huang(a)linux.intel.com]
Sent: Thursday, January 14, 2016 10:53 AM
To: Jaegeuk Kim
Cc: lkp(a)01.org; 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%
Quoted 9 lines

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,

Quoted 43 lines

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