BeagleBone Blackを試す (5)

BBB (BeagleBone Black、以下同様) 上の5回目だ。今回は一定周期で処理を繰り返すDebian weezy上のプログラムで処理のタイミングがどの様にバラつくのか、また優先度を変えるとバラつきが改善されるのか調べた。

プログラミング言語はPythonとCを使った。

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

タイミングのバラつきとスケジューラー

今回の記事はマルチタスクが原因で発生するバラつきを念頭に置いていて、この場合スケジューラーが重要な鍵を握ることになる。これはCPUスケジューラーとかプロセススケジューラーと呼ばれるもので、タスクスケジューラーと呼ばれる場合もあるが、cronのことをこう呼んでいる場合もあるので注意が必要である。

スケジューラーはカーネルバージョンとともに変遷していてBBBではCFS (Completely Fair Scheduler) が使われていると思うのだが、明確にそのことを記載したドキュメントは見つからなかった。インターネットを調べるとスケジューラーに関する情報が多数みつかるが、古い方式のスケジューラーに関するものも多く、あまり参考にならない。また適用されているパッチの種類による違いもあるので、他のLinuxに関するドキュメントからの類推は危険であり、現物の挙動を調べるのが一番確かだ。

なおマルチタスク以外の原因で発生するバラつきもある。

先ずCPUクロックが可変であることによりバラつきが発生する。これは前回紹介した様にCPUクロックを固定してしまえば解決する。別の言い方をするとクロックを固定しない限りバラつきが避けられないので、省電力優先でなければ/etc/rc.localにクロック固定処理を組み込んでしまうと手間もかからないし、忘れる心配もない。この場合目的を明確にする意味でクロックの最低値だけでなく最高値とガバナーも一緒に変えておくと良いだろう。

debian@arm:~$ cat /etc/rc.local
#!/bin/sh -e
#
# rc.local
#
# This script is executed at the end of each multiuser runlevel.
# Make sure that the script will "exit 0" on success or any other
# value on error.
#
# In order to enable or disable this script just change the execution
# bits.
#
# By default this script does nothing.

# Enable BBB ADC
for i in `find /sys/devices/bone_capemgr.*/ -maxdepth 1 -name slots`; do
    echo cape-bone-iio > $i
done

# Lock down the CPU clock to 1GHz
cpufreq-set --min 1GHz --max 1GHz --governor performance

exit 0

次にメモリー関連の事情で発生するバラつきが以下の3種類ある。

CPUキャッシュミス発生頻度が一定しないことによるバラつき: これはキャッシュを使っている限り避けられないが、その程度はせいぜい1µsではないかと思われ、影響は限定的である。

アクセスしようとしたアドレスの仮想メモリーが割り当てられていない場合が時々発生することによるバラつき: これは新たなメモリーを使う場合の問題なのでmallocを行ったり新しいオブジェクトをインスタンス化したりしなければ関係無いと思うかもしれない。しかし関数を呼び出す場合新たなスタック領域が必要なので、大抵の場合普通に起こり得る現象だ。実メモリーがページ単位で仮想メモリーに割り当てられ、ページフォルトは時々しか起こらないので、処理時間がバラつく。この場合バラつきの程度は多分10µs位ではないだろうか。試していないがmlockまたはmlockall関数を使って仮想メモリーを固定すると回避できるらしい。Pythonでは標準でインターフェイスが準備されていないが、ctypesパッケージを利用するなどして独自のインターフェイスを作ることは可能だろう。なお処理時間のバラつきを気にするような場合に普通スワップデバイスは使わないので、スワップアウトされていることが原因で起こるページフォルトの可能性は考える必要がないと思う。

GC (Garbage Collection) が時々発生することによるバラつき: Cは無関係だがPythonにはGCが実装されている。

debian@arm:~$ python
Python 2.7.3 (default, Jan  4 2013, 13:44:41)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import gc
>>> gc.set_debug(gc.DEBUG_STATS)
>>> n = gc.collect()
gc: collecting generation 2...
gc: objects in each generation: 359 3115 0
gc: done, 0.0083s elapsed.
>>> n
0
>>>

Pythonは基本的にC++と同じ参照カウントでオブジェクト管理を行っているので、これでうまく行っている限りGCは不要だ。

