Need help tracing regular write activity in 5 s interval

Need help tracing regular write activity in 5 s interval

[Matthias Andree]

Hello,

I am using some recent Linux 2.4.x version (2.4.19-pre8-ac5 for now),
and I have been observing regular disk activity at 5 s intervals for
some time now which are not related to a particular kernel version.

I have reiserfs and ext3fs file systems mounted.

The first thing that came to mind with the "5 s interval" was DJB's
"svscan", but neither mount -o remount,noatime / nor killall -STOP
svscan helped.

The next thing that comes to mind is that journalling file systems
commit their journal every five seconds. But I have a hard time finding
out which file system does this or which process causes blocks to be
marked dirty again. I'd really like to get rid of this regular activity
unless there's a need.

So: is there any trace software that can tell me "at 15:52:43.012345,
process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
detail so I can figure if it's just an atime update -- as with svscan --
or a write access)? And that is NOT to be attached to a specific process
(hint: strace is not an option).

Also, I'd like to suggest again a mount option that marks filesystems as
"clean" automatically after all changes have been committed. This may be
most useful with "noatime", though.

Thanks in advance,

-- 
Matthias Andree

Re: Need help tracing regular write activity in 5 s interval

[Padraig Brady]

Matthias Andree wrote:
> Hello,
> 
> I am using some recent Linux 2.4.x version (2.4.19-pre8-ac5 for now),
> and I have been observing regular disk activity at 5 s intervals for
> some time now which are not related to a particular kernel version.
> 
> I have reiserfs and ext3fs file systems mounted.
> 
> The first thing that came to mind with the "5 s interval" was DJB's
> "svscan", but neither mount -o remount,noatime / nor killall -STOP
> svscan helped.
> 
> The next thing that comes to mind is that journalling file systems
> commit their journal every five seconds. But I have a hard time finding
> out which file system does this or which process causes blocks to be
> marked dirty again. I'd really like to get rid of this regular activity
> unless there's a need.
> 
> So: is there any trace software that can tell me "at 15:52:43.012345,
> process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> detail so I can figure if it's just an atime update -- as with svscan --
> or a write access)? And that is NOT to be attached to a specific process
> (hint: strace is not an option).
> 
> Also, I'd like to suggest again a mount option that marks filesystems as
> "clean" automatically after all changes have been committed. This may be
> most useful with "noatime", though.
> 
> Thanks in advance,
> 

This thread may be of interest:
http://marc.theaimsgroup.com/?l=linux-kernel&m=101600745431992&w=2

It's very awkward to analyse things like this at present.
For user -> kernel you could use something like syscalltrack.

As an aside, Nautilus (1.0.4) does stuff every 2 seconds
(checking is there a CD inserted) that causes the disk LED to flash.
The same action also causes the kernel (2.4.13) to fill up the ring
buffer with: "VFS: Disk change detected on device ide1(22,0)".

Padraig.

Re: Need help tracing regular write activity in 5 s interval

[Muli Ben-Yehuda]

[-- Attachment #1: Type: text/plain, Size: 1003 bytes --]

On Tue, Jun 04, 2002 at 12:21:20PM +0100, Padraig Brady wrote:
> Matthias Andree wrote:

> > So: is there any trace software that can tell me "at 15:52:43.012345,
> > process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> > detail so I can figure if it's just an atime update -- as with svscan --
> > or a write access)? And that is NOT to be attached to a specific process
> > (hint: strace is not an option).

> This thread may be of interest:
> http://marc.theaimsgroup.com/?l=linux-kernel&m=101600745431992&w=2
> 
> It's very awkward to analyse things like this at present.
> For user -> kernel you could use something like syscalltrack.

Just a short note to mention that if you want to try and trace this
activity with syscalltrack, you will want to grab the latest cvs
version - I commited read(2)/write(2) support a few hours ago. 

Hope this helps, 
Muli. 
-- 
Sterday 13 Forelithe 7466

http://vipe.technion.ac.il/~mulix/
http://syscalltrack.sf.net/

[-- Attachment #2: Type: application/pgp-signature, Size: 189 bytes --]

Re: Need help tracing regular write activity in 5 s interval

[Xavier Bestel]

Le mar 04/06/2002 à 13:21, Padraig Brady a écrit :
> As an aside, Nautilus (1.0.4) does stuff every 2 seconds
> (checking is there a CD inserted) that causes the disk LED to flash.
> The same action also causes the kernel (2.4.13) to fill up the ring
> buffer with: "VFS: Disk change detected on device ide1(22,0)".

It's not really Nautilus but a thing called magicdev. Just remove it and
your LED and syslog will be quieter.

	Xav

Re: Need help tracing regular write activity in 5 s interval

[Erik Andersen]

On Tue Jun 04, 2002 at 12:21:20PM +0100, Padraig Brady wrote:
> As an aside, Nautilus (1.0.4) does stuff every 2 seconds
> (checking is there a CD inserted) that causes the disk LED to flash.
> The same action also causes the kernel (2.4.13) to fill up the ring
> buffer with: "VFS: Disk change detected on device ide1(22,0)".

This should fix the symptom...

--- linux/fs/block_dev.c.orig	Tue Jun  4 06:03:44 2002
+++ linux/fs/block_dev.c	Tue Jun  4 06:03:44 2002
@@ -582,8 +582,11 @@
 	if (!bdops->check_media_change(dev))
 		return 0;
 
+	#if 0
+	/* Polling buggy CD-ROM drives can fill the logs.  Make it shutup. */
 	printk(KERN_DEBUG "VFS: Disk change detected on device %s\n",
 		bdevname(dev));
+	#endif
 
 	sb = get_super(dev);
 	if (sb && invalidate_inodes(sb))
 -Erik

--
Erik B. Andersen             http://codepoet-consulting.com/
--This message was written using 73% post-consumer electrons--

Re: Need help tracing regular write activity in 5 s interval

[Padraig Brady]

I'm sure it will :-)

However this it just masking the "problem", and I don't
think it's "buggy CDROM drives" as I've tried 3 different
machines with the following drives:

SAMSUNG DVD-ROM SD-612
TOSHIBA DVD-ROM SD-C2402
CREATIVE CD5233E

and they all show the same problem. I.E. logs filling with
"VFS: Disk change detected on device ide1(22,0)".

magicdev essentially does:

while (1) {
     cd = open ("/dev/cdrom", O_RDONLY|O_NONBLOCK);
     if (ioctl (cd, CDROM_DRIVE_STATUS, CDSL_CURRENT) == CDS_DISC_OK) {
         /* do stuff */
     }
     close(cd);
     sleep(2);
}

Note, it's the open() that causes the check_media_changed(),
so why does this always return true? Is there a way you
can turn it it off? echoing [01] to /proc/sys/dev/cdrom/check_media
made no difference.

Also related, why does the LED flash on every ATA command?
Is this controlled by the drive or ide controller?
Are you telling me that windows would flash the LED every so often
to automount CDs?

thanks,
Padraig.

Erik Andersen wrote:
> On Tue Jun 04, 2002 at 12:21:20PM +0100, Padraig Brady wrote:
> 
>>As an aside, Nautilus (1.0.4) does stuff every 2 seconds
>>(checking is there a CD inserted) that causes the disk LED to flash.
>>The same action also causes the kernel (2.4.13) to fill up the ring
>>buffer with: "VFS: Disk change detected on device ide1(22,0)".
> 
> 
> This should fix the symptom...
> 
> --- linux/fs/block_dev.c.orig	Tue Jun  4 06:03:44 2002
> +++ linux/fs/block_dev.c	Tue Jun  4 06:03:44 2002
> @@ -582,8 +582,11 @@
>  	if (!bdops->check_media_change(dev))
>  		return 0;
>  
> +	#if 0
> +	/* Polling buggy CD-ROM drives can fill the logs.  Make it shutup. */
>  	printk(KERN_DEBUG "VFS: Disk change detected on device %s\n",
>  		bdevname(dev));
> +	#endif
>  
>  	sb = get_super(dev);
>  	if (sb && invalidate_inodes(sb))
>  -Erik
> 
> --
> Erik B. Andersen             http://codepoet-consulting.com/
> --This message was written using 73% post-consumer electrons--

Re: Need help tracing regular write activity in 5 s interval

[Padraig Brady]

Ah I see this is a FAQ:

http://marc.theaimsgroup.com/?l=linux-kernel&m=101279800921627&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=99099294313922&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=98381407016589&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=97661027509987&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=96125325519621&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=95061999803667&w=2 *
http://marc.theaimsgroup.com/?l=linux-kernel&m=94240877002500&w=2
http://marc.theaimsgroup.com/?l=linux-kernel&m=94036109819436&w=2

*here be dragons

Padraig.

Padraig Brady wrote:
> I'm sure it will :-)
> 
> However this it just masking the "problem", and I don't
> think it's "buggy CDROM drives" as I've tried 3 different
> machines with the following drives:
> 
> SAMSUNG DVD-ROM SD-612
> TOSHIBA DVD-ROM SD-C2402
> CREATIVE CD5233E
> 
> and they all show the same problem. I.E. logs filling with
> "VFS: Disk change detected on device ide1(22,0)".
> 
> magicdev essentially does:
> 
> while (1) {
>     cd = open ("/dev/cdrom", O_RDONLY|O_NONBLOCK);
>     if (ioctl (cd, CDROM_DRIVE_STATUS, CDSL_CURRENT) == CDS_DISC_OK) {
>         /* do stuff */
>     }
>     close(cd);
>     sleep(2);
> }
> 
> Note, it's the open() that causes the check_media_changed(),
> so why does this always return true? Is there a way you
> can turn it it off? echoing [01] to /proc/sys/dev/cdrom/check_media
> made no difference.
> 
> Also related, why does the LED flash on every ATA command?
> Is this controlled by the drive or ide controller?
> Are you telling me that windows would flash the LED every so often
> to automount CDs?
> 
> thanks,
> Padraig.
> 
> Erik Andersen wrote:
> 
>> On Tue Jun 04, 2002 at 12:21:20PM +0100, Padraig Brady wrote:
>>
>>> As an aside, Nautilus (1.0.4) does stuff every 2 seconds
>>> (checking is there a CD inserted) that causes the disk LED to flash.
>>> The same action also causes the kernel (2.4.13) to fill up the ring
>>> buffer with: "VFS: Disk change detected on device ide1(22,0)".
>>
>>
>>
>> This should fix the symptom...
>>
>> --- linux/fs/block_dev.c.orig    Tue Jun  4 06:03:44 2002
>> +++ linux/fs/block_dev.c    Tue Jun  4 06:03:44 2002
>> @@ -582,8 +582,11 @@
>>      if (!bdops->check_media_change(dev))
>>          return 0;
>>  
>> +    #if 0
>> +    /* Polling buggy CD-ROM drives can fill the logs.  Make it 
>> shutup. */
>>      printk(KERN_DEBUG "VFS: Disk change detected on device %s\n",
>>          bdevname(dev));
>> +    #endif
>>  
>>      sb = get_super(dev);
>>      if (sb && invalidate_inodes(sb))
>>  -Erik
>>
>> -- 
>> Erik B. Andersen             http://codepoet-consulting.com/
>> --This message was written using 73% post-consumer electrons--

Re: Need help tracing regular write activity in 5 s interval

[Owen Taylor]

Padraig Brady <padraig@antefacto.com> writes:

> I'm sure it will :-)
> 
> However this it just masking the "problem"

Well, the question is, "what is the problem"? 

Your problem is that a debug message is being output by the kernel and
filling your logs. If the debug message doesn't do anybody any good
(and it doesn't) then removing the debug message is a fine way of
solving the problem.

I looked at _why_ the debug message was being generated in this
particular case a long time ago, and it seemed to essentially be a bug
in the IDE code, but other than generating the debug message,
basically a harmless one, and there was no interest in fixing it among
the kernel people I talked to at the time.

(I don't remember details any more; it was several years ago.)

> , and I don't
> think it's "buggy CDROM drives" as I've tried 3 different
> machines with the following drives:
> 
> SAMSUNG DVD-ROM SD-612
> TOSHIBA DVD-ROM SD-C2402
> CREATIVE CD5233E
> 
> and they all show the same problem. I.E. logs filling with
> "VFS: Disk change detected on device ide1(22,0)".

*This* problem is certainly not a buggy CD-ROM. There are other
(rarer) problems with logs filling with magicdev that do have to do
with buggy CD-ROM drives; so that is perhaps what you heard about.

(Most common one is that some Yamaha CD-RW's apparently report media
in the drive when they don't have any media in the drive.  magicdev
tries to mount it, and that failure generates an error message.)

[...] 

> Also related, why does the LED flash on every ATA command?
> Is this controlled by the drive or ide controller?
> Are you telling me that windows would flash the LED every so often
> to automount CDs?

Are you sure that the LED flashing isn't the debug messages being
written to your hard drive?

Regards,
                                        Owen

Re: Need help tracing regular write activity in 5 s interval

[Padraig Brady]

Owen Taylor wrote:
> Padraig Brady <padraig@antefacto.com> writes:
> 
>>I'm sure it will :-)
>>
>>However this it just masking the "problem"
> 
> Well, the question is, "what is the problem"? 
> 
> Your problem is that a debug message is being output by the kernel and
> filling your logs. If the debug message doesn't do anybody any good
> (and it doesn't) then removing the debug message is a fine way of
> solving the problem.

True. But I thought there might be (future) side affects of
cdrom_media_changed() always returning true. Why is it there at all?

> I looked at _why_ the debug message was being generated in this
> particular case a long time ago, and it seemed to essentially be a bug
> in the IDE code

Yes that's my guess, and I may have time to look at it.

, but other than generating the debug message,
> basically a harmless one, and there was no interest in fixing it among
> the kernel people I talked to at the time.
> 
> (I don't remember details any more; it was several years ago.)
> 
> 
>>, and I don't
>>think it's "buggy CDROM drives" as I've tried 3 different
>>machines with the following drives:
>>
>>SAMSUNG DVD-ROM SD-612
>>TOSHIBA DVD-ROM SD-C2402
>>CREATIVE CD5233E
>>
>>and they all show the same problem. I.E. logs filling with
>>"VFS: Disk change detected on device ide1(22,0)".
> 
> *This* problem is certainly not a buggy CD-ROM. There are other
> (rarer) problems with logs filling with magicdev that do have to do
> with buggy CD-ROM drives; so that is perhaps what you heard about.
> 
> (Most common one is that some Yamaha CD-RW's apparently report media
> in the drive when they don't have any media in the drive.  magicdev
> tries to mount it, and that failure generates an error message.)
> 
> [...] 
> 
>>Also related, why does the LED flash on every ATA command?
>>Is this controlled by the drive or ide controller?
>>Are you telling me that windows would flash the LED every so often
>>to automount CDs?
> 
> Are you sure that the LED flashing isn't the debug messages being
> written to your hard drive?

Yep. Good point though.

thanks,
Padraig.

Re: Need help tracing regular write activity in 5 s interval

[Padraig Brady]

[-- Attachment #1: Type: text/plain, Size: 984 bytes --]

Padraig Brady wrote:
> Owen Taylor wrote:
> 
>> Padraig Brady <padraig@antefacto.com> writes:
>>
>>> I'm sure it will :-)
>>>
>>> However this it just masking the "problem"
>>
>>
>> Well, the question is, "what is the problem"?
>> Your problem is that a debug message is being output by the kernel and
>> filling your logs. If the debug message doesn't do anybody any good
>> (and it doesn't) then removing the debug message is a fine way of
>> solving the problem.
> 
> 
> True. But I thought there might be (future) side affects of
> cdrom_media_changed() always returning true. Why is it there at all?

I had a quick look at this and basically cdrom_media_changed()
is only valid when there is a disc in the drive. If the drive
is open or empty then it always returns true. There are a couple
of comments saying it's like this to catch buggy drives, but
hence the interface is broken IMHO and should be removed/fixed?

The attached test program illustrates the problem.

Padraig.


[-- Attachment #2: tcd.c --]
[-- Type: text/plain, Size: 939 bytes --]

#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <linux/ioctl.h>
#include <linux/cdrom.h>

/* drives have capabilities (CDC*) like CDC_MEDIA_CHANGED.
   These done with CDROM_SET_OPTIONS ioctl. perhaps magicdev
   should turn this off as it doesn't use anyway? */

int main(void) {
    int cd = open("/dev/cdrom", O_RDONLY|O_NONBLOCK); /* This causes VFS: disk change ... */
    while(1) {
        //int cd = open("/dev/cdrom", O_RDONLY|O_NONBLOCK);
        printf ("media changed[%d]\n", ioctl(cd, CDROM_MEDIA_CHANGED, CDSL_CURRENT));
        /*
        switch (ioctl(cd, CDROM_DRIVE_STATUS, CDSL_CURRENT)) {
            case CDS_DISC_OK: printf("DISK_OK\n"); break;
            case CDS_TRAY_OPEN: printf("TRAY_OPEN\n"); break;
            case CDS_DRIVE_NOT_READY: printf("DRIVE_NOT_READY\n"); break;
            default: printf("default\n"); break;
        }
        */
        //close(cd);
        sleep(2);
    }
}

Re: Need help tracing regular write activity in 5 s interval

[Thunder from the hill]

Hi,

> So: is there any trace software that can tell me "at 15:52:43.012345,
> process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> detail so I can figure if it's just an atime update -- as with svscan --
> or a write access)? And that is NOT to be attached to a specific process
> (hint: strace is not an option).

Problem: we'd have to do that using printk. printk issues another write 
call, which will mark things dirty. Issued is another printk, which marks 
things dirty and issues another printk...

I suppose one write would become looped here?

Regards,
Thunder
-- 
ship is leaving right on time	|	Thunder from the hill at ngforever
empty harbour, wave goodbye	|
evacuation of the isle		|	free inhabitant not directly
caveman's paintings drowning	|	belonging anywhere

RE: Need help tracing regular write activity in 5 s interval

[Kevin Krieser]

Couldn't you disable syslog and klog for this test?  Just output to the
console.

-----Original Message-----
From: linux-kernel-owner@vger.kernel.org
[mailto:linux-kernel-owner@vger.kernel.org]On Behalf Of Thunder from the
hill
Sent: Sunday, June 02, 2002 10:26 AM
To: Matthias Andree
Cc: Linux Kernel Mailing List
Subject: Re: Need help tracing regular write activity in 5 s interval


Hi,

> So: is there any trace software that can tell me "at 15:52:43.012345,
> process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> detail so I can figure if it's just an atime update -- as with svscan --
> or a write access)? And that is NOT to be attached to a specific process
> (hint: strace is not an option).

Problem: we'd have to do that using printk. printk issues another write
call, which will mark things dirty. Issued is another printk, which marks
things dirty and issues another printk...

I suppose one write would become looped here?

Regards,
Thunder
--
ship is leaving right on time	|	Thunder from the hill at ngforever
empty harbour, wave goodbye	|
evacuation of the isle		|	free inhabitant not directly
caveman's paintings drowning	|	belonging anywhere

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Need help tracing regular write activity in 5 s interval

[Kenneth Johansson]

On Sun, 2002-06-02 at 17:25, Thunder from the hill wrote:
> Hi,
> 
> > So: is there any trace software that can tell me "at 15:52:43.012345,
> > process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> > detail so I can figure if it's just an atime update -- as with svscan --
> > or a write access)? And that is NOT to be attached to a specific process
> > (hint: strace is not an option).
> 
> Problem: we'd have to do that using printk. printk issues another write 
> call, which will mark things dirty. Issued is another printk, which marks 
> things dirty and issues another printk...
> 
> I suppose one write would become looped here?

Been there done that :) 

I turned on debug output for jffs2 without changing klog/syslog to log
to a remote machine. Did not take long for the machine to get unusable.

Re: Need help tracing regular write activity in 5 s interval

[Matthias Andree]

On Sun, 02 Jun 2002, Thunder from the hill wrote:

> Hi,
> 
> > So: is there any trace software that can tell me "at 15:52:43.012345,
> > process 4321 marked 7 blocks dirty on device /dev/hda5" (or even more
> > detail so I can figure if it's just an atime update -- as with svscan --
> > or a write access)? And that is NOT to be attached to a specific process
> > (hint: strace is not an option).
> 
> Problem: we'd have to do that using printk. printk issues another write 
> call, which will mark things dirty. Issued is another printk, which marks 
> things dirty and issues another printk...

Need not be printk, I can also imagine allocating a buffer, switching
this trace on, exempting the tracer from bein traced, and switching the
trace off if the buffer is full.