clock_gettime()を使った実行時間計測時の差について

for文内に、例えば100個の関数があったとします。
その中の、ある１つの関数(仮にこの関数をhoge()とする)の実行時間計測を以下の２つの方法で行います。

for文内のhoge()以外の関数を無くした状態で、hoge()のみを時間計測
for文内の全ての関数が有る状態で、hoge()のみを時間計測

1と2の計測結果を比較すると、2の方が1よりも計測時間が長くなります。
ということは、for文内の関数が少ない方がhoge()のみを時間計測しているにも関わらず、hoge()の実行時間が短くなっているということになります。

疑問に思っているのは、なぜこの２つで差が出るかです。
考えられる理由としては、LinuxにおけるTickというものが関係しているのかな、と思っています。
自分が使用しているLinuxのCONFIG_HZは1000でしたので、1[msec]の精度でしか時間計測ができないのだと解釈しています。
なので、時間計測をしても、1[msec]進むごとにCPUが時間をカウントしているので結局それよりも細かな精度では時間計測をする事ができないのだと解釈しています。

ですが、それだけだと1と2でなぜ差ができてしまうのかを理解できません。2の場合、hoge()以外の関数がfor文内に有る事で、hoge()の実行が待たされていて、その待たされた分だけ実行時間が伸びたりしているのでしょうか？

以上、よろしくお願い致します。

main() // 1の時の例
{
uint64_t nsec, sec;
struct timespec start, end;
int ERROR=0;
int ii;
for(ii=0; ii<1000000; ii++){
clock_gettime(CLOCK_MONOTONIC, &start);
hoge();
ERROR = clock_gettime(CLOCK_MONOTONIC, &end);
if(ERROR==0){
if((end.tv_nsec - start.tv_nsec) < 0){
end.tv_nsec += 1000000000;
end.tv_sec -= 1;
}
nsec = (end.tv_nsec - start.tv_nsec)/1000; // microsec
sec = (end.tv_sec - start.tv_sec)*1000000; // microsec
}else{
nsec = 0;
sec = 0;
}
ofs << sec << "¥t" << nsec << endl;
}

行動規範の内容に同意します

回答3件

ベストアンサー

こんにちは。

例えば、hogeが0.5mSec程度かかる時、他の関数が無い場合、計時タイマは2回に1回カウントアップします。
他の関数がもし、0.5mSec程度かかっていたら、計時タイマは毎回カウントアップします。
そのような現象が発生しているということはないでしょうか?

hogeの処理時間はどれくらいなのでしょうか?
その時間に対して十分な精度のタイマを用いないと計測は困難と思います。
もしかすると、forループ内に、例えば0mSec以上1.0mSec未満の期間で一様に分布するようなsleep()を入れることで多少は精度改善できるかも知れません。
しかし、hogeだけを十分な回数繰り返し、そのループ全体の処理時間を計測する方が確実です。

投稿2017/01/04 12:44

Chironian

総合スコア23274

退会済みユーザー

2017/01/04 13:21

回答ありがとうございます。 hogeの処理時間は、現状測れている限りでは一回500[nanoSec]ほどです。そもそも、この処理時間に対して一回ずつ測るということが困難なのでしょうか？

Chironian

2017/01/04 13:42

500nSecの時間を1mSec精度のタイマで計測するのは無理と思います。 2000回に1回程度しか1mSec程度のタイマは更新されない筈ですので。ただ、CLOCK_MONOTONICの精度は軽く調べてみた範囲では分かりませんでした。 CONFIG_HZはタイマ割り込み間隔なので、これとは異なる精度かも知れません。

退会済みユーザー

2017/01/04 14:07

2000回に1回程度しかタイマが更新されないのですね。。。調べて下さり、ありがとうございます。それでは、質問をしていた、1と2の差についてはどういった理解をするのが正解なのでしょうか？ 1と2に差が出るのは、計時タイマというものが他の関数がある事によって、カウントアップされてしまい、hoge()の前後で同じように計測しているように思えても、計時タイマのカウントアップの回数が、実は裏では関数のあるなしによって変化しており、それによって差が出てしまう。こういった解釈でよいのでしょうか？よろしくお願い致します。。。

Chironian

2017/01/04 15:02

> 2000回に1回程度しかタイマが更新されないのですね。。。 > 調べて下さり、ありがとうございます。いえ、これは調べた結果ではないです。CLOCK_MONOTONICの精度が1mSecでhoge()の処理時間が500nSecくらいの場合、1,000,000/500=2,000ですから、2,000回に1回と言う単純計算です。 > それでは、質問をしていた、1と2の差についてはどういった理解をするのが正解なのでしょうか？精度不足のタイマで処理時間を計測している場合、追求してもしかたがないと思います。不確定要素が多すぎてなんとも。そもそもCLOCK_MONOTONICの精度は本当に1mSecなのでしょうか？実は100nSecくらいの精度があり、かつ、hoge()の処理時間が他の処理の有無で実際に変わっている可能性もあるのではないでしょうか? (A)hoge()だけのforループ、(B)hoge()以外だけを含むforループ、(C)hoge()とhoge()以外も含むforループについて、それぞれforループ全体の時間を計測することで何か分かると思います。forループ全体が1秒以上かかるなら、1mSec程度の精度で計測しても計測結果の精度は十分でしょう。また、この計測はコンパイル時の最適化をON/OFFの両方で計測することをお勧めします。少なくとも最適化OFFでは(A)+(B)==(C)になる筈です。ならない場合、hoge()とhoge()以外の処理が独立でないということになりますから、ロジックの影響でhoge()の処理時間が変わった可能性もあります。

退会済みユーザー

2017/01/05 10:34

こんばんは。単純計算の件、了解しました。 CLOCK_MONOTONICの精度は、clock_getres()を用いて調べた結果、1[nsec]の精度で計測できるという結果が出てきました。また、(A) + (B) == (C) とはなりませんでした。左辺の計測結果よりも、140秒程右辺の方が長くなっておりました。。。しかし、どう考えてもhoge()は他の関数から独立しています。。。なぜなのか全くわかりません。。ちなみに最適化については、コンパイル時に-o0 とする事でオフになると思いますが合っているでしょうか？

Chironian

2017/01/05 12:30

> 最適化については、コンパイル時に-o0 とする事でオフになると思いますが合っているでしょうか？合ってます。 > 左辺の計測結果よりも、140秒程右辺の方が長くなっておりました。。。 (C)は1ループ当たり140uSec程(A)+(B)より時間がかかるのですね。不思議ですね。ところで、(A), (B), (C)の絶対時間はどの程度だったのでしょうか？ (A)は500nSec * 1,000,000で概ね0.5秒程の筈ですね。（ループ処理でもう少し長い筈ですが。) (B)が150秒だった場合、(A)+(B)=約150秒に対して(C)が290秒なら、もしかするとsharowさんが書かれているキャッシュのヒット・ミスの可能性は出てくると思います。 (A)と(B)がアクセスするメモリが全てキャッシュに入り、(C)ではキャッシュに入りきれないような場合はありえるかも知れません。（私も実際にそのようなケースを目の当たりにしたことはないので、詳しいことは分かりませんが。)

