clock_gettime()

Question

###前提・実現したいこと
現在、Linux上でgccを使ってソースコードをコンパイルしています。clock_gettime()を使ってソースコード内の各処理の時間を計測しているのですが、上手くいきません。
実現したいことは、for文内にある各クラスのインスタンスのメンバ関数の実行時間を、実行する度に計測し、ファイルに吐き出します。後に、吐き出したデータをエクセルで集計し、どこでどれだけ時間が掛かっているかを知りたいです。

###発生している問題・エラーメッセージ

エラーメッセージ

###該当のソースコード

ここにご自身が実行したソースコードを書いてください

const static uint32_t NANO2SEC = 1000000000;
main()
{
uint64_t time;
struct timespec start, end;
int ERROR=0;
int ii;

for(ii=0; ii<1000000; ii++){
    clock_gettime(CLOCK_MONOTONIC, &start);
    hoge->Exec();
    ERROR = clock_gettime(CLOCK_MONOTONIC, &end);
    if(ERROR==0){
        if((end.tv_nsec - start.tv_nsec) < 0){
            end.tv_nsec += NANO2SEC;
            end.tv_sec  -= 1;
        }
        time  = end.tv_nsec - start.tv_nsec;
        time += end.tv_sec  - start.tv_sec;
    }else{
        time = 0;
    }
    ofs << time << endl;

以下、同じ様にそれぞれのメンバ関数の実行時間を計測して行く。
}
###試したこと
課題に対してアプローチしたことを記載してください
各クラスのメンバ関数の実行を回しているfor文の中で、ある一つのメンバ関数以外をコメントアウトして実行時間を計測した場合と、コメントアウトを外して全てのメンバ関数を実行して計測したのですが、実行時間が異なっていました。
何故、２つの場合で異なるのかを教えていただきたいです。
###補足情報(言語/FW/ツール等のバージョンなど)
追記2016/12/27/20:30
早速の回答ありがとうございます。
情報不足でした。２つのソースコードが有りまして、それぞれのソースコードでは、同じクラスのメンバ関数を実行している箇所があります。
なので、その２つのソースコードないで同じ様に時間を計測すれば、その箇所だけで見れば似た様な計測結果となるはずなのです。
しかし、実際に測ってみると3分程の差がありました。
なので、自分のclock_gettime()の使い方が間違っているのかと思っております。
以上、よろしくお願いします。

Comments

[yohhoy]

計測対象が異なれば実行時間が異なると考える方がずっと自然に思えますが、どういうニュアンスの質問でしょうか？

Answer 1

処理の最適化などを実施する際に、C/C++の環境であれが、プロファイラと言う機能を利用すると
実施されたいことが楽になるかと思います。

「GNUプロファイラーによるコード処理速度の向上」
http://www.ibm.com/developerworks/jp/linux/library/l-gnuprof/

が参考になるかと思います。

Comments

[退会済みユーザー]

すみません、間違えてベストアンサーを押してしまいました。。。

本日確認させていただきます。
ありがとうございます。

[nagaetty]

了解です。

Answer 2

こんにちは。

計測が疑わしいのであれば、信頼できる時間を計測してみると良いですよ。
hoge->Exec();の代わりに例えばsleep(3);とするなどです。
3秒を幾つか振ってみて、近しい値が出るなら計測は間違っていないことになります。

しかし、下記はまずいと思いますよ。単純ミスでしょうか?

time = end.tv_nsec - start.tv_nsec;

time += end.tv_sec - start.tv_sec;

あと、nsecの差分が負なら秒を+1しているようですが、主旨が見えません。
これも何か不具合を発生させていそうな印象をうけます。この処理は外しした方がよいように感じます。

最後に、ソース・コードは「ここにご自身が実行したソースコードを書いてください」1行を削除して、そこに貼り付けて下さい。インデントが反映されるようになります。

Comments

[退会済みユーザー]

回答ありがとうございます。

sleep()で試したのですが、近しい値は出ていました。
申し訳ないです、ミスとは具体的にどこのことを言っているのか教えていただけるとありがたいです。。。
timeにはtv_secとtv_nsecの２つを合算する事で経過時間を出す事ができると認識しています。

本日、もう一度確認してから返答させていただきます。
夜になるとは思いますがよろしくお願いします。

[Chironian]

> sleep()で試したのですが、近しい値は出ていました。

近しい値がでているのでしたら、clock_gettime()の使い方ミスではないのでは？
お使いのソースコードを提示されているのでしたら、それはありえません。
timeに入る値は3からはかけ離れていることがほとんどの筈です。どうやって「近しい」と判断されたのでしょうか？

> timeにはtv_secとtv_nsecの２つを合算する事で経過時間を出す事ができると認識しています。

秒とナノ秒の値を単純に足し算した結果の「経過時間」の単位は何でしょうか？
そして、例えば、tv_secの差分が3秒、tv_nsecの差分が1,234ナノ秒の時、足し算したら1,237になります。sleep()での検証時この値が「近しい値」になったのですか？ sleep(3);なら「3秒」が近しい値ですが、timeにはどんな値が入っていましたか？

[退会済みユーザー]

遅くなって申し訳ありません。
NANO2SECを書き忘れていましたね。。。
すみません。
sleep(3);の時は3000160000などの値が入っていました。

本日判明したことをお伝えします。
ファイルに出力する際に、
time = end.tv_nsec - start.tv_nsec;
time += (end.tv_sec - start.tv_sec)*NANO2SEC;
の計算結果を出力していたのですが、これだと何故か計算結果が全く違うものになってしまっていたので、中身を調べて見たところどうやら11桁を超えるとオーバーフローしてしまう様で、少し変えました。

double sec=0;
double nsec=0;

と２つの変数を用意し、timeだった部分を

nsec = (end.tv_nsec - start.tv_nsec)/1000.0;
sec = (end.tv_sec - start.tv_sec)*1000000;

としました。
ファイル出力もsecとnsecで分けて出力し、後でエクセルで計算したところ期待の結果となっていました。

そこでまた疑問が出てきたのですが、こちらのコメント欄ですと見辛いと思いますので、新たに質問させていただきたいと思います。
失礼しました。

[Chironian]

なるほど。やはり書き忘れでしたか。

数値計算する際には計算精度に注意下さい。特に時刻は桁数が多いので要注意です。
NANO2SECは10の9乗ですので約27ビットあります。出力する際にint型を使った場合、多くの処理系でのint型は符号付きで32ビットなので、有効桁は31ビットです。すると31-27=4ビットしか秒を表現するのに使えません。したがって16秒程度しか表現できません。簡単にオーバーフローします。
long longなら64ビット使える処理系が多いので、オーバーフローは事実上しなくなると思います。

ビット数は処理系依存なので、処理系に依存しないuint32_tやuint64_tを使うと安心です。
処理系がサボートしていない場合はコンパイル・エラーになる筈ですので事前に不具合検出できます。

[退会済みユーザー]

Chironian様

明けましておめでとうございます。

非常に参考になりました。ありがとうございました。

改めて、質問を致しましたので、よければ見ていただけると幸いです。

よろしくお願い致します。

PleaseSaveYuri