Re: [PATCH 2/4] writeback: name the bdi in the slow writeback report

[Jan Kara]

On Fri 06-11-26 04:26:32, Breno Leitao wrote:
> The slow writeback report names the waiting task and how long it has
> waited, but not what it is waiting on. On a machine with several
> filesystems there is no way to tell which device is slow.
> 
> Pass the bdi to wb_wait_for_completion() and print its name on a second
> line, together with the number of work items still outstanding. A sync
> issues one work item per cgroup wb with dirty inodes, so the count also
> shows whether a single cgroup is holding up the others.
> 
> wb_wait_for_completion() took the bdi until commit 5b9cce4c7eb0
> ("writeback: Generalize and expose wb_completion") made it usable for
> the memcg foreign flushes. memcg tracks those by bdi id only and passes
> NULL, which bdi_dev_name() prints as "(unknown)".
> 
> The first line does not change, so anything matching on it keeps
> working. A sync on a throttled null_blk device now reports:
> 
>   INFO: The task sync:180 has been waiting for writeback completion for more than 28 seconds.
>         bdi 252:0, work items left: 1
> 
> Signed-off-by: Breno Leitao <leitao@xxxxxxxxxx>

Dunno, I'd put everything on one line. Otherwise things can get interleaved
by other messages. Kernel messages are not really an ABI, we can change
them...

								Honza

> ---
>  fs/fs-writeback.c           | 20 +++++++++++++-------
>  include/linux/backing-dev.h |  3 ++-
>  mm/memcontrol.c             |  2 +-
>  3 files changed, 16 insertions(+), 9 deletions(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 01a00d7542b371..3dee9d65eaf721 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -196,16 +196,20 @@ static void wb_queue_work(struct bdi_writeback *wb,
>  	spin_unlock_irq(&wb->work_lock);
>  }
>  
> -static bool wb_wait_for_completion_cb(struct wb_completion *done)
> +static bool wb_wait_for_completion_cb(struct wb_completion *done,
> +				      struct backing_dev_info *bdi)
>  {
>  	unsigned long timeout = sysctl_hung_task_timeout_secs;
>  	unsigned long waited_secs = (jiffies - done->wait_start) / HZ;
>  
>  	done->progress_stamp = jiffies;
> -	if (timeout && (waited_secs > timeout))
> +	if (timeout && (waited_secs > timeout)) {
>  		pr_info("INFO: The task %s:%d has been waiting for writeback "
>  			"completion for more than %lu seconds.\n",
>  			current->comm, current->pid, waited_secs);
> +		pr_info("      bdi %s, work items left: %d\n",
> +			bdi_dev_name(bdi), atomic_read(&done->cnt));
> +	}
>  
>  	return !atomic_read(&done->cnt);
>  }
> @@ -213,6 +217,7 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
>  /**
>   * wb_wait_for_completion - wait for completion of bdi_writeback_works
>   * @done: target wb_completion
> + * @bdi: bdi work items were issued to, NULL for the memcg foreign flushes
>   *
>   * Wait for one or more work items issued to @bdi with their ->done field
>   * set to @done, which should have been initialized with
> @@ -220,11 +225,12 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
>   * are completed.  Work items which are waited upon aren't freed
>   * automatically on completion.
>   */
> -void wb_wait_for_completion(struct wb_completion *done)
> +void wb_wait_for_completion(struct wb_completion *done,
> +			    struct backing_dev_info *bdi)
>  {
>  	done->wait_start = jiffies;
>  	atomic_dec(&done->cnt);		/* put down the initial count */
> -	wait_event(*done->waitq, wb_wait_for_completion_cb(done));
> +	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
>  }
>  
>  #ifdef CONFIG_CGROUP_WRITEBACK
> @@ -1164,7 +1170,7 @@ static void bdi_split_work_to_wbs(struct backing_dev_info *bdi,
>  		last_wb = wb;
>  
>  		rcu_read_unlock();
> -		wb_wait_for_completion(&fallback_work_done);
> +		wb_wait_for_completion(&fallback_work_done, bdi);
>  		goto restart;
>  	}
>  	rcu_read_unlock();
> @@ -2972,7 +2978,7 @@ static void __writeback_inodes_sb_nr(struct super_block *sb, unsigned long nr,
>  	WARN_ON(!rwsem_is_locked(&sb->s_umount));
>  
>  	bdi_split_work_to_wbs(sb->s_bdi, &work, skip_if_busy);
> -	wb_wait_for_completion(&done);
> +	wb_wait_for_completion(&done, bdi);
>  }
>  
>  /**
> @@ -3069,7 +3075,7 @@ void sync_inodes_sb(struct super_block *sb)
>  	/* protect against inode wb switch, see inode_switch_wbs_work_fn() */
>  	bdi_down_write_wb_switch_rwsem(bdi);
>  	bdi_split_work_to_wbs(bdi, &work, false);
> -	wb_wait_for_completion(&done);
> +	wb_wait_for_completion(&done, bdi);
>  	bdi_up_write_wb_switch_rwsem(bdi);
>  
>  	wait_sb_inodes(sb);
> diff --git a/include/linux/backing-dev.h b/include/linux/backing-dev.h
> index c2284466e7aa66..808d939d2ca7f9 100644
> --- a/include/linux/backing-dev.h
> +++ b/include/linux/backing-dev.h
> @@ -39,7 +39,8 @@ struct backing_dev_info *bdi_alloc(int node_id);
>  void wb_start_background_writeback(struct bdi_writeback *wb);
>  void wb_workfn(struct work_struct *work);
>  
> -void wb_wait_for_completion(struct wb_completion *done);
> +void wb_wait_for_completion(struct wb_completion *done,
> +			    struct backing_dev_info *bdi);
>  
>  extern spinlock_t bdi_lock;
>  extern struct list_head bdi_list;
> diff --git a/mm/memcontrol.c b/mm/memcontrol.c
> index ac6c43ea8c5a6d..df462d279a655e 100644
> --- a/mm/memcontrol.c
> +++ b/mm/memcontrol.c
> @@ -4525,7 +4525,7 @@ static void mem_cgroup_css_free(struct cgroup_subsys_state *css)
>  
>  #ifdef CONFIG_CGROUP_WRITEBACK
>  	for (i = 0; i < MEMCG_CGWB_FRN_CNT; i++)
> -		wb_wait_for_completion(&memcg->cgwb_frn[i].done);
> +		wb_wait_for_completion(&memcg->cgwb_frn[i].done, NULL);
>  #endif
>  	if (cgroup_subsys_on_dfl(memory_cgrp_subsys) && !cgroup_memory_nosocket)
>  		static_branch_dec(&memcg_sockets_enabled_key);
> 
> -- 
> 2.53.0-Meta
> 
-- 
Jan Kara <jack@xxxxxxxx>
SUSE Labs, CR