Running many tests is slow

[keith-packard]

Describe the bug
When there are a lot of tests (thousands), the meson overhead per test is large. In the test case provided with 17576 tests, meson itself consumes over 7 minutes of CPU time, essentially all of which is 'sys' time:

$ time meson test
...
Ok:                17576
Fail:              0   
...
real	7m19.887s
user	0m12.862s
sys	7m16.123s

Each test consumes about 25ms of sys time.

Some experimentation with cProfile and strace shows that the 'clone' syscall is taking a large amount of time (20ms or more). As that scales with memory usage, I looked at the virtual address space of the meson process and discovered that while running the test, python is using over 300MB of memory. Running a subset of the tests by adding --suite a reduces the virtual size to about 170MB:

$ time meson test --suite a
...
Ok:                676 
Fail:              0   
...
real	0m10.037s
user	0m1.146s
sys	0m9.222s

Each test in this subset consumes 14ms of sys time, making the overhead scale linearly with virtual address space of the python process.

To Reproduce

project('meson-test', 'c')

prog = find_program('true', required: true)

letters = ['a', 'b', 'c', 'd', 'e', 'f', 'g', 'h', 'i', 'j', 'k', 'l', 'm', 'n', 'o', 'p', 'q', 'r', 's', 't', 'u', 'v', 'w', 'x', 'y', 'z']

foreach a : letters
  foreach b : letters
    foreach c : letters
      test('test-@0@-@1@-@2@'.format(a, b, c), prog, suite: c)
    endforeach
  endforeach
endforeach

Run just a subset of the tests:

$ time meson test --suite a

Run all of the tests:

$ time meson test

Expected behavior
I expect meson to introduce minimal per-test overhead so that testing time is not dominated by meson overhead.

system parameters

• Is this a cross build or just a plain native build (for the same computer)?
  • plain native build
• what operating system (e.g. MacOS Catalina, Windows 10, CentOS 8.0, Ubuntu 18.04, etc.)
  • Debian Unstable
• what Python version are you using e.g. 3.8.0
  • 3.14.6
• what meson --version
  • 1.12.0.rc2
• what ninja --version if it's a Ninja build
  • 1.13.2

[eli-schwartz]

As discussed in IRC, the issue essentially boils down to "python stdlib subprocesses are slow because fork+exec". And e.g. no route to posix_spawn. Assume we can't fix python.

