[Armadillo:03328] Re: NAND上のファイルへのlsに時間がかかります

fukunaga email@hidden
2008年 8月 27日 (水) 13:40:38 JST


福長と申します。(本件の質問をした高橋の同僚です。)

>At Wed, 06 Aug 2008 11:38:00 +0900,
>Yasushi SHOJI wrote:
>というスクリプトで1日動かしてみたのですが、lsの速度は変りませんでした。
>8時間で2400回くらいループします。

実験していただきありがとうございます。
こちらでも試していたのですが、マウント後にlsが遅くなる現象の
再現方法がわかりました。

以下のような、open,write,closeを繰り返すプログラムを作成します。
(エラー処理は省略しています。)
(同一ファイルに上書きするので、繰り返してもファイルサイズは変わりません。
 書き出す内容も固定です。)

void test1( int cnt )
{
     int     i;
     FILE    *file;

     for( i=0; i<cnt; i++ ){
         file = fopen( "/mnt/nand/test.csv", "w" );
         fputs( "1234567890", file );
         fclose( file )
     }
}

NANDに弊社で必要な実行環境を全て入れます。(lighttpdなど)
以下のようなディレクトリ構成です。
(コピーするだけで、いずれも動作はさせません。)

/mnt/nand/etc:
/mnt/nand/etc/config:
/mnt/nand/etc/init.d:
/mnt/nand/etc/rc.d:
/mnt/nand/lib:
/mnt/nand/sbin:
/mnt/nand/usr:
/mnt/nand/usr/bin:
/mnt/nand/usr/lib:
/mnt/nand/usr/lib/lighttpd:
/mnt/nand/usr/sbin:
/mnt/nand/usr/弊社アプリ:
/mnt/nand/var:
/mnt/nand/var/log:
/mnt/nand/var/spool:
/mnt/nand/var/spool/cron:
/mnt/nand/var/spool/cron/crontabs:

この環境で、上記テストプログラムを10万回ループさせると、
マウント後のlsに14秒程度かかるようになりました。

ここで問題なのは、実行環境がない場合(flash_eraseall直後で
ファイルやディレクトリがない場合)には、100万回ループさせても
現象は発生しません。
ファイルやディレクトリがあることが問題となるようです。

上でlsが遅くなったNANDに、さらに10万回ループを実行すると、
マウント直後のlsが3分になりました。
その後、一旦NANDをアンマウントしてマウントしなおすと、今度は
51秒になりました。マウント後のlsの前後でのdfでみた使用量をみると
若干減っており、ガベッジコレクトされた様子がありますが、
その後、アンマウント、マウントを繰り返しても、lsは51秒のままで
Usedのサイズも変化がありません。
(詳細は下記の実験ログ)

ちなみにループを100万回実行すると、1時間かかってもlsが返って
こなくなりました。

---------------------------------------以下、実験のログ
<10万回  1回目>
・10万回書いてみる
・実行直後(ここでのlsは速い)
         [email@hidden (ttyAM0) /mnt/nand]# time ls -lhaR /mnt/nand/
         (中略)
         real    0m 1.52s
         user    0m 0.14s
         sys     0m 1.38s
・アンマウントして再度マウント
         [email@hidden (ttyAM0) /]# time mount -t jffs2 /dev/mtdblock4 /mnt/nand
         real    0m 5.01s
         user    0m 0.00s
         sys     0m 5.02s

         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144     11208    250936   4% /mnt/nand

・lsしたら遅くなった!!14秒かかっている。
         [email@hidden (ttyAM0) /mnt/nand]# time ls -lhaR /mnt/nand/
         (中略)
         real    0m 14.87s
         user    0m 0.11s
         sys     0m 1.44s

<10万回  2回目>
・もう10万回やる
・実行直後(ここでのlsは速い)
         [email@hidden (ttyAM0) /mnt/nand]# time ls -lhaR /mnt/nand/
         (中略)
         real    0m 1.53s
         user    0m 0.15s
         sys     0m 1.39s
・アンマウントしてmount,df,ls,dfを連続して行う
         [email@hidden (ttyAM0) /]# time mount -t jffs2 /dev/mtdblock4 /mnt/nand
         real    0m 5.84s
         user    0m 0.01s
         sys     0m 5.82s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144     13124    249020   5% /mnt/nand
         [email@hidden (ttyAM0) /]# time ls -lhaR /mnt/nand/
         (中略)
         real    3m 42.03s
         user    0m 0.10s
         sys     3m 38.16s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144      9228    252916   4% /mnt/nand

         lsに3分かかるようになった。ls前のNANDのUsedは13124。
         もう一度、アンマウントとマウント

         [email@hidden (ttyAM0) /]# cd /;umount /mnt/nand
         [email@hidden (ttyAM0) /]# time mount -t jffs2 /dev/mtdblock4 /mnt/nand
         nt/nand/
         df
         real    0m 4.90s
         user    0m 0.00s
         sys     0m 4.90s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144     11076    251068   4% /mnt/nand
         [email@hidden (ttyAM0) /]# time ls -lhaR /mnt/nand/
         (中略)
         real    0m 51.98s
         user    0m 0.14s
         sys     0m 49.03s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144      9228    252916   4% /mnt/nand


         今度は51秒でいけたなあ。ls前のNANDのUsedは11076に減っている。
         もう一度、アンマウントとマウント

         [email@hidden (ttyAM0) /]# cd /;umount /mnt/nand
         [email@hidden (ttyAM0) /]# time mount -t jffs2 /dev/mtdblock4 /mnt/nand
         nt/nand/
         df
         real    0m 4.90s
         user    0m 0.01s
         sys     0m 4.89s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144     11076    251068   4% /mnt/nand
         [email@hidden (ttyAM0) /]# time ls -lhaR /mnt/nand/
         real    0m 52.03s
         user    0m 0.14s
         sys     0m 49.10s
         [email@hidden (ttyAM0) /]# df
         Filesystem           1k-blocks      Used Available Use% Mounted on
         /dev/ram0                 8059      5855      1795  77% /
         /dev/mtdblock4          262144      9228    252916   4% /mnt/nand

         今度は52秒であまりかわらない。
         mount前のUsedが前回とかわってない。11076

---------------------------------------実験のログ ここまで





==============================================
<CEW>(株)中央製作所    http://www.cew.co.jp
         技術部 設計二課       福長 明子
         E-Mail  email@hidden
         TEL     0223-34-3317
         FAX     0223-34-3487




armadillo メーリングリストの案内