[Question] How to fix the order in which commands run?

[MikeBusuttil]

I'm working on a repo where running scons results in 12 commands being run. For optimal performance, many commands can be run in parallel (see "Optimal Order of Commands" below). I believe our scons configuration results in sub-optimal command running. Would anyone be able to help me figure out what the current command ordering is now and how to tell scons to parallelize the offending commands?

Scons configuration files

• Sconstruct
• Sconscipt
• opendbc/dbc/Sconscipt
• opendbc/can/Sconscipt
• site_scons/site_tools/cython.py

Optimal Order of Commands

graph TB;
    classDef bottleneck stroke:#f00
    A[g++ -o common.os<br>.3 s<br>];
    B[g++ -o dbc.os<br>1.0 s<br><br><br><br><br><br><br><br>];
    C[g++ -o parser.os<br>.6 s<br><br><br><br>];
    D[g++ -o packer.os<br>.5 s<br><br><br>];
    E[g++ -o libdbc.so - .1 s];
    F[cythonize packer_pyx.pyx<br>.5 s<br><br><br>];
    G[g++ -o packer_pyx.o<br>.7 s<br><br><br><br><br>];
    H[g++ -o packer_pyx.so - .1 s];
    I[cythonize parser_pyx.pyx<br>.6 s<br><br><br><br>]:::bottleneck;
    J[g++ -o parser_pyx.o<br>1.1 s<br><br><br><br><br><br><br><br><br>]:::bottleneck;
    K[g++ -o parser_pyx.so - .1 s]:::bottleneck;
    L[python3 generator.py];
    Scons[Scons overhead<br>.9 s<br><br><br><br><br><br><br>]:::bottleneck;
    A-->E;
    B-->E;
    B-->H;
    B-->K;
    C-->E;
    D-->E;
    F-->G;
    G-->H;
    I-->J;
    J-->K;
    Scons-->A;
    Scons-->B;
    Scons-->C;
    Scons-->D;
    Scons-->F;
    Scons-->I;
    Scons-->L;
    Start-->Scons;

Loading

Commands resulting from scons

1. g++ -o opendbc/can/common.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/common.cc
2. g++ -o opendbc/can/dbc.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/dbc.cc
3. g++ -o opendbc/can/parser.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/parser.cc
4. g++ -o opendbc/can/packer.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/packer.cc
5. cythonize opendbc/can/packer_pyx.pyx
6. cythonize opendbc/can/parser_pyx.pyx
7. python3 opendbc/dbc/generator/generator.py
8. g++ -o opendbc/can/packer_pyx.o -c -std=c++1z -g -fPIC -O0 -Wunused -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -Wno-#warnings -Wno-shadow -Wno-deprecated-declarations -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 -I.venv/lib/python3.12/site-packages/numpy/_core/include opendbc/can/packer_pyx.cpp
9. g++ -o opendbc/can/parser_pyx.o -c -std=c++1z -g -fPIC -O0 -Wunused -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -Wno-#warnings -Wno-shadow -Wno-deprecated-declarations -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 -I.venv/lib/python3.12/site-packages/numpy/_core/include opendbc/can/parser_pyx.cpp
10. g++ -o opendbc/can/libdbc.so -shared opendbc/can/dbc.os opendbc/can/parser.os opendbc/can/packer.os opendbc/can/common.os -Lopendbc/can -L/opt/homebrew/lib
11. g++ -o opendbc/can/packer_pyx.so -pthread -shared -Wl,-rpath=/root/opendbc/opendbc/can opendbc/can/packer_pyx.o -Lopendbc/can -L/opt/homebrew/lib -Lopendbc/can -ldbc
12. g++ -o opendbc/can/parser_pyx.so -pthread -shared -Wl,-rpath=/root/opendbc/opendbc/can opendbc/can/parser_pyx.o -Lopendbc/can -L/opt/homebrew/lib -Lopendbc/can -ldbc -lre2

Why I believe the command order is sub-optimal

• scons -j16 takes 3.25s to run
• the following node script (which hard-codes the run order) takes 2.4s to run

const util = require('util');
const exec = util.promisify(require('child_process').exec);

