(toppers-users 2281) 時間計測とsyslog

[Tetsuo TAKAHASHI]

高橋と申します。

SH4 7750 をターゲットに使用した開発を行っています。
今のところターゲットがないので、サンプルとしてMS7750SE01を 
用いて試用しています。

ターゲットに載せる予定の処理が、想定している時間内で終了するかど 
うかを確認する為、
以下のようなテストを実施しています。

1.タスク１つのみを実行する。
2.1.のタスク内で必要な処理(処理A)を実行する。
3.処理Aが、どのくらいの処理時間が必要なのか測る為、処理 
Aの前後で時刻を取得。
4.時刻の取得には、vxget_tim()を使用する。
5.取得した2つの時刻から、処理時間を計算し、syslog() 
で出力する。

下記の様なコードになります。
#簡略化して書きます。

main_task()
{
     ...

     vxget_tim(&t1); // start time
     example();
     vxget_tim(&t2); // end time

     time = t2 - t1;

     syslog(LOG_NOTICE,"time %d",time);

     ...
}

ここで、質問というか疑問なのですが、時間計測の前後(start time/ 
end timeの外側)で、
別途syslog()で文字の出力をしようとした所、上記で実施してい 
る時間計測に1secオーダ
の違い(3secで終了するはずが5secかかるとか)が出 
ました。

具体的には、
main_task()
{
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");

     vxget_tim(&t1); // start time
     example();
     vxget_tim(&t2); // end time

     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");
     syslog(LOG_NOTICE,"aaaaaaaaaaaaa");

     time = t2 - t1;

     syslog(LOG_NOTICE,"time %d",time);

}
と言う記述をしてます。

時間計測の間にsyslog()を入れたのであれば、当然時間が変化す 
るのは分かるのですが、
外側に入れて処理Aの処理時間が変わる(というか時刻の取 
得タイミングが変わる？)原因が
つかめないでいます。

このような現象について、何かご存知の方はいらっしゃらないでしょう 
か？
それとも、そもそも何か間違っているのでしょうか？


PS:
config/sh3/solution_engine/ms7750se01.h
内の記述で、
/*
*  キャッシュモードの設定
*  P0,U0,P1ライトスルーモード
*/
#define CCR_MODE      0x0000898d

とありますが、コピーバックモードの設定のように見えるのです 
が・・・。
SHの設定は、経験が少ないので勘違いかもしれません。

--
// Tetsuo TAKAHASHI <tetsu-t ＠ mbd.ocn.ne.jp>