# RAID causes periodic I/O -- what's up with that?

## dbc

In my file server system there is I/O about every 4 or 5 seconds that seems to be caused by the RAID system.  Nothing else is going on in the system, just RAID rattling the disks for it's own entertainment.

fstab:

```

/dev/md1                /boot           ext3            noauto,noatime  1 2

/dev/md3                /               ext3            noatime         0 1

/dev/sda2               none            swap            defaults,pri=1  0 0

/dev/sdb2               none            swap            defaults,pri=1  0 0

/dev/cdrom              /mnt/cdrom      audo            noauto,ro,user  0 0

/dev/fd0                /mnt/floppy     auto            noauto,user     0 0

LABEL=BACKUP            /mnt/bu         ext3            noauto          0 0

```

This is set up for simple RAID mirroring.  Works nicely, actually, just is overly active for no reason.

And lm-profiler gives me lots of:

```

....

Accesses at 548/600 in run: md3_raid1                                       

Accesses at 551/600 in run: md3_raid1                                       

Accesses at 556/600 in run: md3_raid1                                       

Accesses at 561/600 in run: md3_raid1                                       

Accesses at 562/600 in run: md3_raid1                                       

Accesses at 563/600 in run: md3_raid1                                       

Accesses at 565/600 in run: md3_raid1                                       

Accesses at 566/600 in run: md3_raid1                                       

Accesses at 570/600 in run: md3_raid1                                       

Accesses at 575/600 in run: md3_raid1                                       

Accesses at 580/600 in run: md3_raid1                                       

Accesses at 584/600 in run: md3_raid1                                       

Accesses at 585/600 in run: md3_raid1                                       

Accesses at 586/600 in run: md3_raid1                                       

Accesses at 587/600 in run: md3_raid1                                       

Accesses at 589/600 in run: md3_raid1                                       

Accesses at 594/600 in run: md3_raid1                                       

Accesses at 596/600 in run: md3_raid1                                       

Accesses at 599/600 in run: md3_raid1                                       

Profiling run completed.                   

```

Interestingly, md1 doesn't show up.  

In the entire 10 minute profiling run, only two other incidental disk I/O's showed up, both normal.  And the system is not swapping -- only 40% of available RAM is being used, and 0% of swap space.

How do I get rid of this extraneous I/O?  Is this a symptom of RAID being misconfigured?

-dave

----------

## Cyker

Both ext3 (and I think mdadm RAID5) resync periodically.

ext3 defaults to a 5 second sync, but you can change it by modifying your fstab - Just append commit=<some value of seconds> to the options line (e.g. noatime becomes noatime,commit=60)

I don't think this can be disabled (Why??) which is a pity because it totally destroys any chance of powersaving  :Sad: 

----------

## Rob1n

 *Cyker wrote:*   

> Both ext3 (and I think mdadm RAID5) resync periodically.
> 
> ext3 defaults to a 5 second sync, but you can change it by modifying your fstab - Just append commit=<some value of seconds> to the options line (e.g. noatime becomes noatime,commit=60)
> 
> I don't think this can be disabled (Why??) which is a pity because it totally destroys any chance of powersaving 

 

ext3 sync is an entirely different thing - this just means that ext3 will write any buffered data out to disk after a maximum of 5 seconds (it buffers the data to optimise the write process by ordering and/or combining writes).  It can't be disabled as this could cause major data loss in the event of a crash/power loss.  This shouldn't affect powersaving much as it'll only happen if something's writing data to disk.

As for the RAID writes, I don't know - does lm-profiler give you the originator of the I/O or just the immediate parent (i.e. do you actually see applications doing I/O or just the intermediate block devices)?  It may be you have some application reading/writing regularly.

----------

## adsmith

To figure out what's going on, log to a non-block filesystem (e.g., tmpfs) and turn on /proc/sys/vm/block_dump

----------

## dbc

OK, there must be a clue in here somewhere.... darned if I can see it.

-dave

Edit: So... it seems to point to nmbd?   Why would Samba be hitting the disk every few seconds when there aren't even any clients connected?

