2002-06-02 13:55:05

by Matthias Andree

[permalink] [raw]
Subject: Need help tracing regular write activity in 5 s interval

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


2002-06-02 15:25:57

by Thunder from the hill

[permalink] [raw]
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

2002-06-02 15:41:05

by Kevin Krieser

[permalink] [raw]
Subject: RE: Need help tracing regular write activity in 5 s interval

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

-----Original Message-----
From: [email protected]
[mailto:[email protected]]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

2002-06-02 16:12:13

by Kenneth Johansson

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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.

2002-06-02 20:19:49

by Matthias Andree

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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.

2002-06-04 11:21:35

by Padraig Brady

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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.

2002-06-04 11:43:57

by Xavier Bestel

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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

2002-06-04 11:43:41

by Muli Ben-Yehuda

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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/


Attachments:
(No filename) (977.00 B)
(No filename) (189.00 B)
Download all attachments

2002-06-04 12:04:38

by Erik Andersen

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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--

2002-06-05 14:09:09

by Padraig Brady

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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--



2002-06-05 15:13:54

by Padraig Brady

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

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--

2002-06-05 15:50:23

by Owen Taylor

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval


Padraig Brady <[email protected]> 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

2002-06-05 16:44:49

by Padraig Brady

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

Owen Taylor wrote:
> Padraig Brady <[email protected]> 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.

2002-06-05 22:21:58

by Padraig Brady

[permalink] [raw]
Subject: Re: Need help tracing regular write activity in 5 s interval

#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);
}
}


Attachments:
tcd.c (939.00 B)