Improve benchmark runner output in case of errors

[lhstrh]

[2021-11-02 18:51:26,446][run_benchmark][INFO] - run command: cog -r -D workers=100 -D pieces=10000000 -D left=1.0 -D right=5.0 -D threads=2 -D threaded_runtime=False src/Trapezoidal.lf
[2021-11-02 18:51:26,494][cog][INFO] - Cogging src/Trapezoidal.lf  (changed)
[2021-11-02 18:51:26,503][run_benchmark][INFO] - run command: /home/runner/work/lingua-franca/lingua-franca/bin/lfc src/Trapezoidal.lf
[2021-11-02 18:51:27,697][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - Generating code for: file:/home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src/Trapezoidal.lf
[2021-11-02 18:51:27,698][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** mode: STANDALONE
[2021-11-02 18:51:27,699][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** source file: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src/Trapezoidal.lf
[2021-11-02 18:51:27,699][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** generated sources: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src-gen/Trapezoidal
[2021-11-02 18:51:27,700][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** generated binaries: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/bin
[2021-11-02 18:51:27,837][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** Using 1 threads.
[2021-11-02 18:51:27,998][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - --- Current working directory: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src-gen/Trapezoidal/build
[2021-11-02 18:51:27,998][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - --- Executing command: cmake -DCMAKE_INSTALL_PREFIX=/home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43 -DCMAKE_INSTALL_BINDIR=bin /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src-gen/Trapezoidal
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- The C compiler identification is GNU 9.3.0
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Detecting C compiler ABI info
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Detecting C compiler ABI info - done
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Check for working C compiler: /usr/bin/cc - skipped
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Detecting C compile features
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Detecting C compile features - done
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Configuring done
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Generating done
[2021-11-02 18:51:28,128][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Build files have been written to: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src-gen/Trapezoidal/build
[2021-11-02 18:51:28,132][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - --- Current working directory: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/src-gen/Trapezoidal/build
[2021-11-02 18:51:28,133][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - --- Executing command: cmake --build . --target install --parallel 2 --config Release
[2021-11-02 18:51:28,332][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - [ 50%] Building C object CMakeFiles/Trapezoidal.dir/core/platform/lf_linux_support.c.o
[2021-11-02 18:51:28,332][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - [ 50%] Building C object CMakeFiles/Trapezoidal.dir/Trapezoidal.c.o
[2021-11-02 18:51:28,332][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - [ 75%] Building C object CMakeFiles/Trapezoidal.dir/ctarget.c.o
[2021-11-02 18:51:31,931][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - [100%] Linking C executable Trapezoidal
[2021-11-02 18:51:31,950][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - [100%] Built target Trapezoidal
[2021-11-02 18:51:31,950][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - Install the project...
[2021-11-02 18:51:31,950][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Install configuration: "Release"
[2021-11-02 18:51:31,950][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - -- Installing: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/18-49-18/43/bin/Trapezoidal
[2021-11-02 18:51:31,950][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - SUCCESS: Compiling generated code for Trapezoidal finished with no errors.
[2021-11-02 18:51:31,959][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - Code generation finished.
[2021-11-02 18:51:31,967][run_benchmark][INFO] - run command: timeout 1 bash -c seq 1 | xargs -I{} bin/Trapezoidal
Error executing job with overrides: ['test_mode=True', 'iterations=1', 'benchmark=savina_concurrency_barber', 'target=lf-c', 'iterations=1']
An error occurred during Hydra's exception formatting:
TypeError("print_exception() got an unexpected keyword argument 'etype'")
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/utils.py", line 283, in run_and_report
    print_exception(etype=None, value=ex, tb=final_tb)  # type: ignore
TypeError: print_exception() got an unexpected keyword argument 'etype'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/runner/work/lingua-franca/lingua-franca/benchmark/runner/run_benchmark.py", line 194, in <module>
    main()
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/main.py", line 48, in decorated_main
    _run_hydra(
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/utils.py", line 385, in _run_hydra
    run_and_report(
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/utils.py", line 294, in run_and_report
    raise ex
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/utils.py", line 211, in run_and_report
    return func()
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/utils.py", line 386, in <lambda>
    lambda: hydra.multirun(
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/hydra.py", line 140, in multirun
    ret = sweeper.sweep(arguments=task_overrides)
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/_internal/core_plugins/basic_sweeper.py", line 161, in sweep
    _ = r.return_value
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/core/utils.py", line 233, in return_value
    raise self._return_value
  File "/opt/hostedtoolcache/Python/3.10.0/x64/lib/python3.10/site-packages/hydra/core/utils.py", line 160, in run_job
    ret.return_value = task_function(task_cfg)
  File "/home/runner/work/lingua-franca/lingua-franca/benchmark/runner/run_benchmark.py", line 75, in main
    check_return_code(code, continue_on_error)
  File "/home/runner/work/lingua-franca/lingua-franca/benchmark/runner/run_benchmark.py", line 107, in check_return_code
    raise RuntimeError(
RuntimeError: Command returned with non-zero exit code (1)
Error: Process completed with exit code 1.

See https://github.com/lf-lang/lingua-franca/actions/runs/1414065663.

[cmnrd]

There is something odd going on in CI. For some reason hydra's internal error handling fails while processing an error. I cannot reproduce this locally. Maybe this is because CI is running on Python 3.10 already. However, the actual error is always printed. It only is located further up. The line

Error executing job with overrides: ['test_mode=True', 'iterations=1', 'benchmark=savina_concurrency_barber', 'target=lf-c', 'iterations=1']

in your snippet tells you that an error occurred during the barber benchmark in the LF C target. When searching the log for babrer, you get this:

[2021-11-02 20:42:14,415][run_benchmark][INFO] - run command: cp -r /home/runner/work/lingua-franca/lingua-franca/benchmark/C/Savina/src/include /home/runner/work/lingua-franca/lingua-franca/benchmark/C/Savina/src/concurrency src
[2021-11-02 20:42:14,429][run_benchmark][INFO] - run command: cog -r -D numHaircuts=2000 -D waitingRoomSize=1000 -D averageProductionRate=1000 -D averageHaircutRate=1000 -D threads=2 -D threaded_runtime=True src/concurrency/SleepingBarber.lf
[2021-11-02 20:42:14,471][cog][INFO] - Cogging src/concurrency/SleepingBarber.lf  (changed)
[2021-11-02 20:42:14,481][run_benchmark][INFO] - run command: /home/runner/work/lingua-franca/lingua-franca/bin/lfc src/concurrency/SleepingBarber.lf
[2021-11-02 20:42:16,177][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - Generating code for: file:/home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/20-42-09/2/src/concurrency/SleepingBarber.lf
[2021-11-02 20:42:16,177][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** mode: STANDALONE
[2021-11-02 20:42:16,177][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** source file: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/20-42-09/2/src/concurrency/SleepingBarber.lf
[2021-11-02 20:42:16,177][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** generated sources: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/20-42-09/2/src-gen/concurrency/SleepingBarber
[2021-11-02 20:42:16,177][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - ******** generated binaries: /home/runner/work/lingua-franca/lingua-franca/multirun/2021-11-02/20-42-09/2/bin
[2021-11-02 20:42:16,345][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - WARNING: Failed to find file /lib/c/reactor-c/util/deque.h
[2021-11-02 20:42:16,347][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - WARNING: Failed to find file /lib/c/reactor-c/util/deque.c
[2021-11-02 20:42:16,369][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - lfc: error: Failed to find file /lib/c/reactor-c/util/deque.c specified in the files target property.
[2021-11-02 20:42:16,370][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] -  --> (unknown file):null:1 - Failed to find file /lib/c/reactor-c/util/deque.c specified in the files target property.
[2021-11-02 20:42:16,370][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - 
[2021-11-02 20:42:16,370][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - lfc: error: Failed to find file /lib/c/reactor-c/util/deque.h specified in the files target property.
[2021-11-02 20:42:16,370][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] -  --> (unknown file):null:1 - Failed to find file /lib/c/reactor-c/util/deque.h specified in the files target property.
[2021-11-02 20:42:16,370][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - 
[2021-11-02 20:42:16,372][/home/runner/work/lingua-franca/lingua-franca/bin/lfc][INFO] - lfc: fatal error: Aborting due to 2 previous errors

[Soroosh129]

Nice catch!

Looks like that branch is using an older version of reactor-c.

[housengw]

From my experience fixing bugs in the C benchmarks for lf-lang/lingua-franca#777, the TypeError("print_exception() got an unexpected keyword argument 'etype'") error showed up when there was a segfault during the benchmark run