```

fileshare2 shm # tail -f log-messages 

Aug 20 08:35:02 fileshare2 syslog-ng[3920]: new configuration initialized

Aug 20 08:35:20 fileshare2 su[24583]: Successful su for root by dave

Aug 20 08:35:20 fileshare2 su[24583]: + pts/2 dave:root

Aug 20 08:35:20 fileshare2 su(pam_unix)[24583]: session opened for user root by (uid=1000)

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 319553544 on md3

Aug 20 08:36:51 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:36:51 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:36:51 fileshare2 kjournald(1000): WRITE block 53208 on md3

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 319553576 on md3

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 319553760 on md3

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 319553768 on md3

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 319701016 on md3

Aug 20 08:36:51 fileshare2 pdflush(11842): WRITE block 331087872 on md3

Aug 20 08:36:51 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:36:51 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:36:56 fileshare2 pdflush(11842): WRITE block 0 on md3

Aug 20 08:36:56 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:36:56 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:36:56 fileshare2 pdflush(11842): WRITE block 80 on md3

Aug 20 08:36:56 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:36:56 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:37:32 fileshare2 nmbd(5210): dirtied inode 16042091 (log.nmbd) on md3

Aug 20 08:37:32 fileshare2 nmbd(5210): dirtied inode 16042091 (log.nmbd) on md3

Aug 20 08:37:32 fileshare2 nmbd(5210): dirtied inode 16042091 (log.nmbd) on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 256804880 on md3

Aug 20 08:37:37 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:37:37 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 256805016 on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 53216 on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 53224 on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 53232 on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 53240 on md3

Aug 20 08:37:37 fileshare2 kjournald(1000): WRITE block 53248 on md3

Aug 20 08:37:38 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:37:38 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:38:11 fileshare2 pdflush(11842): WRITE block 256638976 on md3

Aug 20 08:38:11 fileshare2 kjournald(1000): WRITE block 53256 on md3

Aug 20 08:38:11 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:38:11 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:38:11 fileshare2 pdflush(11842): WRITE block 256639528 on md3

Aug 20 08:38:12 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:38:12 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:38:16 fileshare2 pdflush(11842): WRITE block 64 on md3

Aug 20 08:38:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:38:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:38:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:38:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:39:03 fileshare2 nmbd(5210): dirtied inode 16042085 (unexpected.tdb) on md3

Aug 20 08:39:36 fileshare2 pdflush(11842): WRITE block 256804304 on md3

Aug 20 08:39:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:39:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:39:36 fileshare2 pdflush(11842): WRITE block 256804312 on md3

Aug 20 08:39:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:39:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:39:41 fileshare2 kjournald(1000): WRITE block 53264 on md3

Aug 20 08:39:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:39:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:39:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:39:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:39:43 fileshare2 nmbd(5210): dirtied inode 16042085 (unexpected.tdb) on md3

Aug 20 08:40:01 fileshare2 cron[24595]: (root) CMD (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )

Aug 20 08:40:01 fileshare2 touch(24603): dirtied inode 15435232 (lastrun) on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53272 on md3

Aug 20 08:40:06 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:06 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53280 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53288 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53296 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53304 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53312 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53320 on md3

Aug 20 08:40:06 fileshare2 kjournald(1000): WRITE block 53328 on md3

Aug 20 08:40:06 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:06 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:16 fileshare2 pdflush(11842): WRITE block 256804304 on md3

Aug 20 08:40:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:16 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:16 fileshare2 pdflush(11842): WRITE block 256804312 on md3

Aug 20 08:40:17 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:17 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:21 fileshare2 kjournald(1000): WRITE block 53336 on md3

Aug 20 08:40:21 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:21 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:22 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:22 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384001 (error_log) on md3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384001 (error_log) on md3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384001 (error_log) on md3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384152 (access_log) on md3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384152 (access_log) on md3

Aug 20 08:40:24 fileshare2 apache2(4691): dirtied inode 16384152 (access_log) on md3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 262148112 on md3

Aug 20 08:40:29 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:29 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 262148184 on md3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 53344 on md3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 53352 on md3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 53360 on md3

Aug 20 08:40:29 fileshare2 kjournald(1000): WRITE block 53368 on md3

Aug 20 08:40:29 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:29 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 246939656 on md3

Aug 20 08:40:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:36 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 246939744 on md3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 246940032 on md3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 246956320 on md3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 262144016 on md3

Aug 20 08:40:36 fileshare2 pdflush(11842): WRITE block 262144048 on md3

Aug 20 08:40:37 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:37 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:41 fileshare2 pdflush(11842): WRITE block 0 on md3

Aug 20 08:40:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:41 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:41 fileshare2 pdflush(11842): WRITE block 64 on md3

Aug 20 08:40:42 fileshare2 md3_raid1(994): WRITE block 621169152 on sdb3

Aug 20 08:40:42 fileshare2 md3_raid1(994): WRITE block 621169152 on sda3

Aug 20 08:40:47 fileshare2 bash(24460): dirtied inode 4026531944 (block_dump) on proc

Aug 20 08:41:38 fileshare2 syslog-ng[3920]: SIGHUP received, restarting syslog-ng

                

```

----------

## Rob1n

Looks to me like the sequence goes something like:

 Application (cron, nmbd, apache) writes to log/status file.

 After 5 seconds data gets written to journal (kjournald & md3_raid1).

 Sometime later data gets written to disk (pdflush & md3_raid1).

It all looks to be application driven anyway.  You can check the log files to see what the apps were writing.

----------

## adsmith

It looks to me like several things are contributing, some logs, nmbd and tdb.

