BeagleBone Blackを試す (4)

前回に引き続きBBB (BeagleBone Black、以下同様) 上のDebian weezyでADC (Analog-to-Digital Converter、以下同様) を使ってみる。今回はADCから値を読むのに要する時間を詳しく調べた。

プログラミング言語はPythonに加え、処理速度の比較のためにCも使った。

/*-----------  -----------*/

Pythonだから遅い?

前回Pythonで作ったプログラムは、どれもサンプルを1つ読むのに約1.2msかかっていた。これはPythonだから遅い可能性を否定できない。Cで書けば1/10位になるかもしれないので、出来るだけ余計な処理をせずに実行時間を計るプログラムを作って確かめることにした。

CPUクロックについて

BBBのSoC Ti AM3359に入っているCortex A8プロセッサーはクロック周波数可変である。ディフォルト設定は

debian@arm:~$ cpufreq-info
cpufrequtils 008: cpufreq-info (C) Dominik Brodowski 2004-2009
Report errors and bugs to cpufreq@vger.kernel.org, please.
analyzing CPU 0:
  driver: generic_cpu0
  CPUs which run at the same hardware frequency: 0
  CPUs which need to have their frequency coordinated by software: 0
  maximum transition latency: 300 us.
  hardware limits: 300 MHz - 1000 MHz
  available frequency steps: 300 MHz, 600 MHz, 800 MHz, 1000 MHz
  available cpufreq governors: conservative, ondemand, userspace, powersave, performance
  current policy: frequency should be within 300 MHz and 1000 MHz.
                  The governor "ondemand" may decide which speed to use
                  within this range.
  current CPU frequency is 300 MHz.
  cpufreq stats: 300 MHz:nan%, 600 MHz:nan%, 800 MHz:nan%, 1000 MHz:nan%

クロック周波数は300MHz～1GHzの間の (正確には300、600、800、および1000MHzのとびとびの) 値を取る。負荷の増減に応じてクロック周波数を変えるようソフトウエアで制御しているのだ。普段CPUの負荷が低いときは最低の300MHzで動かしていて負荷が増えるとクロック周波数を上げるのだが、これには遅れが伴う。ハードウエアのレイテンシーは300µs以下と表示されているが、CPU負荷が増えたとソフトウエアが認識してクロック周波数を変えるのには桁違いに長い時間がかかる。ディフォルト設定の状態で試すと400ms程度かかり、試す都度時間が変わっていた。これでは処理時間の比較に不都合なのでcpufreq-setコマンドを使ってクロックを固定する。

debian@arm:~$ sudo cpufreq-set --min 1GHz
[sudo] password for debian:
debian@arm:~$ cpufreq-info
cpufrequtils 008: cpufreq-info (C) Dominik Brodowski 2004-2009
Report errors and bugs to cpufreq@vger.kernel.org, please.
analyzing CPU 0:
  driver: generic_cpu0
  CPUs which run at the same hardware frequency: 0
  CPUs which need to have their frequency coordinated by software: 0
  maximum transition latency: 300 us.
  hardware limits: 300 MHz - 1000 MHz
  available frequency steps: 300 MHz, 600 MHz, 800 MHz, 1000 MHz
  available cpufreq governors: conservative, ondemand, userspace, powersave, performance
  current policy: frequency should be within 1000 MHz and 1000 MHz.
                  The governor "ondemand" may decide which speed to use
                  within this range.
  current CPU frequency is 1000 MHz.
  cpufreq stats: 300 MHz:nan%, 600 MHz:nan%, 800 MHz:nan%, 1000 MHz:nan%

ちなみに1000MHz = 1GHzだ。正式なドキュメントに記述されていないが周波数の単位は最初の一文字だけ、例えば1GHzの代わりに1Gでも大丈夫だった。再起動するとディフォルト設定に戻ったハズなので、必要なら再びクロック周波数を固定するのを忘れないよう注意が必要だ。なおcpufreq系のコマンドがcommand not foundになる場合、apt-getでcpufrequtilsパッケージをインストールする必要がある。

