[PATCH] kernel/hung_task.c: Use continuously blocked time when reporting.

[PATCH] kernel/hung_task.c: Use continuously blocked time when reporting.

[Tetsuo Handa]

Since commit a2e514453861dd39 ("kernel/hung_task.c: allow to set checking
interval separately from timeout") added hung_task_check_interval_secs,
setting a value different from hung_task_timeout_secs

  echo 0 > /proc/sys/kernel/hung_task_panic
  echo 120 > /proc/sys/kernel/hung_task_timeout_secs
  echo 5 > /proc/sys/kernel/hung_task_check_interval_secs

causes confusing output as if the task was blocked for
hung_task_timeout_secs seconds from the previous report.

  [  399.395930] INFO: task kswapd0:75 blocked for more than 120 seconds.
  [  405.027637] INFO: task kswapd0:75 blocked for more than 120 seconds.
  [  410.659725] INFO: task kswapd0:75 blocked for more than 120 seconds.
  [  416.292860] INFO: task kswapd0:75 blocked for more than 120 seconds.
  [  421.932305] INFO: task kswapd0:75 blocked for more than 120 seconds.

Although we could update t->last_switch_time after sched_show_task(t) if
we want to report only every 120 seconds, reporting every 5 seconds might
not be very bad for monitoring after a problematic situation has started.
Thus, let's use continuously blocked time instead of updating previously
reported time.

  [  677.985011] INFO: task kswapd0:80 blocked for more than 122 seconds.
  [  693.856126] INFO: task kswapd0:80 blocked for more than 138 seconds.
  [  709.728075] INFO: task kswapd0:80 blocked for more than 154 seconds.
  [  725.600018] INFO: task kswapd0:80 blocked for more than 170 seconds.
  [  741.473133] INFO: task kswapd0:80 blocked for more than 186 seconds.

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 kernel/hung_task.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/hung_task.c b/kernel/hung_task.c
index 4a91916..6429139 100644
--- a/kernel/hung_task.c
+++ b/kernel/hung_task.c
@@ -126,7 +126,7 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
 		if (sysctl_hung_task_warnings > 0)
 			sysctl_hung_task_warnings--;
 		pr_err("INFO: task %s:%d blocked for more than %ld seconds.\n",
-			t->comm, t->pid, timeout);
+		       t->comm, t->pid, (jiffies - t->last_switch_time) / HZ);
 		pr_err("      %s %s %.*s\n",
 			print_tainted(), init_utsname()->release,
 			(int)strcspn(init_utsname()->version, " "),
-- 
1.8.3.1

Re: [PATCH] kernel/hung_task.c: Use continuously blocked time when reporting.

[Dmitry Vyukov]

On Tue, Feb 26, 2019 at 10:58 AM Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> Since commit a2e514453861dd39 ("kernel/hung_task.c: allow to set checking
> interval separately from timeout") added hung_task_check_interval_secs,
> setting a value different from hung_task_timeout_secs
>
>   echo 0 > /proc/sys/kernel/hung_task_panic
>   echo 120 > /proc/sys/kernel/hung_task_timeout_secs
>   echo 5 > /proc/sys/kernel/hung_task_check_interval_secs
>
> causes confusing output as if the task was blocked for
> hung_task_timeout_secs seconds from the previous report.
>
>   [  399.395930] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  405.027637] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  410.659725] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  416.292860] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  421.932305] INFO: task kswapd0:75 blocked for more than 120 seconds.
>
> Although we could update t->last_switch_time after sched_show_task(t) if
> we want to report only every 120 seconds, reporting every 5 seconds might
> not be very bad for monitoring after a problematic situation has started.
> Thus, let's use continuously blocked time instead of updating previously
> reported time.
>
>   [  677.985011] INFO: task kswapd0:80 blocked for more than 122 seconds.
>   [  693.856126] INFO: task kswapd0:80 blocked for more than 138 seconds.
>   [  709.728075] INFO: task kswapd0:80 blocked for more than 154 seconds.
>   [  725.600018] INFO: task kswapd0:80 blocked for more than 170 seconds.
>   [  741.473133] INFO: task kswapd0:80 blocked for more than 186 seconds.
>
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> ---
>  kernel/hung_task.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/kernel/hung_task.c b/kernel/hung_task.c
> index 4a91916..6429139 100644
> --- a/kernel/hung_task.c
> +++ b/kernel/hung_task.c
> @@ -126,7 +126,7 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
>                 if (sysctl_hung_task_warnings > 0)
>                         sysctl_hung_task_warnings--;
>                 pr_err("INFO: task %s:%d blocked for more than %ld seconds.\n",
> -                       t->comm, t->pid, timeout);
> +                      t->comm, t->pid, (jiffies - t->last_switch_time) / HZ);

Looks like an improvement to me.

Acked-by: Dmitry Vyukov <dvyukov@google.com>



>                 pr_err("      %s %s %.*s\n",
>                         print_tainted(), init_utsname()->release,
>                         (int)strcspn(init_utsname()->version, " "),
> --
> 1.8.3.1

Re: [PATCH] kernel/hung_task.c: Use continuously blocked time when reporting.

[Andrew Morton]

On Tue, 26 Feb 2019 18:58:03 +0900 Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> wrote:

> Since commit a2e514453861dd39 ("kernel/hung_task.c: allow to set checking
> interval separately from timeout") added hung_task_check_interval_secs,
> setting a value different from hung_task_timeout_secs
> 
>   echo 0 > /proc/sys/kernel/hung_task_panic
>   echo 120 > /proc/sys/kernel/hung_task_timeout_secs
>   echo 5 > /proc/sys/kernel/hung_task_check_interval_secs
> 
> causes confusing output as if the task was blocked for
> hung_task_timeout_secs seconds from the previous report.
> 
>   [  399.395930] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  405.027637] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  410.659725] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  416.292860] INFO: task kswapd0:75 blocked for more than 120 seconds.
>   [  421.932305] INFO: task kswapd0:75 blocked for more than 120 seconds.
> 
> Although we could update t->last_switch_time after sched_show_task(t) if
> we want to report only every 120 seconds, reporting every 5 seconds might
> not be very bad for monitoring after a problematic situation has started.
> Thus, let's use continuously blocked time instead of updating previously
> reported time.
> 
>   [  677.985011] INFO: task kswapd0:80 blocked for more than 122 seconds.
>   [  693.856126] INFO: task kswapd0:80 blocked for more than 138 seconds.
>   [  709.728075] INFO: task kswapd0:80 blocked for more than 154 seconds.
>   [  725.600018] INFO: task kswapd0:80 blocked for more than 170 seconds.
>   [  741.473133] INFO: task kswapd0:80 blocked for more than 186 seconds.

hm, maybe.

The user asked for a report if a task was blocked for more than 120
seconds, so the kernel is accurately reporting that this happened.  The
actual blockage time is presumably useful information, but that's a
different thing.

We could report both:

"blocked for 122 seconds which is more than 120 seconds"

But on the other hand, what is the point in telling the user how they
configured their own kernel?

I think I'll stop arguing with myself and apply the patch ;)