退会済みユーザー

2017/01/09 12:54

回答が遅れてしまい申し訳ないです。本題の件ですが、自分のミスでございました。。。。 hoge以外の関数が、hogeに依存している部分がありました。。。ここまで親身に教えていただいたにもかかわらず、このような結果となってしまい、申し訳ないです。まだ分からないことが多々ありますので、ご教授いただければ幸いです。本当にありがとうございました。

Chironian

2017/01/09 13:22

いいえ、よくあることの一つです。こちらこそ、よろしく。

行動規範の内容に同意します

パイプライン処理・分岐予測・投機実行・メモリキャッシュ・コード最適化技術
このあたりをキーワードについて勉強してみることをおすすめします。

この分野は、アセンブラ言語どころかCPU内部のマイクロコードレベルまで突き詰めなければ具体的な話が
できない実に奥が深い世界なのですが、とりあえずこのあたりの技術概要を知れば、程度問題はさておき
1より2が遅いのが普通だし、A+B=Cとは限らないことも当たり前だと思えるようになると思います。

なお、Z80だとかMC68000だとかのパイプラインもメモリキャッシュもない古いシステムで、コンパイラ
による最適化もなしでやれば1=2かつA+B=Cになるはずです。古いCPU（の載った環境）のエミュレータを
探して、処理にかかったクロックカウント（実行時間だと、エミュレータが動作クロックまでを
エミュレートしていない限り、エミュレータを動かす側で1クロックあたりの時間が変動するため）を
比較できればいいのですが。

投稿2017/01/07 22:23

himazin.blm

総合スコア596

退会済みユーザー

2017/01/09 12:55

非常に参考になりました。勉強させていただきます。ありがとうございました。

行動規範の内容に同意します

自分が使用しているLinuxのCONFIG_HZは1000でしたので、1[msec]の精度でしか時間計測ができないのだと解釈しています。

それはタイマー割り込みの頻度です。

clock_gettime()の精度はclock_getres()で取得できます。

c
1#define _GNU_SOURCE
2
3#include <stdio.h>
4#include <time.h>
5
6int main(void)
7{
8    struct timespec ts;
9    clock_getres(CLOCK_MONOTONIC, &ts);
10    printf("tv_sec: %lld\n", (long long)ts.tv_sec);
11    printf("tv_nsec: %lld\n", (long long)ts.tv_nsec);
12}

私の環境では1ns(1ナノ秒)でした。環境や設定(clocksource)で異なるのでご自身の環境で確認してみてください。Intel系でTSCを使っていればみんな10ns以下だとは思います。

本題の方ですが、hoge()以外の関数がたくさんあることでCPUのキャッシュのヒット率には多少の差がでると思われます。linuxのPerfはハードウェアが対応していればキャッシュのヒット率なども取得できるのでこれらの情報も何かヒントになるかもしれません。

投稿2017/01/04 16:57

sharow

総合スコア1151

退会済みユーザー

2017/01/05 10:49

回答ありがとうございます。本日確認したところ、自分の環境でも1[nsec]の精度であると出ました。また、キャッシュ情報ですが、 1.の時 8226263758 cycles 6293569532 instructions 70999935 cache-references 4355879 cache-misses 3.103704084 seconds time elapsed 0.765 IPC 2.の時 278614996415 cycles 437980263462 instructions 184177558 cache-references 24264648 cache-misses 104.866233353 seconds time elapsed 1.572 IPC となりました。

sharow

2017/01/05 15:36

情報ありがとうございます。総実行命令に占めるキャッシュミスの割合の差が1と2で10倍以上ありますね。それによってでしょうか、1のIPC(Instruction per cycle)である0.765は私の感覚では高すぎる気がします。つまり・・これは私の印象ですが、2が遅くて1が速いのではなく、2は普通で1が理想に近い実行効率を出してる感じがします。その理由をキャッシュだけに求めるのは無理があるかもしれませんが、頂いたデータからは1要因として考えられるかもしれません。

退会済みユーザー

2017/01/09 12:57

新しい側面からの情報を与えてくださり、参考になりました。ありがとうございました。

行動規範の内容に同意します

あなたの回答