前回のプログラムはnumpyなどかなり規模の大きなモジュールをimportしている。その際比較的長時間 (0.5秒以上) CPUに負荷がかかりクロックは間違いなく上限まで達するので、特にCPUクロックを固定していなかったが影響はほとんど無いはずである。

ADCの読み込み時間比較のプログラム

先ず前々回同様P9_39 (AIN0) とP9_39 (GNDA_ADC)の間に100kΩの抵抗を接続しておく。

同時に他のタスクが動こうとする可能性を出来るだけ小さくするためstartxしていない環境を使う。ただし結果をコピー/ペーストするためTera Termを使いsshセッションで実行している。時間計測対象のADCから値を読む処理中はコンソールとの入出力が無いので、これはプログラムが表示する結果にほとんど影響ないハズだ。

先ずPythonバージョン。

debian@arm:~$ cd python/
debian@arm:~/python$ cat read_adc.py
#!/usr/bin/python

import timeit, os, adc_path

raw0 = adc_path.get_raw_path(0)
raw_name = os.path.split(raw0)[-1]
adc_value = 0

print "\nPython: Reading 1,000 ADC samples from %s" % raw_name

f = open(raw0, "r", 0)
start = timeit.default_timer()
for i in range(1000):
    adc_value += int(f.readline() )
    f.seek(0, 0)
end = timeit.default_timer()
f.close()
diff = end - start

print "The average value of %s = %.3f" % (raw_name, 1e-3 * adc_value)
print "Time elapsed %.3f [sec or ms/sample]" % diff
debian@arm:~/python$ time ./read_adc.py

Python: Reading 1,000 ADC samples from in_voltage0_raw
The average value of in_voltage0_raw = 24.492
Time elapsed 1.087 [sec or ms/sample]

real    0m1.227s
user    0m0.109s
sys     0m1.100s

実行時間に関する情報を得るためLinuxのtimeコマンドを使った。realは実時間で、これには目的のプログラムを実行していない時間も含まれる。userとsysはCPUの使用時間で、それぞれユーザーとカーネルモードの値である。つまりこの場合だと処理全体に1.227秒かかったが、その間でCPUを使えたのは0.109 + 1.100 = 1.209秒で、残り0.018秒はこのプログラム以外のタスクを実行していた。これらの数値から目的のプログラムの全実行期間平均CPU使用率 = 100 × (user + sys) ÷ real = 100 × 1.209 ÷ 1.227 = 98.5 [%] と計算できる。

ただしこれらの数値には結果を出力する処理や、プログラムには現れない実行環境を初期化する処理の時間が含まれ、Pythonでは後者がかなり長い (100ms以上)。

次にCバージョン。

debian@arm:~/python$ cd ../C/read_adc/
debian@arm:~/C/read_adc$ cat read_adc.c
#include <stdio.h>
#include <time.h>

int main(int argc, char *argv[]){
        FILE *Handle = NULL;
        char *Raw0 = "/sys/bus/iio/devices/iio:device0/in_voltage0_raw";
        struct timespec start, end;
        int i, j, adc_value = 0;
        float diff;

        printf("\nC: Reading 1,000 ADC samples from in_voltage0_raw\n");

        if((Handle = fopen(Raw0, "r")) == NULL){
                printf("Unable to open the adc.\n");
                return 1;
        }
        setbuf(Handle, NULL);
        clock_gettime(CLOCK_MONOTONIC, &start);
        for(i=0; i<1000; i++) {
                fscanf(Handle, "%d", &j);
                adc_value += j;
                fseek(Handle, 0, SEEK_SET);
        }
        clock_gettime(CLOCK_MONOTONIC, &end);
        fclose(Handle);
        diff += (float) (end.tv_sec - start.tv_sec)
                        + 1e-9 * (end.tv_nsec - start.tv_nsec);

        printf("The average value of in_voltage0_raw = %.3f\n", 1e-3 * adc_value);
        printf("Time elapsed %.3f [sec or ms/sample]\n", diff);

        return 0;
}
debian@arm:~/C/read_adc$ gcc -v -o read_adc read_adc.c -lrt
    (中略)
debian@arm:~/C/read_adc$ time ./read_adc

