- PR -

nanoTime()メソッド

1|2 次のページへ»
投稿者投稿内容
風
会議室デビュー日: 2005/12/27
投稿数: 13
投稿日時: 2007-07-08 06:24
初めて投稿させていただきます。

早速ですが、質問です。
現在、System.nanoTime()メソッドを用いて、プログラムの実行時間を測定しています。第一回目と第二回目の測定結果は、なぜそんなに大きな差が生まれますか？

ご存知の方、ご教授いただければ幸いです。

実行の結果：
----------------------------------------------------------------
elapsed time: 49483664　　　　　　　単位：ナノ秒
elapsed time: 347530
elapsed time: 258412
elapsed time: 231370
elapsed time: 287746
elapsed time: 307022
elapsed time: 260648
elapsed time: 349207
elapsed time: 270425
elapsed time: 338032
----------------------------------------------------------------

ソースコード：
----------------------------------------------------------------
import java.io.*;

public class Testa {
　　public static void main(String[] args) {
　　　　　try {
　　　　　　　　　　for(int a=0;a<10;a++)
　　　　　　　　　　{
　　　　　　　　　　　long start = System.nanoTime();

　　　　　　　　　　　ByteArrayOutputStream ob = new ByteArrayOutputStream();
　　　　　　　　　　　ObjectOutputStream objOsw = new ObjectOutputStream( ob );
　　　　　　　　　　　Test k=new Test();
　　　　　　　　　　　objOsw.writeObject(k);
　　　　　　　　　　　objOsw.close();

　　　　　　　　　　　long end = System.nanoTime();
　　　　　　　　　　　System.out.println("elapsed time: " + (end - start));
　　　　　　　　　　}
　　　　　　　}catch (Exception e) {}
　　}
}
----------------------------------------------------------------
よろしくお願いします。
unibon
ぬし
会議室デビュー日: 2002/08/22
投稿数: 1532
お住まい・勤務地: 美人谷　　　　　　　　良回答(20pt)
投稿日時: 2007-07-08 10:24
引用:

龍さんの書き込み (2007-07-08 06:24) より:
elapsed time: 49483664　　　　　　　単位：ナノ秒

単位がナノ秒なのででかく見えますが、およそ50ミリ秒ですよね。
ストリームはループの中で毎回クローズしているので、シリアライズのための時間ではなさそうですし、推測ですが、クラスロードにかかる時間ではないでしょうか。
クラスファイルをハードディスクから読み込むのにかかる時間か、クラスロードの処理そのものにかかる時間のどちらかは分かりませんが。

--
unibon {B73D0144-CD2A-11DA-8E06-0050DA15BC86}
朝日奈ありす
大ベテラン
会議室デビュー日: 2007/05/02
投稿数: 189
お住まい・勤務地: 最北の地
投稿日時: 2007-07-08 11:36
試していないのでエラーがでるかもしれませんが。下記のように経過時間をみてください。
どの初回処理で時間がかかっているかがわかると思います。
コード:
import java.io.*;

public class Testa {
  public static void main(String[] args) {
    try {
      for(int a=0;a<10;a++) {
        long start = System.nanoTime();

        ByteArrayOutputStream ob = new ByteArrayOutputStream();
        System.out.println("> " + (System.nanoTime() -start));

        ObjectOutputStream objOsw = new ObjectOutputStream( ob );
        System.out.println("> " + (System.nanoTime() -start));

        Test k=new Test();
        System.out.println("> " + (System.nanoTime() -start));

        objOsw.writeObject(k);
        System.out.println("> " + (System.nanoTime() -start));

        objOsw.close();
        System.out.println("> " + (System.nanoTime() -start));

        long end = System.nanoTime();
        System.out.println("elapsed time: " + (end - start));
      }
    }catch (Exception e) {
      e.printStak();
    }
  }
}

風
会議室デビュー日: 2005/12/27
投稿数: 13
投稿日時: 2007-07-08 15:37
ご返答ありがとうございます。
杏さんからいただました方法で、詳しい測定しましたが、測定の結果は以下の通りです。結果から観察して、第一回と第二回の処理時間の差は結構大きいです。初学者なので、知識まで足りないと思いますが、もっと詳細に教えていただければ、幸いです。

