bazel - 如何获取bazel中每个测试的执行时间？

Question

运行 bazel 测试时，输出仅包含所有测试的摘要，包括总运行时间。

运行 bazel 并进行性能分析并没有帮助，因为它不指示每个测试时间。

那么如何获取每个测试执行时间的信息呢？

更新:

我有一个示例存储库来重现我的问题:

$ git clone https://github.com/MikhailTymchukFT/bazel-java
$ cd bazel-java
$ bazel test //:AllTests --test_output=all --test_summary=detailed

Starting local Bazel server and connecting to it...
INFO: Analyzed 2 targets (20 packages loaded, 486 targets configured).
INFO: Found 2 test targets...
INFO: From Testing //:GreetingTest:
==================== Test output for //:GreetingTest:
JUnit4 Test Runner
..
Time: 0.017

OK (2 tests)


BazelTestRunner exiting with a return value of 0
JVM shutdown hooks (if any) will run now.
The JVM will exit once they complete.

-- JVM shutdown starting at 2020-04-07 09:44:56 --

================================================================================
INFO: From Testing //:MainTest:
==================== Test output for //:MainTest:
JUnit4 Test Runner
.
Time: 0.016

OK (1 test)


BazelTestRunner exiting with a return value of 0
JVM shutdown hooks (if any) will run now.
The JVM will exit once they complete.

-- JVM shutdown starting at 2020-04-07 09:44:57 --

================================================================================
INFO: Elapsed time: 21.009s, Critical Path: 6.68s
INFO: 10 processes: 6 darwin-sandbox, 4 worker.
INFO: Build completed successfully, 18 total actions
Test cases: finished with 3 passing and 0 failing out of 3 test cases

INFO: Build completed successfully, 18 total actions

我可以在 GreetingTest 中看到两个测试的执行时间

==================== Test output for //:GreetingTest:
JUnit4 Test Runner
..
Time: 0.017
OK (2 tests)

，但无法看到该类/规则中每个测试的执行时间。

Answer 1

与 --test_summary=short (默认值)，输出的结尾如下所示(其他 325 个测试的行被截断):

INFO: Elapsed time: 148.326s, Critical Path: 85.71s, Remote (0.00% of the time): [queue: 0.00%, setup: 0.00%, process: 0.00%]
INFO: 680 processes: 666 linux-sandbox, 14 worker.
INFO: Build completed successfully, 724 total actions
//third_party/GSL/tests:no_exception_throw_test                 (cached) PASSED in 0.4s
//third_party/GSL/tests:notnull_test                            (cached) PASSED in 0.5s
//aos/events:shm_event_loop_test                                         PASSED in 12.3s
  Stats over 5 runs: max = 12.3s, min = 2.4s, avg = 6.3s, dev = 3.7s
//y2018/control_loops/superstructure:superstructure_lib_test             PASSED in 2.3s
  Stats over 5 runs: max = 2.3s, min = 1.3s, avg = 1.8s, dev = 0.4s

Executed 38 out of 329 tests: 329 tests pass.
INFO: Build completed successfully, 724 total actions

令人困惑的是，--test_summary=detailed 不包括时间，尽管这个名字听起来应该包含更多信息。

对于分片测试，该输出并不完全包含每个测试执行，但它确实提供了有关它们的统计信息，如上所示。

如果您想以编程方式访问持续时间，build event protocol有一个TestResult.test_attempt_duration_millis字段。

或者，使用 --test_output=all将打印实际测试二进制文件的所有输出，包括通过的输出。许多测试框架都会在那里打印总执行时间。