Ruby の test-unit のプロファイルを取る
RSpec だと --format json で実行すると各 example の実行時間が取得できるんですが、test-unit だとそのようなことができなさそうなのでプロファイルを取れるようにしてみました。
ちなみに test_benchmark という gem もあるんですが、もうメンテナンスされてなさそうです。
使用例
例えば fluentd で使用する場合、test/helper.rb で読み込むと良いです。
diff --git a/test/helper.rb b/test/helper.rb
index a373ede5..168b67f6 100644
--- a/test/helper.rb
+++ b/test/helper.rb
@@ -50,6 +50,7 @@ require 'fluent/msgpack_factory'
require 'fluent/time'
require 'serverengine'
require 'helpers/fuzzy_assert'
+require 'test_unit_profiler'
module Fluent
module Plugin
これで一部のテストを実行してみます。
% bundle exec rake test TEST='test/test_plugin_*' TEST_UNIT_PROFILE_OUTPUT=profile.json
/Users/arabiki/.anyenv/envs/rbenv/versions/2.6.2/bin/ruby -w -I"lib:test" -Eascii-8bit:ascii-8bit -I"/Users/arabiki/.anyenv/envs/rbenv/versions/2.6.2/lib/ruby/gems/2.6.0/gems/rake-11.3.0/lib" "/Users/arabiki/.anyenv/envs/rbenv/versions/2.6.2/lib/ruby/gems/2.6.0/gems/rake-11.3.0/lib/rake/rake_test_loader.rb" "test/test_plugin_classes.rb" "test/test_plugin_helper.rb" "test/test_plugin_id.rb"
/Users/arabiki/.anyenv/envs/rbenv/versions/2.6.2/lib/ruby/gems/2.6.0/gems/rake-11.3.0/lib/rake/thread_pool.rb:106: warning: mismatched indentations at 'rescue' with 'def' at 94
Loaded suite /Users/arabiki/.anyenv/envs/rbenv/versions/2.6.2/lib/ruby/gems/2.6.0/gems/rake-11.3.0/lib/rake/rake_test_loader
Started
.................
Finished in 0.01285 seconds.
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
17 tests, 42 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
100% passed
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1322.96 tests/s, 3268.48 assertions/s
% jq . profile.json
[
{
"name": "ConfigTest",
"class": "Test::Unit::TestSuite",
"self": 4.299997817724943e-05,
"total": 0.0042360000079497695,
"children": [
{
"name": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"class": "Test::Unit::TestSuite",
"self": 0.0001810002140700817,
"total": 0.00419300002977252,
"children": [
{
"name": "test: plugin can 2 or more helpers at once(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.0014799999771639705,
"total": 0.0014799999771639705,
"children": []
},
{
"name": "test: plugin can include helper child_process(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.0007340000011026859,
"total": 0.0007340000011026859,
"children": []
},
{
"name": "test: plugin can include helper event_emitter(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.00045900000259280205,
"total": 0.00045900000259280205,
"children": []
},
{
"name": "test: plugin can include helper event_loop(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.0005049998871982098,
"total": 0.0005049998871982098,
"children": []
},
{
"name": "test: plugin can include helper thread(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.00047199998516589403,
"total": 0.00047199998516589403,
"children": []
},
{
"name": "test: plugin can include helper timer(ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules)",
"class": "ConfigTest::Fluent::Plugin::Base.helpers method works as shortcut to include helper modules",
"self": 0.0003619999624788761,
"total": 0.0003619999624788761,
"children": []
}
]
}
]
},
{
"name": "PluginIdTest",
"class": "Test::Unit::TestSuite",
"self": 0.00010499998461455107,
"total": 0.008328000083565712,
-- snip --
}
]
良い感じですね！ちなみに、Test::Unit::TestCase 等には elapsed_time がセットされているので、基本的にはそれを使えば実行時間が取れるんですが、fluent/fluentd#2550 のように正確な時間が取れないケースがあったので、Process.clock_gettime を使っています。
もし時間のかかっているテストを抽出したい場合は jq を使って次のような感じで抽出できます。
% jq '[limit(3; [.[] | recurse(.children[]) | select(.children | length == 0)] | sort_by(.self) | reverse | .[])]' profile.json
[
{
"name": "test: delete a value from the counter(CounterStoreTest::delete)",
"class": "CounterStoreTest::delete",
"self": 0.0017229999648407102,
"total": 0.0017229999648407102,
"children": []
},
{
"name": "test: raise a error when a passed key doesn't exist and raise_error option is true(CounterStoreTest::get)",
"class": "CounterStoreTest::get",
"self": 0.0014179999707266688,
"total": 0.0014179999707266688,
"children": []
},
{
"name": "test: raise an error when passed key doesn't exist(CounterStoreTest::delete)",
"class": "CounterStoreTest::delete",
"self": 0.0012679999927058816,
"total": 0.0012679999927058816,
"children": []
}
]