On Wed Sep 23, 2026 at 3:04 PM EDT, Trevor Gamblin wrote:
> This series is motivated by the need to compare durations for various test
> results (originally, ptest) as reported by the Autobuilder. In particular,
> I've
> been looking at the intermittent ptest issues seen on the AB for the
> qemuriscv64-ptest builders, but we needed a good way to compare per-package
> durations before and after commit 6d6aaf4204be ("qemu: backport RISC-V TLB
> page
> flushing patches"). I tested this change locally with coreutils (which showed
> roughly 38% improvement on my workstation) and other tests (e.g. libpng, which
> showed no meaningful change), and review on the upstream QEMU list confirmed
> it
> helped with boot and runtime performance for qemuriscv64.
>
> This resulttool durations feature provides a means to quantify changes in
> duration across more packages at a scale beyond what my machines can handle,
> and
> might be useful to compare before and after other changes (e.g. toolchain
> tests)
> over time. I've also added a variety of test cases for oeqa selftests,
> covering
> everything from basic results parsing to making sure the tool respects
> thresholds. Each of those tests is added as a separate commit to make review
> easier.
>
> I used Claude Code to help build this out. Design took some refinement,
> especially with:
>
> - Comparing delta results for very short tests (i.e. those running for 5-10
> seconds or less) were mostly noise, especially when fractional runtimes were
> calculated under the hood and ended up reporting "0" for both runtimes but
> large (68%, 350%, etc.) deltas. I don't think we have much use for tracking
> differences in such short tests, but I did provide a '-m/--min-duration' to
> tweak this (defaulting to 10) if we want to be able to look at those.
> - Durations can vary small amounts (5-10 seconds) across consecutive tests
> even
> under little or no load, and higher when the host system is under heavy load
> (like the AB workers), so a '-t/--threshold' option is available to filter
> out
> any tests whose deltas are under a certain percentage. I didn't set a
> default
> here, but 10% is probably a reasonable one for people to use.
> - A sort option '-s/--sort-by-delta' was an obvious add so that it can be used
> to check what the biggest changes are from run to run.
> - Importantly, resulttool durations can compare more than two sources. This
> will
> be critical for tracking how results trend over time, but reporting deltas
> in
> this case seemed more debatable. For now I've left it at only reporting
> deltas
> between consecutive runs (so RUN1->RUN2 and RUN2->RUN3, but not RUN1->RUN3).
> If we need the overall delta then that should be an easy follow-up.
>
> This has already been useful/promising for inspecting the AB experience with
> qemuriscv64-ptest since the aforementioned QEMU patch backport. For example, I
> ran the following yesterday to get the top 25 largest deltas for
> qemuriscv64-ptest:
>
> 1. resulttool report
> https://valkyrie.yocto.io/pub/non-release/20260922-113/testresults/qemuriscv64-ptest/testresults.json
> > 113.log
> 2. resulttool report
> https://valkyrie.yocto.io/pub/non-release/20260922-114/testresults/qemuriscv64-ptest/testresults.json
> > 114.log
> 3. resulttool durations -s -l 25 114.log 113.log
>
> And here's what it showed:
>
> |diffstat 96 34 -62 -65
> |xz 14 5 -9 -64
> |diffutils 44 16 -28 -64
> |quilt 836 307 -529 -63
> |busybox 94 35 -59 -63
> |coreutils 2997 1166 -1831 -61
> |dpkg 647 256 -391 -60
> |gettext 1910 762 -1148 -60
> |findutils 110 44 -66 -60
> |m4 680 281 -399 -59
> |util-linux 1522 643 -879 -58
> |gawk 171 74 -97 -57
> |elfutils 459 213 -246 -54
> |bluez5 115 54 -61 -53
> |libssh2 94 48 -46 -49
> |logrotate 186 95 -91 -49
> |sed 142 73 -69 -49
> |opkg 199 113 -86 -43
> |openssh 2846 1662 -1184 -42
> |gdbm 27 17 -10 -37
> |bzip2 300 409 109 36
> |parted 473 311 -162 -34
> |wayland 12 8 -4 -33
>
> Interestingly, bzip2's runtime actually increased (a lot!). A proper analysis
> would require averaging the results over several runs, but there seems to be a
> trend with some compression and encryption packages that I'll be looking into.
> In the meantime, hopefully this feature for resulttools will prove useful to
> others too, even if they'd like to see further improvements. Note that I've
> tested it for non-ptest cases, and it works there too.
>
> Using the following command and results:
>
> - resulttool durations -s -t 10
> -
> https://valkyrie.yocto.io/pub/non-release/20260923-8/testresults/qemux86-64/testresults.json
> -
> https://valkyrie.yocto.io/pub/non-release/20260923-50/testresults/qemux86-64/testresults.json
>
> I see:
>
> |=== runtime/poky/qemux86-64/core-image-sato-sdk ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |stap.StapTest.test_stap 7 13
> 5 73
> |kernelmodule.KernelModuleTest.test_kernel_module 22 30
> 8 36
> |buildcpio.BuildCpioTest.test_cpio 28 31
> 3 10
> |
> |=== sdk/qemux86-64/i686/core-image-sato ===
> |TESTCASE RUN1 RUN2 RUN1->RUN2 %
> |cmake.CMakeTest.test_assimp 71 83 12 17
> |
> |=== sdk/qemux86-64/x86_64/core-image-sato ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |rust.RustHostCompileTest.test_cargo_build 13 18
> 4 33
> |cmake.CMakeTest.test_assimp 71 92
> 22 31
> |autotools.AutotoolsTest.test_cpio 24 27
> 3 11
> |
> |=== sdkext/qemux86-64/x86_64/core-image-minimal ===
> |TESTCASE RUN1
> RUN2 RUN1->RUN2 %
> |maturin.MaturinTest.test_maturin_list_python 4
> 21 18 459
> |devtool.DevtoolTest.test_devtool_build_esdk_package 28
> 132 104 372
> |python.Python3Test.test_python3 5
> 22 17 335
> |devtool.DevtoolTest.test_extend_autotools_recipe_creation 82
> 319 238 291
> |devtool.DevtoolTest.test_recipes_for_nodejs 15
> 25 9 61
> |devtool.DevtoolTest.test_devtool_kernelmodule 433
> 580 147 34
> |cmake.CMakeTest.test_assimp 75
> 95 21 27
> |devtool.DevtoolTest.test_devtool_add_reset 12
> 15 3 26
> |devtool.DevtoolTest.test_devtool_build_cmake 29
> 36 7 23
> |
> |=== sdkext/qemux86-64/x86_64/core-image-sato ===
> |TESTCASE RUN1
> RUN2 RUN1->RUN2 %
> |devtool.DevtoolTest.test_devtool_build_cmake 30
> 236 206 686
> |maturin.MaturinTest.test_maturin_list_python 4
> 22 18 469
> |python.Python3Test.test_python3 5
> 22 17 377
> |devtool.DevtoolTest.test_devtool_kernelmodule 429
> 1394 965 225
> |devtool.DevtoolTest.test_devtool_add_reset 13
> 18 5 39
> |maturin.MaturinDevelopTest.test_maturin_develop 24
> 32 9 36
> |cmake.CMakeTest.test_assimp 73
> 97 24 33
> |devtool.DevtoolTest.test_extend_autotools_recipe_creation 81
> 105 24 30
> |devtool.DevtoolTest.test_recipes_for_nodejs 15
> 19 4 24
> |devtool.DevtoolTest.test_devtool_build_make 33
> 39 6 17
> |autotools.AutotoolsTest.test_cpio 24
> 27 3 11
>
> Some other examples of use:
>
> First five results when comparing two reports from 'resulttool report':
>
> |tgamblin@megalith ~/workspace/ypbuilds/poky-qemuriscv64/build $ resulttool
> durations -l 5 tlb_before.log tlb_tweak.log
> |
> |=== qemuriscv64 PTest Result Summary (Libc: glibc) ===
> |TESTCASE RUN1 RUN2 RUN1->RUN2 %
> |apr 50 48 -2 -4
> |apr-util 13 11 -2 -15
> |babeltrace2 1302 1042 -260 -20
> |bc 82 82 0 0
> |bluez5 115 71 -44 -38
>
> First five results from the same reports when sorted by highest change:
>
> |tgamblin@megalith ~/workspace/ypbuilds/poky-qemuriscv64/build $ resulttool
> durations -l 5 -s tlb_before.log tlb_tweak.log
> |
> |=== qemuriscv64 PTest Result Summary (Libc: glibc) ===
> |TESTCASE RUN1 RUN2 RUN1->RUN2 %
> |libseccomp 3833 1686 -2147 -56
> |quilt 836 438 -398 -48
> |findutils 110 58 -52 -47
> |diffstat 96 52 -44 -46
> |diffutils 44 24 -20 -45
>
> Raw (and truncated) testresults.json comparison for two sources from the
> Autobuilder:
>
> |tgamblin@megalith
> ~/workspace/ypbuilds/poky-qemuriscv64/layers/openembedded-core ((no branch,
> rebasing master))$ resulttool durations
> https://valkyrie.yocto.io/pub/non-release/20260923-79/testresults/qemuriscv64-ptest/testresults.json
>
> https://valkyrie.yocto.io/pub/non-release/20260923-78/testresults/qemuriscv64-ptest/testresults.json
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-apr ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 48 48
> 0 1
> |ptestresult.sections.apr 46 47
> 1 2
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-apr-util ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 12 13
> 1 9
> |ptestresult.sections.apr-util 11 11
> 0 0
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-babeltrace2 ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 981 1066
> 85 9
> |ptestresult.sections.babeltrace2 973 1058
> 85 9
>
> The same results with '-l 1' (one line max):
>
> |tgamblin@megalith
> ~/workspace/ypbuilds/poky-qemuriscv64/layers/openembedded-core ((no branch,
> rebasing master))$ resulttool durations -l 1
> https://valkyrie.yocto.io/pub/non-release/20260923-79/testresults/qemuriscv64-ptest/testresults.json
>
> https://valkyrie.yocto.io/pub/non-release/20260923-78/testresults/qemuriscv64-ptest/testresults.json
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-apr ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 48 48
> 0 1
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-apr-util ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 12 13
> 1 9
> |
> |=== runtime/poky/qemuriscv64/core-image-ptest-babeltrace2 ===
> |TESTCASE RUN1 RUN2
> RUN1->RUN2 %
> |ptest.PtestRunnerTest.test_ptestrunner_expectfail 981 1066
> 85 9
Realizing I didn't provide an example of the three-sources case. This is what
the raw output looks like:
|TESTCASE RUN1 RUN2
RUN3 RUN1->RUN2 % RUN2->RUN3 %
|ptestresult.sections.util-linux 1522 643
935 -879 -58 292 45
|ptest.PtestRunnerTest.test_ptestrunner_expectfail 1525 645
937 -880 -58 292 45
|
|=== runtime/poky/qemuriscv64/core-image-ptest-wayland ===
|TESTCASE RUN1 RUN2
RUN3 RUN1->RUN2 % RUN2->RUN3 %
|ptestresult.sections.wayland 12 8
10 -4 -33 2 25
|ptest.PtestRunnerTest.test_ptestrunner_expectfail 14 10
11 -5 -33 2 19
|
|=== runtime/poky/qemuriscv64/core-image-ptest-xz ===
|TESTCASE RUN1 RUN2
RUN3 RUN1->RUN2 % RUN2->RUN3 %
|ptestresult.sections.xz 14 5
9 -9 -64 4 80
|ptest.PtestRunnerTest.test_ptestrunner_expectfail 16 7
10 -9 -57 3 41
And using reports:
|tgamblin@megalith
~/workspace/ypbuilds/poky-qemuriscv64/layers/openembedded-core
(tgamblin/resulttool-durations)$ resulttool durations -s -t 10 114.log 113.log
64.log
|
|=== qemuriscv64 PTest Result Summary (Libc: glibc) ===
|TESTCASE RUN1 RUN2 RUN3 RUN1->RUN2
% RUN2->RUN3 %
|xz 14 5 9 -9
-64 4 80
|flex 33 11 19 -22
-67 8 73
|libseccomp 3833 1098 1766 -2735
-71 668 61
|busybox 94 35 58 -59
-63 23 66
|diffstat 96 34 55 -62
-65 21 62
Trevor
>
> Trevor Gamblin (13):
> scripts: resulttool: add 'durations' option
> selftest: resulttooltests.py: add basic durations test
> selftest: resulttooltests.py: add report-log Time(s) column test
> selftest: resulttooltests.py: add zero-round pct suppression test
> selftest: resulttooltests.py: add consecutive-pair delta test
> selftest: resulttooltests.py: add threshold filtering test
> selftest: resulttooltests.py: add threshold-disabled test
> selftest: resulttooltests.py: add multi-pair threshold test
> selftest: resulttooltests.py: add None-pct threshold test
> selftest: resulttooltests.py: add sort-by-delta test
> selftest: resulttooltests.py: add limit-after-sort test
> selftest: resulttooltests.py: add short-tables ordering test
> selftest: resulttooltests.py: add min-duration default test
>
> .../oeqa/selftest/cases/resulttooltests.py | 201 ++++++++++++++++++
> scripts/lib/resulttool/durations.py | 187 ++++++++++++++++
> scripts/resulttool | 2 +
> 3 files changed, 390 insertions(+)
> create mode 100644 scripts/lib/resulttool/durations.py
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#246559):
https://lists.openembedded.org/g/openembedded-core/message/246559
Mute This Topic: https://lists.openembedded.org/mt/121399132/21656
Group Owner: [email protected]
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[[email protected]]
-=-=-=-=-=-=-=-=-=-=-=-
