dirty md raid5 slab bio leak

dirty md raid5 slab bio leak

[Ernst Herzberg]

Moin.

The machine:

amd64, 2G mem, 4 SATA disks on SiI 3114 [SATALink/SATARaid] Serial ATA 
Controller, configured as md raid5/raid1, using [cfq-scheduler], running 
2.6.12-rc6 (application postgresql)

The story:

This morning the machine was very slow, first check shows that the machine 
swaps and all disk i/o are very slow.

Looking further slabtop shows

 Active / Total Objects (% used)    : 19821561 / 19828316 (100.0%)
 Active / Total Slabs (% used)      : 369737 / 369739 (100.0%)
 Active / Total Caches (% used)     : 80 / 120 (66.7%)
 Active / Total Size (% used)       : 1415795.50K / 1416586.19K (99.9%)
 Minimum / Average / Maximum Object : 0.02K / 0.07K / 128.00K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME
9865575 9864690  99%    0.02K  43847      225    175388K biovec-1
9865254 9864654  99%    0.12K 318234       31   1272936K bio
 28755  28755 100%    0.09K    639       45      2556K buffer_head
 16856  16856 100%    0.52K   2408        7      9632K radix_tree_node
 11286  10852  96%    0.21K    627       18      2508K dentry_cache
  5955   5953  99%    0.73K   1191        5      4764K shmem_inode_cache
  5795   3461  59%    0.06K     95       61       380K size-64
  5566   5506  98%    0.17K    253       22      1012K vm_area_struct
  3294   3294 100%    0.66K    549        6      2196K reiser_inode_cache
  3240   3212  99%    0.07K     60       54       240K sysfs_dir_cache
  2046   2046 100%    0.12K     66       31       264K size-128
  2023   1657  81%    0.03K     17      119        68K size-32

*ouch*

I decided to first compile 2.6.12 (final) and reboot the machine to reproduce 
the problem.

During reboot md shows that /dev/sdd are failed. Log:

[...]
Jun 23 11:23:45 c64 ata4: command 0x35 timeout, stat 0xd8 host_stat 0x0
Jun 23 11:23:45 c64 ata4: status=0xd8 { Busy }
Jun 23 11:23:45 c64 SCSI error : <3 0 0 0> return code = 0x8000002
Jun 23 11:23:45 c64 sdd: Current: sense key: Aborted Command
Jun 23 11:23:45 c64 Additional sense: Scsi parity error
Jun 23 11:23:45 c64 end_request: I/O error, dev sdd, sector 234436299
Jun 23 11:23:45 c64 raid5: Disk failure on sdd3, disabling device. Operation 
continuing on 3 devices
Jun 23 11:23:45 c64 RAID5 conf printout:
Jun 23 11:23:45 c64 --- rd:4 wd:3 fd:1
Jun 23 11:23:45 c64 disk 0, o:1, dev:sda3
Jun 23 11:23:45 c64 disk 1, o:1, dev:sdb3
Jun 23 11:23:45 c64 disk 2, o:1, dev:sdc3
Jun 23 11:23:45 c64 disk 3, o:0, dev:sdd3
Jun 23 11:23:45 c64 RAID5 conf printout:
Jun 23 11:23:45 c64 --- rd:4 wd:3 fd:1
Jun 23 11:23:45 c64 disk 0, o:1, dev:sda3
Jun 23 11:23:45 c64 disk 1, o:1, dev:sdb3
Jun 23 11:23:45 c64 disk 2, o:1, dev:sdc3
Jun 23 11:24:39 c64 ATA: abnormal status 0xD8 on port 0xFFFFC200000066C7
Jun 23 11:24:39 c64 ATA: abnormal status 0xD8 on port 0xFFFFC200000066C7
Jun 23 11:24:39 c64 ATA: abnormal status 0xD8 on port 0xFFFFC200000066C7
Jun 23 11:25:09 c64 ata4: command 0x25 timeout, stat 0xd8 host_stat 0x1
Jun 23 11:25:09 c64 ata4: status=0xd8 { Busy }
Jun 23 11:25:09 c64 SCSI error : <3 0 0 0> return code = 0x8000002
Jun 23 11:25:09 c64 sdd: Current: sense key: Aborted Command
Jun 23 11:25:09 c64 Additional sense: Scsi parity error
Jun 23 11:25:09 c64 end_request: I/O error, dev sdd, sector 2640176
Jun 23 11:25:09 c64 raid5: Disk failure on sdd2, disabling device. Operation 
continuing on 3 devices
Jun 23 11:25:09 c64 RAID5 conf printout:
Jun 23 11:25:09 c64 --- rd:4 wd:3 fd:1
Jun 23 11:25:09 c64 disk 0, o:1, dev:sda2
Jun 23 11:25:09 c64 disk 1, o:1, dev:sdb2
Jun 23 11:25:09 c64 disk 2, o:1, dev:sdc2
Jun 23 11:25:09 c64 disk 3, o:0, dev:sdd2
Jun 23 11:25:09 c64 RAID5 conf printout:
Jun 23 11:25:09 c64 --- rd:4 wd:3 fd:1
Jun 23 11:25:09 c64 disk 0, o:1, dev:sda2
Jun 23 11:25:09 c64 disk 1, o:1, dev:sdb2
Jun 23 11:25:09 c64 disk 2, o:1, dev:sdc2
[...]

