Rustで実行時間測定 マクロ
家庭教師 clippy
祖母の口癖で、人のふり見て我が身を直せ ってのを思い出す。今の子供たちだと、それって没個性、目立つと苛められるからって理解するのかな。
rustで初めて作った、 血圧グラフプログラムで、気分が悪い所を思い出した。
fn csv_read(sname: &str) -> (Vec<Vec<String>>, Vec<Vec<String>>) {
let mut am: Vec<Vec<String>> = Vec::new();
let mut pm: Vec<Vec<String>> = Vec::new();
型の指定がVecの二段重ねになってて、分かりづらい。これはもう、前回のscheme.rsの方式を真似るに限るな。
type Rec = Vec<String>;
fn csv_read(sname: &str) -> (Vec<Rec>, Vec<Rec>) {
let mut am: Vec<Rec> = Vec::new();
let mut pm: Vec<Rec> = Vec::new();
こんな風にすれば、すっきりと分かり易くなる。
そして、これまた前回AIかと思った、clippyが、非常に良い仕事をしてくれたので、添削を受けてみる亊にした。
sakae@deb:/tmp/bld$ cargo clippy
Checking bld v0.1.0 (/tmp/bld)
warning: the loop variable `m` is only used to index `seed`
--> src/main.rs:41:14
|
41 | for m in seed.len() - HOWLONG..seed.len() {
| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
|
= note: `#[warn(clippy::needless_range_loop)]` on by default
= help: for further information visit https://rust-lang.github.io/rust-clippy/master/index.html#needless_range_loop
help: consider using an iterator
|
41 | for <item> in seed.iter().skip(seed.len() - HOWLONG) {
| ~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
warning: `bld` (bin "bld") generated 1 warning
Finished dev [unoptimized + debuginfo] target(s) in 0.66s
データが入ったseedって名前のVecの最後からHOWLOG分を取出したいって要求。その為にインデックス番号のmを使うって意図だ。それを、下のように変更出来るとな。中坊から脱却しなさいって誘導だな。
seedのイテレータを作って、前の方はスキップしましょうって提案。きっとインデックスでのアクセスより御利益が有るんだろうね。誰かが、スピード対決をやってるだろう。 Rustに於いての「.iter()」メソッド等イテレータの存在意義とは
for r in seed.iter().skip(seed.len() - HOWLONG) {
writeln!(file, "{} {} {}", r[0], r[1], r[2])
.expect("write error");
}
これが最終版。前のに比べて、すっきりしたな。
もう、手とり足取りで個人教授。AIが発達すると、人間の能力が低下しますなあ。まて、そこまで賢いなら、人の手を煩わせず、自動修整して欲しいぞ。人間は王様なんで、よきに図らえ って、ならないものか。
bench
丁度良い機会なので、ベンチマークのやり方を調べておく。
Rustのベンチマーク測定（criterionとtest::bench）
criterion なんてのを入れると、stable版でベンチ出来るとな。DLも活発になされているみたいで、皆に愛されている亊が分る。但し、依存が大杉だ。
お手軽にやるなら、夜版を入れとくと安心らしいので、入れてみる。
sakae@deb:/tmp/com$ rustup install nightly
Rust bench 実行時間測定 から、頂いてきたソースの冒頭に下記を追加
#![feature(test)]
そして、下記のように実行。夜版を指定するのが味噌
sakae@deb:/tmp/com$ cargo +nightly bench
Compiling com v0.1.0 (/tmp/com)
Finished bench [optimized] target(s) in 2.22s
Running unittests (target/release/deps/com-0226a78174429e55)
running 2 tests
test tests::int_test ... ignored
test tests::int_bench ... bench: 5,797,385 ns/iter (+/- 175,247)
test result: ok. 0 passed; 0 failed; 1 ignored; 1 measured; 0 filtered out; finished in 5.24s
できたな。
安定版と夜版の切り換えは rustup default [toolchain] を使うとな。
ARGS:
<toolchain> Toolchain name, such as 'stable', 'nightly', or '1.8.0'.
sakae@deb:/tmp$ cargo -V cargo 1.58.0 (f01b232bc 2022-01-19) sakae@deb:/tmp$ rustup default nightly info: using existing install for 'nightly-i686-unknown-linux-gnu' info: default toolchain set to 'nightly-i686-unknown-linux-gnu' nightly-i686-unknown-linux-gnu unchanged - rustc 1.60.0-nightly (71226d717 2022-02-04) sakae@deb:/tmp$ cargo -V cargo 1.60.0-nightly (25fcb13 2022-02-01)
time meas
ベンチマークって大袈裟過ぎないか。もっと軽いノリで、実行時間の計測をしたい。んで、調べてみた。
CookBook 二つのコード間の速度計測 なかなか実用的
マクロにされた、分った方の例が有ったので、謹んで利用させて頂く。 分った方は、無駄に細かい桁まで表示はしないもの。msオーダーに丸めているのは、妥当と思える。
マクロ部分を別ファイル(mytime.rs)にして、src/ に入れた。main.rsは、本筋だけを記述する。
vbox$ cat src/mytime.rs
// time meas
//use std::time::{Duration, Instant};
macro_rules! meas {
( $x:expr) => {{
let start = std::time::Instant::now();
let result = $x;
let end = start.elapsed();
println!(
"Elapsed: {}.{:03}",
end.as_secs(),
end.subsec_nanos() / 1_000_000
);
result
}};
}
Vecを中坊宜しくindexでアクセスした場合と、大人の対応iterを使った場合の比較だ。
vbox$ cat src/main.rs
#[macro_use]
mod mytime;
fn by_index(){
let xs = [1; 1_000_000];
let mut _d = 0;
for i in 0..xs.len(){
_d = xs[i];
}
}
fn by_iter(){
let xs = [1; 1_000_000];
let mut _d = 0;
for v in xs.iter() {
_d = *v;
}
}
fn main() {
meas!( by_index() );
meas!( by_iter() );
}
vbox$ cargo r
Finished dev [unoptimized + debuginfo] target(s) in 0.04s
Running `target/debug/meas`
Elapsed: 0.114
Elapsed: 0.068
vbox$ cargo r
Finished dev [unoptimized + debuginfo] target(s) in 0.04s
Running `target/debug/meas`
Elapsed: 0.113
Elapsed: 0.065
vbox$ cargo r --release
Finished release [optimized] target(s) in 0.04s
Running `target/release/meas`
Elapsed: 0.000
Elapsed: 0.000
iterの方が断トツに速いね。それからリリース版だともっと速い。これは、何もやる亊が無いから、即座に関数から復帰してしまう為だ。
release版で負荷かける
偉そうに上記のコードを使うとリリース版では何もやらないって断言しちゃったよ。汗水たらさないで偉そうに講釈を垂れる、どこかのコメンテーターみたいだな。しばし反省。
fn by_iter() {
let mut xs = [1; 2_000_000];
for v in xs.iter_mut() {
*v += 1;
}
}
それぞれのエレメントを、Read Modify Write するように変更。変更の過程で、コンパイラーに文句を言われたのは言うまでもない。iterもそれなりにしろってのは、初めてしったぞ。
そして、リリース版なら実行スピードが断トツ(ああ文学的表現だ)に速いんで、もっと大きなVecでもいいんでないかい。 5_000_000 にしてみた。
sakae@deb:/tmp/meas/src$ cargo r --release
Finished release [optimized] target(s) in 0.02s
Running `/tmp/meas/target/release/meas`
thread 'main' has overflowed its stack
fatal runtime error: stack overflow
Aborted
あえなく撃沈。非常に大きな奴をぶん回す時の方策ってあるの？
clippyで添削をうける
全体に短かいコードなんで、何も言われないだろうと思っていたら、突っ込みが入った。 conciseって、我が辞書には載っていなかった、ナポレオンみたい。
まあ、雰囲気はら、コンパクトになるよって亊だろうね。
warning: calling `subsec_millis()` is more concise than this calculation --> src/mytime.rs:12:13 | 12 | end.subsec_nanos() / 1_000_000 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ help: try: `end.subsec_millis()` | ::: src/main.rs:12:5 | 12 | meas!(by_iter()); | ---------------- in this macro invocation | = note: `#[warn(clippy::duration_subsec)]` on by default = help: for further information visit https://rust-lang.github.io/rust-clippy/master/index.html#duration_subsec = note: this warning originates in the macro `meas` (in Nightly builds, run with -Z macro-backtrace for more info)
macroは難しい
マクロの部分だけ、今回は別ファイルに移項した。あっ、移項ってのは受験数学で出て来るあれだ。正確には移行ってか移動だな。まあ、本当の所はコピペなんですが、そこは大人の事情ってか、ソフトに言いくるめてる訳です。
で、当初、エラーを食っていた訳よ。
sakae@deb:/tmp/meas$ cargo b Compiling meas v0.1.0 (/tmp/meas) error[E0433]: failed to resolve: use of undeclared type `Instant` --> src/mytime.rs:6:21 | 6 | let start = Instant::now(); | ^^^^^^^ not found in this scope | ::: src/main.rs:12:5 | 12 | meas!(by_iter()); | ---------------- in this macro invocation | = note: this error originates in the macro `meas` (in Nightly builds, run with -Z macro-backtrace for more info) help: consider importing this struct | 1 | use std::time::Instant; |
useしてるのに、それが見付からないって亊だ。夜版を使うとマクロ展開出来るっぽいけど、そんな夜も安心は、男なら関係無いって亊で、哲学の道を散歩しながら考えた訳よ。
マクロって、展開してからコンパイルって挙動。展開する時、use したものが見えないんではなかろうかと仮定。
macro_rules! meas {
use std::time::Instant;
($x:expr) => {{
:
こんな風に、マクロの中にuseを押し込んでみた。したら、
error: no rules expected the token `std` --> src/mytime.rs:4:9 | 4 | use std::time::Instant; | ^^^ no rules expected this token in macro call
それは駄目よと嗜められた。エラーを喰らうだけ成長すると思うぞ。
そんな訳で、Instant::now()の表現を、絶対PATHで記述して動くようになったのが上記だ。 こういう亊は、余り書かれていないので、あえて書いてみた。
優雅に水面を滑っている白鳥も、水面下では、一生懸命にバタバタしてますって言う一齣でした。
更に私考。環境問題について考える。これ世の中の流行です。SDG's って言うんでしたっけ？ 人類、わがままになって、CO2を出しすぎなんで控えましょうって言ったって、もう遅いと思うよ。既に臨海点を越えてしまっているだろう。まあ、そういうのは置いておいて。。
use std::time::Instant; #[macro_use] mod mytime; :
main.rsにuseを記述してあげたら、有効になった。最初にコンパイラーのエントリー・ファイルであるmain.rsに記述して、環境を作っておけ。それから、やおらmytimeのコンパイルにかかるって訳。起点はmain.rsって亊を忘れるな。
でも、この方法だとmain.rsを幾ら眺めても、std::timeを使っている場面で出会さない。プチ気味が悪い。 mesa! を使う時は、マクロ使うよ。それからmytimeにそれが入っているからねって方がすっきりする。
関数名が欲しい
渡された関数の名前が欲しい。んで、こんなの作った。
pub fn print_typename<T>(_: T) {
println!("{}", std::any::type_name::<T>());
}
macro_rules! meas {
($x:expr) => {{
let start = std::time::Instant::now();
let result = $x;
let end = start.elapsed();
mytime::print_typename($x);
println!("Elapsed: {}.{:03}", end.as_secs(), end.subsec_millis());
result
}};
}
けど、これ型を出すやつ。
() Elapsed: 0.075
見るも無惨。でも、 print_typename が見付からなくて焦った。モジュール名を前置しないと駄目なのね。手を動かすと色々と分ってくる。
で、 macro 識別子を駆使すれば、何とかなる？ なんとかなったんで、最終報告をば。
result files
src/mytime.rs
/// scheme like time
/// meas!( f_name(arg...) )
/// Usage: add below 2 line's into main.rs
/// #[macro_use]
/// mod mytime;
macro_rules! meas {
($x:expr) => {{
let start = std::time::Instant::now();
let result = $x;
let end = start.elapsed();
println!(
"{} Elapsed: {}.{:03}",
stringify!($x),
end.as_secs(),
end.subsec_millis()
);
result
}};
}
src/main.rs
#[macro_use]
mod mytime;
fn by_iter(n:i32) {
let mut xs = [1; 1_000_000];
for v in xs.iter_mut() {
*v += n;
}
}
fn calc(x:i32, y:i32) -> i32 {
let mut rv = 0;
for z in 0..1_000_000 { rv = x + y + z; }
rv
}
fn main() {
meas!( by_iter(3) );
let res = meas!( calc(1,2) );
println!("{}", res);
}
そして実行結果。
by_iter(3) Elapsed: 0.041 calc(1, 2) Elapsed: 0.063 1000002
meas!の呼び出した関数の結果は表示しません(schemeとかのtimeマクロとは微妙に違う)。結果が必要なら、例のように一旦受け取ってから、表示してください。
また、 meas!( by_iter(var) ); みたいに、引数を変数で渡しても、結果表示は、 by_iter(var) になる。展開されたものが表示される訳ではないのであしからず。まあ、この挙動からマクロの動きが察せられるんだけどね。要する字面がマクロ呼出でコンパイラー側へ伝わり、マクロ内部で展開されて、それがコンパイルされる。
今回の立役者である、stringify! を、rust/library/core/src/macros/mod.rsで見付けた。
#[stable(feature = "rust1", since = "1.0.0")]
#[rustc_builtin_macro]
#[macro_export]
#[cfg_attr(not(test), rustc_diagnostic_item = "stringify_macro")]
macro_rules! stringify {
($($t:tt)*) => {
/* compiler built-in */
};
}
コンパイラーの奧深かい所で、ごそごそやってる訳ね。
実戦投入
ちゃんと動くか、血圧グラフで確認。冒頭に、マクロ使うよと、mod mytime; を追加。 main内部の目星い関数に、プローブを仕込む。
fn main() {
let rv = meas!(csv_read("current.csv"));
let am = rv.0;
let pm = rv.1;
let sd = meas!(dump4gp("am.dat", am));
let _ = dump4gp("pm.dat", pm);
meas!(scr4gp("topdf.plt"));
meas!(run4gp(sd));
:
まずは、debugモード
sakae@deb:/tmp/meas$ cargo r
Finished dev [unoptimized + debuginfo] target(s) in 0.02s
Running `target/debug/meas`
csv_read("current.csv") Elapsed: 0.083
dump4gp("am.dat", am) Elapsed: 0.004
scr4gp("topdf.plt") Elapsed: 0.000
run4gp(sd) Elapsed: 0.129
そして、次はリリースモード
sakae@deb:/tmp/meas$ cargo r --release
Finished release [optimized] target(s) in 0.02s
Running `target/release/meas`
csv_read("current.csv") Elapsed: 0.007
dump4gp("am.dat", am) Elapsed: 0.001
scr4gp("topdf.plt") Elapsed: 0.000
run4gp(sd) Elapsed: 0.129
CSVの読込みは10倍速くなった。dump4grは、読み込んだデータからgnuplot用にデータファイルを作成するやつ。IOが使われているので、それによって律速されやうのかな？
scr4gpは、文字列として埋め込んであるgnuplot用スクリプトを、ファイルに書き出すやつ。元々が小さいので、スピードアップの恩恵無し。
run4gpは、gnuplotを叩いてPDFを作る。rustの範囲外なので、一定速度になる。
まあ、思っていた亊が、手軽に確認出来た。貴方もおそばに是非、mytime.rsを。自由にお使いください。
後は、このプローブを付けたり外したりが、簡単に出来るようにしたいな。editorのマクロでも組めばいいのか。