On Fri, Jan 11, 2019 at 11:10 AM Tetsuo Handa
<penguin-kernel@xxxxxxxxxxxxxxxxxxx> wrote:
>
> When something let __find_get_block_slow() hit all_mapped path, it calls
> printk() for 100+ times per a second. But there is no need to print same
> message with such high frequency; it is just asking for stall warning, or
> at least bloating log files.
>
> [ 399.866302][T15342] __find_get_block_slow() failed. block=1, b_blocknr=8
> [ 399.873324][T15342] b_state=0x00000029, b_size=512
> [ 399.878403][T15342] device loop0 blocksize: 4096
> [ 399.883296][T15342] __find_get_block_slow() failed. block=1, b_blocknr=8
> [ 399.890400][T15342] b_state=0x00000029, b_size=512
> [ 399.895595][T15342] device loop0 blocksize: 4096
> [ 399.900556][T15342] __find_get_block_slow() failed. block=1, b_blocknr=8
> [ 399.907471][T15342] b_state=0x00000029, b_size=512
> [ 399.912506][T15342] device loop0 blocksize: 4096
>
> This patch reduces frequency to approximately once per a second, in
> addition to concatenating three lines into one. This patch uses plain
> time_in_range() than __ratelimit(), for there is no need to allocate
> space for debug objects in ratelimit_state.lock field.
>
> [ 399.866302][T15342] __find_get_block_slow() failed. block=1, b_blocknr=8, b_state=0x00000029, b_size=512, device loop0 blocksize: 4096
>
> Signed-off-by: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
> ---
> fs/buffer.c | 17 ++++++++---------
> 1 file changed, 8 insertions(+), 9 deletions(-)
>
> diff --git a/fs/buffer.c b/fs/buffer.c
> index 52d024b..3fc9167 100644
> --- a/fs/buffer.c
> +++ b/fs/buffer.c
> @@ -200,6 +200,7 @@ void end_buffer_write_sync(struct buffer_head *bh, int uptodate)
> struct buffer_head *head;
> struct page *page;
> int all_mapped = 1;
> + static unsigned long last;
/\/\/\/\/\/\
We will have to re-fix this when we start testing with KTSAN, data
race detector.
> index = block >> (PAGE_SHIFT - bd_inode->i_blkbits);
> page = find_get_page_flags(bd_mapping, index, FGP_ACCESSED);
> @@ -227,15 +228,13 @@ void end_buffer_write_sync(struct buffer_head *bh, int uptodate)
> * file io on the block device and getblk. It gets dealt with
> * elsewhere, don't buffer_error if we had some unmapped buffers
> */
> - if (all_mapped) {
> - printk("__find_get_block_slow() failed. "
> - "block=%llu, b_blocknr=%llu\n",
> - (unsigned long long)block,
> - (unsigned long long)bh->b_blocknr);
> - printk("b_state=0x%08lx, b_size=%zu\n",
> - bh->b_state, bh->b_size);
> - printk("device %pg blocksize: %d\n", bdev,
> - 1 << bd_inode->i_blkbits);
> + if (all_mapped && !time_in_range(jiffies, last, last + HZ)) {
> + printk("__find_get_block_slow() failed. block=%llu, b_blocknr=%llu, b_state=0x%08lx, b_size=%zu, device %pg blocksize: %d\n",
> + (unsigned long long)block,
> + (unsigned long long)bh->b_blocknr,
> + bh->b_state, bh->b_size, bdev,
> + 1 << bd_inode->i_blkbits);
> + last = jiffies;
> }
> out_unlock:
> spin_unlock(&bd_mapping->private_lock);
> --
> 1.8.3.1
