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

Question

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

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

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

UPD:

我有一个样本回购来重现我的问题：

$ 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

有一个文件夹，您可以在其中找到每个测试用例的执行时间的.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>

Answer 2

对于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并不包括“时代”，尽管这个名字听起来应该有更多的信息。

对于切分测试，该输出并不是每个测试都有执行，但它确实提供了有关它们的统计信息，如上面所示。

如果希望以编程方式访问工期，则构建事件协议有一个米利斯字段。

或者，使用更高级的output=all将打印来自实际测试二进制文件的所有输出，包括通过测试的二进制文件。许多测试框架都会打印出总执行时间。