Perhaps tail | grep "dirtied inode" on this file for an hour or so to get more wholistic stats.

----------

## dbc

Yeah,  this was too short of a test, since I am crunched for time right now.  The cron and apache activity I'm guessing is normal.  I did a quick test "by ear" of simply turning off Samba and listening for a couple of minutes.  60 seconds went by without activity, so right now my money is on Samba -- but yeah, I need to re-run the tests, logging for a much longer time.  Thanks for the pointer.  Maybe later today I'll have time to do the experiment properly.

-dave

----------

## dbc

Hmmm... well, this disk I/O that I am hearing seems to be mostly legit activity, but I have one concern left.

There are a smattering of expected things... Firefox tucking things away, cron waking up once in a while to do its bit.  But most of the periodic disk traffic does originate with nmbd.  Of that, a bunch of it is simply logging browse-master related activity.  I'm guessing I can adjust a logging level somewhere to eliminate that.  I don't need a log full of "Yo! I be da browse master!"

But... one mystery remains.  nmbd is also periodically hitting "unexpected.tdb", which I gather from Googling is  logging received packets which it doesn't know what to do with.  Is this a sign of bogus activity originating someplace else on my net?  Should I be concerned?  How do I find out what these mystery packets are?

-dave

----------

## Cyker

 *Rob1n wrote:*   

>  *Cyker wrote:*   Both ext3 (and I think mdadm RAID5) resync periodically.
> 
> ext3 defaults to a 5 second sync, but you can change it by modifying your fstab - Just append commit=<some value of seconds> to the options line (e.g. noatime becomes noatime,commit=60)
> 
> I don't think this can be disabled (Why??) which is a pity because it totally destroys any chance of powersaving  
> ...

 

Oh! In that case... I have a similar problem!!  :Shocked: 

I'd just assumed it was ext3 because the commit time exactly matched the frequency of the disk access, no matter what I set it to (At least up to 120s..)

Also, I may be mistaken about the RAID sync - I thought there was, but I can't find anything in the notes I made when I made the array about it...

----------

## dbc

Cyker, Rob1n,

lm-profiler information is not fine-grained enough.  Follow adsmith's adivce and temporarily tweak syslog-ng.conf to point to ram disk, and turn on block logging:

```
echo 1 > /proc/sys/vm/block_dump
```

As to the excess I/O... setting "log level = 1" in smb.conf got rid of a lot of the extra glop I don't need, and reduced disk traffic down to where the only thing that puzzles me is the periodic hits to "unexpected.tdb"

-dave

----------

## eccerr0r

I was battling this for a bit and gave up as this machine was intended to be used as an always-ready machine, and that spin-up time would kill interactive performance anyway (since the RAID houses the root disk.)

Anyway, I found out at least my issue of it never spinning down: Squid is currently on my "evil programs" list - apparently even if nobody's using the cache it still seems to be doing something.  After it reads and dirties a block, then I get those mysterious raid and pdflush activity.  Cups was another evil, but it wasn't as hard to quiet it down.

But in any case I still wanted syslog to be up to date to help out in hacker forensics and detection, so I didn't want to sacrifice that, so I just left the disks running all the time.  Plus the asynchronous timing of mail which must be commit to disk as soon as it can.  Oh well.

----------

## Rob1n

 *dbc wrote:*   

> As to the excess I/O... setting "log level = 1" in smb.conf got rid of a lot of the extra glop I don't need, and reduced disk traffic down to where the only thing that puzzles me is the periodic hits to "unexpected.tdb"

 

This doesn't sound normal - I've had nothing written to mine in over a month now (it's 16k in total).  You could try running wireshark to capture traffic on the nmbd ports and check what it actually is.

----------

## dbc

well, hey, I'm learning about a lot of new tools.... like tdbdump.

So, this is interesting:

```

fileshare2 samba # tdbdump unexpected.tdb 

fileshare2 samba # 

```

Ummmm.... so.... if nmbd writing unexpected.tdb so frequently, why is there nothing to dump?

----------

## dbc

Well, as nearly as I can tell:

1. unexpected.tdb exists to collect and re-route incorrectly addressed traffic to Samba's UDP 137/138 ports from buggy Microsoft clients.

2. wireshark shows there is none of this traffic on my net.  The only traffic on my net during my test period on UDP 137/138 not originated by the fileserver itself are coming from a printer that announces itself once on a great while.

3. tdbdump shows unexpected.tdb to be utterly empty.

Therefore, I conclude that nmbd checks every 4 seconds to make sure that unexpected.tdb  is well and truly empty, and as a side-effect causes the software raid to jump through hoops and rattle both disks.  *sheesh* 

Anyway, although this traffic seems totally silly, there doesn't seem to be much I can do about it except turn off Samba -- and it won't be much of a fileshare system if I do that.

Thanks, everyone, for all your help.

-dave

----------