C: Reading 1,000 ADC samples from in_voltage0_raw
The average value of in_voltage0_raw = 24.417
Time elapsed 1.066 [sec or ms/sample]

real    0m1.076s
user    0m0.016s
sys     0m1.053s

毎回ちゃんとAD変換した値を読み込んでいることを確認するため平均値を表示するようにした。たとえばCでfseek(Handle, 0, SEEK_SET); を入れ忘れてしまうと

time ./read_adc

C: Reading 1,000 ADC samples from in_voltage0_raw
The average value of in_voltage0_raw = 24.000
Time elapsed 0.004 [sec or ms/sample]

real    0m0.013s
user    0m0.000s
sys     0m0.008s

1回目はADCから値を読み込むが、2回目以降はfscanfがエラーになりjの値が更新されない。しかしそのまま処理を続けてしまうので非常に短い時間で実行が終わるが、平均値の小数点以下が全てゼロになるので、毎回ちゃんとAD変換した値を読んでいないことがわかる。このケースでPythonなら例外が発生するが、そうならない場合が無いとも限らないのでこの様なチェックを入れている。

ADCの読み込み時間の比較結果

結果をまとめよう。特に記載した場合を除き数値の単位は秒である。

言語	試行	ADC読み込み	time (real)	time (user)	time (sys)	CPU使用率 [%]	CPU使用率残り [%] (100 - CPU使用率)
Python	1	1.087	1.227	0.109	1.100	98.5	1.5
	2	1.086	1.224	0.109	1.100	98.8	1.2
	3	1.086	1.225	0.102	1.111	99.0	1.0
	4	1.086	1.224	0.113	1.104	99.4	0.6
	5	1.086	1.225	0.107	1.107	99.1	0.9
	平均	1.086	1.225	0.108	1.104	99.0	1.0
C	1	1.066	1.076	0.012	1.055	99.2	0.8
	2	1.066	1.077	0.002	1.064	99.0	1.0
	3	1.066	1.077	0.021	1.045	99.0	1.0
	4	1.064	1.075	0.006	1.059	99.1	0.9
	5	1.066	1.077	0.008	1.059	99.1	0.9
	平均	1.066	1.076	0.010	1.056	99.1	0.9

PythonとCそれぞれ5回ずつ試したが特に極端な値は無かったので全ての平均を取った。他のどの数字も大きな変動は無いが、CPU使用率残りだけ0.6～1.5%とバラつきが大きくなっている。これは目的のプログラムと同時に動こうとしたタスクの状況に左右され、それには偶然の要因が多いからである。

ADCを1,000回読み込むのに要した時間はCが1.066秒であるのに対してPythonは1.086秒で確かに遅いが、その違いは2%未満である。これは実時間の比較だ。しかしCPU使用率が100%に近いので、CPU時間で比較しても

言語	ADCの値を読むのに要したCPU時間
Python	1.086 × 0.990 = 1.075 [秒]
C	1.066 × 0.991 = 1.056 [秒]

結論は変わらない。

PythonもCも同じインターフェイスを使っているので、ADCから値を読むのに必要なカーネルモードのCPU時間に違いは無いと考えられる。つまり差は全てユーザーモードで使っている時間の差だ。

Cの場合timeコマンドが出力したユーザーモードで使用したCPU時間が10msである。これにはADCを読む以外、例えば結果の出力や実行環境の初期化に使った時間も含まれるので、ADCを読むのに使ったCPU時間は0～10msの範囲だ。Pythonはこれより19ms余計に時間がかかり、この部分だけだとかなり大きな差になる可能性がある。経験的に10倍近く違うのは良くあることなので、妥当な範囲ではないだろうか。しかしカーネルモードでCPUを1秒、ADCのサンプル1つ当たりだと1ms以上使っていて、全体の処理時間はほとんどこの部分で決まってしまう訳だ。

Cの場合、ADCを1,000回読むのにユーザーモードでCPUを5ms使っていたと仮定すると、それぞれの場合で使用したCPU時間の内訳は以下の様に推定できる。

