Re: [PATCH] fs: ratelimit __find_get_block_slow() failure message.

[Jan Kara <jack@suse.cz>]

On Fri 11-01-19 19:10:33, Tetsuo Handa 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@I-love.SAKURA.ne.jp>

I agree with collapsing three printks into one. I just don't think that
those couple bytes saved do warrant not using printk_ratelimited(). Those
bytes are not worth people's time looking into the code and trying to
understand why you did that special thing (let alone if they start poking
into possibility of data races like Dmitry pointed out).

								Honza

> ---
>  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;
>  
>  	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
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR