high cpu usage using nftl for DOC2000

high cpu usage using nftl for DOC2000

[edward jose]

hello,

i don't know if any one else experience this, i have a doc2000 with linux 
2.4.17 kernel compiled with mtd and doc modules. i use the kernel to boot 
the doc2000 everything is ok, but when i check the cpu load, it uses all the 
cpu.  this is the same when i use m-system's kernel module.

can someone explain to me why this happen?

thanks

_________________________________________________________________
MSN 8 helps eliminate e-mail viruses. Get 2 months FREE*. 
http://join.msn.com/?page=features/virus

Re: high cpu usage using nftl for DOC2000

[Selwyn Tang]

Hi Edward,

On 10/02/2003 02:54 PM, edward jose wrote:
> i don't know if any one else experience this, i have a doc2000 with linux 
> 2.4.17 kernel compiled with mtd and doc modules. i use the kernel to boot 
> the doc2000 everything is ok, but when i check the cpu load, it uses all the 

I experienced the same problem recently. I notice that whenever I try to
access the DOC, the process [nftla] starts to use up all the cpu time.
Right now I am suspecting that it is the problem with the filesystem on
the DOC. Sometimes, after running e2fsck on my ext2 partition on the
DOC, the problem just goes away. I have this problem both in 2.4.22 and
2.4.17, both patched with mtd snapshots of different dates. Therefore, I
 think it is a problem with the mtd driver.

Any ideas are appreciated.

Selwyn

Re: high cpu usage using nftl for DOC2000

[David Woodhouse]

On Fri, 2003-10-03 at 10:07 +0800, Selwyn Tang wrote:
> Hi Edward,
> 
> On 10/02/2003 02:54 PM, edward jose wrote:
> > i don't know if any one else experience this, i have a doc2000 with linux 
> > 2.4.17 kernel compiled with mtd and doc modules. i use the kernel to boot 
> > the doc2000 everything is ok, but when i check the cpu load, it uses all the 
> 
> I experienced the same problem recently. I notice that whenever I try to
> access the DOC, the process [nftla] starts to use up all the cpu time.
> Right now I am suspecting that it is the problem with the filesystem on
> the DOC. Sometimes, after running e2fsck on my ext2 partition on the
> DOC, the problem just goes away. I have this problem both in 2.4.22 and
> 2.4.17, both patched with mtd snapshots of different dates. Therefore, I
>  think it is a problem with the mtd driver.

Boot with 'profile=1' and use readprofile to see where it's spending all
the CPU time. Note your driver must be built-in to the kernel for this.

-- 
dwmw2

Re: high cpu usage using nftl for DOC2000

[Selwyn Tang]

Hi Dave,

On 10/03/2003 01:54 PM, David Woodhouse wrote:
> Boot with 'profile=1' and use readprofile to see where it's spending all
> the CPU time. Note your driver must be built-in to the kernel for this.

The followings, among others, are reported by readprofile:

  147 handle_IRQ_event			1.5978
   17 ide_outb				1.4167
 3288 _DoC_Delay			32.8800
 6634 __rdtsc_delay			236.9286

I don't know how to interpret them :-)

Selwyn

Re: high cpu usage using nftl for DOC2000

[David Woodhouse]

On Fri, 2003-10-03 at 16:22 +0800, Selwyn Tang wrote:
> The followings, among others, are reported by readprofile:
> 
>   147 handle_IRQ_event			1.5978
>    17 ide_outb				1.4167
>  3288 _DoC_Delay			32.8800
>  6634 __rdtsc_delay			236.9286
> 
> I don't know how to interpret them :-)

Run it through 'sort -n'. Ignore the third column; the first tells you
how many times, when a timer tick happened, we interrupted the function
named in the second column.

So on 147 occasions when the timer tick happened, the CPU was in
handle_IRQ_event(). During the period of this profiling run, we
(statistically speaking) spent about 1.47 seconds in that function.

We also spend 33 seconds in _DoC_Delay() and 66 seconds in
__rdtsc_delay(). It looks like the flash is very busy. Can you show me
the rest of the profile too?

Also, can you reset the profile counts (readprofile -r) and get a
reading from the time when it's doing this alone, rather than including
everything from boot onwards.

If it does it only sometimes, is there any pattern to when it starts or
stops?

-- 
dwmw2

Re: high cpu usage using nftl for DOC2000

[Selwyn Tang]

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

On 10/03/2003 04:52 PM, David Woodhouse wrote:
> Also, can you reset the profile counts (readprofile -r) and get a
> reading from the time when it's doing this alone, rather than including
> everything from boot onwards.

Here is the output of readprofile after reset and before nftld holds my cpu:

     1 __generic_copy_to_user                     0.0139
     1 write_profile                              0.0208
   380 default_idle                               9.5000
   382 total                                      0.0003

Then I simply entered "ls /mnt/doc" (which is mounted at boot to
/dev/nftla1), and got the following result (I skipped those with one
occasion only):

     2 __delay                                    0.0333
     2 sock_poll                                  0.0500
     2 unix_poll                                  0.0135
     3 __const_udelay                             0.0833
   284 _DoC_WaitReady                             2.8400
   577 __rdtsc_delay                             20.6071
  1199 default_idle                              29.9750
  2084 total                                      0.0018

This is the output a few seconds later (also skipped some lines):

     2 add_wait_queue                             0.0500
     2 __generic_copy_to_user                     0.0278
     2 sock_poll                                  0.0500
     3 __delay                                    0.0500
     3 unix_poll                                  0.0203
     5 __const_udelay                             0.1389
   607 _DoC_WaitReady                             6.0700
  1199 default_idle                              29.9750
  1243 __rdtsc_delay                             44.3929
  3082 total                                      0.0026

So, __rdtsc_delay and _DoC_WaitReady seem to be the source of the
problem. I hope these will help you investigate. I have attached the
three outputs of readprofile for your reference.

> If it does it only sometimes, is there any pattern to when it starts or
> stops?

Once it has started, it would never stop. Sometimes, after fsck on the
doc, and remount, it becomes normal. But this time, I even tried booting
using the doc and perform some operations (like 'find .') and rebooting
back using my harddisk, and also tried booting using dos floppy and used
dinfo without the problem, but when back to Linux the problem was still
there.

I think dformating in dos is my last resort.

Selwyn


