[grandixximo]

Following up on the slow tests found in #4765.

Every linuxcnc shutdown waited 2 s for nothing. Cleanup in scripts/linuxcnc waits until halcmd is the last component before it stops realtime, but that never happened: a thread is listed as a __<name> pseudo component, which unload all leaves in place, and milltask never called hal_exit() on iocontrol.0 since the IO handling moved into task, so the component outlived the process. Both are fixed: the Task destructor releases iocontrol.0, and the wait ignores the pseudo components. One linuxcnc -r in a test goes from 3.3 s to 1.2 s here, and every real shutdown is 2 s faster.

tests/abort/g64 and tests/workplane-retain called wait_complete() right after AUTO_RUN. For a program run that waits for the end of the program, which these never reach before the abort, so every case sat out the 5 s timeout. They now wait for the point they abort at.

abort/g64 also ran its five mode settings back to back in one session, which made it the floor of a parallel run. Each setting is now a test of its own directory; a one-line test.ini includes the shared settings in g64.inc.

Times on my machine, before => after:

• workplane-retain: 70 s => 24 s
• abort/g64: 72 s => five tests of about 10 s, 11 s with -j 5
• mdi-while-queuebuster-waitflag: 65 s => 24 s (20 linuxcnc starts)

Under load (6 copies of each test at once plus 4 busy loops) all pass, 42 s against 73 s on master. Full suite passes, 354/354 with -j 4.

[hdiethelm]

Nice, down to 48s at -j32.

abort/g64 looks like 5 separate tests in one.

1. 10s
2. 10s
3. 11s
4. 10s
5. 6.4s

Total 46.4 / Run at once 45.8s

This could be optimized by splitting them but it does not help that much. If I run just 1/5 of these tests, I am down to 41s.

The order helps a bit, due to the tests are sorted alphabetically, this does the trick:

mv tests/ui-smoke tests/a-ui-smoke
mv tests/workplane-retain tests/a-workplane-retain
mv tests/tp tests/a-tp

-> still 48s

But now when I run 1/5 of the tests in abort/g64: 32s due to after changing the order, abort/g64 is the limiting factor. Due to this test starts with a, it was always run first.

For my machine, -j32 is the sweet spot. More jobs make it slower, less to.

From my side, I would call it good enough with this PR as it is, not worth investing hours to squeeze a few second more out of it. However, from 13min to 1m30 and now 48s where quite nice improvements.

[grandixximo]

@BsAtHome

What is this sleep doing? What procedure needs to finish or stabilize in these 200 milliseconds?

Sorry, that was sloppy of me: I swapped a 5 s timeout for fixed sleeps and did not check the tests under load before pushing.

Both sleeps were stand-ins. The 0.2 s gave the read ahead time to get past the slow move; the abort now waits for s.motion_line on the F10 line and s.read_line at the queue buster or M2, where the read ahead stops. The 0.3 s is gone: the run waits for the end of the program or of the abort with wait_complete(30), then for interp idle. The other command waits in both tests get 30 s instead of the 5 s default.

@hdiethelm

abort/g64 looks like 5 separate tests in one.

Thanks for measuring; split in the last commit: abort/g64 is now five tests, one per mode setting, about 10 s each. A one-line test.ini per case includes the shared settings in g64.inc. With the slow tests started first that should give your 32 s at -j 32; I can send the ordering after #4765 is in.

Checked with 6 copies of each test at once plus 4 busy loops: all pass, twice, 42 s (master 73 s under the same load).

[BsAtHome]

Just ran all tests 5 times and took an average. Some cherry picked parts of this PR were applied (linuxcnc script and component cleanup). There are only 26/350 tests that take 10 seconds or more.
list: tests.txt

If we can get those that run 20+ seconds down (8/350) then we'd be running much better. Note: abort/g64 is already stripped down in this PR but not tested. The worst offenders are:

72.286 ../tests/abort/g64
38.690 ../tests/ui-smoke/gmoccapy
36.524 ../tests/ui-smoke/axis
36.056 ../tests/ui-smoke/touchy
30.340 ../tests/mdi-while-queuebuster-waitflag
28.360 ../tests/mdi-queue/oword-queue-buster
21.222 ../tests/mdi-queue/simple-queue-buster
20.344 ../tests/workplane-retain

Getting all tests to run less than 20 seconds would help a lot.

[hdiethelm]

Thanks for the additional improvements. Now I measure ~37s.

A quick hack to measure the runtime of each test:

diff --git a/scripts/runtests.in b/scripts/runtests.in
index e0eeb30246..fb70ed7336 100755
--- a/scripts/runtests.in
+++ b/scripts/runtests.in
@@ -346,6 +346,8 @@ run_tests () {
         parallel -j "$PARALLEL" "$CMD" < "$TMPDIR/alltests_realpath" 4> "$TMPDIR/testlog"
         RET_PARALLEL=$? #Will be nonzero if any command failed
 
+        cp "$TMPDIR/testlog" .
+
         #Create sumary based on testlog
         ALL=$(wc -l < "$TMPDIR/alltests")
         SHMERR=$(grep -c SHMERR < "$TMPDIR/testlog")
@@ -527,20 +529,21 @@ elif [ $WORKER -eq 1 ]; then
         echo ERROR: worker mode does not take -j argument
         exit 1;
     fi
+    SECONDS=0
     run_one_test "$1"
     #FD 4 is used in parallel to log test results, so stdout / stderr / fd 3 used above don't interfere
     echo -n "$1" >&4
     if [ "$SHMERR" -ne 0 ]; then
-        echo " SHMERR" >&4
+        echo " SHMERR ${SECONDS}" >&4
     fi
     if [ "$FAIL" -ne 0 ]; then
-        echo " FAILED" >&4
+        echo " FAILED ${SECONDS}" >&4
         exit 1;
     elif [ "$SKIP" -ne 0 ]; then
-        echo " SKIPPED" >&4
+        echo " SKIPPED ${SECONDS}" >&4
         exit 0;
     else
-        echo " SUCCESS" >&4
+        echo " SUCCESS ${SECONDS}" >&4
         exit 0;
     fi
 else

Result, sorted with: cat "testlog" | sort -k3,3nr > testlog_sorted
And yes, there is a race outputting the data over FD 4 fo a single file, PR will follow...
testlog_sorted.txt

[hdiethelm]

And a quick hack that does the tests in descending runtime order:

diff --git a/scripts/runtests.in b/scripts/runtests.in
index f0c7a44d44..bb77354d32 100755
--- a/scripts/runtests.in
+++ b/scripts/runtests.in
@@ -203,6 +203,7 @@ test_and_remove_shmem() {
 }
 
 run_one_test() {
+    SECONDS=0
     if [ "$#" -ne 1 ]; then
         echo "ERROR: run_one_test testfile"
         return 1
@@ -287,6 +288,9 @@ run_one_test() {
             rm -f "$testdir/stderr" "$testdir/result" \
                 "$testdir"/*.var "$testdir"/*.var.bak
         fi
+        if [ $RUNTIME -ne 0 ]; then
+            echo $SECONDS > "$testdir/runtime"
+        fi
     fi
 
     if ! test_and_remove_shmem; then
@@ -307,10 +311,21 @@ run_tests () {
        | sort > "$TMPDIR/alltests"
 
     if [ "$PARALLEL" -gt 0 ]; then
-        #convert relative to full path
+        #convert relative to full path and sort by runtime
         while read -r testname; do
-            realpath -s "$testname" >> "$TMPDIR/alltests_realpath"
-        done < "$TMPDIR/alltests"
+            realpath=$(realpath -s "$testname")
+            runtime="$(dirname "$realpath")/runtime"
+            if [[ -f "$runtime" ]]; then
+                printf '%s\t%s\n' "$(cat "$runtime")" "$realpath"
+            else
+                printf '0\t%s\n' "$realpath"
+            fi
+        done < "$TMPDIR/alltests" > "$TMPDIR/alltests_realpath_tmp"
+
+        cat "$TMPDIR/alltests_realpath_tmp" | sort -nr -k1,1 | cut -f2- > "$TMPDIR/alltests_realpath"
+
+        cp "$TMPDIR/alltests_realpath_tmp" .
+        cp "$TMPDIR/alltests_realpath" .
 
         #ro-bind: / (root) so if any files are written at an unknown location, an error is generated
         #dev: add device files
@@ -472,6 +487,7 @@ STOP=0
 PRINT=0
 PARALLEL=0
 PARALLEL_OUTDIR=""
+RUNTIME=1
 WORKER=0
 WORKER_OPT=()
 while getopts cnvsphdj:o:w opt; do

This would probably be the nicer solution than checking for ini. The only downside is, that here are runtime files that need to be updated if a new test is created or a test is changed generating noise in the diffs.

An easy solution would be to rename the tests to start with 0_ / 1_ and so on to define the running order by name.

37s -> 29s.

[BsAtHome]

The trick is that the running time distribution must be truly even random for long runs to cancel out the variability. We have several long running processes at the end of the alphabetically sorted queue, which will additionally skew the total running time.

The second thing is that we do not want outliers. Any slow outlier will become part of a long tail. Therefore, we need to reduce each test to run some max time and if it is too slow, try to split the test so that parallel runs make it better (like abort/g64). The max time for a single test must always be less than the total running time of all the other tests in parallel. That is why the ui-smoke tests need speeding up. They are the next bottleneck.

[hdiethelm]

The trick is that the running time distribution must be truly even random for long runs to cancel out the variability. We have several long running processes at the end of the alphabetically sorted queue, which will additionally skew the total running time.

A viable solution is to record the runtime once. After this, you can run the tests in descending runtime order to reduce the influence of long running tests. Worst case is starting the longest running test at the end which is nearly the case right now, workplane-retain, 19s starts last.

The second thing is that we do not want outliers. Any slow outlier will become part of a long tail. Therefore, we need to reduce each test to run some max time and if it is too slow, try to split the test so that parallel runs make it better (like abort/g64). The max time for a single test must always be less than the total running time of all the other tests in parallel. That is why the ui-smoke tests need speeding up. They are the next bottleneck.

Right now, mdi-while-queuebuster-waitflag is the slowest test with 20s. By ordering, the long tail is reduced considerably.

Just checked, by removing the slowest 10 tests (with ordering) it goes from 29s to 24s, diminishing returns.