2009-07-29 06:21:12

by Paul Rolland

[permalink] [raw]
Subject: 2.6.31-rc4 - slab entry tak_delay_info leaking ???

Hello,

Since I'm running 2.6.31-rc? (3 or 4 I think), I often find my machine with
my X session killed in the morning, and the kdm login screen displayed.

This morning, I decided to save the /var/log/messages to check it before
rebooting, and saw that the OOM killer triggered during the night.
So, I quickly made a copy of it, and a slabtop output. There came the
surprise :
OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME
12899448 12899445 99% 0.11K 358318 36 1433272K
task_delay_info

On a freshly booted machine, the same entry shows :
3204 3191 99% 0.11K 89 36 356K task_delay_info
after the X session is started.

Please find attached the slabtop -o output.

Regards,
Paul


Attachments:
(No filename) (738.00 B)
rol.crash2 (5.94 kB)
Download all attachments

2009-07-30 10:07:18

by Paul Rolland

[permalink] [raw]
Subject: Re: 2.6.31-rc4 - slab entry tak_delay_info leaking ???

Hello,

On Wed, 29 Jul 2009 08:20:47 +0200
Paul Rolland <[email protected]> wrote:

> Hello,
>
> Since I'm running 2.6.31-rc? (3 or 4 I think), I often find my machine
> with my X session killed in the morning, and the kdm login screen
> displayed.
>
> This morning, I decided to save the /var/log/messages to check it before
> rebooting, and saw that the OOM killer triggered during the night.
> So, I quickly made a copy of it, and a slabtop output. There came the
> surprise :
> OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME
> 12899448 12899445 99% 0.11K 358318 36 1433272K
> task_delay_info
>
> On a freshly booted machine, the same entry shows :
> 3204 3191 99% 0.11K 89 36 356K task_delay_info
> after the X session is started.
>
> Please find attached the slabtop -o output.