The remaining possibility is to reduce the overhead of meson itself. Keith suggested one possibility is to implement a meson test --spawn-helper subprocess to background and then handle the work of this, and I agree that seems the most plausible way to fix it (assuming someone, probably Keith, spends the time figuring out how to implement such a thing, as it's ... nontrivial).

[keith-packard]

For Linux, it might be reasonable to fork() early in the test run (before loading anything), then use socketpair() to communicate between main test process and the helper. Send command lines and file descriptors through the socket to try to minimize the impact outside the subprocess function. Essentially the helper reads command+fds from the socket, uses an async subprocess to run them and then reports back status values. All of the I/O remains up in the main test process.

[dnicolodi]

I looked at the virtual address space of the meson process and discovered that while running the test, python is using over 300MB of memory.

Even accounting for a large base memory usage, assuming I didn't do a silly mistake, this accounts for at least 7 kB of memory allocated per test, which seems quite a lot: 17576 tests use more than 300 MB of memory, an unspecified subset of these use 170 MB, thus each test uses at least (300 - 170) / 17576 MB of memory, which is 7.4 kB.

Does anyone have an idea of where all of it goes?

[keith-packard]

The 170MB value was having 17576 tests available but only selecting 676 of them. Presumably about half of the memory was used by tests being available and the other half by tests prepared for execution.

How does one even go about measuring memory usage by Python objects?

[dnicolodi]

The 170MB value was having 17576 tests available but only selecting 676 of them.

I knew I was doing a silly mistake somewhere.

[keith-packard]

If I create only 676 tests and run all of them, meson is only 64MB and tests run in 3.8 seconds, or 5.6ms per test, which continues the linear scaling based on virtual memory size.

So, yes, if we reduced the amount of memory used by each test (both potential and actual), then things should speed up dramatically. Maybe there's something which could be shared and ends up getting duplicated for each test?

[dnicolodi]

How does one even go about measuring memory usage by Python objects?

The memory profiling tool I know about is tracemalloc. But I don't know how easy it would be to get something useful out of it in this case.

[dnicolodi]

For Linux, it might be reasonable to fork() early in the test run (before loading anything), then use socketpair() to communicate between main test process and the helper

I think that forking early may not be required: the cost for forking the "big" main process can be paid once and the "smaller" child process can be used to spawn the worker subprocesses.

[keith-packard]

I think that forking early may not be required: the cost for forking the "big" main process can be paid once and the "smaller" child process can be used to spawn the worker subprocesses.

"small" is the key here -- if you want to just use 'fork' and not run a separate program, then you need to fork before meson gets too large.

[dnicolodi]

I think that forking early may not be required: the cost for forking the "big" main process can be paid once and the "smaller" child process can be used to spawn the worker subprocesses.

"small" is the key here -- if you want to just use 'fork' and not run a separate program, then you need to fork before meson gets too large.

Sure, I was thinking of a scheme where meson forks and executes an auxiliary program that works as a launcher for the process that supervises each test. This spawn off process would probably be even smaller than the one running meson.

[keith-packard]

Sure, I was thinking of a scheme where meson forks and executes an auxiliary program that works as a launcher for the process that supervises each test. This spawn off process would probably be even smaller than the one running meson.

True 'nuf. I was just thinking that if the fork() happened early enough, the main meson process might not be huge yet, and avoiding an exec() seemed like a nice simplification. Of course, all of this relies on someone figuring out how to make this actually work. I took a brief look and it doesn't look easy...

[keith-packard]

I don't currently have the bandwidth to work on this; feel free to give it a shot.

[eli-schwartz]

This is Aiden on behalf of Dex

Is this supposed to mean something specific to us? Who is Aiden and why don't you have your own account if you're a human asking questions for someone else's sake?

[thesamesam]

We're not interested in agent comments. Thanks.

[eli-schwartz]

This is Aiden on behalf of Dex

Aiden is the name we use for an AI coding agent working under Dex's direction. Dex owns and operates this account and reviews its public actions.

Assuming Dex ever sees my reply, which I admit is not guaranteed, Dex should be aware that it is morally and ethically forbidden for an autonomous LLM to comment or in fact interact with humans in any way shape or form in a nonconsensual manner (and no prior permission has been given in this case). Having a human "review" it after the fact is... 🤣

That's not a Meson project rule, that is a general rule of human society -- but meson can enforce that rule in this case, by permanently banning Dex from the meson organization.

I acknowledge and understand that GitHub has no interest in effective moderation of their platform and that every other project would have to independently ban bad actors. Unfortunate but there's nothing we can do about it.

[eli-schwartz]

This is definitely the first time I've ever accidentally fat-fingered the mobile site so badly that it converted a bug report into a discussion.

[eli-schwartz]

(and of course you cannot reverse it once done)

[black-sliver]

Assuming we don't care about Windows, python's multiprocessing has a mode called forkserver that maybe already solves that exact issue. I have not looked at Meson's source code too closely yet, but it looks like tests are run in a futures.ProcessPoolExecutor, which already uses multiprocessing under the hood?

Python3.14 switched to forkserver by default. Did any of the testing here happen on 3.14 or only older? Maybe just switching to latest python already fixes this, if not, maybe starting the forkserver explicitly at a known point (before RSS gets too big) would solve it.

[bonzini]

Assuming we don't care about Windows, python's multiprocessing has a mode called forkserver that maybe already solves that exact issue. I have not looked at Meson's source code too closely yet, but it looks like tests are run in a futures.ProcessPoolExecutor, which already uses multiprocessing under the hood?

ProcessPoolExecutor is used for Meson's own tests, while this issue/discussion is about the meson test command.

For the latter, tests are run using asyncio.subprocess.Process. Maybe it's possible to write a wrapper that exposes the asyncio API on top of ProcessPoolExecutor and "regular" subprocesses.

[bonzini]

@keith-packard, can you test this? It should make it possible to use vfork instead of fork...

diff --git a/mesonbuild/mtest.py b/mesonbuild/mtest.py
index 6446f7df2..8982db14f 100644
--- a/mesonbuild/mtest.py
+++ b/mesonbuild/mtest.py
@@ -1596,28 +1596,25 @@ class SingleTestRunner:
             signal.signal(signal.SIGINT, signal.SIG_IGN)
 
         def preexec_fn() -> None:
-            if self.options.interactive:
-                # Restore the SIGINT handler for the child process to
-                # ensure it can handle it.
-                signal.signal(signal.SIGINT, signal.SIG_DFL)
-            else:
-                # We don't want setsid() in gdb because gdb needs the
-                # terminal in order to handle ^C and not show tcsetpgrp()
-                # errors avoid not being able to use the terminal.
-                os.setsid()
+            # Restore the SIGINT handler for the child process to
+            # ensure it can handle it.
+            signal.signal(signal.SIGINT, signal.SIG_DFL)
 
         def postwait_fn() -> None:
             if self.options.interactive:
                 # Let us accept ^C again
                 signal.signal(signal.SIGINT, previous_sigint_handler)
 
+        start_new_session = not (is_windows() or is_os2()) and not self.options.interactive
+        need_preexec_fn = not (is_windows() or is_os2()) and self.options.interactive
         p = await asyncio.create_subprocess_exec(*args,
                                                  stdin=stdin,
                                                  stdout=stdout,
                                                  stderr=stderr,
                                                  env=env,
                                                  cwd=cwd,
-                                                 preexec_fn=preexec_fn if not (is_windows() or is_os2()) else None)
+                                                 start_new_session=start_new_session,
+                                                 preexec_fn=preexec_fn if need_preexec_fn else None)
         return TestSubprocess(p, stdout=stdout, stderr=stderr,
                               postwait_fn=postwait_fn if not is_windows() else None)
 

[eli-schwartz]

The code is unfortunately wrong: I tried to also deprecate the sigint handler change, but...

If restore_signals is true (the default) all signals that Python has set to SIG_IGN are restored to SIG_DFL in the child process before the exec. Currently this includes the SIGPIPE, SIGXFZ and SIGXFSZ signals. (POSIX only)

Annoying.

[eli-schwartz]

See also:

python/cpython#82616 (comment)
python/cpython#82616 (comment)

[bonzini]

Annoying indeed but performance doesn't matter for --interactive.

[eli-schwartz]

Yeah. Let me look into rebasing this commit tonight either way. :)

Getting rid of preexec_fn is necessary cleanup regardless of anything else.

[bonzini]

It works! Cut to 11*11*11 tests, before:

real	0m24.617s
user	0m8.998s
sys	0m18.025s

After:

real	0m7.087s
user	0m6.362s
sys	0m2.284s

Roughly a 3x improvement, with the "before" times ranging 0.02s to 0.15s and the after stable at 0.01s-0.02s.

[keith-packard]

I finally got around to testing the proposed patch and ...

HURRAY! IT WORKS!

This reduces testing time by a huge factor. What is needed to get this finished up and merged?

[eli-schwartz]

Due to the holidays, I've had drastically reduced availability all September. Today and tomorrow were supposed to be my "Eli is getting back up to speed" days, so your question is excellent timing. :D This is one of the things I will focus on this week.