>>> for i in range(1000):
...     x = [1] * 1000
...
>>>

上の例ではループをまわる度に要素数1,000のリストが作成されるが、次のリストが作成された時点で前のリストは参照されなくなり自動的に破棄される。しかし循環参照が生じると参照カウントがゼロにならないので、これによる破棄メカニズムが働かなくなりGCが必要になる。

>>> for i in range(1000):
...     x = [1, 2, 3]
...     x[0] = x
...
gc: collecting generation 0...
gc: objects in each generation: 695 0 3393
gc: done, 688 unreachable, 0 uncollectable, 0.0012s elapsed.
>>> x, x[0], x[0][0][0][0]
([[...], 2, 3], [[...], 2, 3], [[...], 2, 3])
>>>

xそのもの、xの最初の要素、そのまた最初の要素・・・と見ていっても全く同じ内容になっているので循環参照していることが分ると思う。ただしGCを行って始めてPythonには循環参照になっているかどうか分るので、オブジェクトの生成数から廃棄数を引いた数、つまり新たに生成されて残っているオブジェクト数が一定の数になる都度GCが走っている。

>>> gc.get_threshold()
(700, 10, 10)
>>> x = [1] * 1000
>>> for i in range(1000):
...     x[i] = [1, 2, 3]
...
gc: collecting generation 0...
gc: objects in each generation: 786 1 3393
gc: done, 0.0010s elapsed.
>>>

ディフォルトだと新規作成されて残っているオブジェクトが700になる都度GCが走るようになっている (実際には多少前後する)。ただし循環参照を起こす可能性の無い数値や文字列 (Pythonでは単純な数値を含む全てのデータはオブジェクトだ) はカウントの対象外である。上の例では循環参照が発生していないのでGCが走っても破棄されたオブジェクトは無い。

ここまで見てきた例だとGCが走るのに1～9msかかっているが、個々のオブジェクトサイズが大きくなると100ms台に及ぶことがある。これは処理タイミングのバラつきとしては深刻な長さだ。

循環参照が発生しないことが確認できればgc.disable()で自動GCを止めてしまうのが確実である。循環参照がないことに確信が持てない状況なら、自動GCを止めた上、バラつきが問題にならないタイミングにgc.collect()で強制GCを行うのが現実的な対応だろう。

タイマーの分解能

分解能 (resolution) よりも粒度 (granularity) と言うべきなのかもしれないが、いずれにせよタイマーの最小目盛りの意味である。Windowsで以下の様に調べると