chains = [
  [
    [
      `g++ -o opendbc/can/common.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/common.cc`,
      `g++ -o opendbc/can/dbc.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/dbc.cc`,
      `g++ -o opendbc/can/parser.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/parser.cc`,
      `g++ -o opendbc/can/packer.os -c -std=c++1z -DDBC_FILE_PATH='"/root/opendbc/opendbc/dbc"' -g -fPIC -O0 -Wunused -Werror -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -fPIC -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 opendbc/can/packer.cc`,
    ],
    [
      `g++ -o opendbc/can/libdbc.so -shared opendbc/can/dbc.os opendbc/can/parser.os opendbc/can/packer.os opendbc/can/common.os -Lopendbc/can -L/opt/homebrew/lib`,
    ],
  ],
  [
    [`cythonize opendbc/can/packer_pyx.pyx`],
    [`g++ -o opendbc/can/packer_pyx.o -c -std=c++1z -g -fPIC -O0 -Wunused -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -Wno-#warnings -Wno-shadow -Wno-deprecated-declarations -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 -I.venv/lib/python3.12/site-packages/numpy/_core/include opendbc/can/packer_pyx.cpp`],
    [`g++ -o opendbc/can/packer_pyx.so -pthread -shared -Wl,-rpath=/root/opendbc/opendbc/can opendbc/can/packer_pyx.o -Lopendbc/can -L/opt/homebrew/lib -Lopendbc/can -ldbc`], // race condition: this must be run after "g++ -o opendbc/can/dbc.os" completes
  ],
  [
    [`cythonize opendbc/can/parser_pyx.pyx`],
    [`g++ -o opendbc/can/parser_pyx.o -c -std=c++1z -g -fPIC -O0 -Wunused -Wshadow -Wno-vla-cxx-extension -Wno-unknown-warning-option -Wno-#warnings -Wno-shadow -Wno-deprecated-declarations -I. -I/usr/lib/include -I/opt/homebrew/include -I/usr/include/python3.12 -I.venv/lib/python3.12/site-packages/numpy/_core/include opendbc/can/parser_pyx.cpp`],
    [`g++ -o opendbc/can/parser_pyx.so -pthread -shared -Wl,-rpath=/root/opendbc/opendbc/can opendbc/can/parser_pyx.o -Lopendbc/can -L/opt/homebrew/lib -Lopendbc/can -ldbc -lre2`], // race condition: this must be run after "g++ -o opendbc/can/dbc.os" completes
  ],
  [
    [`python3 opendbc/dbc/generator/generator.py`],
  ],
]

const run_series = async(chain) => {
  for(cmds of chain) {
    await Promise.all(cmds.map(cmd => exec(cmd)))
  }
}

for(const chain of chains) {
  run_series(chain)
}

[bdbaddog]

Have you tried using scons --tree=all to see all the dependencies which SCons is aware of?
What's the command line you're using to run SCons which results in the build log you've shared above?
How many cores does your machine have?

[MikeBusuttil]

Have you tried using scons --tree=all to see all the dependencies which SCons is aware of?

ya, I get a tree with 2090 lines (generated files) but no indication of the 12 commands that generated those files

What's the command line you're using to run SCons which results in the build log you've shared above?

scons -j$(nproc)

How many cores does your machine have?

16 cores

Thanks for responding so fast @bdbaddog 🚀!!

[MikeBusuttil]

After further investigation I now believe that scons actually does run the commands in the optimal order. I now believe the time difference is because of scons overhead. The scons: Reading SConscript files ... step appears to take ~1s to run which fully accounts for the difference.

[mwichmann]

--debug=time should give you some information on this, if you weren't already doing that.

Yes, building the dependency tree on each run is not a cost-free exercise. There are some things you can do to shortcut some of the steps if the timing ends up being a problem. If it's for human consumption, <1s doesn't seem too onerous. (There's a wiki page with some thoughts, https://github.com/scons/scons/wiki/GoFastButton. Sadly, github doesn't allow search engines to index project wikis...)

[MikeBusuttil]

--debug=time should give you some information on this, if you weren't already doing that.

I wasn't @mwichmann , thanks for that!! It gives a clearer picture of where the bottlenecks might be. The initial scons overhead appears to be around 0.75s

