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

Question

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

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

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

UPD：

我有一个示例 repo 来重现我的问题：

$ 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 将打印您实际测试二进制文件的所有输出，包括通过的那些。许多测试框架在那里打印总执行时间。

Answer 2

有一个testlogs folder，您可以在其中找到.xml 文件，其中包含每个测试用例的执行时间。

bazel-testlogs 符号链接指向同一个位置。

对于我的示例，这些文件将位于 /private/var/tmp/_bazel_<user>/<some md5 hash>/execroot/<project name>/bazel-out/<kernelname>-fastbuild/testlogs/GreetingTest/test.xml

那个文件的内容是这样的：

<?xml version='1.0' encoding='UTF-8'?>
<testsuites>
  <testsuite name='com.company.core.GreetingTest' timestamp='2020-04-07T09:58:28.409Z' hostname='localhost' tests='2' failures='0' errors='0' time='0.01' package='' id='0'>
    <properties />
    <testcase name='sayHiIsString' classname='com.company.core.GreetingTest' time='0.01' />
    <testcase name='sayHi' classname='com.company.core.GreetingTest' time='0.0' />
    <system-out />
    <system-err /></testsuite></testsuites>