CPU使用時間内訳 (推定)	Python (user)	Python (sys)	Python (合計)	C (user)	C (sys)	C (合計)
ADCから値の読み込み	0.024	1.051	1.075	0.005	1.051	1.056
実行環境の初期化と結果の出力	0.084	0.053	0.137	0.005	0.005	0.010
合計	0.108	1.104	1.212	0.010	1.056	1.066

ADC以外のGPIO

ADCの変換時間は5µsだったハズである。sysfsにエクスポートするため文字列変換するのにある程度時間がかかるが、今回作ったCのプログラムで文字列から2進数に変換する処理時間が最大10µsであることを考えると、1サンプル読むのにカーネルモードで1ms以上もCPUを使うのは不思議だ。これはADCに限ったことなのか、それともBBBのGPIO全般にこの様な状況なのか気になる。予定外だがADC以外のGPIOについて、入出力処理にどの位時間がかかるか調べてみた。

#include <stdio.h>
#include <time.h>

void echo_to(const char * where, const char * what) {
        FILE *f;
        f = fopen(where, "w");
        fprintf(f, "%s\n", what);
        fclose(f);
}

int main(int argc, char *argv[]){
        int i, N=1000;
        FILE *f;
        struct timespec start, end;
        float diff;

        printf("Prepare gpio30 as output\n");
        echo_to("/sys/class/gpio/export", "30");
        echo_to("/sys/class/gpio/gpio30/direction", "out");

        printf("C: Write %d pulses to gpio30\n", N);
        f = fopen("/sys/class/gpio/gpio30/value", "w");
        setbuf(f, NULL);
        clock_gettime(CLOCK_MONOTONIC, &start);
        for(i=0; i<N; i++) {
                fprintf(f, "0");
                fseek(f, 0, SEEK_SET);
                fprintf(f, "1");
                fseek(f, 0, SEEK_SET);
        }
        clock_gettime(CLOCK_MONOTONIC, &end);
        fclose(f);
        diff += (float) (end.tv_sec - start.tv_sec)
                        + 1e-9 * (end.tv_nsec - start.tv_nsec);

        printf("Unexport gpio30\n");
        echo_to("/sys/class/gpio/unexport", "30");

        printf("Pulse period %.3f [us]\n", 1e6 * diff / N);

        return 0;
}

これはGPIO_30をデジタル出力に設定して全速力でトグルした場合に出力されるパルスの周期がどのくらいになるか調べるプログラムだ。sysfsに書き込むのでroot権限が必要である。sudoを忘れるとSegmentation faultを起こすが、そう言うことなので慌てないよう。

debian@arm:~/C/gpio_pulse$ ./gpio_pulse
Prepare gpio30 as output
Segmentation fault
debian@arm:~/C/gpio_pulse$ sudo ./gpio_pulse
[sudo] password for debian:
Prepare gpio30 as output
C: Write 1000 pulses to gpio30
Unexport gpio30
Pulse period 9.626 [us]

プログラムがちゃんと動いているかどうか確かめるにはオシロスコープが要る。

プログラムが表示するパルス周期は全実行期間の平均で、実行の都度若干バラつくが概ね10µsである。パルス1つに2回デジタル出力を書き換えているので、1回なら約5µsだ。この位の数字なら「まぁこんなものかな」と納得できる。ADCが1msかかるのは何か特殊な事情があるのかもしれない。

同じ事をPythonにやらせると大体4倍時間がかかった。処理時間が2桁短くなっているので違いが顕著である。

時間軸を2段階長めにし、さらにズームアウトして処理全体の波形を見ると少し違う風景が見えてきた。

図に記入した番号1～4は

1. GPIO_30がデジタル出力に設定された
2. 最初の「1」が出力された
3. 最後の「1」が出力された
4. GPIO_30がunexportされた

タイミングである。1～2は1.4ms、3～4は2.4msかかっている。出力の書き換えに比べて200倍以上長時間かかっているが、sysfsの構造を変えているので「まぁこんなもの」かもしれない。ADCの場合にあてはめるとecho cape-bone-iio > /sys/devices/bone_capemgr.*/slotsと同様の処理である。実用的なケースでは頻繁に行う必要が無いハズなので、多少時間がかかってもあまり影響はない。

前の図に記入した番号の内まだ触れていない5はパルスに隙間があるように見える箇所である。この部分をクローズアップすると