And with some print statements and time.process_time in the SConstruct file I found that this Environment call takes the bulk of that time:

env = Environment(
  ENV=os.environ,
  CC='gcc',
  CXX='g++',
  CCFLAGS=[
    "-g",
    "-fPIC",
    "-O0",
    "-Wunused",
    "-Werror",
    "-Wshadow",
    "-Wno-vla-cxx-extension",
    "-Wno-unknown-warning-option",  # for compatibility across compiler versions
  ],
  LIBPATH=[
    "#opendbc/can/",
    "/opt/homebrew/lib",
  ],
  CFLAGS="-std=gnu11",
  CXXFLAGS=["-std=c++1z"],
  CPPPATH=[
    '#',
    '/usr/lib/include',
    '/opt/homebrew/include',
    '/usr/include/python3.12'
  ],
  CYTHONCFILESUFFIX=".cpp",
  tools=["default", "cython"]
)

However, what is bizarre to me is that if I put

import time
start_time = time.process_time()

at the top of SConstruct and

print(time.process_time() - start_time)

at the bottom, the total time is only 0.0660552

some stuff happening asynchronously perhaps??

This begs the questions:

• how can I get a more reliable measure of how much time each line in SConstruct takes?
• is there any way to speed up that Environment(...) call?

[MikeBusuttil]

Thanks @bdbaddog for the speed-up tip. HUGE gains (>700ms!):

[bdbaddog]

Each line in SConstruct doesn't add much to the build, but it does set up the graph which tells SCons what to do, it's the doing which takes the time.
So bottom line no great correlation from lines in SConstruct to run time, unless it's doing something complicated in the SConstruct.

[bdbaddog]

@MikeBusuttil try adding the following to your SConstruct (at the top)
DefaultEnvironment(tools=[])
Then also reduce the list of tools in your Environment() initialization to only those you use, so I'd guess
tools=['gcc','g++','gnulink','gas','cython']
(assuming you're using the gnu toolchain for compiling)
Limiting to only initializing the tools you need can yield a minor speed up on non-windows, and sometimes significant speedup on windows.

[bdbaddog]

That's not what I recommended.
Set
DefaultEnvironment(tools=[])
And CHANGE your existing Environment() as above with the very specific list.
If you are linking anything, you'll need gnulink right?

[MikeBusuttil]

WOAH that totally worked!!! Thanks @bdbaddog 🔥 I'm gonna add you as a co-author to that commit lol

[MikeBusuttil]

teamwork 💪

However that broke the mac builds:

g++ -o opendbc/can/packer_pyx.so -bundle -undefined dynamic_lookup -Wl,-rpath=/Users/runner/work/opendbc/opendbc/opendbc/can opendbc/can/packer_pyx.o -Lopendbc/can -L/opt/homebrew/lib -Lopendbc/can -ldbc
ld: unknown options: -rpath=/Users/runner/work/opendbc/opendbc/opendbc/can 
clang: error: linker command failed with exit code 1 (use -v to see invocation)
scons: *** [opendbc/can/packer_pyx.so] Error 1

I'm gonna shell in and try to debug

[bdbaddog]

for mac you probably need ['gcc','g++','applelink'] Take a look at SCons/Tools/__init__.py at the bottom is the per platform choices for default.
If it needs to build on windows, you'd need another section for that.

[MikeBusuttil]

that worked! 😄 I'm SUPER grateful @bdbaddog - thanks so much brother 💪

[mwichmann]

Yes, if you're going to be linking, you normally need a linker tool initialized.

People are more commonly focused on rebuild time (and in the pathological case: how long does it take to rebuild if there's nothing at all to rebuild), so your interest is a little different. For rebuild time, things like eliminating rescanning for dependencies (by caching implicit deps) and avoiding computing hashes (using a different decider) can help. And a little more esoterically, you can use interactive mode - just for grins you could try that. Run scons --interactive, then issue the clean command, then the build command. Since this is the same scons instance, not a fresh one between calls, some of the startup cost may be saved.

I've temporarily reopened this topic since comments are still happening, will close when it settles back down.

[mwichmann]

guess it settled down