C:\>python
Python 2.7.2 (default, Jun 12 2011, 15:08:59) [MSC v.1500 32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import time
>>> def test():
...     t1 = time.time()
...     t2 = time.time()
...     return t1, t2, t2 - t1
...
>>> test()
(1391517394.114, 1391517394.114, 0.0)
>>> test()
(1391517399.398, 1391517399.398, 0.0)
>>>

どうやら最小目盛りは1msらしいことが分る。これだと1msよりも短い時間単位のタイミング制御はおろか、時間計測すら出来ない。

BBBで同じ事を行うと

debian@arm:~$ python
Python 2.7.3 (default, Jan  4 2013, 13:44:41)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import time
>>> def test():
...     t1 = time.time()
...     t2 = time.time()
...     return t1, t2, t2- t1
...
>>> test()
(1391517056.047999, 1391517056.048004, 5.0067901611328125e-06)
>>> test()
(1391517060.371316, 1391517060.371321, 5.0067901611328125e-06)
>>>

最小目盛りは5µsのように見える。実は前々回の記事を書く前にここまでは確かめたのだが、今回の記事を書くにあたりもう少し詳しく調べてみた。調べるのに使ったPythonプログラムの主要な部分は以下の通りである。

import numpy as np
import time

N = 1000
a = np.zeros(N)
i = 0
c = 0
while i < N:
    t1 = time.time()
    t2 = time.time()
    d = t2 - t1
    c += 1
    if d != 0:
        a[i] = d
        i += 1

この後、配列aの値およびその階差をプロットしているが、個別の場合ごとに調整していて、結構煩雑な処理になってしまったので掲載は省いた。

これをWindows上で実行すると、最小目盛り1msであることがはっきり分る。±250ns位の細かいバラつきが見られるが、数値を扱う際の端数の影響ではないかと考えられる。

BBBの場合

これを見ると最小目盛りは1µsだが1回ループをまわるのに3µsかかっていると言うことらしい。Pythonの浮動小数点数値はCで言うdouble型なので有効数字16桁である。time.time()関数の出力が整数部10桁、小数部6桁なのでギリギリ有効数字に収まっているが、そのため最小桁の数字が2通りになったのだと考えられる。

しかしこの状態だと有効数字で最小目盛りが決まっている可能性がある。これを確かめるためにCで同じことをやってみた。clock_gettimeが扱うtimespec構造体は1ナノ秒の単位まで表現可能な有効数字がある。以下は主要な部分を抜き出したものだ。

struct timespec t1, t2;
double a[1000];
int i=0, c=0, N=1000;
long d;
while(i < N) {
        clock_gettime(CLOCK_MONOTONIC, &t1);
        clock_gettime(CLOCK_MONOTONIC, &t2);
        d = SEC_IN_NANO * (t2.tv_sec - t1.tv_sec)
                                        + t2.tv_nsec - t1.tv_nsec;
        c++;
        if(d != 0) {
                a[i] = 1e-3 * d;        // convert nsec -> usec
                i++;
        }
}

時間差は大きくても数µsなので、ナノ秒で表現しても有効数字4桁以内だ。double型で問題なく取り扱える。結果をファイルに書き出Pythonのプログラムでグラフにした。

どうやら最小目盛り41nsになっているらしい。これはLinuxが起動するときシリアルコンソールに出力しているメッセージにあるGPTIMER1またはGPTIMER2の値をそのまま使っていると考えられる。

[    0.000000] OMAP clockevent source: GPTIMER1 at 24000000 Hz
[    0.000000] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 178956ms
[    0.000000] OMAP clocksource: GPTIMER2 at 24000000 Hz

ただしクロック24MHzの正確な周期は41.6...nsなので、nsに丸めた値の変化ステップは41の場合と42の場合が出るため小さくバラついている。

Pythonも同じ元データを利用しているハズだがdouble型に変換する際最小目盛り1µsになってしまっているようだ。

sleep関数の最小目盛り

時間を計る時計の最小目盛りがPythonなら1µs、Cだと41nsらしいことが分ったが、それがそのまま制御にも使えるとは限らないので別途確認しよう。

#!/usr/bin/python

import time
import numpy as np
import matplotlib.pyplot as pl

N = 1000
M = 11
t = np.zeros(N)

for j in range(M):
    sleep_time = 1e-3 + 10e-6 * (M - 1) - 10e-6 * j
    for i in range(N):
        t0 = time.time()
        time.sleep(sleep_time)
        t1 = time.time()
        t[i] = t1 - t0
    pl.plot(np.arange(N), 1e3 * t, '.',
            label="%.3f [ms]" % (1e3 * sleep_time) )
pl.grid(True)
pl.ylim(1.05, 1.30)
pl.legend()
pl.show()

大きくバラついている部分を除けば10µs単位にきれいに分離できている。Pythonのsleep関数の最小目盛りは1µsだが、実行時間に数µs程度のバラつきがあると考えるのが妥当ではないだろうか。CPUキャッシュの影響にしては大き過ぎるような気がする。タイマー割り込みに対するレイテンシーのバラつきかもしれない。

なおsleep時間を1msに設定した場合の結果が約1.09msになっているのはsleepから目覚める処理などの遅れも計測値に含めるようなアルゴリズムを使っているからである。

最小目盛りを客観的に確認する

これまで行ってきたタイミングの計測はBBBの時計でBBBの制御の正確さを測ったもので、言ってみればBBBの主観的な言い分である。BBBの時計が大きく異なった時を刻んでいることはあまり考えられないが、一応現実世界の時計で確認しておく必要があるだろう。

GPIO_30をデジタル出力にして、引数で指定した周期のパルスを出力するようにした。

#!/usr/bin/python
import time, sys

def echo_to(where, what):
    f = open(where, "w")
    print >> f, what
    f.close()

p = 1e-3
if len(sys.argv) > 1:
    p = 1e-6 * float(sys.argv[1] )
w = 2e-4
w0 = p - w

echo_to("/sys/class/gpio/export", "30")
echo_to("/sys/class/gpio/gpio30/direction", "out")
f = open("/sys/class/gpio/gpio30/value", "w", 0)
t = time.time()
for i in range(1000):
    t += w0
    s = t - time.time()
    if s > 0:
        time.sleep(s)
        print >> f, "1"
        f.seek(0, 0)
    t += w
    s = t - time.time()
    if s > 0:
        time.sleep(s)
    print >> f, "0"
    f.seek(0, 0)
f.close()
echo_to("/sys/class/gpio/unexport", "30")

パルスの周期はµs単位で指定する。

debian@arm:~/python$ sudo ./gpio_pulse2.py 600

600µsから10µs刻みで640µsまで周期を変えて、その通り出力されるかデジタルオシロで測ってみた。校正していない計測器なので絶対値の精度は保証できないが、相対的な変化はそこそこ正確に測れるハズである。

左側に「1→」と表示されているのが600µs、「R1」～「R4」がそれぞれ610～640µsである。これを見ると一応それらしく制御できているようだ。各パルスは必ずしも等間隔ではないが、sleep関数の最小目盛りを調べたときのグラフのバラつき具合と比べれば「まぁこんなもの」だろう。

ただし時々大きく乱れることがあるのも事実で、この波形を採るのに何度かやり直している。この乱れこそが今回の本題だ。

niceで優先度が調整できない!

本題に入る前にもう一つ片付けておかなければならないことがある。

マルチタスクが原因で発生するタイミングのバラつきを小さくするにはタスクの優先度を調整する必要がある。伝統的な方法はnice値を変えることなのだがBBBではうまく働かないことに気付いた。正確にはうまく働く条件が限られていて、予定していた使い方はダメだと分かった。これは何とかする必要がある。

やったことはこうだ。先ずTera Termでsshセッションを3つ開き以下の様に試してみた。

片方のnice値を最優先である-20にしたのだが、使えるCPU時間がほとんど増えない。

フォアグランド同士だとうまく行かないという情報があったので両方ともバックグランドにしてみたが、変化は無い。

なんとなく同じ端末から起動したプロセス同士ならうまく行くのではないかと思えたので試してみた。フォアグランドとバックグランドの組み合わせにしてみよう。先ずnice値が同じ場合、どちらのプロセスもほぼ平等にCPUを使わせてもらえている。

バックグラウンドのプロセスのnice値を、先ほど同様-20にしてみた。

topコマンドが表示する％CPUは直近の1秒間の値だったと思うがpsコマンドでは累積CPU時間に基づいて計算しているようである。nice値を変えた直ぐ後にpsを実行した結果と、しばらくしてもう1回実行した結果を比べると、nice値が-20のプロセスはCPUを53秒使えたがnice値が0の方は1秒しか使えていない。これは％CPUの直近の値の差がpsコマンドで表示されているよりもはるかに大きいことを意味している。これは期待していた結果だ。

どうやらnice値による優先度の調整は同じ端末から起動された、または同じシェルの子プロセス同士でないと効かないようだ。対話的に複数ユーザーがログインできるUnixの伝統をLinuxは引き継いでいるので、この様な取り扱いはなんとなく納得できる。

しかし今回の目的はどの端末から起動されたかには無関係に優先度を調整することだ。niceはこの様な目的に使えるようには作られていない。

スケジューリング・ポリシーとスケジューリング・クラス

niceでタスクの優先度を調整するのは10年位前にLinuxを使い始めたときに読んだ入門書で覚えた。それ以来BBBに触るまで実際に使った記憶はほとんど無い。イザ使ってみると何か思っていたのと違うゾ、と言う次第である。

BBBを使い始めてから色々調べてだんだん分ってきたのだが、Linuxにはスケジューリング･ポリシー が5つある。またスケジューリング・クラスと言う用語も使われていて、スケジューリング・ポリシーと同義のように扱っている資料がある一方、ポリシーをリアルタイムとそれ以外に分類していると理解できる資料もあり、やや混沌としている。私がちゃんと理解しているかどうかもイマイチ自信が持てないが、話の筋としては後者の方が納得しやすいので、この記事ではその意味として使うことにする。

資料から理解したことと現物で調べたことを総合すると、niceで優先度を調整できるのはSCHED_OTHERおよびSCHED_BATCHポリシーで動いているタスクである。またSCHED_IDLEで動いているタスクは実際に設定されている値に関係なく19よりも優先度の低いnice値が設定されているように振舞う。これらがリアルタイムではないその他のスケジューリング・クラスに分類されるポリシーである。ただし既に述べた様に、この様な効果があるのは同じ端末から起動されたタスク同士についてだけである。異なる端末から起動されたタスク同士では設定されたnice値に関係なく公平にCPU時間が分配される。これはポリシーがSCHED_IDLEであっても同様である。

今回の目的である処理タイミングのバラつきを改善するにはリアルタイム・クラスに分類されるSCHED_FIFOまたはSCHED_RRポリシーに設定する必要がある。これらのポリシーで動いているタスクは設定された優先度が最低でも、他のポリシーで最高の優先度 (nice値-20) を設定されたものよりも優先してスケジュールされる。

プログラムの中ならCのsched_setscheduler関数を使えばスレッド単位でポリシーと優先度を設定できる。適当なインターフェイスを書けばPythonからも利用できるだろう。プロセス単位の操作になるがLinuxコマンドchrtを使うことも可能である。

今回は手軽に試したかったのでchrtコマンドを使うことにする。

なお無限ループを起こす可能性のあるタスクをリアルタイム・クラスのスケジューリング・ポリシーで動かすとシステム全体がフリーズするおそれがあるので注意が必要だ。プログラムをリアルタイム・クラスのスケジューリング・ポリシーで動かしてテストする必要がある場合、別の仮想端末で目的のプログラムよりも高い優先度でシェルを起動しておけばkillコマンドなどでタスクをキャンセルする最後の手段を残すことができる。

タイミングのバラつきを調べるプログラム

発生頻度の低い現象も捉えたいので1分間の状況を記録できるようにした。

#!/usr/bin/python
# -*- coding: utf-8 -*-
import sys, time, numpy as np, matplotlib.pyplot as pl

comment = ""
if len(sys.argv) > 2:
    comment = "\n" + " ".join(sys.argv[1:] )
N = 12000           # 60 ÷ 0.005
inteval = 60.0 / N  # 0.005 [sec] = 5 [ms]
dt = np.zeros(N)
at = np.zeros(N)
with open("/proc/uptime", "r") as f:
    uptime = float(f.read().split()[0] )
    offset = uptime % 10 - time.time()

next_time = time.time() + inteval
for i in range(N):
    s = next_time - time.time()
    if s > 0:
        time.sleep(s)
    ta = time.time()
    dt[i] = ta - next_time
    at[i] = ta + offset
    next_time += inteval

dt *= 1e3    # convert sec -> ms
stat = u"\nμ=%.3f [ms], σ=%.3f [ms]" % (np.average(dt), dt.std() )
pl.plot(at, dt, 'bo-', label=u"δt = tActual - tTarget" + stat, alpha=0.5)
pl.grid(True)
pl.xlabel("sec from uptime=%d" % (uptime // 10 * 10) )
pl.ylabel("ms")
pl.title(("Timing error on %s" % sys.platform) + comment)
pl.legend(loc="upper left").draggable(True)
pl.show()

5ms間隔で12,000回、目標と実際の時刻の差を記録してプロットするプログラムである。時間差を記録している部分で、例えばADCを読んでその値を記録するようなユースケースを想定している。なおdmesgで表示されるカーネルメッセージと突き合わせられるよう、時刻はuptimeに合わせた。

なお一気にプロットまで処理するのでstartxしたGUIの使える環境で実行する必要がある。

バラつきの測定結果

上のプログラムを実行する前に、予め別の仮想端末でCPUに負荷をかける処理を始めておく。

debian@arm:~/python$ python -c "while 1: pass" &
[1] 3009
debian@arm:~/python$ ./intermittent.py
Press Ctrl+C to quit...

継続的および間歇的にCPUを使おうとする処理それぞれ1つずつを開始している。間歇的にCPUを使おうとする処理intermittent.pyは以下のようなものである。

#!/usr/bin/python
import time

print "Press Ctrl+C to quit..."
t0 = time.time()
try:
    while 1:
        t1 = t0 + 0.003 # 3ms busy
        t0 += 0.053     # 53ms interval
        while time.time() < t1: # busy loop
            pass
        s = t0 - time.time()
        if s > 0:
            time.sleep(s)
except KeyboardInterrupt:
    pass
except:
    raise

バラつきを測る処理と同期関係にならないよう、負荷をかける時間と周期はわざとキリの悪い数字にしている。

先ず優先度の調整を行わずに実行してみた。

この条件だと最大2.5msのバラつきが発生する。標準偏差が70µsなので大きくバラついたサンプルはそんなに多くないと考えられるが、最大値が所定の時間間隔の50%に及ぶのをどう評価するのか難しいところである。なおタイミングのバラつきの平均値は91µsの遅れとなっていて、これはsleepから目覚める処理と time.time() 関数で現在時刻を得る処理の遅れが反映されたものだと考えられる。

次にSCHED_FIFOポリシーで最大優先度の99を指定して実行した。

debian@arm:~/python$ sudo chrt -f 99 ./schd_stability.py w/additional CPU load + SCHED_FIFO 99
[sudo] password for debian:

CPUに負荷をかける処理は動かしたままである。前のグラフとは縦軸の目盛りが大きく変わっていることに注意して欲しい。バラつきの最大値は0.25ms弱、標準偏差だと14µsまで小さくなった。また時間遅れの平均値も35µsと、前の場合の半分以下になっている。これはリアルタイム・クラスのポリシーにした結果スリープから目覚めるのに必要な処理時間が短縮されているのではないかと考えられる。

バラつきの最大値でも所定の時間間隔の5%以下なので、これはいいのではないか？と思ったのだが落とし穴があった。

偶然発見したのだが、ワイヤレスマウスのレシーバーをBBBにつなげたUSBハブにホットプラグするとひどくバラつくのだ。

設定し得る最大の優先度にしているが、これはあくまでユーザーモードで動いているタスクの間での最大だ。私の理解が間違っていなければ、ハードウエアの割り込みに対するサービスはどんなユーザーモードのタスクよりも高い優先度で動いたハズだし、USBのホットプラグに伴う処理は割り込みがキッカケで動いている可能性が高い。

時間軸を拡大して詳細なタイミングを調べ

dmesgコマンドの出力と突き合わせて、本当にUSBデバイスのホットプラグが原因なのかどうか確認しておく。このプロットの時間軸37.2はuptimeだと4887.2に相当する。

[ 4887.157107] hub 1-1:1.0: state 7 ports 4 chg 0000 evt 0008
[ 4887.157612] hub 1-1:1.0: port 3, status 0101, change 0001, 12 Mb/s
[ 4887.265806] hub 1-1:1.0: debounce: port 3: total 100ms stable 100ms status 0x101
[ 4887.332206] usb 1-1.3: new full-speed USB device number 17 using musb-hdrc
[ 4887.427681] usb 1-1.3: ep0 maxpacket = 32
[ 4887.428806] usb 1-1.3: skipped 1 descriptor after interface
[ 4887.428825] usb 1-1.3: skipped 1 descriptor after interface
[ 4887.429015] usb 1-1.3: default language 0x0409
[ 4887.429467] usb 1-1.3: udev 17, busnum 1, minor = 16
[ 4887.429481] usb 1-1.3: New USB device found, idVendor=046d, idProduct=c526
[ 4887.436716] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 4887.444378] usb 1-1.3: Product: USB Receiver
[ 4887.448858] usb 1-1.3: Manufacturer: Logitech
[ 4887.466867] usb 1-1.3: usb_probe_device
[ 4887.466894] usb 1-1.3: configuration #1 chosen from 1 choice
[ 4887.469463] usb 1-1.3: adding 1-1.3:1.0 (config #1, interface 0)
[ 4887.469765] usbhid 1-1.3:1.0: usb_probe_interface
[ 4887.469784] usbhid 1-1.3:1.0: usb_probe_interface - got id
[ 4887.472750] input: Logitech USB Receiver as /devices/ocp.3/47400000.usb/musb-hdrc.1.auto/usb1/1-1/1-1.3/1-1.3:1.0/input/input29
[ 4887.527601] hid-generic 0003:046D:C526.001D: input: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-musb-hdrc.1.auto-1.3/input0
[ 4887.582271] usb 1-1.3: adding 1-1.3:1.1 (config #1, interface 1)
[ 4887.582538] usbhid 1-1.3:1.1: usb_probe_interface
[ 4887.582555] usbhid 1-1.3:1.1: usb_probe_interface - got id
[ 4887.594113] input: Logitech USB Receiver as /devices/ocp.3/47400000.usb/musb-hdrc.1.auto/usb1/1-1/1-1.3/1-1.3:1.1/input/input30
[ 4887.645078] hid-generic 0003:046D:C526.001E: input: USB HID v1.11 Device [Logitech USB Receiver] on usb-musb-hdrc.1.auto-1.3/input1

バラつきは6回起こっているが、それらがどのメッセージと関連しているのかまでは分らない。しかしUSBデバイスをホットプラグしたことで一連のバラつきが発生したと断定してよいだろう。

USBデバイスをホットプラグすると最高の優先度で動かしているタスクでも最悪20ms程度の処理の遅延が発生する。これは処理を周期5msで動かそうとすると致命的な場合が多いが、周期をもっと長く、例えば1sにすれば許容できる場合が増えるだろう。これは周期に対する最悪の遅延の相対的割合が400%から2%に小さくなることもあるが、遅延の発生頻度が劇的に下がることも理由の一つである。

周期5msで実行できている処理が実際にCPUを使っている時間は5ms未満でなければならない。これを1s周期で動かすと少なくとも995msはsleepしていることになる。USBデバイスをホットプラグしたとき発生する処理の遅延は断続的に350ms程度継続しているので、周期1sならsleepしている期間に全て収まってしまう場合がかなりの頻度で出てくる。また1回のホットプラグで2回以上遅延が発生することは考えられない。

1回のホットプラグで発生する遅延時間の合計は70ms程度なので、周期1sで動かしている場合に遅延が発生する確率は7%程度である。また周期5msで動かしている場合ホットプラグ1回について遅延時間20ms以上の遅延が1回、他の5回は10ms程度かそれ以下なので、周期1sで動かすとホットプラグを100回行った場合93回は遅延が発生せず、遅延が発生しても10msを大きく超えるのは1回程度だろうと予測できる。周期5msで処理を行っている場合はホットプラグを行うと必ず複数回遅延が発生し、その内最も長い遅延が常に20ms程度になるのと比べると大違いである。

ただし周期1sで動かしても最悪の場合は20ms程度の遅延が発生することは変わらない。頻度が下がるだけである。

周期350ms以上では1回のホットプラグで遅延が起こるのは多くても1回なので、上の考え方が適用できる。しかし周期が350ms未満では1回のホットプラグで何回遅延が起こるか場合分けが必要になり、確率などの計算は容易ではない。

今回のまとめ

BBBのDebian上で動かすプログラムで実時間のタイミングを制御する場合、スケジューリング・ポリシーSCHED_FIFOで最大優先度にするとタイミングのバラつき、すなわち処理の遅延を通常の動作中は最大値で250µsにすることができた。これはPythonのプログラムで確認した。Cを使えばもう少し小さくなるかもしれないが、結果が劇的に変わる余地はあまり無さそうである。

なお最大優先度に設定したプログラムのCPU使用率が高かったり1回の処理あたりのCPU使用時間が長過ぎたりすると、マルチタスクに支障が出る場合が考えられるので注意が必要だ。

またUSBデバイスをホットプラグした場合、最悪20ms程度の遅延が発生する。これを簡単に防止する方法は無さそうで、タイミングのバラつきを避けたい処理を行っている間はUSBデバイスのホットプラグを運用で禁止するのが最も現実的ではないかと思われる。USBデバイスのホットプラグ以外にも同様の対応が必要なイベントが無いとは言えない。全てを予め網羅することはできないので発見の都度検討が避けられないだろう。