next-20090202: task kmemleak:763 blocked for more than 120 seconds.

next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Alexander Beregalov]

Hi

It seems it is blocked forever.

[ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
[ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
[ 1704.862460]  ffff88007d497e60 0000000000000046 ffff88007d497da0
ffff88007d6a4000
[ 1704.951037]  ffff88007d6a4000 0000000000004000 0000000000000002
ffff88007d6a4000
[ 1705.039609]  ffff88007d80a000 ffff88007d6a4398 0000000200000000
00000001000758b5
[ 1705.128202] Call Trace:
[ 1705.157383]  [<ffffffff806379f2>] ? _spin_unlock_irqrestore+0x42/0x80
[ 1705.234396]  [<ffffffff80634c86>] ? schedule_timeout+0x66/0xe0
[ 1705.304137]  [<ffffffff80634a43>] schedule+0x13/0x40
[ 1705.363483]  [<ffffffff80634c86>] schedule_timeout+0x66/0xe0
[ 1705.431145]  [<ffffffff8024c7c0>] ? process_timeout+0x0/0x10
[ 1705.498918]  [<ffffffff80634c81>] ? schedule_timeout+0x61/0xe0
[ 1705.568663]  [<ffffffff80634d19>] schedule_timeout_uninterruptible+0x19/0x20
[ 1705.652987]  [<ffffffff802c3830>] kmemleak_scan_thread+0x120/0x170
[ 1705.726889]  [<ffffffff802c3710>] ? kmemleak_scan_thread+0x0/0x170
[ 1705.800784]  [<ffffffff80258d66>] kthread+0x56/0x90
[ 1705.859088]  [<ffffffff8020ce9a>] child_rip+0xa/0x20
[ 1705.918441]  [<ffffffff80235489>] ? finish_task_switch+0x89/0x110
[ 1705.991303]  [<ffffffff80637986>] ? _spin_unlock_irq+0x36/0x60
[ 1706.061041]  [<ffffffff8020c880>] ? restore_args+0x0/0x30
[ 1706.125584]  [<ffffffff80258d10>] ? kthread+0x0/0x90
[ 1706.184917]  [<ffffffff8020ce90>] ? child_rip+0x0/0x20
[ 1706.246334] no locks held by kmemleak/763.

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Catalin Marinas]

Alexander Beregalov <a.beregalov@gmail.com> wrote:
> It seems it is blocked forever.

Scanning the full memory may take a lot of time, depending on the
amount of RAM and the number of objects allocated. It is not unlikely
to take more than 120 seconds on some loaded systems. However, it
should call schedule() periodically to let other tasks run. Is your
system unresponsive during this?

> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
[...]
> [ 1706.246334] no locks held by kmemleak/763.

It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
This happens when it calls schedule_timeout_uninterruptible() to sleep
between scans. It probably took more than 120 to scan the memory and
hence the report.

It doesn't look like a problem, only that the watchdog thread checks
for uninterruptible tasks. I can try to make it sleep with
TASK_INTERRUPTIBLE to avoid the message.

Thanks.

-- 
Catalin

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Frédéric Weisbecker]

2009/2/2 Catalin Marinas <catalin.marinas@arm.com>:
> Alexander Beregalov <a.beregalov@gmail.com> wrote:
>> It seems it is blocked forever.
>
> Scanning the full memory may take a lot of time, depending on the
> amount of RAM and the number of objects allocated. It is not unlikely
> to take more than 120 seconds on some loaded systems. However, it
> should call schedule() periodically to let other tasks run. Is your
> system unresponsive during this?
>
>> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
>> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> disables this message.
>> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
> [...]
>> [ 1706.246334] no locks held by kmemleak/763.
>
> It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
> This happens when it calls schedule_timeout_uninterruptible() to sleep
> between scans. It probably took more than 120 to scan the memory and
> hence the report.
>
> It doesn't look like a problem, only that the watchdog thread checks
> for uninterruptible tasks. I can try to make it sleep with
> TASK_INTERRUPTIBLE to avoid the message.
>
> Thanks.
>
> --
> Catalin
> --


Hi,

May be it would be better to make the softlockup detector hooking into
schedule_timeout()
(ie by using a tracepoint) to check if a thread chose to sleep more
than hung_task_timeout_secs
intentionally in a TASK_UNINTERRUPTIBLE state.

Fixing it into kmemleak would not solve the problem in other tasks
which do similar sleeps...

Mandeep, if you want I can try something? Or perhaps you prefer to do
it yourself. As you wish.

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Frédéric Weisbecker]

