test-user-mode: make perfect like build-userland

Multithreading and target selection.

README.adoc

@@ -3506,7 +3506,20 @@ The gem5 tests require building statically with build id `static`, see also: <<g
 
 See: <<test-this-repo>> for more useful testing tips.
 
-==== User mode with host toolchain and QEMU
+=== User mode Buildroot executables
+
+If you followed <<qemu-buildroot-setup>>, you can now run the executables created by Buildroot directly as:
+
+....
+./run \
+  --userland "$(./getvar buildroot_target_dir)/bin/echo" \
+  --userland-args='asdf' \
+;
+....
+
+Here is an interesting examples of this: <<linux-test-project>>
+
+=== User mode with host toolchain and QEMU
 
 If you are lazy to built the Buildroot toolchain and QEMU, you can get away on Ubuntu 18.04 with just:
 
@@ -3537,11 +3550,11 @@ This present the usual trade-offs of using prebuilts as mentioned at: <<prebuilt
 
 When you build with the native host toolchain, you can also execute many of the executables directly natively on the host: <<userland-setup-getting-started-natively>>.
 
-==== User mode simulation with glibc
+=== User mode simulation with glibc
 
 At 125d14805f769104f93c510bedaa685a52ec025d we <<libc-choice,moved Buildroot from uClibc to glibc>>, and caused some user mode pain, which we document here.
 
-===== FATAL: kernel too old
+==== FATAL: kernel too old
 
 Happens on all gem5 <<user-mode-simulation>> setups, but not on QEMU on Ubuntu 18.04 host.
 
@@ -3572,7 +3585,7 @@ In gem5, there are tons of missing syscalls, and that number currently just gets
 
 The ID is just hardcoded on the source:
 
-===== stack smashing detected
+==== stack smashing detected
 
 For some reason QEMU / glibc x86_64 picks up the host libc, which breaks things.
 
@@ -3611,7 +3624,7 @@ A non-QEMU-specific example of stack smashing is shown at: https://stackoverflow
 
 Tested at: 2e32389ebf1bedd89c682aa7b8fe42c3c0cf96e5 + 1.
 
-==== User mode static executables
+=== User mode static executables
 
 Example:
 
@@ -3637,7 +3650,7 @@ However, in case something goes wrong, you can also try statically linked execut
 * gem5 user mode currently only supports static executables: <<gem5-syscall-emulation-mode>>
 * QEMU x86_64 guest on x86_64 host was failing with <<stack-smashing-detected>>, but we found a workaround
 
-===== User mode static executables with dynamic libraries
+==== User mode static executables with dynamic libraries
 
 One limitation of static executables is that Buildroot mostly only builds dynamic versions of libraries (the libc is an exception).
 
@@ -3742,6 +3755,8 @@ which we parse in link:run[] and then exit with the correct result ourselves...
 
 Let's see if user mode runs considerably faster than full system or not.
 
+First we build Dhrystone manually statically since dynamic linking is broken in gem5: <<gem5-syscall-emulation-mode>>.
+
 gem5 user mode:
 
 ....
@@ -3796,6 +3811,28 @@ Result on <<p51>> at bad30f513c46c1b0995d3a10c0d9bc2a33dc4fa0:
 * QEMU user: 45 seconds
 * QEMU full system: 223 seconds
 
+=== QEMU user mode does not show stdout immediately
+
+At 8d8307ac0710164701f6e14c99a69ee172ccbb70 + 1, I noticed that if you run link:userland/posix/count.c[]:
+
+....
+./run --userland userland/posix/count.c --userland-args 3
+....
+
+it first waits for 3 seconds, and then dumps all the output at once, instead of counting once every second as expected.
+
+The same can be reproduced by copying the raw QEMU command and piping it through `tee`, so I don't think it is a bug in our setup:
+
+....
+/path/to/linux-kernel-module-cheat/out/qemu/default/x86_64-linux-user/qemu-x86_64 \
+  -L /path/to/linux-kernel-module-cheat/out/buildroot/build/default/x86_64/target \
+  /path/to/linux-kernel-module-cheat/out/userland/default/x86_64/posix/count.out \
+  3 \
+| tee
+....
+
+TODO: investigate further and then possibly post on QEMU mailing list.
+
 == Kernel module utilities
 
 === insmod