約100µsの間パルスが出ていないことが分る。この時Linuxが他のタスクを処理していたのだと考えられる箇所だ。別の言い方をすると、普段5µs位でデジタル出力の値を書き換えられているのが、この箇所だけ実時間で100µsかかっている。中断時間の長さからハードウエアの割り込みに対するサービスを行っていた可能性が高い。プログラムが連続して動き続けようとしてもマルチタスクを実現するため時々止められてしまうのだ。

ADC読み込み時間の考察

ADCを1回読むのに約1.05msかかることが分った。これはカーネルモードで使う正味のCPU時間である。単純なデジタル出力の書き換えに比べて200倍以上長い時間がかかっていて、ハードウエアの仕組みの違いを考慮しても異常に長いと思えるが、正確な理由は良くわからない。

ユーザーモードで使うCPU時間はADCから読んだ値をどのように利用するかで大きく異なる。1回の読み込みあたりカーネルモードの時間と合計で2msだと想定すると、今回作ったようなスタイルのプログラムなら毎秒500回読み込めることになるが、これはマルチタスク環境で動かすには具合が悪い。

こう書くと「他のタスクが使うCPU時間が無くなるから」が模範解答だと思う人が多いかもしれないが、残念ながらそうではない。意図的にタスクの優先度を細工していない限り、スケジューラーが他のタスクの使うCPU時間を確保するからである。むしろ具合が悪いのはADCを読む処理が使えるCPU時間が他のタスクの有無により変わってしまう事だ。読み込み回数が毎秒300回や200回になったり、また読み込みタイミングも一定ではなくなったりする。これでは具合の悪い場合が少なくないのだ。こう言った不具合を避けようとしてADCを読む処理の優先度を極端に上げると他のタスクが使うCPU時間が無くなる。つまりマルチタスクが破綻する。従って模範解答ではないが、完全な誤答でもない。

実用的なプログラムはタイマーを使ってADCを読むタイミングを制御する必要がある。典型的なパターンは擬似的なコードで以下の様に書くことができる。

next_time = 現在の時刻;
while(処理継続条件){
    next_time += 処理を行う時間間隔;
    sleep(next_time - 現在の時刻);
    繰り返す処理;
}

ここで「処理を行う時間間隔」をどのように決めるかが重要になってくる。

先ず明らかなのがsleep無しでwhileループを1回まわるのにかかる時間よりも長くしなければならないことだ。前に書いた想定に従うと2ms以上にする必要がある。またこれにはCPU使用率も加味する必要があり、ADCを読む処理のCPU使用率を50%以下に抑えたいなら時間間隔を4ms以上にする必要がある。

次に処理のタイミングの正確さをどの程度要求するか。これは他のタスクにより処理が待たされる場合の頻度と時間の割合をどの程度許すか、と言う事である。

処理を行う時間間隔を長くすれば相対的にバラつきの割合が小さくなるのに加え、sleepしている時間の割合が増えるので他のタスクの影響を受ける確率が減る。定性的にはこの通りだ。しかし他のタスクの実行頻度と継続時間を正確に予測できないので、定量的な見積もりには何らか実情に即した想定を置かざるを得ない。例えばデジタル出力にパルスを書き出しているときに見つけた100µsの待ちが避けられないと想定すると、バラつきの最悪値を1%以下にしたいなら時間間隔は10ms以上にする必要がある。(多分これは甘い想定である)

処理タイミングの正確さには、タスクの優先度やそれに対するスケジューラーの挙動など他にも影響する要素があるので、稿を改めて掘り下げてみたいと思う。

今回のまとめ

ADCから値を読み込む処理はカーネルモードだけでもCPUを1ms以上使っていることが分った。デジタル出力の値を書き換えるのは約5µsで済むので、それに比べて200倍以上長時間かかっていることになるが、なぜそうなるのか良くわからない。

ただし処理タイミングの正確さが必要な場合ADCを読む処理を行う時間間隔を長くする必要があり、これは読み込み処理自体に必要な時間とはほとんど無関係なので、1ms以上かかることが実用上障害とならない場合が多いかもしれない。