tests/qtest/qom-test.c | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-)
We're still running into the problem that some logs are cut in the
gitlab-CI since they got too big. The biggest part of the log is
still the output of the qom-test. Let's stop printing the properties
by default to get to a saner size here. The full output can still
be enabled by setting V=2 (or higher) in the environment.
Signed-off-by: Thomas Huth <thuth@redhat.com>
---
v2: Use atoi() to do proper checking of the verbosity level
tests/qtest/qom-test.c | 12 +++++++++++-
1 file changed, 11 insertions(+), 1 deletion(-)
diff --git a/tests/qtest/qom-test.c b/tests/qtest/qom-test.c
index 13510bc349..d380261f8f 100644
--- a/tests/qtest/qom-test.c
+++ b/tests/qtest/qom-test.c
@@ -14,6 +14,8 @@
#include "qemu/cutils.h"
#include "libqtest.h"
+static bool verbose;
+
static void test_properties(QTestState *qts, const char *path, bool recurse)
{
char *child_path;
@@ -49,7 +51,9 @@ static void test_properties(QTestState *qts, const char *path, bool recurse)
}
} else {
const char *prop = qdict_get_str(tuple, "name");
- g_test_message("-> %s", prop);
+ if (verbose) {
+ g_test_message("-> %s", prop);
+ }
tmp = qtest_qmp(qts,
"{ 'execute': 'qom-get',"
" 'arguments': { 'path': %s, 'property': %s } }",
@@ -103,6 +107,12 @@ static void add_machine_test_case(const char *mname)
int main(int argc, char **argv)
{
+ char *v_env = getenv("V");
+
+ if (v_env && atoi(v_env) >= 2) {
+ verbose = true;
+ }
+
g_test_init(&argc, &argv, NULL);
qtest_cb_for_every_machine(add_machine_test_case, g_test_quick());
--
2.31.1On Thu, 15 Dec 2022 at 15:30, Thomas Huth <thuth@redhat.com> wrote: > > We're still running into the problem that some logs are cut in the > gitlab-CI since they got too big. The biggest part of the log is > still the output of the qom-test. Let's stop printing the properties > by default to get to a saner size here. The full output can still > be enabled by setting V=2 (or higher) in the environment. > > Signed-off-by: Thomas Huth <thuth@redhat.com> > --- > v2: Use atoi() to do proper checking of the verbosity level Applied to master in the hope of improving the CI logs; thanks. -- PMM
On Mon, 16 Jan 2023 at 16:55, Peter Maydell <peter.maydell@linaro.org> wrote: > > On Thu, 15 Dec 2022 at 15:30, Thomas Huth <thuth@redhat.com> wrote: > > > > We're still running into the problem that some logs are cut in the > > gitlab-CI since they got too big. The biggest part of the log is > > still the output of the qom-test. Let's stop printing the properties > > by default to get to a saner size here. The full output can still > > be enabled by setting V=2 (or higher) in the environment. > > > > Signed-off-by: Thomas Huth <thuth@redhat.com> > > --- > > v2: Use atoi() to do proper checking of the verbosity level > > Applied to master in the hope of improving the CI logs; thanks. Looks like we can still hit the gitlab log limit in some cases, even with this patch; here's an example job: https://gitlab.com/qemu-project/qemu/-/jobs/3610621992 thanks -- PMM
On 17/01/2023 11.23, Peter Maydell wrote: > On Mon, 16 Jan 2023 at 16:55, Peter Maydell <peter.maydell@linaro.org> wrote: >> >> On Thu, 15 Dec 2022 at 15:30, Thomas Huth <thuth@redhat.com> wrote: >>> >>> We're still running into the problem that some logs are cut in the >>> gitlab-CI since they got too big. The biggest part of the log is >>> still the output of the qom-test. Let's stop printing the properties >>> by default to get to a saner size here. The full output can still >>> be enabled by setting V=2 (or higher) in the environment. >>> >>> Signed-off-by: Thomas Huth <thuth@redhat.com> >>> --- >>> v2: Use atoi() to do proper checking of the verbosity level >> >> Applied to master in the hope of improving the CI logs; thanks. > > Looks like we can still hit the gitlab log limit in some > cases, even with this patch; here's an example job: > https://gitlab.com/qemu-project/qemu/-/jobs/3610621992 Ok, too bad ... three ideas to improve this situation further: - We could shut up those "Obtaining properties of" lines by default - Stop running the tests with "V=1" - Instead of doing "cat meson-logs/testlog.txt" in the CI scripts, we switch to "tail -n 1000 meson-logs/testlog.txt" instead What do you think? Thomas
On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
> On 17/01/2023 11.23, Peter Maydell wrote:
> > On Mon, 16 Jan 2023 at 16:55, Peter Maydell <peter.maydell@linaro.org> wrote:
> > >
> > > On Thu, 15 Dec 2022 at 15:30, Thomas Huth <thuth@redhat.com> wrote:
> > > >
> > > > We're still running into the problem that some logs are cut in the
> > > > gitlab-CI since they got too big. The biggest part of the log is
> > > > still the output of the qom-test. Let's stop printing the properties
> > > > by default to get to a saner size here. The full output can still
> > > > be enabled by setting V=2 (or higher) in the environment.
> > > >
> > > > Signed-off-by: Thomas Huth <thuth@redhat.com>
> > > > ---
> > > > v2: Use atoi() to do proper checking of the verbosity level
> > >
> > > Applied to master in the hope of improving the CI logs; thanks.
> >
> > Looks like we can still hit the gitlab log limit in some
> > cases, even with this patch; here's an example job:
> > https://gitlab.com/qemu-project/qemu/-/jobs/3610621992
>
> Ok, too bad ... three ideas to improve this situation further:
>
> - We could shut up those "Obtaining properties of" lines by
> default
Yes, they add little value in debugging test results from CI.
There's plenty of other largely useless junk printed too
Pages and pages of:
Looking for expected file 'tests/data/acpi/q35/FACP.memhp'
Looking for expected file 'tests/data/acpi/q35/FACP'
Using expected file 'tests/data/acpi/q35/FACP'
Looking for expected file 'tests/data/acpi/q35/APIC.memhp'
Looking for expected file 'tests/data/acpi/q35/APIC'
...
Something random that looks like bad text data
▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....�������������
And what i think is test float being overly verbose
>> Testing f16_le_quiet
46464 tests total.
10000
20000
30000
40000
46464 tests performed.
Could be written as
>> Testing f16_le_quiet: 46464 tests total .... OK
(one '.' for each 10,000 tests run, before final 'OK' is printed)
> - Stop running the tests with "V=1"
Definitely not, the info about individual test cases being
executed is absolutely critical when a test hangs, so we can
narrow down what was running when it hung.
I think the key is that when we pass 'V=1' to tests, we want to
see lists of individual test cases being run, but we don't want
to see adhoc debugging output. The latter should either be deleted
if useless, or hidden by a getenv("QEMU_TESTS_DEBUG") check
> - Instead of doing "cat meson-logs/testlog.txt" in the CI
> scripts, we switch to "tail -n 1000 meson-logs/testlog.txt"
> instead
Tail requires that it has consumed the entire doc before it prints
anything. This in turn implies that the test suite has finished.
IOW, we'll get zero output if it hangs IIUC.
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
On 17/01/2023 11.44, Daniel P. Berrangé wrote: ... > And what i think is test float being overly verbose > > >> Testing f16_le_quiet > > 46464 tests total. > > 10000 > 20000 > 30000 > 40000 > 46464 tests performed. > > Could be written as > > >> Testing f16_le_quiet: 46464 tests total .... OK > > (one '.' for each 10,000 tests run, before final 'OK' is printed) Unfortunately, the float tests are included via a git submodule, so the source code is not under our direct control here ... has anybody a good idea how to get this tackled best? Thomas
Thomas Huth <thuth@redhat.com> writes: > On 17/01/2023 11.44, Daniel P. Berrangé wrote: > ... >> And what i think is test float being overly verbose >> >> Testing f16_le_quiet >> 46464 tests total. >> 10000 >> 20000 >> 30000 >> 40000 >> 46464 tests performed. >> Could be written as >> >> Testing f16_le_quiet: 46464 tests total .... OK >> (one '.' for each 10,000 tests run, before final 'OK' is printed) > > Unfortunately, the float tests are included via a git submodule, so > the source code is not under our direct control here ... has anybody a > good idea how to get this tackled best? It is under our control. It is a lightly patched version of the downstream testfloat package so we can patch it some more. That said reducing 5 lines to one is hardly a massive reduction. If we just stopped passing V=1 you would get: ➜ make check-softfloat GIT ui/keycodemapdb meson tests/fp/berkeley-testfloat-3 tests/fp/berkeley-softfloat-3 dtc roms/SLOF [1/1] Generating qemu-version.h with a custom command (wrapped by meson to capture output) /usr/bin/python3 -B /home/alex/lsrc/qemu.git/meson/meson.py test --no-rebuild -t 0 --num-processes 1 --print-errorlogs --suite softfloat 1/17 qemu:softfloat+softfloat-conv / fp-test-float-to-float OK 0.02s 2/17 qemu:softfloat+softfloat-conv / fp-test-int-to-float OK 0.01s 3/17 qemu:softfloat+softfloat-conv / fp-test-uint-to-float OK 0.01s 4/17 qemu:softfloat+softfloat-conv / fp-test-float-to-int OK 0.02s 5/17 qemu:softfloat+softfloat-conv / fp-test-float-to-uint OK 0.01s 6/17 qemu:softfloat+softfloat-conv / fp-test-round-to-integer OK 0.01s 7/17 qemu:softfloat+softfloat-compare / fp-test-eq_signaling OK 0.05s 8/17 qemu:softfloat+softfloat-compare / fp-test-le OK 0.05s 9/17 qemu:softfloat+softfloat-compare / fp-test-le_quiet OK 0.05s 10/17 qemu:softfloat+softfloat-compare / fp-test-lt_quiet OK 0.05s 11/17 qemu:softfloat+softfloat-ops / fp-test-add OK 0.58s 12/17 qemu:softfloat+softfloat-ops / fp-test-sub OK 0.59s 13/17 qemu:softfloat+softfloat-ops / fp-test-mul OK 2.83s 14/17 qemu:softfloat+softfloat-ops / fp-test-div OK 2.11s 15/17 qemu:softfloat+softfloat-ops / fp-test-rem OK 1.27s 16/17 qemu:softfloat+softfloat-ops / fp-test-sqrt OK 0.03s 17/17 qemu:softfloat+softfloat-ops / fp-test-log2 OK 0.02s Ok: 17 Expected Fail: 0 Fail: 0 Unexpected Pass: 0 Skipped: 0 Timeout: 0 Full log written to /home/alex/lsrc/qemu.git/builds/all/meson-logs/testlog.txt with the testlog being: wc -l meson-logs/testlog.txt 2553 meson-logs/testlog.txt > > Thomas -- Alex Bennée Virtualisation Tech Lead @ Linaro
On 17/01/2023 11.44, Daniel P. Berrangé wrote:
> On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
...
>> - Instead of doing "cat meson-logs/testlog.txt" in the CI
>> scripts, we switch to "tail -n 1000 meson-logs/testlog.txt"
>> instead
>
> Tail requires that it has consumed the entire doc before it prints
> anything. This in turn implies that the test suite has finished.
> IOW, we'll get zero output if it hangs IIUC.
I was referring to the places where we are dumping the testlog.txt like this:
make --output-sync -j`nproc` check
|| { cat meson-logs/testlog.txt; exit 1; }
See .gitlab-ci.d/custom-runners/* or .gitlab-ci.d/windows.yml for example. I
assume it should be ok to switch to "tail" instead of "cat" there?
Thomas
On Wed, Jan 18, 2023 at 01:55:49PM +0100, Thomas Huth wrote:
> On 17/01/2023 11.44, Daniel P. Berrangé wrote:
> > On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
> ...
> > > - Instead of doing "cat meson-logs/testlog.txt" in the CI
> > > scripts, we switch to "tail -n 1000 meson-logs/testlog.txt"
> > > instead
> >
> > Tail requires that it has consumed the entire doc before it prints
> > anything. This in turn implies that the test suite has finished.
> > IOW, we'll get zero output if it hangs IIUC.
>
> I was referring to the places where we are dumping the testlog.txt like this:
>
> make --output-sync -j`nproc` check
> || { cat meson-logs/testlog.txt; exit 1; }
>
> See .gitlab-ci.d/custom-runners/* or .gitlab-ci.d/windows.yml for example. I
> assume it should be ok to switch to "tail" instead of "cat" there?
Yes, it would be OK, bug lets make sure meson-logs/testlog.txt is included
as an artifact published by the job, so we can access the full set if
needed
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote: > Something random that looks like bad text data > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....������������� I don't understand this one. The string comes from tests/unit/ptimer-test.c:add_ptimer_tests() but that code creates the test string using g_strlcat() and g_strdup_printf(), so I don't see how it could end up being junk, especially not at that point in the string. I guess it's possible something else in the test is managing to corrupt the g_test test name strings? > And what i think is test float being overly verbose Yes, the float tests are massively over-verbose. This is a problem not just in the length of the test log but also in finding the actual cause of a test failure, because often the float tests were running in parallel with the failed test and print all their very verbose output after the failed test output, so you have to scroll back up for miles to find it. thanks -- PMM
On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote: > On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote: > > Something random that looks like bad text data > > > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....������������� > > I don't understand this one. The string comes from > tests/unit/ptimer-test.c:add_ptimer_tests() but that > code creates the test string using g_strlcat() and > g_strdup_printf(), so I don't see how it could end > up being junk, especially not at that point in > the string. I guess it's possible something else in > the test is managing to corrupt the g_test test name > strings? Actually it looks like something else spewing ���������� a to stderr, and this getting intermixed with stdout from the test suite. The test case name isn't corrupt, as I see the remaining "reload,..." bit that jouins with 'policy=no_immediate_" Wonder what's responsible for this garbage on stderr... With regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
On Tue, 17 Jan 2023 at 12:02, Daniel P. Berrangé <berrange@redhat.com> wrote: > > On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote: > > On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote: > > > Something random that looks like bad text data > > > > > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....������������� > > > > I don't understand this one. The string comes from > > tests/unit/ptimer-test.c:add_ptimer_tests() but that > > code creates the test string using g_strlcat() and > > g_strdup_printf(), so I don't see how it could end > > up being junk, especially not at that point in > > the string. I guess it's possible something else in > > the test is managing to corrupt the g_test test name > > strings? > > Actually it looks like something else spewing ���������� > a to stderr, and this getting intermixed with stdout from the > test suite. The test case name isn't corrupt, as I see the > remaining "reload,..." bit that jouins with 'policy=no_immediate_" > > Wonder what's responsible for this garbage on stderr... Mmm. Also I notice that we could save some output if we can fix whatever it is that's producing out-of-spec TAP format and causing this to be printed for every test: Unknown TAP version. The first line MUST be `TAP version <int>`. Assuming version 12. -- PMM
On Tue, Jan 17, 2023 at 12:22:35PM +0000, Peter Maydell wrote: > On Tue, 17 Jan 2023 at 12:02, Daniel P. Berrangé <berrange@redhat.com> wrote: > > > > On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote: > > > On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote: > > > > Something random that looks like bad text data > > > > > > > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....������������� > > > > > > I don't understand this one. The string comes from > > > tests/unit/ptimer-test.c:add_ptimer_tests() but that > > > code creates the test string using g_strlcat() and > > > g_strdup_printf(), so I don't see how it could end > > > up being junk, especially not at that point in > > > the string. I guess it's possible something else in > > > the test is managing to corrupt the g_test test name > > > strings? > > > > Actually it looks like something else spewing ���������� > > a to stderr, and this getting intermixed with stdout from the > > test suite. The test case name isn't corrupt, as I see the > > remaining "reload,..." bit that jouins with 'policy=no_immediate_" > > > > Wonder what's responsible for this garbage on stderr... > > Mmm. > > Also I notice that we could save some output if we can > fix whatever it is that's producing out-of-spec TAP > format and causing this to be printed for every test: > > Unknown TAP version. The first line MUST be `TAP version <int>`. > Assuming version 12. That's a meson bug caused by this misguided change https://github.com/mesonbuild/meson/pull/11186 and suggested to revert https://github.com/mesonbuild/meson/pull/11242 Though it seems the meson maintainer prefers their only patch: https://github.com/eli-schwartz/meson/commit/f0928378d2246bcf8a81be35c44b1350a549d647 but that's not submitted for merge that I've found. With regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
On 15/12/22 16:30, Thomas Huth wrote: > We're still running into the problem that some logs are cut in the > gitlab-CI since they got too big. The biggest part of the log is > still the output of the qom-test. Let's stop printing the properties > by default to get to a saner size here. The full output can still > be enabled by setting V=2 (or higher) in the environment. > > Signed-off-by: Thomas Huth <thuth@redhat.com> > --- > v2: Use atoi() to do proper checking of the verbosity level > > tests/qtest/qom-test.c | 12 +++++++++++- > 1 file changed, 11 insertions(+), 1 deletion(-) Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
© 2016 - 2024 Red Hat, Inc.