2009/2/2 Catalin Marinas <catalin.marinas@arm.com>:
> Alexander Beregalov <a.beregalov@gmail.com> wrote:
>> It seems it is blocked forever.
>
> Scanning the full memory may take a lot of time, depending on the
> amount of RAM and the number of objects allocated. It is not unlikely
> to take more than 120 seconds on some loaded systems. However, it
> should call schedule() periodically to let other tasks run. Is your
> system unresponsive during this?
>
>> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
>> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> disables this message.
>> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
> [...]
>> [ 1706.246334] no locks held by kmemleak/763.
>
> It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
> This happens when it calls schedule_timeout_uninterruptible() to sleep
> between scans. It probably took more than 120 to scan the memory and
> hence the report.
>
> It doesn't look like a problem, only that the watchdog thread checks
> for uninterruptible tasks. I can try to make it sleep with
> TASK_INTERRUPTIBLE to avoid the message.
>
> Thanks.
>
> --
> Catalin
> --


Hi,

May be it would be better to make the softlockup detector hooking into
schedule_timeout()
(ie by using a tracepoint) to check if a thread chose to sleep more
than hung_task_timeout_secs
intentionally in a TASK_UNINTERRUPTIBLE state.

Fixing it into kmemleak would not solve the problem in other tasks
which do similar sleeps...

Mandeep, if you agree I can try something? Or perhaps you prefer to do
it yourself. As you wish.

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Mandeep Singh Baines]

Frédéric Weisbecker (fweisbec@gmail.com) wrote:
> 2009/2/2 Catalin Marinas <catalin.marinas@arm.com>:
> > Alexander Beregalov <a.beregalov@gmail.com> wrote:
> >> It seems it is blocked forever.
> >
> > Scanning the full memory may take a lot of time, depending on the
> > amount of RAM and the number of objects allocated. It is not unlikely
> > to take more than 120 seconds on some loaded systems. However, it
> > should call schedule() periodically to let other tasks run. Is your
> > system unresponsive during this?
> >
> >> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
> >> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> >> disables this message.
> >> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
> > [...]
> >> [ 1706.246334] no locks held by kmemleak/763.
> >
> > It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
> > This happens when it calls schedule_timeout_uninterruptible() to sleep
> > between scans. It probably took more than 120 to scan the memory and
> > hence the report.
> >
> > It doesn't look like a problem, only that the watchdog thread checks
> > for uninterruptible tasks. I can try to make it sleep with
> > TASK_INTERRUPTIBLE to avoid the message.
> >
> > Thanks.
> >
> > --
> > Catalin
> > --
> 
> 
> Hi,
> 
> May be it would be better to make the softlockup detector hooking into
> schedule_timeout()
> (ie by using a tracepoint) to check if a thread chose to sleep more
> than hung_task_timeout_secs
> intentionally in a TASK_UNINTERRUPTIBLE state.
> 
> Fixing it into kmemleak would not solve the problem in other tasks
> which do similar sleeps...
> 

The hung_task timeout is now 480 seconds because of sys_sync:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=fb822db465bd9fd4208eef1af4490539b236c54e

But are there are really any other tasks which call
schedule_timeout_uninterruptibl() for with a timeout >480 seconds?

Right now kmemleak appears to be the only exception. (A quick grep didn't turn
anything up.) And it is trivial to change kmemleak to use INTERRUPTIBLE.
Might even be a nice feature. You could stop it faster that way.

I suspect cases where long UNINTERRUPTIBLE sleeps is the right solution are
extremely rare. Since kmemleak can be modified, maybe hold off on ignoring
schedule_timeout_uninterruptible(). Not exempting schedule_timeout_uninter*
reduces code sprawl and discourages long UNINTERRUPTIBLE sleeps.

> Mandeep, if you agree I can try something? Or perhaps you prefer to do
> it yourself. As you wish.

Nah, don't wait for me. If you have a useful patch, just send it;) I'm
actually not the maintainer of hung_task, mingo@elte.hu is, but I am more than
happy to review patches.

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Frederic Weisbecker]

On Mon, Feb 02, 2009 at 01:57:40PM -0800, Mandeep Singh Baines wrote:
> Frédéric Weisbecker (fweisbec@gmail.com) wrote:
> > 2009/2/2 Catalin Marinas <catalin.marinas@arm.com>:
> > > Alexander Beregalov <a.beregalov@gmail.com> wrote:
> > >> It seems it is blocked forever.
> > >
> > > Scanning the full memory may take a lot of time, depending on the
> > > amount of RAM and the number of objects allocated. It is not unlikely
> > > to take more than 120 seconds on some loaded systems. However, it
> > > should call schedule() periodically to let other tasks run. Is your
> > > system unresponsive during this?
> > >
> > >> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
> > >> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > >> disables this message.
> > >> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
> > > [...]
> > >> [ 1706.246334] no locks held by kmemleak/763.
> > >
> > > It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
> > > This happens when it calls schedule_timeout_uninterruptible() to sleep
> > > between scans. It probably took more than 120 to scan the memory and
> > > hence the report.
> > >
> > > It doesn't look like a problem, only that the watchdog thread checks
> > > for uninterruptible tasks. I can try to make it sleep with
> > > TASK_INTERRUPTIBLE to avoid the message.
> > >
> > > Thanks.
> > >
> > > --
> > > Catalin
> > > --
> > 
> > 
> > Hi,
> > 
> > May be it would be better to make the softlockup detector hooking into
> > schedule_timeout()
> > (ie by using a tracepoint) to check if a thread chose to sleep more
> > than hung_task_timeout_secs
> > intentionally in a TASK_UNINTERRUPTIBLE state.
> > 
> > Fixing it into kmemleak would not solve the problem in other tasks
> > which do similar sleeps...
> > 
> 
> The hung_task timeout is now 480 seconds because of sys_sync:
> 
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=fb822db465bd9fd4208eef1af4490539b236c54e