実行の結果：
----------------------------------------------------------------
>>>>>第1回
> 64813
> 1324470
> 14621970
> 33561808
> 72355
>>>>>第2回
> 7822
> 50006
> 31848
> 314565
> 17600
>>>>>第3回
> 8940
> 50565
> 12851
> 261765
> 17600
>>>>>第4回
> 9778
> 51124
> 30451
> 383289
> 14806
>>>>>第5回
> 8381
> 40787
> 15086
> 230755
> 14806
>>>>>第6回
> 7543
> 40229
> 10895
> 249473
> 15086
----------------------------------------------------------------

ソースコード：
----------------------------------------------------------------
import java.io.*;

public class Testa {
　public static void main(String[] args) {
　　try {
　　　for(int a=1;a<11;a++) {

　　　　　　　System.out.println(">>>>>第"+a+"回");

　　　　　　　long start_1 = System.nanoTime();
　　　　　　　ByteArrayOutputStream ob = new ByteArrayOutputStream();
　　　　　　　System.out.println("> " + (System.nanoTime() -start_1));

　　　　　　　long start_2 = System.nanoTime();
　　　　　　　ObjectOutputStream objOsw = new ObjectOutputStream( ob );
　　　　　　　System.out.println("> " + (System.nanoTime() -start_2));

　　　　　　　long start_3 = System.nanoTime();
　　　　　　　Test k=new Test();
　　　　　　　System.out.println("> " + (System.nanoTime() -start_3));

　　　　　　　long start_4 = System.nanoTime();
　　　　　　　objOsw.writeObject(k);
　　　　　　　System.out.println("> " + (System.nanoTime() -start_4));

　　　　　　　long start_5 = System.nanoTime();
　　　　　　　objOsw.close();
　　　　　　　System.out.println("> " + (System.nanoTime() -start_5));

　　　}
　　}catch (Exception e) {}
　}
}
------------------------------------------------------------------------
風
会議室デビュー日: 2005/12/27
投稿数: 13
投稿日時: 2007-07-08 17:21
引用:

unibonさんの書き込み (2007-07-08 10:24) より:

推測ですが、クラスロードにかかる時間ではないでしょうか。

unibonさん＞
返信ありがとうございます。
測定した結果の第二回から、キャッシュメモリのコピーが使用されるので、第一回と大きな差があるという事で理解して、よろしいでしょか？
ちいにぃ
大ベテラン
会議室デビュー日: 2002/05/28
投稿数: 244
投稿日時: 2007-07-08 23:47
手元でも同じ傾向が見られました。JDK 1.5.0_12 を使用。
値は1000で割ってあります（＝μ秒単位）

elapsed time: 13883.458
elapsed time: 60.626
elapsed time: 42.394
elapsed time: 44.008
elapsed time: 46.028
elapsed time: 42.711
elapsed time: 41.921
elapsed time: 44.068
elapsed time: 44.829
elapsed time: 46.297

jvmstat 3.0 b07のvisualgc で調べてみました。

具体的には、mainの先頭にSystem.in.read() を挿入し、
プログラム起動後にjpsでプロセス番号を取得して、visualgc.cmd に渡した後、
キー入力でループを開始します。

visualgc では次の処理が検出されました。

- Compile Time: 10 compiles - 3.848 ms
- Class Loader Time: 22 loaded, 0 unloaded - 5.463 ms

これがたぶんループの初回で発生しているのだと思います。
ただし、これらの処理を除いても、まだ 13883.458 - (3848 + 5463) = 4572.458 μ秒分の
処理が不明です。
マーサ
ベテラン
会議室デビュー日: 2004/11/26
投稿数: 87
投稿日時: 2007-07-09 14:37
引用:

龍さんの書き込み (2007-07-08 17:21) より:
引用:

unibonさんの書き込み (2007-07-08 10:24) より:

推測ですが、クラスロードにかかる時間ではないでしょうか。

unibonさん＞
返信ありがとうございます。
測定した結果の第二回から、キャッシュメモリのコピーが使用されるので、第一回と大きな差があるという事で理解して、よろしいでしょか？

私の見解もunibonさんと同様です。
そして、龍さんの考えで理解して良いでしょう。

話は変わるのですが、
引用:

ByteArrayOutputStream ob = new ByteArrayOutputStream();
ObjectOutputStream objOsw = new ObjectOutputStream( ob );
Test k=new Test();

for文中でnewを行うのはあまり好ましくありませんね。
極力ループ外でnewを済ませるようにしましょう。
風
会議室デビュー日: 2005/12/27
投稿数: 13
投稿日時: 2007-07-10 00:11
マーサさん
ご返答ありがとうございます。
1|2 次のページへ»

スキルアップ／キャリアアップ（JOB@IT）