@@ -8349,7 +8386,7 @@ exit01      1  TPASS  :  exit() test PASSED
 
 and has source code at: https://github.com/linux-test-project/ltp/blob/20190115/testcases/kernel/syscalls/exit/exit01.c
 
-Besides testing any kernel modifications you make, LTP can also be used to the system call implementation of <<user-mode-simulation>>:
+Besides testing any kernel modifications you make, LTP can also be used to the system call implementation of <<user-mode-simulation>> as shown at <<user-mode-buildroot-executables>>:
 
 ....
 ./run --userland "$(./getvar buildroot_target_dir)/usr/lib/ltp-testsuite/testcases/bin/exit01"
@@ -9924,6 +9961,7 @@ Usage:
   --emulator gem5 \
   --static \
   --userland cpp/bst_vs_heap \
+  --userland-args='1000' \
 ;
 ./bst-vs-heap --arch aarch64 > bst_vs_heap.dat
 ./bst-vs-heap.gnuplot

bst-vs-heap

@@ -7,7 +7,7 @@ class Main(common.LkmcCliFunction):
         super().__init__(
             defaults={
                 'emulator': 'gem5',
-                'print_time': False,
+                'show_time': False,
             },
             description='''\
 Convert a BST vs heap stat file into a gnuplot input

build

@@ -402,7 +402,7 @@ Which components to build. Default: qemu-buildroot
         def f():
             args = self.get_common_args()
             args.update(extra_args)
-            args['print_time'] = False
+            args['show_time'] = False
             self.import_path_main(component_file)(**args)
         return f
 

build-doc

@@ -9,7 +9,7 @@ class Main(common.LkmcCliFunction):
     def __init__(self):
         super().__init__(
             defaults = {
-                'print_time': False,
+                'show_time': False,
             },
             description='''\
 https://github.com/cirosantilli/linux-kernel-module-cheat#build-the-documentation

common.py

@@ -1,23 +1,28 @@
 #!/usr/bin/env python3
 
 import argparse
+import bisect
 import collections
 import copy
 import datetime
 import enum
+import functools
 import glob
 import imp
 import inspect
+import itertools
 import json
 import math
 import os
 import platform
 import pathlib
+import queue
 import re
 import shutil
 import signal
 import subprocess
 import sys
+import threading
 import time
 import urllib
 import urllib.request
@@ -152,6 +157,7 @@ class LkmcCliFunction(cli_function.CliFunction):
         self._common_args = set()
         super().__init__(*args, **kwargs)
         self.supported_archs = supported_archs
+        self.print_lock = threading.Lock()
 
         # Args for all scripts.
         arches = consts['arch_short_to_long_dict']
@@ -219,12 +225,14 @@ Which toolchain binaries to use:
 '''
         )
         self.add_argument(
-            '--print-time',
+            '-j',
-            default=True,
+            '--nproc',
-            help='''\
+            default=len(os.sched_getaffinity(0)),
-Print how long it took to run the command at the end.
+            type=int,
-Implied by --quiet.
+            help='''Number of processors to use for the action.
-'''
+This is currently only implemented for the following scripts:
+all ./build-* scripts, test-user-mode.
+''',
         )
         self.add_argument(
             '-q',
@@ -240,6 +248,14 @@ TODO: implement fully, some stuff is escaping it currently.
             default=True,
             help='''\
 Stop running at the first failed test.
+'''
+        )
+        self.add_argument(
+            '--show-time',
+            default=True,
+            help='''\
+Print how long it took to run the command at the end.
+Implied by --quiet.
 '''
         )
         self.add_argument(
@@ -985,13 +1001,15 @@ lunch aosp_{}-eng
         return self.supported_archs is None or arch in self.supported_archs
 
     def log_error(self, msg):
-        print('error: {}'.format(msg), file=sys.stdout)
+        with self.print_lock:
+            print('error: {}'.format(msg), file=sys.stdout)
 
     def log_info(self, msg='', flush=False, **kwargs):
-        if not self.env['quiet']:
+        with self.print_lock:
-            print('{}'.format(msg), **kwargs)
+            if not self.env['quiet']:
-        if flush:
+                print('{}'.format(msg), **kwargs)
-            sys.stdout.flush()
+            if flush:
+                sys.stdout.flush()
 
     def main(self, *args, **kwargs):
         '''
@@ -1087,7 +1105,7 @@ lunch aosp_{}-eng
         return '{:02}:{:02}:{:02}'.format(int(hours), int(minutes), int(seconds))
 
     def print_time(self, ellapsed_seconds):
-        if self.env['print_time'] and not self.env['quiet']:
+        if self.env['show_time'] and not self.env['quiet']:
             print('time {}'.format(self.seconds_to_hms(ellapsed_seconds)))
 
     def raw_to_qcow2(self, qemu_which=False, reverse=False):
@@ -1280,14 +1298,6 @@ class BuildCliFunction(LkmcCliFunction):
             default=False,
             help='Clean the build instead of building.',
         ),