Here it starts again :( The machine is up for a little bit more that 1 day
[root@tux infocast]# uptime
12:04:42 up 1 day, 3:53, 12 users, load average: 0.18, 0.37, 0.48

I feel it because the machine seems to be slower when it happens, probably
because it does have less and less memory available...

And here what the slabtop output monitoring reports :
Thu Jul 30 11:49:04 CEST 2009
task_delay_info 3292 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:50:04 CEST 2009
task_delay_info 3292 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:51:05 CEST 2009
task_delay_info 3292 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:52:05 CEST 2009
task_delay_info 3292 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:53:05 CEST 2009
task_delay_info 3292 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:54:05 CEST 2009
task_delay_info 3289 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:55:11 CEST 2009
task_delay_info 3309 3312 112 36 1 : tunables 0 0 0 : slabdata 92 92 0
Thu Jul 30 11:56:15 CEST 2009
task_delay_info 16631 16632 112 36 1 : tunables 0 0 0 : slabdata 462 462 0
Thu Jul 30 11:57:15 CEST 2009
task_delay_info 58860 58860 112 36 1 : tunables 0 0 0 : slabdata 1635 1635 0
Thu Jul 30 11:58:15 CEST 2009
task_delay_info 98422 98424 112 36 1 : tunables 0 0 0 : slabdata 2734 2734 0
Thu Jul 30 11:59:15 CEST 2009
task_delay_info 138023 138024 112 36 1 : tunables 0 0 0 : slabdata 3834 3834 0
Thu Jul 30 12:00:15 CEST 2009
task_delay_info 177587 177588 112 36 1 : tunables 0 0 0 : slabdata 4933 4933 0
Thu Jul 30 12:01:16 CEST 2009
task_delay_info 217151 217152 112 36 1 : tunables 0 0 0 : slabdata 6032 6032 0
Thu Jul 30 12:02:17 CEST 2009
task_delay_info 256715 256716 112 36 1 : tunables 0 0 0 : slabdata 7131 7131 0
Thu Jul 30 12:03:17 CEST 2009
task_delay_info 296316 296316 112 36 1 : tunables 0 0
0 : slabdata 8231 8231 0


Anyone with an idea ???
Paul

2009-07-30 10:26:16

by Paul Rolland

[permalink] [raw]
Subject: Re: 2.6.31-rc4 - slab entry tak_delay_info leaking ???

Hello,

On Thu, 30 Jul 2009 12:07:15 +0200
Paul Rolland <[email protected]> wrote:

> Hello,
>
> On Wed, 29 Jul 2009 08:20:47 +0200
> Paul Rolland <[email protected]> wrote:
>
> > Hello,
> >
> > Since I'm running 2.6.31-rc? (3 or 4 I think), I often find my machine
> > with my X session killed in the morning, and the kdm login screen
> > displayed.
> >
> > This morning, I decided to save the /var/log/messages to check it before
> > rebooting, and saw that the OOM killer triggered during the night.
> > So, I quickly made a copy of it, and a slabtop output. There came the
> > surprise :
> > OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME
> > 12899448 12899445 99% 0.11K 358318 36 1433272K
> > task_delay_info
> >
> > On a freshly booted machine, the same entry shows :
> > 3204 3191 99% 0.11K 89 36 356K task_delay_info
> > after the X session is started.
> >
> > Please find attached the slabtop -o output.
>
> Here it starts again :( The machine is up for a little bit more that 1 day
> [root@tux infocast]# uptime
> 12:04:42 up 1 day, 3:53, 12 users, load average: 0.18, 0.37, 0.48
>
> I feel it because the machine seems to be slower when it happens,
> probably because it does have less and less memory available...
>
> And here what the slabtop output monitoring reports :
> Thu Jul 30 11:49:04 CEST 2009
> task_delay_info 3292 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:50:04 CEST 2009
> task_delay_info 3292 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:51:05 CEST 2009
> task_delay_info 3292 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:52:05 CEST 2009
> task_delay_info 3292 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:53:05 CEST 2009
> task_delay_info 3292 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:54:05 CEST 2009
> task_delay_info 3289 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:55:11 CEST 2009
> task_delay_info 3309 3312 112 36 1 : tunables 0 0
> 0 : slabdata 92 92 0 Thu Jul 30 11:56:15 CEST 2009
> task_delay_info 16631 16632 112 36 1 : tunables 0 0
> 0 : slabdata 462 462 0 Thu Jul 30 11:57:15 CEST 2009
> task_delay_info 58860 58860 112 36 1 : tunables 0 0
> 0 : slabdata 1635 1635 0 Thu Jul 30 11:58:15 CEST 2009
> task_delay_info 98422 98424 112 36 1 : tunables 0 0
> 0 : slabdata 2734 2734 0 Thu Jul 30 11:59:15 CEST 2009
> task_delay_info 138023 138024 112 36 1 : tunables 0 0
> 0 : slabdata 3834 3834 0 Thu Jul 30 12:00:15 CEST 2009
> task_delay_info 177587 177588 112 36 1 : tunables 0 0
> 0 : slabdata 4933 4933 0 Thu Jul 30 12:01:16 CEST 2009
> task_delay_info 217151 217152 112 36 1 : tunables 0 0
> 0 : slabdata 6032 6032 0 Thu Jul 30 12:02:17 CEST 2009
> task_delay_info 256715 256716 112 36 1 : tunables 0 0
> 0 : slabdata 7131 7131 0 Thu Jul 30 12:03:17 CEST 2009
> task_delay_info 296316 296316 112 36 1 : tunables 0 0
> 0 : slabdata 8231 8231 0
>
>
> Anyone with an idea ???

Well, I've killed my X session, and it stopped the "leak"... but didn't recover
the "lost" task_delay_info...

Attached is .config.

Video is :
00:02.0 VGA compatible controller: Intel Corporation Mobile 945GM/GMS, 943/940GML Express Integrated Graphics Controller (rev 03)
00:02.1 Display controller: Intel Corporation Mobile 945GM/GMS/GME,
943/940GML Express Integrated Graphics Controller (rev 03)

Paul


Attachments:
(No filename) (3.77 kB)
.config (64.00 kB)
Download all attachments

2009-07-30 15:53:42

by Catalin Marinas

[permalink] [raw]
Subject: Re: 2.6.31-rc4 - slab entry tak_delay_info leaking ???

Paul Rolland <[email protected]> wrote:
>> On Wed, 29 Jul 2009 08:20:47 +0200
>> Paul Rolland <[email protected]> wrote:
>> > Since I'm running 2.6.31-rc? (3 or 4 I think), I often find my machine
>> > with my X session killed in the morning, and the kdm login screen
>> > displayed.
[...]
> Well, I've killed my X session, and it stopped the "leak"... but
> didn't recover the "lost" task_delay_info...

You could try to enable CONFIG_KMEMLEAK and see if you get any leaks
reported for the "lost" task_delay_info (see Documentation/kmemleak.txt).

--
Catalin

2009-07-31 20:04:22

by Paul Rolland

[permalink] [raw]
Subject: Re: 2.6.31-rc4 - slab entry tak_delay_info leaking ???

Hi Catalin,

On Thu, 30 Jul 2009 16:53:33 +0100
Catalin Marinas <[email protected]> wrote:

> Paul Rolland <[email protected]> wrote:
> >> On Wed, 29 Jul 2009 08:20:47 +0200
> >> Paul Rolland <[email protected]> wrote:
> >> > Since I'm running 2.6.31-rc? (3 or 4 I think), I often find my
> >> > machine with my X session killed in the morning, and the kdm login
> >> > screen displayed.
> [...]
> > Well, I've killed my X session, and it stopped the "leak"... but
> > didn't recover the "lost" task_delay_info...
>
> You could try to enable CONFIG_KMEMLEAK and see if you get any leaks
> reported for the "lost" task_delay_info (see Documentation/kmemleak.txt).

I'm now running a kmemleak-eanbled version of the kernel, and waiting for
the same problem to happen again.

In the meantime, my machine is kmemleak-complaining a lot :
Jul 31 20:57:35 tux kernel: kmemleak: 52 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:07:41 tux kernel: kmemleak: 34 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:17:47 tux kernel: kmemleak: 23 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:27:54 tux kernel: kmemleak: 33 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:38:01 tux kernel: kmemleak: 20 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:48:07 tux kernel: kmemleak: 21 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)
Jul 31 21:58:15 tux kernel: kmemleak: 32 new suspected memory leaks
(see /sys/kernel/debug/kmemleak)

What should I do with these reports ? Is there an easy way to check if they
are normal (false-positive) ?

Regards,
Paul

--
Paul Rolland E-Mail : rol(at)witbe.net
CTO - Witbe.net SA Tel. +33 (0)1 47 67 77 77
Les Collines de l'Arche Fax. +33 (0)1 47 67 77 99
F-92057 Paris La Defense RIPE : PR12-RIPE

Please no HTML, I'm not a browser - Pas d'HTML, je ne suis pas un
navigateur "Some people dream of success... while others wake up and work
hard at it"

"I worry about my child and the Internet all the time, even though she's
too young to have logged on yet. Here's what I worry about. I worry that 10
or 15 years from now, she will come to me and say 'Daddy, where were you
when they took freedom of the press away from the Internet?'"
--Mike Godwin, Electronic Frontier Foundation