前回の記事に書いた通り、STM32 上で Rust Embassy を使ってみたわけですが、SSD1306 OLED ディスプレイの表示が C で書いたものよりも遅いのが気になりました。SSD1306 クレイトのコードをざっと読んでみましたがなんとなくオーバーヘッドが大きそうで、ライブラリの実行速度を疑ってはいるのですが、では Embassy の潜在能力はどれぐらいか？という点が気になります。ということで調べてみました。
何を測定するか
Embassy を使いたい最大の理由は、非同期のコーディングを楽にしたいためです。なので、まずはメモリやペリフェラルへのアクセスの少ないコードを使って以下の条件下での実行速度を計測して Embassy 実行フレームワークの基本性能がどれぐらいなのかを知りたいと思います。
- シングルスレッド、タスク登録なしの実行
- コンテクスト切り替えするが他にタスクがない状態での実行
- 二つのタスクをコンテクスト切り替えにより交互に実行する状態での実行
測定プログラム
今回の計測に向いているプログラムは以下のようなものです
- メモリへのアクセスが少ない
- ペリフェラルへのアクセスがない、あるいは非常に少ない
- 答えを求めるために多くの繰り返しを必要とする
- 浮動小数点演算など複雑な演算を必要としない
この条件を満たすプログラム、何があるかなーと思案しましたが、素数を求めるプログラムを使うことにしました。詳細は後ろの節に書きます。
測定結果
テストにどんなコードを使ったか書いたら長くなったので、忙しい人のために結果だけ先に載せてしまいます。
| Framework | single thread | single task | two tasks | context / no context | 2 tasks / 1 task |
|---|---|---|---|---|---|
| C uevloop | 3198 | 4991 | 6636 | 1.56 | 1.33 |
| Rust Embassy | 2228 | 3269 | 3987 | 1.47 | 1.21 |
これはどういう測定の結果かというと、0xfffffff から始めて素数を 10 個探すプログラムの実行時間です。単位はミリ秒です。single thread は一本のスレッド上でコンテクスト切り替えなしの条件での実行。この実行が各環境で最速になります。single task は、コンテクスト切り替えを行うけれども他にタスクがない状態での実行です。two tasks は、非常に軽いタスクがもう一つ同時に走っている状態での実行です。コンテクストの切り替えは計測中 20 万回ほど発生しました。
結果、Rust Embassy が C の実装を圧倒しました。コンテクスト切り替えなしの状態でも Rust が速かったのは興味深いです。コンパイラの地力の差なんでしょうか。もう一つ面白いのがコンテクスト切り替えを行うと切り替えのオーバーヘッドが出るためどうしても実行が遅くなりますが、オーバーヘッドの割り合いが Rust のほうがだいぶん少ないことです。Rust ではコンテクスト切り替えが高速なスタックレスコルーチンが使われていますが、その効果なのかもしれません。コルーチンのコンテクスト切り替えは、アセンブリコードを使って C 言語の仕様では書けない動きをさせるため 、C だけで書いた今回の実験プログラムではオーバーヘッドの点で勝てないのでは、と思います。
測定の詳細
ここから以降、測定にどんなプログラムを使ったのかをもう少し詳しく書いていきます。かなり長いですけれども良かったら読んでいってください。
測定プログラムを決める
再度、今回の計測に向いているプログラムは以下のようなものと考えました。
- メモリへのアクセスが少ない
- ペリフェラルへのアクセスがない、あるいは非常に少ない
- 答えを求めるために多くの繰り返しを必要とする
- 浮動小数点演算など複雑な演算を必要としない
何故そう考えるか？ 1) メモリを大量に使うプログラムはアロケーションやメモリアクセスのための操作に実行時間を割くことになり、実行フレームワークの基本性能を測るときには雑音になってしまいます。2) ペリフェラルへのアクセスも同様ですが、実行の進行をチェックするのに数回アクセスする程度なら邪魔にはならないと思います。3) 答えを求めるために多くの繰り返しを必要とするプログラムは頻繁にコンテクスト切り替えを行うことができ、コンテクスト切り替えにかかるコストを計測しやすくなります。4) 複雑な演算を避けたいのも実行フレームワークの性能を見たいからです。特に条件によって計算のステップ数が変わったりするとフレームワークの効率を測定するには邪魔になると考えられます。
以上を鑑みると、素数を求めるプログラムが上記の条件をおおまかに満たしていると考えてそれを使いました。
おおもとの実装は以下の通り
#include <stdio.h>
#include <stdint.h>
static uint32_t loops = 0;
uint8_t IsPrime(uint64_t n) {
// If number is less than/equal to 1, it is not prime
if (n <= 1) {
return 0;
}
// Check whehter n is dividable by i in range 2 to sqrt(n)
for (uint64_t i = 2; i * i <= n; i++) {
++loops;
if (n % i == 0) {
return 0;
}
}
return 1;
}
int main() {
int count = 0;
uint64_t nstart = 0xfffffff;
uint64_t n = nstart;
while (count < 10) {
if (IsPrime(n)) {
printf("found a prime number: %lu\n", n);
++count;
}
++n;
}
printf("tested numbers: %lu\n", n - nstart);
printf("loops: %u\n", loops);
return 0;
}あんまり凝ってない素数チェックプログラムを 0xfffffff から走らせて、1ずつ値を増やしてゆき、素数が 10 個見つかったところで止まります。上のプログラムを Linux で実行すると以下のような感じ、177 個の整数を調べて、約20万回割り切れるかのチェックが行われます。この20万回の繰り返しごとにコンテクスト切り替えをしようという目論見です。演算は剰余なので軽くはないですがループ一回につき一個だけなのでとりあえず良しとします。結果コンテクスト切り替えの影響は測定できたので大丈夫だったようです。
$ cc -o prime_numbers prime_numbers.c
$ ./prime_numbers
found a prime number: 268435459
found a prime number: 268435463
found a prime number: 268435493
found a prime number: 268435523
found a prime number: 268435537
found a prime number: 268435561
found a prime number: 268435577
found a prime number: 268435579
found a prime number: 268435597
found a prime number: 268435631
tested numbers: 177
loops: 202336C でのテストプログラムの実装
このプログラムを STM32 上で走らせて実行時間を測っていきます。まずは C 言語から。コンパイルは STM32CubeIDE 備え付けの gcc で、最適化には -O3 を使いました。
C: シングルスレッド・タスク登録なし
C なのでもとプログラムとほぼ同じです。IsPrime() 関数は上記のものと全く同じです。以下をメインプログラムに埋め込みます。途中結果の表示に SSD1306 を使っていますが約20万回のループのうち10回だけなので実行時間に影響は出ないでしょう。
int count = 0;
uint64_t n = 0xfffffff;
uint32_t start = counter;
char buf[32];
while (count < 10) {
if (IsPrime(n)) {
snprintf(buf, sizeof(buf), "%d", count + 1);
ssd1306_SetCursor(10, 10);
ssd1306_WriteString(buf, Font_6x8, White);
ssd1306_UpdateScreen();
++count;
}
++n;
}
uint32_t elapsed_time = counter - start;
ssd1306_SetCursor(10, 25);
snprintf(buf, sizeof(buf), "%ld ms", elapsed_time);
ssd1306_WriteString(buf, Font_6x8, White);
ssd1306_UpdateScreen();実行結果は以下のようになりました
C: 1 タスクでの実行
次に使う版は、タスクとして実行、途中、割り切れるかどうかチェックするループごとにコンテクスト切り替えを行います。しかし他にタスクを走らせず結局自分自身に戻ってくる状態で実行します。実行環境は uevloop を使いました。枠組みは十分シンプルなので他のフレームワークで実装しても同じような速度になると思います。
struct find_primes {
uel_closure_t is_prime;
uel_closure_t is_dividable;
int count;
int max_count;
uint64_t n;
uint64_t i;
uint32_t start;
uint32_t invocations;
};
uint32_t loop_count = 0;
static void *IsDividable(void*, void*);
void *IsPrimeAsync(void *context, void *) {
struct find_primes *ctx = (struct find_primes *)context;
++ctx->invocations;
ctx->i = 2;
uel_evloop_enqueue_closure(&my_app.event_loop, &ctx->is_dividable, NULL);
return NULL;
}
void *IsDividable(void *context, void*) {
struct find_primes *ctx = (struct find_primes *)context;
if (ctx->n <= 1) {
// it's not prime, proceed to the next number
++ctx->n;
uel_evloop_enqueue_closure(&my_app.event_loop, &ctx->is_prime, NULL);
}
if (ctx->i * ctx->i > ctx->n) {
// it's a prime
char buf[32];
snprintf(buf, sizeof(buf), "%d", ctx->count + 1);
ssd1306_SetCursor(10, 0);
ssd1306_WriteString(buf, Font_6x8, White);
ssd1306_UpdateScreen();
++ctx->count;
if (ctx->count < ctx->max_count) {
// proceed to the next number
++ctx->n;
uel_evloop_enqueue_closure(&my_app.event_loop, &ctx->is_prime, NULL);
} else {
char buf[32];
uint32_t elapsed_time = counter - ctx->start;
snprintf(buf, sizeof(buf), "elapsed: %ld ms", elapsed_time);
ssd1306_SetCursor(10, 15);
ssd1306_WriteString(buf, Font_6x8, White);
snprintf(buf, sizeof(buf), "trials: %ld", ctx->invocations);
ssd1306_SetCursor(10, 30);
ssd1306_WriteString(buf, Font_6x8, White);
snprintf(buf, sizeof(buf), "loops: %ld", loop_count);
ssd1306_SetCursor(10, 45);
ssd1306_WriteString(buf, Font_6x8, White);
ssd1306_UpdateScreen();
}
} else if (ctx->n % ctx->i == 0) {
// it's not prime, proceed to the next number
++ctx->n;
uel_evloop_enqueue_closure(&my_app.event_loop, &ctx->is_prime, NULL);
} else {
// try the next divisor
++ctx->i;
uel_evloop_enqueue_closure(&my_app.event_loop, &ctx->is_dividable, NULL);
}
return NULL;
}C 言語での非同期実行の実装はうんざりするぐらい複雑になります。基本的に対象の数がある数で割り切れるかどうかのチェックをひとタスクとして、チェックが終了するたびに割る数を増やしてタスク登録し直します。C で非同期関数を実装する場合、実行のコンテクストを保持するのにスタックが使えないので、別に構造体 find_primes を作ってそこにコンテクストを乗せて行きます。変数 loop_count は今は使いませんが次の測定で使います。この関数を呼び出すには以下をメインプログラムで実行します
struct find_primes find_primes = {
.count = 0,
.max_count = 10,
.n = 0xfffffff,
.start = counter,
.invocations = 0,
};
find_primes.is_prime = uel_closure_create(IsPrimeAsync, &find_primes);
find_primes.is_dividable = uel_closure_create(IsDividable, &find_primes);
uel_evloop_enqueue_closure(&my_app.event_loop, &find_primes.is_prime, NULL); // タスク登録実行結果は以下のとおり。タスク切り替えのオーバーヘッドが入るため実行が少し遅くなりました。まだ他にタスクがなくて loop_count を更新する人がいないので 0 になってます。
それにしてもごっちゃごちゃです。このテスト、ブログ記事だけ見て再現できるんでしょうか。
C: 2 タスクでの実行
交互実行するタスクの反対側は、単純にカウンタを1ずつ増やしてゆくものにしました。
void *SimpleCounter(void *context, void *) {
uel_closure_t *self = (uel_closure_t*) context;
++loop_count;
uel_evloop_enqueue_closure(&my_app.event_loop, self, NULL);
return NULL;
}メインプログラムでのタスク登録部分が少しだけ増えます
struct find_primes find_primes = {
.count = 0,
.max_count = 10,
.n = 0xfffffff,
.start = counter,
.invocations = 0,
};
find_primes.is_prime = uel_closure_create(IsPrimeAsync, &find_primes);
find_primes.is_dividable = uel_closure_create(IsDividable, &find_primes);
uel_evloop_enqueue_closure(&my_app.event_loop, &find_primes.is_prime, NULL); // タスク 1 登録
uel_closure_t incrementer = uel_closure_create(SimpleCounter, NULL);
incrementer.context = &incrementer;
uel_evloop_enqueue_closure(&my_app.event_loop, &incrementer, NULL); // タスク 2 登録このようにするとイベントループがタスクを 1, 2 の順で実行しますが、どちらのタスクも自分自身を登録し直すので、続いて 1, 2 また 1, 2 と交互に繰り返すことになります。
以下が実行結果です。loop_count はカウンタが更新しているのですが、素数プログラムの実行回数の約20万回とほぼ同じとなっており、きちんと交互に実行されていたことがわかります。そして、実行時間がさらに少し長くなりました。
Rust でのテストプログラムの実装
Rust では Embassy フレームワークを使います。コンパイラの最適化レベルは s としました。
Rust: シングルスレッド・タスク登録なし
Embassy のタスク上でコンテクスト切り替えなしの実行をします。プログラムは C のものをそのまま移植します。
static mut COUNTER: u32 = 0;
fn is_prime(n: u64) -> bool {
// If number is less than/equal to 1, it is not prime
if n <= 1 {
return false;
}
// Check whehter n is dividable by i in range 2 to sqrt(n)
let mut i = 2u64;
loop {
if i * i > n {
return true;
}
if n % i == 0 {
return false;
}
i += 1;
}
}
#[embassy_executor::task]
async fn find_primes() {
let mut count = 0;
let mut n = 0xfffffff;
let start = Instant::now();
let mut trials = 0;
while count < 10 {
trials += 1;
if is_prime(n) {
count += 1;
info!("found a prime number {} {}", count, n);
}
n += 1;
}
let elapsed = start.elapsed();
unsafe {
info!(
"done elapsed = {} ms, trials={}, loops={}",
elapsed.as_millis(),
trials,
COUNTER
);
}
}このプログラムは、非同期として宣言されていますが実際には終了するまでコンテクストを譲りません。長時間占有する代わりにコンテクスト切り替えに時間を使わないので実行は最速になります。結果は RTT を使って PC 側で確認します。これも実行中には 10 回使うだけなので大勢に影響が出ないと考えています。静的変数の COUNTER にアクセスするため unsafe を使っています。ほんとはダメなんですけどちゃんとコーディングするとごちゃつくしテスト目的ではこんなもんで良いとしました。
このタスクを実行するにはメインタスクから spawn をかけます
#[embassy_executor::main]
async fn main(_spawner: Spawner) -> ! {
...
info!("spawning find_primes");
_spawner.spawn(find_primes()).unwrap();
loop {
Timer::after_secs(1).await;
}
}実行結果はこんな風になりました。なんと、C と比べてもかなり速いです。大体同じぐらいになるのだと思っていましたが予想外でした。
Programming ✔ 100% [####################] 26.00 KiB @ 1.78 KiB/s (took 15s) Finished in 40.59s
0.000000 [DEBUG] rcc: Clocks { hclk1: MaybeHertz(48000000), hsiker: MaybeHertz(48000000), lse: MaybeHertz(0), pclk1: MaybeHertz(48000000), pclk1_tim: MaybeHertz(48000000), rtc: MaybeHertz(32000), sys: MaybeHertz(48000000) } (embassy_stm32 src/rcc/mod.rs:81)
3.133422 [INFO ] spawning find_primes (hello_ssd1306 rust-project/src/main.rs:236)
3.313507 [INFO ] found a prime number 1 268435459 (hello_ssd1306 rust-project/src/main.rs:139)
3.493408 [INFO ] found a prime number 2 268435463 (hello_ssd1306 rust-project/src/main.rs:139)
3.781768 [INFO ] found a prime number 3 268435493 (hello_ssd1306 rust-project/src/main.rs:139)
3.990814 [INFO ] found a prime number 4 268435523 (hello_ssd1306 rust-project/src/main.rs:139)
4.172027 [INFO ] found a prime number 5 268435537 (hello_ssd1306 rust-project/src/main.rs:139)
4.505523 [INFO ] found a prime number 6 268435561 (hello_ssd1306 rust-project/src/main.rs:139)
4.686828 [INFO ] found a prime number 7 268435577 (hello_ssd1306 rust-project/src/main.rs:139)
4.866729 [INFO ] found a prime number 8 268435579 (hello_ssd1306 rust-project/src/main.rs:139)
5.078765 [INFO ] found a prime number 9 268435597 (hello_ssd1306 rust-project/src/main.rs:139)
5.361541 [INFO ] found a prime number 10 268435631 (hello_ssd1306 rust-project/src/main.rs:139)
5.361633 [INFO ] done elapsed = 2228 ms, trials=177, loops=0 (hello_ssd1306 rust-project/src/main.rs:154)Rust: 1 タスクでの実行
ここから Rust に移行したい理由が顕著に見えるようになります。非同期実行の C での複雑さとは裏腹に、Rust ではほとんどコードが同じ、すっきりしています。spawn のところは全く同じなので、タスクのコードだけ載せるとこんな感じ。ほとんど間違い探しですね。
static mut COUNTER: u32 = 0;
async fn is_prime_async(n: u64) -> bool {
// If number is less than/equal to 1, it is not prime
if n <= 1 {
return false;
}
// Check whehter n is dividable by i in range 2 to sqrt(n)
let mut i = 2u64;
loop {
yield_now().await;
if i * i > n {
return true;
}
if n % i == 0 {
return false;
}
i += 1;
}
}
#[embassy_executor::task]
async fn find_primes() {
let mut count = 0;
let mut n = 0xfffffff;
let start = Instant::now();
let mut trials = 0;
while count < 10 {
trials += 1;
if is_prime_async(n).await {
count += 1;
info!("found a prime number {} {}", count, n);
}
n += 1;
}
let elapsed = start.elapsed();
unsafe {
info!(
"done elapsed = {} ms, trials={}, loops={}",
elapsed.as_millis(),
trials,
COUNTER
);
}
}変わったのは is_prime 関数が非同期になり、中でループごとに yield をかけている点です。コードの見た目はほとんど同じですが、この版ではループごとにコンテクスト切り替えがあります。ただ、切り替えても他にタスクがいないのですぐに自分自身に戻ってきます。
以下が実行結果です。やはり実行時間が少し長くなりましたが、C の実装と比べて実行時間増加の割合は少ないです。関数コールによるタスク切り替えよりもスタックレスコルーチンのほうが手数が少なく速いとされていますが、そこはまだ詳しく理解できていなくて勉強したいところです。
0.000000 [DEBUG] rcc: Clocks { hclk1: MaybeHertz(48000000), hsiker: MaybeHertz(48000000), lse: MaybeHertz(0), pclk1: MaybeHertz(48000000), pclk1_tim: MaybeHertz(48000000), rtc: MaybeHertz(32000), sys: MaybeHertz(48000000) } (embassy_stm32 src/rcc/mod.rs:81)
3.133453 [INFO ] spawning find_primes (hello_ssd1306 rust-project/src/main.rs:236)
3.397888 [INFO ] found a prime number 1 268435459 (hello_ssd1306 rust-project/src/main.rs:139)
3.662048 [INFO ] found a prime number 2 268435463 (hello_ssd1306 rust-project/src/main.rs:139)
4.084777 [INFO ] found a prime number 3 268435493 (hello_ssd1306 rust-project/src/main.rs:139)
4.391357 [INFO ] found a prime number 4 268435523 (hello_ssd1306 rust-project/src/main.rs:139)
4.657379 [INFO ] found a prime number 5 268435537 (hello_ssd1306 rust-project/src/main.rs:139)
5.146362 [INFO ] found a prime number 6 268435561 (hello_ssd1306 rust-project/src/main.rs:139)
5.412567 [INFO ] found a prime number 7 268435577 (hello_ssd1306 rust-project/src/main.rs:139)
5.676727 [INFO ] found a prime number 8 268435579 (hello_ssd1306 rust-project/src/main.rs:139)
5.987670 [INFO ] found a prime number 9 268435597 (hello_ssd1306 rust-project/src/main.rs:139)
6.402435 [INFO ] found a prime number 10 268435631 (hello_ssd1306 rust-project/src/main.rs:139)
6.402526 [INFO ] done elapsed = 3269 ms, trials=177, loops=0 (hello_ssd1306 rust-project/src/main.rs:154)Rust: 2 タスクでの実行
上の素数探しのタスクに加えて C と同様カウンタを増やしてゆくタスクを追加します。
#[embassy_executor::task]
async fn count_up() {
loop {
yield_now().await;
unsafe {
COUNTER += 1;
}
}
}こちらでもループごとに yield_now() 関数を使ってコンテクスト切り替えを行うので交互に実行されることになります。spawn の要領は find_prime のタスクと同じです。
実行結果は以下の通り。前の実行では loops が 0 だったのが約 20 万になりました。想定通りコンテクスト切り替えが行われているのがここからわかります。
Erasing ✔ 100% [####################] 26.00 KiB @ 1.73 KiB/s (took 15s)
Programming ✔ 100% [####################] 26.00 KiB @ 1.56 KiB/s (took 17s) Finished in 31.79s
0.000000 [DEBUG] rcc: Clocks { hclk1: MaybeHertz(48000000), hsiker: MaybeHertz(48000000), lse: MaybeHertz(0), pclk1: MaybeHertz(48000000), pclk1_tim: MaybeHertz(48000000), rtc: MaybeHertz(32000), sys: MaybeHertz(48000000) } (embassy_stm32 src/rcc/mod.rs:81)
3.133453 [INFO ] spawning find_primes (hello_ssd1306 rust-project/src/main.rs:236)
3.133514 [INFO ] spawning count_up (hello_ssd1306 rust-project/src/main.rs:238)
3.456176 [INFO ] found a prime number 1 268435459 (hello_ssd1306 rust-project/src/main.rs:139)
3.778564 [INFO ] found a prime number 2 268435463 (hello_ssd1306 rust-project/src/main.rs:139)
4.294097 [INFO ] found a prime number 3 268435493 (hello_ssd1306 rust-project/src/main.rs:139)
4.667846 [INFO ] found a prime number 4 268435523 (hello_ssd1306 rust-project/src/main.rs:139)
4.992401 [INFO ] found a prime number 5 268435537 (hello_ssd1306 rust-project/src/main.rs:139)
5.588714 [INFO ] found a prime number 6 268435561 (hello_ssd1306 rust-project/src/main.rs:139)
5.913513 [INFO ] found a prime number 7 268435577 (hello_ssd1306 rust-project/src/main.rs:139)
6.235870 [INFO ] found a prime number 8 268435579 (hello_ssd1306 rust-project/src/main.rs:139)
6.615051 [INFO ] found a prime number 9 268435597 (hello_ssd1306 rust-project/src/main.rs:139)
7.120910 [INFO ] found a prime number 10 268435631 (hello_ssd1306 rust-project/src/main.rs:139)
7.121002 [INFO ] done elapsed = 3987 ms, trials=177, loops=202346 (hello_ssd1306 rust-project/src/main.rs:154)以上、コードがとっちらかったままですが、こんな要領でテストを実施しました。ブログにコメントを書かれる方が全然いない昨今ですが動くコードが見たい方がいらしたら「見たい！」とコメント入れていただければコードを整理して Github に上げようと思います。
結論
この結果から見ると、馬のアニメーションが遅かったのは Embassy の実行フレームワークが非効率だからというわけではなさそうです。Embassy の HAL もしくは SSD1306 ライブラリに原因があるようですが、現時点ではどちらかわからずです。ただ、Embassy 本を読むと、HAL はそれよりも低レベルの PAC というレイヤの上に構築されているとあるので、どうしても高速に動かさなくてはならない部分は PAC のコードを直接書く必要があるのかもしれません。
Embassy 自体が遅いわけではないということがわかったので、まだおっかなびっくりですが次のプロジェクトは Rust で実装してみようと考えています。