(next i should look at the machines even i am at linuxtag:-)

Now i readded /dev/sdd[2,3] and everthing worked again (after checking all 
cables).

Looks like a BUG, slab should not be filled up if a disk fails.

Ok, this is a 'needed' testingmachine, but i'm willing to try reproducing it, 
if nobody else are able to do it ;-)

<earny>

Re: dirty md raid5 slab bio leak

[Neil Brown]

On Monday June 27, list-lkml@net4u.de wrote:
> Moin.
> 
> The machine:
> 
> amd64, 2G mem, 4 SATA disks on SiI 3114 [SATALink/SATARaid] Serial ATA 
> Controller, configured as md raid5/raid1, using [cfq-scheduler], running 
> 2.6.12-rc6 (application postgresql)
> 
> The story:
> 
> This morning the machine was very slow, first check shows that the machine 
> swaps and all disk i/o are very slow.
> 
> Looking further slabtop shows
> 
>  Active / Total Objects (% used)    : 19821561 / 19828316 (100.0%)
>  Active / Total Slabs (% used)      : 369737 / 369739 (100.0%)
>  Active / Total Caches (% used)     : 80 / 120 (66.7%)
>  Active / Total Size (% used)       : 1415795.50K / 1416586.19K (99.9%)
>  Minimum / Average / Maximum Object : 0.02K / 0.07K / 128.00K
> 
>   OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME
> 9865575 9864690  99%    0.02K  43847      225    175388K biovec-1
> 9865254 9864654  99%    0.12K 318234       31   1272936K bio


raid5 never allocates from these slabs, so this cannot be a raid5
problem.
raid1 does, and you mention in the intro that raid1 might be involved,
but there are now more details...
Could you say a little bit more about your setup.. How are each of
raid1 and raid5 used.  Was there any error on a drive involved in raid1?

I just checked my test machine (running 2.6.12-rc3-mm3) and it had a
really large number of bio and biovec-1 in use too (and it's been
sitting fairly idle for several days).

I've quickly reviewed the raid1 code and I cannot see a bio leak
(though that doesn't mean there isn't one..)

If anyone else has a large 'bio' slab, please report the configuration
(kernel, is md in use, etc).

NeilBrown

Re: dirty md raid5 slab bio leak

[Neil Brown]

On Tuesday June 28, neilb@cse.unsw.edu.au wrote:
> 
> I just checked my test machine (running 2.6.12-rc3-mm3) and it had a
> really large number of bio and biovec-1 in use too (and it's been
> sitting fairly idle for several days).
> 
> I've quickly reviewed the raid1 code and I cannot see a bio leak
> (though that doesn't mean there isn't one..)
> 
> If anyone else has a large 'bio' slab, please report the configuration
> (kernel, is md in use, etc).