Oh ok.

 
> But are there are really any other tasks which call
> schedule_timeout_uninterruptibl() for with a timeout >480 seconds?


I doubt it, you're right :-)


> Right now kmemleak appears to be the only exception. (A quick grep didn't turn
> anything up.) And it is trivial to change kmemleak to use INTERRUPTIBLE.
> Might even be a nice feature. You could stop it faster that way.


Right. BTW, I wonder how it behaves in case of suspend to disk.
But changing the state to TASK_INTERRUPTIBLE wouldn't change it in this case since the
signals are only sent to userpace threads to freeze them.

Kernel threads try to freeze by themselves.

But for such very long schedule_timeout, will the hibernation wait for kmemleak
to wake up and then try_to_freeze() before suspend to disk?

Does kmemleak listen to power events to wake up itself in such case? Sorry
I didn't look at kmemleak sources...


> I suspect cases where long UNINTERRUPTIBLE sleeps is the right solution are
> extremely rare. Since kmemleak can be modified, maybe hold off on ignoring
> schedule_timeout_uninterruptible(). Not exempting schedule_timeout_uninter*
> reduces code sprawl and discourages long UNINTERRUPTIBLE sleeps.

Right.


> > Mandeep, if you agree I can try something? Or perhaps you prefer to do
> > it yourself. As you wish.
> 
> Nah, don't wait for me. If you have a useful patch, just send it;) I'm
> actually not the maintainer of hung_task, mingo@elte.hu is, but I am more than
> happy to review patches.


Thanks, but since the delay has been enlarged and such long sleeping threads should be rare,
it doesn't seem to required yet. And if it needs to be changed, false warning will be reported :-)

Thanks.

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Alexander Beregalov]

2009/2/2 Catalin Marinas <catalin.marinas@arm.com>:
> Alexander Beregalov <a.beregalov@gmail.com> wrote:
>> It seems it is blocked forever.
>
> Scanning the full memory may take a lot of time, depending on the
> amount of RAM and the number of objects allocated. It is not unlikely
> to take more than 120 seconds on some loaded systems. However, it
> should call schedule() periodically to let other tasks run. Is your
> system unresponsive during this?
No, it is responsible.
kmemleak proccess is not running all the time, but it is counted for
the loadavg value.
And it produceses lockdep message every 180 sec.
>
>> [ 1704.619898] INFO: task kmemleak:763 blocked for more than 120 seconds.
>> [ 1704.697951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> disables this message.
>> [ 1704.791613] kmemleak      D 0000000000000001  6008   763      2
> [...]
>> [ 1706.246334] no locks held by kmemleak/763.
>
> It looks like the kmemleak thread is in the TASK_UNINTERUPTIBLE state.
> This happens when it calls schedule_timeout_uninterruptible() to sleep
> between scans. It probably took more than 120 to scan the memory and
> hence the report.
>
> It doesn't look like a problem, only that the watchdog thread checks
> for uninterruptible tasks. I can try to make it sleep with
> TASK_INTERRUPTIBLE to avoid the message.
>
> Thanks.
>
> --
> Catalin
>

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Catalin Marinas]

On Mon, 2009-02-02 at 13:57 -0800, Mandeep Singh Baines wrote:
> The hung_task timeout is now 480 seconds because of sys_sync:
> 
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=fb822db465bd9fd4208eef1af4490539b236c54e
> 
> But are there are really any other tasks which call
> schedule_timeout_uninterruptibl() for with a timeout >480 seconds?
> 
> Right now kmemleak appears to be the only exception. (A quick grep didn't turn
> anything up.) And it is trivial to change kmemleak to use INTERRUPTIBLE.
> Might even be a nice feature. You could stop it faster that way.

I changed the code as below as it makes more sense:

--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -1044,6 +1044,7 @@ static int kmemleak_scan_thread(void *arg)
 
 	while (!kthread_should_stop()) {
 		struct kmemleak_object *object;
+		signed long timeout = jiffies_scan_wait;
 
 		mutex_lock(&scan_mutex);
 
@@ -1069,7 +1070,8 @@ static int kmemleak_scan_thread(void *arg)
 
 		mutex_unlock(&scan_mutex);
 		/* wait before the next scan */
-		schedule_timeout_uninterruptible(jiffies_scan_wait);
+		while (timeout && !kthread_should_stop())
+			timeout = schedule_timeout_interruptible(timeout);
 	}
 
 	pr_info("kmemleak: Automatic memory scanning thread ended\n");

-- 
Catalin

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Catalin Marinas]

On Tue, 2009-02-03 at 01:41 +0100, Frederic Weisbecker wrote:
> Right. BTW, I wonder how it behaves in case of suspend to disk.
> But changing the state to TASK_INTERRUPTIBLE wouldn't change it in this case since the
> signals are only sent to userpace threads to freeze them.
> 
> Kernel threads try to freeze by themselves.
> 
> But for such very long schedule_timeout, will the hibernation wait for kmemleak
> to wake up and then try_to_freeze() before suspend to disk?

I haven't added anything to kmemleak for this. Does something like below
look feasible?

--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -88,6 +88,7 @@
 #include <linux/errno.h>
 #include <linux/uaccess.h>
 #include <linux/string.h>
+#include <linux/freezer.h>
 
 #include <asm/sections.h>
 #include <asm/processor.h>
@@ -1070,8 +1071,11 @@ static int kmemleak_scan_thread(void *arg)
 
 		mutex_unlock(&scan_mutex);
 		/* wait before the next scan */
-		while (timeout && !kthread_should_stop())
+		while (timeout && !kthread_should_stop()) {
+			if (try_to_freeze())
+				break;
 			timeout = schedule_timeout_interruptible(timeout);
+		}
 	}
 
 	pr_info("kmemleak: Automatic memory scanning thread ended\n");

Thanks.

-- 
Catalin

Re: next-20090202: task kmemleak:763 blocked for more than 120 seconds.

[Frederic Weisbecker]

On Tue, Feb 03, 2009 at 12:48:34PM +0000, Catalin Marinas wrote:
> On Tue, 2009-02-03 at 01:41 +0100, Frederic Weisbecker wrote:
> > Right. BTW, I wonder how it behaves in case of suspend to disk.
> > But changing the state to TASK_INTERRUPTIBLE wouldn't change it in this case since the
> > signals are only sent to userpace threads to freeze them.


I made a mistake here. Only kernel threads in TASK_INTERRUPTIBLE are woken up
while hibernation.
Yes, if you want kmemleak to be freezable, that's the right state.

 
> > Kernel threads try to freeze by themselves.
> > 
> > But for such very long schedule_timeout, will the hibernation wait for kmemleak
> > to wake up and then try_to_freeze() before suspend to disk?
> 
> I haven't added anything to kmemleak for this. Does something like below
> look feasible?
> 
> --- a/mm/kmemleak.c
> +++ b/mm/kmemleak.c
> @@ -88,6 +88,7 @@
>  #include <linux/errno.h>
>  #include <linux/uaccess.h>
>  #include <linux/string.h>
> +#include <linux/freezer.h>
>  
>  #include <asm/sections.h>
>  #include <asm/processor.h>
> @@ -1070,8 +1071,11 @@ static int kmemleak_scan_thread(void *arg)
>  
>  		mutex_unlock(&scan_mutex);
>  		/* wait before the next scan */
> -		while (timeout && !kthread_should_stop())
> +		while (timeout && !kthread_should_stop()) {
> +			if (try_to_freeze())
> +				break;
>  			timeout = schedule_timeout_interruptible(timeout);
> +		}
>  	}


That looks good, but you have to set kmemleak thread as freezable before
by calling set_freezable() in the beggining of your thread.

Note that requiring kmemleak to be freezable looks only relevant if it does
some memory allocations (hibernation needs some memory and prefer that there
are not too much parallel memory allocations.)


>  
>  	pr_info("kmemleak: Automatic memory scanning thread ended\n");
> 
> Thanks.
> 
> -- 
> Catalin
> 

Re: next-20090202: task kmemleak:763 blocked for more than 120seconds.

[Catalin Marinas]

On Tue, 2009-02-03 at 20:52 +0000, Frederic Weisbecker wrote:
> Note that requiring kmemleak to be freezable looks only relevant if it does
> some memory allocations (hibernation needs some memory and prefer that there
> are not too much parallel memory allocations.)

OK. In this case, there is no need for the kmemleak thread to be
freezable. It only scans the memory periodically but doesn't allocate
any itself.

Thanks.

-- 
Catalin