[-- Attachment #2: before --]
[-- Type: text/plain, Size: 230 bytes --]

     1 __generic_copy_to_user                     0.0139
     1 write_profile                              0.0208
   380 default_idle                               9.5000
   382 total                                      0.0003



[-- Attachment #3: after --]
[-- Type: text/plain, Size: 1313 bytes --]

     1 add_wait_queue                             0.0250
     1 do_softirq                                 0.0061
     1 do_wp_page                                 0.0020
     1 __find_get_page                            0.0227
     1 __generic_copy_to_user                     0.0139
     1 get_pid                                    0.0029
     1 handle_IRQ_event                           0.0109
     1 journal_add_journal_head                   0.0050
     1 strncpy_from_user                          0.0132
     1 supplemental_group_member                  0.0179
     1 __switch_to                                0.0054
     1 sys_gettimeofday                           0.0032
     1 system_call                                0.0179
     1 tty_poll                                   0.0071
     1 write_profile                              0.0208
     2 __delay                                    0.0333
     2 sock_poll                                  0.0500
     2 unix_poll                                  0.0135
     3 __const_udelay                             0.0833
   284 _DoC_WaitReady                             2.8400
   577 __rdtsc_delay                             20.6071
  1199 default_idle                              29.9750
  2084 total                                      0.0018



[-- Attachment #4: after2 --]
[-- Type: text/plain, Size: 1484 bytes --]

     1 do_anonymous_page                          0.0047
     1 do_softirq                                 0.0061
     1 do_wp_page                                 0.0020
     1 __find_get_page                            0.0227
     1 __generic_copy_from_user                   0.0114
     1 get_pid                                    0.0029
     1 handle_IRQ_event                           0.0109
     1 journal_add_journal_head                   0.0050
     1 __loop_delay                               0.0250
     1 strncpy_from_user                          0.0132
     1 supplemental_group_member                  0.0179
     1 __switch_to                                0.0054
     1 sys_gettimeofday                           0.0032
     1 system_call                                0.0179
     1 tty_poll                                   0.0071
     1 write_profile                              0.0208
     2 add_wait_queue                             0.0500
     2 __generic_copy_to_user                     0.0278
     2 sock_poll                                  0.0500
     3 __delay                                    0.0500
     3 unix_poll                                  0.0203
     5 __const_udelay                             0.1389
   607 _DoC_WaitReady                             6.0700
  1199 default_idle                              29.9750
  1243 __rdtsc_delay                             44.3929
  3082 total                                      0.0026

Re: high cpu usage using nftl for DOC2000

[David Woodhouse]

It looks like it's thrashing the flash, but I can't tell why, since the
NFTL code isn't showing up on the trace. 

Can you throw printk statements into various routines in nftlcore.c so
we can it actually thinks it's doing?

You _are_ mounting your file system with -onoatime, aren't you?

-- 
dwmw2

Re: high cpu usage using nftl for DOC2000

[Selwyn Tang]

On 10/08/2003 05:58 PM, David Woodhouse wrote:
> Can you throw printk statements into various routines in nftlcore.c so
> we can it actually thinks it's doing?

I will try my best to do that later.

> You _are_ mounting your file system with -onoatime, aren't you?

I compiled in the driver to the kernel and set fstab with the line:

  /dev/nftla1	/mnt/doc	auto	defaults	0 0

What do you mean by -onoatime? Should I change "defaults" to "noatime"?

Selwyn

Re: high cpu usage using nftl for DOC2000

[David Woodhouse]

On Wed, 2003-10-08 at 18:16 +0800, Selwyn Tang wrote:
> I will try my best to do that later.

Thanks.

> What do you mean by -onoatime? Should I change "defaults" to "noatime"?

man 8 mount

       noatime
              Access timestamps are not updated when a file is read.
 
With atime enabled, every _read_ of a file or directory causes a write
to the flash, because the 'access timestamp' is updated.

On flash, this is a Bad Thing(tm).

-- 
dwmw2

Re: high cpu usage using nftl for DOC2000

[Selwyn Tang]

On 10/08/2003 06:22 PM, David Woodhouse wrote:
>        noatime
>               Access timestamps are not updated when a file is read.
>  
> With atime enabled, every _read_ of a file or directory causes a write
> to the flash, because the 'access timestamp' is updated.
> 
> On flash, this is a Bad Thing(tm).

I now set fstab to mount it with noatime, but it doesn't help the problem.

Besides, I added a printk to each function in nftlcore.c, printing the
name of the function when it is called, eg. "mtdcore: init_mtd". Then in
boot up, I got the followings:

/**** begin ****/
mtdcore: init_mtd
mtdcore: register_mtd_user
NFTL driver: nftlcore.c $Revision: 1.94 $, nftlmount.c $Revision: 1.34 $
DiskOnChip 2000 found at address 0xD4000
Flash chip found: Manufacturer ID: 98, Chip ID: 73 (Toshiba:NAND 16MiB 3,3V)
1 flash chips found. Total DiskOnChip size: 16 MiB
mtdcore: add_mtd_device
mtd: Giving out device 0 to DiskOnChip 2000
NFTL: add_mtd for DiskOnChip 2000
NFTL: UnitSizeFactor 0x00 detected. This violates the spec but we think
we know what it means...
 nftla: nftla1
/**** end ****/

There are only three mtdcore printk messages here: init_mtd,
register_mtd_user and add_mtd_device. Then I cat'd /proc/kmsg and ls'd
/mnt/doc. nftld immediately held all my cpu time, and /proc/kmsg didn't
give me any messages.

Where should I add printk to to get more clues?

Selwyn

Re: high cpu usage using nftl for DOC2000

[David Woodhouse]

On Thu, 2003-10-09 at 11:54 +0800, Selwyn Tang wrote:
> Besides, I added a printk to each function in nftlcore.c, printing the
> name of the function when it is called, eg. "mtdcore: init_mtd". Then in
> boot up, I got the followings:

strcmp("nftlcore", "mtdcore");

-- 
dwmw2