It's OK, I found it.  The bio leaks when writing the md superblock.

Thanks,
NeilBrown


--
insert a missing bio_put when writting the md superblock.

Without this we have a steady growth in the "bio" slab.

Signed-off-by: Neil Brown <neilb@cse.unsw.edu.au>

### Diffstat output
 ./drivers/md/md.c |    1 +
 1 files changed, 1 insertion(+)

diff ./drivers/md/md.c~current~ ./drivers/md/md.c
--- ./drivers/md/md.c~current~	2005-06-22 13:16:28.000000000 +1000
+++ ./drivers/md/md.c	2005-06-28 13:02:04.000000000 +1000
@@ -338,6 +338,7 @@ static int super_written(struct bio *bio
 
 	if (atomic_dec_and_test(&rdev->mddev->pending_writes))
 		wake_up(&rdev->mddev->sb_wait);
+	bio_put(bio);
 	return 0;
 }
 

Re: dirty md raid5 slab bio leak

[Andrew Morton]

Neil Brown <neilb@cse.unsw.edu.au> wrote:
>
> It's OK, I found it.  The bio leaks when writing the md superblock.
> 

Thanks.

>  insert a missing bio_put when writting the md superblock.

Does 2.6.12.x need this?

Re: dirty md raid5 slab bio leak

[Neil Brown]

On Monday June 27, akpm@osdl.org wrote:
> Neil Brown <neilb@cse.unsw.edu.au> wrote:
> >
> > It's OK, I found it.  The bio leaks when writing the md superblock.
> > 
> 
> Thanks.
> 
> >  insert a missing bio_put when writting the md superblock.
> 
> Does 2.6.12.x need this?

Hmmm.. probably, though it isn't Ooopsable, and isn't a security
problem.  Just a slow leak with a trivial patch...  

Is there a web-page somewhere that lists the acceptance criterea? I
didn't save the mail message.

Do I just mail the patch to stable@kernel.org ??

NeilBrown

Re: dirty md raid5 slab bio leak

[Andrew Morton]

Neil Brown <neilb@cse.unsw.edu.au> wrote:
>
> On Monday June 27, akpm@osdl.org wrote:
> > Neil Brown <neilb@cse.unsw.edu.au> wrote:
> > >
> > > It's OK, I found it.  The bio leaks when writing the md superblock.
> > > 
> > 
> > Thanks.
> > 
> > >  insert a missing bio_put when writting the md superblock.
> > 
> > Does 2.6.12.x need this?
> 
> Hmmm.. probably, though it isn't Ooopsable, and isn't a security
> problem.  Just a slow leak with a trivial patch...  

It's a pretty sad bug if it hits you though.

> Is there a web-page somewhere that lists the acceptance criterea? I
> didn't save the mail message.

Me either.  Just send 'em any old thing and let them decide ;)

> Do I just mail the patch to stable@kernel.org ??

That's OK, I'll add it to my backport queue - we should leave it to bake in
2.6.13-rc1 for a bit first.

Re: dirty md raid5 slab bio leak

[Ernst Herzberg]

On Dienstag 28 Juni 2005 06:13, Neil Brown wrote:
> On Tuesday June 28, neilb@cse.unsw.edu.au wrote:
> > I just checked my test machine (running 2.6.12-rc3-mm3) and it had a
> > really large number of bio and biovec-1 in use too (and it's been
> > sitting fairly idle for several days).
> >
> > I've quickly reviewed the raid1 code and I cannot see a bio leak
> > (though that doesn't mean there isn't one..)
> >
> > If anyone else has a large 'bio' slab, please report the configuration
> > (kernel, is md in use, etc).
>
> It's OK, I found it.  The bio leaks when writing the md superblock.
>

Thanks.

Even here is my forgotten setup, for completeness:

c64 ~ # cat /proc/mdstat
Personalities : [linear] [raid0] [raid1] [raid5]
md2 : active raid1 sdb1[1] sda1[0]
      192640 blocks [2/2] [UU]