-        self.add_argument(
-            '-j',
-            '--nproc',
-            default=len(os.sched_getaffinity(0)),
-            type=int,
-            help='Number of processors to use for the build.',
-        )
-        self.test_results = []
         self._build_arguments = {
             '--ccflags': {
                 'default': '',
@@ -1354,23 +1364,30 @@ https://github.com/cirosantilli/linux-kernel-module-cheat#gem5-debug-build
         else:
             return self.build()
 
-# from aenum import Enum  # for the aenum version
+TestStatus = enum.Enum('TestStatus', ['PASS', 'FAIL'])
-TestResult = enum.Enum('TestResult', ['PASS', 'FAIL'])
 
-class Test:
+@functools.total_ordering
+class TestResult:
     def __init__(
         self,
-        test_id: str,
+        test_id: str ='',
-        result : TestResult =None,
+        status : TestStatus =TestStatus.PASS,
-        ellapsed_seconds : float =None
+        ellapsed_seconds : float =0
     ):
         self.test_id = test_id
-        self.result = result
+        self.status = status
         self.ellapsed_seconds = ellapsed_seconds
+
+    def __eq__(self, other):
+        return self.test_id == other.test_id
+
+    def __lt__(self, other):
+        return self.test_id < other.test_id
+
     def __str__(self):
         out = []
-        if self.result is not None:
+        if self.status is not None:
-            out.append(self.result.name)
+            out.append(self.status.name)
         if self.ellapsed_seconds is not None:
             out.append(LkmcCliFunction.seconds_to_hms(self.ellapsed_seconds))
         out.append(self.test_id)
@@ -1385,13 +1402,13 @@ class TestCliFunction(LkmcCliFunction):
 
     def __init__(self, *args, **kwargs):
         defaults = {
-            'print_time': False,
+            'show_time': False,
         }
         if 'defaults' in kwargs:
             defaults.update(kwargs['defaults'])
         kwargs['defaults'] = defaults
         super().__init__(*args, **kwargs)
-        self.tests = []
+        self.test_results = queue.Queue()
 
     def run_test(
         self,
@@ -1440,36 +1457,38 @@ class TestCliFunction(LkmcCliFunction):
             expected_exit_status = 0
         if not self.env['dry_run']:
             if exit_status == expected_exit_status:
-                test_result = TestResult.PASS
+                test_result = TestStatus.PASS
             else:
-                test_result = TestResult.FAIL
+                test_result = TestStatus.FAIL
-            self.log_info('test_result {}'.format(test_result.name))
             ellapsed_seconds = run_obj.ellapsed_seconds
         else:
-            test_result = None
+            test_result = TestStatus.PASS
-            ellapsed_seconds = None
+            ellapsed_seconds = 0
-        self.log_info()
+        test_result = TestResult(
-        self.tests.append(Test(test_id_string, test_result, ellapsed_seconds))
+            test_id_string,
+            test_result,
+            ellapsed_seconds
+        )
+        self.log_info(test_result)
+        self.test_results.put(test_result)
         return test_result
 
     def teardown(self):
         '''
         :return: 1 if any test failed, 0 otherwise
         '''
-        self.log_info('Test result summary')
+        self.log_info('\nTest result summary')
         passes = []
         fails = []
-        for test in self.tests:
+        while not self.test_results.empty():
-            if test.result in (TestResult.PASS, None):
+            test = self.test_results.get()
-                passes.append(test)
+            if test.status in (TestStatus.PASS, None):
+                bisect.insort(passes, test)
             else:
-                fails.append(test)
+                bisect.insort(fails, test)
-        if passes:
+        for test in itertools.chain(passes, fails):
-            for test in passes:
+            self.log_info(test)
-                self.log_info(test)
         if fails:
-            for test in fails:
-                self.log_info(test)
             self.log_error('A test failed')
             return 1
         return 0

example_properties.py

@@ -22,8 +22,12 @@ class ExecutableProperties:
             not self.more_than_1s
 
 executable_properties = {
-    'c/assert_fail.c': ExecutableProperties(exit_status=0),
+    'c/assert_fail.c': ExecutableProperties(exit_status=1),
-    'c/false.c': ExecutableProperties(exit_status=0),
+    'c/false.c': ExecutableProperties(exit_status=1),
+    'c/infinite_loop.c': ExecutableProperties(more_than_1s=True),
+    'posix/count.c': ExecutableProperties(more_than_1s=True),
+    'posix/sleep_forever.c': ExecutableProperties(more_than_1s=True),
+    'posix/virt_to_phys_test.c': ExecutableProperties(more_than_1s=True),
 }
 
 def get(test_path):

gem5-stat

@@ -6,7 +6,7 @@ class Main(common.LkmcCliFunction):
     def __init__(self):
         super().__init__(
             defaults={
-                'print_time': False,
+                'show_time': False,
             },
             description='''\
 Get the value of a gem5 stat from the stats.txt file.

getvar

@@ -6,7 +6,7 @@ class Main(common.LkmcCliFunction):
     def __init__(self):
         super().__init__(
             defaults = {
-                'print_time': False,
+                'show_time': False,
             },
             description='''\
 Print the value of a self.env['py'] variable.

release-zip

@@ -12,7 +12,7 @@ class Main(common.LkmcCliFunction):
 https://github.com/cirosantilli/linux-kernel-module-cheat#release-zip
 ''',
             defaults = {
-                'print_time': False,
+                'show_time': False,
             }
         )
         self.zip_files = []

run

@@ -20,7 +20,7 @@ Run some content on an emulator.
         self.add_argument(
             '--background', default=False,
             help='''\
-Send QEMU output to a file instead of the terminal so it does not require a
+Send QEMU serial output to a file instead of the terminal so it does not require a
 terminal attached to run on the background. Interactive input cannot be given.
 TODO: use a port instead. If only there was a way to redirect a serial to multiple
 places, both to a port and a file? We use the file currently to be able to have
@@ -166,6 +166,10 @@ Setup a kernel init parameter that makes the emulator quit immediately after boo
             '-r', '--record', default=False,
             help='Record a QEMU run record for later replay with `-R`'
         )
+        self.add_argument(
+            '--show-stdout', default=True,
+            help='''Show emulator stdout and stderr on the host terminal.'''
+        )
         self.add_argument(
             '--terminal', default=False,
             help='''\
@@ -238,7 +242,7 @@ Run QEMU with VNC instead of the default SDL. Connect to it with:
         )
 
     def timed_main(self):
-        show_stdout = True
+        show_stdout = self.env['show_stdout']
         # Common qemu / gem5 logic.
         # nokaslr:
         # * https://unix.stackexchange.com/questions/397939/turning-off-kaslr-to-debug-linux-kernel-using-qemu-and-gdb
@@ -455,6 +459,7 @@ Run QEMU with VNC instead of the default SDL. Connect to it with:
                         os.path.join(self.env['qemu_build_dir'], '{}-linux-user'.format(self.env['arch']), 'qemu-{}'.format(self.env['arch'])), LF,
                         '-L', self.env['userland_library_dir'], LF,
                         '-r', self.env['kernel_version'], LF,
+                        '-seed', '0', LF,
                     ] +
                     qemu_user_and_system_options +
                     debug_args

shell_helpers.py

@@ -52,10 +52,9 @@ class ShellHelpers:
         https://stackoverflow.com/questions/3029816/how-do-i-get-a-thread-safe-print-in-python-2-6
         The initial use case was test-gdb which must create a thread for GDB to run the program in parallel.
         '''
-        cls._print_lock.acquire()
+        with cls._print_lock:
-        sys.stdout.write(string + '\n')
+            sys.stdout.write(string + '\n')
-        sys.stdout.flush()
+            sys.stdout.flush()
-        cls._print_lock.release()
 
     def add_newlines(self, cmd):
         out = []
@@ -217,16 +216,16 @@ class ShellHelpers:
         :return: exit status of the command
         :rtype: int
         '''
-        if out_file is not None:
+        if out_file is None:
-            stdout = subprocess.PIPE
-            stderr = subprocess.STDOUT
-        else:
             if show_stdout:
                 stdout = None
                 stderr = None
             else:
                 stdout = subprocess.DEVNULL
                 stderr = subprocess.DEVNULL
+        else:
+            stdout = subprocess.PIPE
+            stderr = subprocess.STDOUT
         if extra_env is None:
             extra_env = {}
         if delete_env is None:

test-user-mode

@@ -5,13 +5,14 @@ import sys
 
 import common
 import example_properties
+from thread_pool import ThreadPool
 
 class Main(common.TestCliFunction):
     def __init__(self):
         super().__init__(
             description='''\
 https://github.com/cirosantilli/linux-kernel-module-cheat#user-mode-tests
-'''
+''',
         )
         self.add_argument(
             'tests',
@@ -25,36 +26,46 @@ If given, run only the given tests. Otherwise, run all tests.
         run = self.import_path_main('run')
         run_args = self.get_common_args()
         run_args['ctrl_c_host'] = True
+        run_args['show_stdout'] = False
+        run_args['show_time'] = False
         if self.env['emulator'] == 'gem5':
             run_args['userland_build_id'] = 'static'
-        if self.env['tests'] == []:
-            test_paths = [
-                'c/add.c',
-                'c/false.c',
-                'c/hello.c',
-                'c/print_argv.c',
-                'cpp/hello.cpp',
-            ]
-        else:
-            test_paths = self.env['tests']
         had_failure = False
-        for test_path in test_paths:
+        rootdir_abs_len = len(self.env['userland_source_dir'])
-            test = example_properties.get(test_path)
+        with ThreadPool(
-            if test.should_be_tested():
+            self.run_test,
-                # for test in self.sh.walk(self.resolve_userland_source(test_dir_or_file)):
+            nthreads=self.env['nproc'],
-                run_args['userland'] = test_path
+        ) as thread_pool:
-                test_result = self.run_test(
+            try:
-                    run,
+                for path, in_dirnames, in_filenames in self.walk_source_targets(
-                    run_args,
+                    self.env['tests'],
-                    test_id=test_path,
+                    self.env['userland_in_exts']
-                    expected_exit_status=test.exit_status
+                ):
-                )
+                    path_abs = os.path.abspath(path)
-                if test_result != common.TestResult.PASS:
+                    dirpath_relative_root = path_abs[rootdir_abs_len + 1:]
-                    if self.env['quit_on_fail']:
+                    for in_filename in in_filenames:
-                        return 1
+                        path_relative_root = os.path.join(dirpath_relative_root, in_filename)
-                    else:
+                        test = example_properties.get(path_relative_root)
-                        had_failure = True
+                        if test.should_be_tested():
-        if had_failure:
+                            cur_run_args = run_args.copy()
+                            cur_run_args.update({
+                                'background': True,
+                                'userland': path_relative_root,
+                            })
+                            error = thread_pool.submit({
+                                'expected_exit_status': test.exit_status,
+                                'run_args': cur_run_args,
+                                'run_obj': run,
+                                'test_id': path_relative_root,
+                            })
+                            if error is not None:
+                                if self.env['quit_on_fail']:
+                                    raise common.ExitLoop()
+            except common.ExitLoop:
+                pass
+        error = thread_pool.get_error()
+        if error is not None:
+            print(error)
             return 1
         else:
             return 0

thread_pool.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python3
 
 from typing import Any, Callable, Dict, Iterable, Union
+import os
 import queue
 import sys
 import threading
@@ -13,10 +14,10 @@ class ThreadPool:
     This is similar to the stdlib concurrent, but I could not find
     how to reach all my design goals with that implementation:
 
-    - the input function does not need to be modified
+    * the input function does not need to be modified
-    - limit the number of threads
+    * limit the number of threads
-    - queue sizes closely follow number of threads
+    * queue sizes closely follow number of threads
-    - if an exception happens, optionally stop soon afterwards
+    * if an exception happens, optionally stop soon afterwards
 
     Functional form and further discussion at:
     https://stackoverflow.com/questions/19369724/the-right-way-to-limit-maximum-number-of-threads-running-at-once/55263676#55263676
@@ -25,10 +26,12 @@ class ThreadPool:
 
     Quick test with:
 
-        ./thread_limit.py 2 -10 20 0
+    ....
-        ./thread_limit.py 2 -10 20 1
+    python3 thread_pool.py 2 -10 20 0
-        ./thread_limit.py 2 -10 20 2
+    python3 thread_pool.py 2 -10 20 1
-        ./thread_limit.py 2 -10 20 3
+    python3 thread_pool.py 2 -10 20 2
+    python3 thread_pool.py 2 -10 20 3
+    ....
 
     These ensure that execution stops neatly on error.
     '''
@@ -49,9 +52,9 @@ class ThreadPool:
 
             Signature is: handle_output(input, output, exception) where:
 
-            - input: input given to func
+            * input: input given to func
-            - output: return value of func
+            * output: return value of func
-            - exception: the exception that func raised, or None otherwise
+            * exception: the exception that func raised, or None otherwise
 
             If this function returns non-None or raises, stop feeding
             new input and exit ASAP when all currently running threads
@@ -79,6 +82,16 @@ class ThreadPool:
             thread.start()
 
     def __enter__(self):
+        '''
+        __exit__ automatically calls join() for you.
+
+        This is cool because it automatically ends the loop if an exception occurs.
+
+        But don't forget that errors may happen after the last submit is called, so you
+        likely want to check for that with get_error after the with.
+
+        get_error() returns the same as the explicit join().
+        '''
         return self
 
     def __exit__(self, type, value, traceback):
@@ -124,14 +137,12 @@ class ThreadPool:
             try:
                 handle_output_return = self.handle_output(work, out, exception)
             except Exception as e:
-                self.error_output_lock.acquire()
+                with self.error_output_lock:
-                self.error_output = (work, out, e)
+                    self.error_output = (work, out, e)
-                self.error_output_lock.release()
             else:
                 if handle_output_return is not None:
-                    self.error_output_lock.acquire()
+                    with self.error_output_lock:
-                    self.error_output = handle_output_return
+                        self.error_output = handle_output_return
-                    self.error_output_lock.release()
             finally:
                 self.in_queue.task_done()
 

userland/c/false.c

@@ -1,4 +1,5 @@
-/* Exit with status 1.
+/* Exit with status 1 like the POSIX false utility:
+ * http://pubs.opengroup.org/onlinepubs/9699919799/utilities/false.html
  *
  * Can be uesd to test that emulators forward the exit status properly.
  * https://github.com/cirosantilli/linux-kernel-module-cheat#gem5-syscall-emulation-exit-status

userland/c/infinite_loop.c

@@ -0,0 +1,29 @@
+/* Loop infinitely. Print an integer whenever a period is reached:
+ *
+ * ....
+ * ./infinite_loop [period]
+ * ....
+ */
+
+#include <inttypes.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
+
+int main(int argc, char **argv) {
+    uintmax_t i, j, period;
+    if (argc > 1) {
+        period = strtoumax(argv[1], NULL, 10);
+    } else {
+        period = 100000000;
+    }
+    i = 0;
+    j = 0;
+    while (1) {
+        i++;
+        if (i % period == 0) {
+            printf("%ju\n", j);
+            j++;
+        }
+    }
+}

userland/c/stderr.c

@@ -0,0 +1,7 @@
+/* Print hello to stderr. */
+
+#include <stdio.h>
+
+int main(void) {
+    fputs("hello\n", stderr);
+}

userland/cpp/bst_vs_heap.cpp

@@ -20,7 +20,7 @@ int main(int argc, char **argv) {
     if (argc > 1) {
         n = std::stoi(argv[1]);
     } else {
-        n = 1000;
+        n = 1;
     }
 
     // Action.