[Development] Reducing CI test run verbosity

[Volker Hilsheimer]

> On 25 Sep 2024, at 13:09, Dimitrios Apostolou via Development <development at qt-project.org> wrote:
> 
> On Wed, 25 Sep 2024, Assam Boudjelthia via Development wrote:
> 
>> This would be very nice!
>> Also, consider removing the "Label Time Summary:” section from the logs which outputs the run tests with their execution times, which is just duplicate information to what ctest printed before it.
>> — Assam
>> 
>>      On Sep 25, 2024, at 12:01 PM, Tor Arne Vestbø via Development <development at qt-project.org> wrote:
>> Hello,
>> As described in https://bugreports.qt.io/browse/QTQAINFRA-6592, we currently execute ctest -V (verbose), which logs all of the output from all tests to the resulting test log, even for passing tests.
>> This practice presents challenges in investigating test failures, as it requires loading and navigating through approximately 25MB (qtbase) of logs within a (mobile) web browser or editor to identify a test failure.
>> To address this issue, we propose implementing https://codereview.qt-project.org/c/qt/qtbase/+/592470, which will enable us to pass —output-on-failure to ctest. This modification will significantly reduce the ctest output and
>> signal-to-noise ratio.
>> In certain cases, it may still be beneficial to examine the full verbose log. Therefore, we will continue to store this information as CTest.log within the testresults.tar.gz for those who require a comprehensive analysis.
>> It is important to note that enabling —output-on-failure will not impact our test reporting to https://testresults.qt.io/grafana. This reporting is based on XML output that we still generate for each test.
>> An example of how this change would manifest is available here: https://testresults.qt.io/coin/integration/qt/qtbase/tasks/1727203984
>> Let us know if you have any concerns not addressed in the corresponding bug reports.
>> Cheers,
>> Tor Arne 
> 
> The reduction in verbosity is very welcome, especially since we retain the full log in the downloads. Thank you Tor Arne!

Good improvement indeed!

> Regarding the label time summary, it is actually different output than what is before it. For reasons I don't know (feedback welcome), we assign a LABEL to each test that includes its full path. I believe a group of test can even have the same LABEL. That is the summary of these labels.
> 
> They are assigned in cmake/QTestHelpers.cmake, function qt_internal_add_test():
> 
>    602     # Generate a label in the form tests/auto/foo/bar/tst_baz
>    603     # and use it also for XML output
>    604     set(label_base_directory "${PROJECT_SOURCE_DIR}")
>    605     if (QT_SUPERBUILD)
>    606         # Prepend repository name for qt5 builds, so that tests can be run for
>    607         # individual repositories.
>    608         set(label_base_directory "${label_base_directory}/..")
>    609     endif()
>    610     file(RELATIVE_PATH label "${label_base_directory}" "${CMAKE_CURRENT_SOURCE_DIR}/${name}")
> ...
>    755         set_tests_properties("${testname}" PROPERTIES RUN_SERIAL "${arg_RUN_SERIAL}" LABELS "${label}")
> 
> 
> Example output from CTest:
> 
> agent:2024/09/24 20:04:49 build.go:404: 100% tests passed, 0 tests failed out of 605
> agent:2024/09/24 20:04:49 build.go:404: Label Time Summary:
> agent:2024/09/24 20:04:49 build.go:404: tests/auto/concurrent/qtconcurrentfilter/tst_qtconcurrentfilter                                             =   0.77 sec*proc (1 test)
> agent:2024/09/24 20:04:49 build.go:404: tests/auto/concurrent/qtconcurrentfiltermapgenerated/tst_qtconcurrentfiltermapgenerated                     =   0.48 sec*proc (1 test)
> agent:2024/09/24 20:04:49 build.go:404: tests/auto/concurrent/qtconcurrentiteratekernel/tst_qtconcurrentiteratekernel                               =   1.80 sec*proc (1 test)
> agent:2024/09/24 20:04:49 build.go:404: tests/auto/concurrent/qtconcurrentmap/tst_qtconcurrentmap                                                   =   1.26 sec*proc (1 test)
> agent:2024/09/24 20:04:49 build.go:404: tests/auto/concurrent/qtconcurrentmedian/tst_qtconcurrentmedian                                             =   0.46 sec*proc (1 test)
> ...
> 
> 
> I support removing this summary, if we don't have any particular use for the labels.
> 
> 
> Dimitris


The labels we set in the build system allow us to run a group of tests via

% ctest -L ‘foo’

E.g. I can run all qtsvg tests in a toplevel build via

% ctest -L ‘qtsvg’

This is incredibly useful.

Some of this is possible via 

% ctest -R ‘pattern’

but it’s not quite the same. E.g. 

% ctest -R ‘qtsvg’

runs nothing, because none of the tests has qtsvg in their name, and

% ctest -R ‘qsvg’

would not run the tst_qicon_svg (which the -L equivalent does run).


So please keep the label :) But indeed, if possible to remove, then the summary at the end is not useful for a reader of the log trying to understand what failed, as long as we can capture it for statistics from the XML output.

Volker