md1 : active raid5 sdd2[3] sdc2[2] sdb2[1] sda2[0]
      5855424 blocks level 5, 64k chunk, algorithm 2 [4/4] [UUUU]

md0 : active raid5 sdd3[3] sdc3[2] sdb3[1] sda3[0]
      345220416 blocks level 5, 64k chunk, algorithm 2 [4/4] [UUUU]

unused devices: <none>
c64 ~ # mount
/dev/md0 on / type reiserfs (rw,noatime)
proc on /proc type proc (rw)
sysfs on /sys type sysfs (rw)
udev on /dev type tmpfs (rw,nosuid)
devpts on /dev/pts type devpts (rw)
/dev/md2 on /boot type ext3 (rw,noatime)
none on /dev/shm type tmpfs (rw)
usbfs on /proc/bus/usb type usbfs (rw)
c64 ~ # cat /proc/swaps
Filename                                Type            Size    Used    
Priority
/dev/md/1                               partition       5855416 169236  -1


The failed disk was /dev/sdd, so only raid5 was involved. The 
partitions /dev/sdc1 and /dev/sdd1 are not used.

<earny>

Re: dirty md raid5 slab bio leak [FIXED]

[Ernst Herzberg]

On Tuesday 28 June 2005 08:17, Andrew Morton wrote:
> Neil Brown <neilb@cse.unsw.edu.au> wrote:
> > On Monday June 27, akpm@osdl.org wrote:
> > > Neil Brown <neilb@cse.unsw.edu.au> wrote:
> > > > It's OK, I found it.  The bio leaks when writing the md superblock.
> > >
> > > Thanks.
> > >
> > > >  insert a missing bio_put when writting the md superblock.
> > >
> > > Does 2.6.12.x need this?
> >
> > Hmmm.. probably, though it isn't Ooopsable, and isn't a security
> > problem.  Just a slow leak with a trivial patch...
>
> It's a pretty sad bug if it hits you though.
>
> > Is there a web-page somewhere that lists the acceptance criterea? I
> > didn't save the mail message.
>
> Me either.  Just send 'em any old thing and let them decide ;)
>
> > Do I just mail the patch to stable@kernel.org ??
>
> That's OK, I'll add it to my backport queue - we should leave it to bake in
> 2.6.13-rc1 for a bit first.
>

2.6.13-rc1 fixed this. Verified on the same machine, same hardware, same 
disk-failure, but new kernel.

Jul  6 06:33:47 c64 ata4: command 0x35 timeout, stat 0xd8 host_stat 0x0
Jul  6 06:33:47 c64 ata4: status=0xd8 { Busy }
Jul  6 06:33:47 c64 SCSI error : <3 0 0 0> return code = 0x8000002
Jul  6 06:33:47 c64 sdd: Current: sense key: Aborted Command
Jul  6 06:33:47 c64 Additional sense: Scsi parity error
Jul  6 06:33:47 c64 end_request: I/O error, dev sdd, sector 234436299
Jul  6 06:33:47 c64 raid5: Disk failure on sdd3, disabling device. Operation 
continuing on 3 devices

-----------------------
 Active / Total Objects (% used)    : 277222 / 287112 (96.6%)
 Active / Total Slabs (% used)      : 11137 / 11137 (100.0%)
 Active / Total Caches (% used)     : 77 / 118 (65.3%)
 Active / Total Size (% used)       : 42630.65K / 44791.06K (95.2%)
 Minimum / Average / Maximum Object : 0.02K / 0.16K / 128.00K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME
220455 216543  98%    0.09K   4899       45     19596K buffer_head
 17283  14714  85%    0.52K   2469        7      9876K radix_tree_node
 11250  10616  94%    0.21K    625       18      2500K dentry_cache
  5940   5930  99%    0.69K    540       11      4320K shmem_inode_cache
  4620   4620 100%    0.17K    210       22       840K vm_area_struct
 [....]


Ordering a new disk drive now:-)

Thanks

<earny>