Как узнать время выполнения каждого теста в Базеле? - PullRequest
Новая
       6

Как узнать время выполнения каждого теста в Базеле?

0 голосов
/ 04 апреля 2020

При запуске теста 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)

, но не могу видеть время выполнения каждого теста в этом классе / правиле.

Ответы [ 2 ]

2 голосов
/ 05 апреля 2020

При - 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 не включает в себя время, даже если имя звучит так, как будто оно должно содержать строго больше информации.

Для проверенных тестов этот вывод не совсем имеет каждое выполнение теста, но он дает статистику о них, как показано выше.

Если вы хотите получить доступ к длительностям программно, протокол событий построения имеет поле TestResult.test_attempt_duration_millis .

В качестве альтернативы, использование - test_output = all распечатает все выходные данные из ваших реальных двоичных файлов теста, включая те, которые прошли. Многие тестовые среды выводят общее время выполнения там.

0 голосов
/ 07 апреля 2020

Существует папка testlogs , в которой вы можете найти .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>
...