Repository navigation
Unreasonably slow behaviour of CompileMacro #7774
Description
- Checked for duplicates
Describe the bug
I have a PDF class implemented in C++ that I want to use in a python script through ROOT.gSystem.CompileMacro(). It is unreasonably slow to load each time, O(minutes). When running with "kO" option it is better, but still long - too long for normal usage - whereas it should be instantaneous, if I understand correctly. I have tested ROOT 6.22 and with nightlies, and nightlies are even slower.
The time for a first compilation, so how long it's processing the line Info in <TUnixSystem::ACLiC>: creating shared library /afs/cern.ch/user/t/tnanut/public/Stephan/RooThreshold_cpp.so, for running a script and directly the CompileMacro command in ipython:
| Version | py file | ipython |
|---|---|---|
| Nightlies | 3m25s | 1m55s |
| 6.22 | 1m35s | 1m05s |
The run time with "kO" option for the 2nd iteration of running, once binaries are created:
| Version | py file |
|---|---|
| Nightlies | 1m15s |
| 6.22 | 0m30s |
All above times are on same lxplus machine. Between different lxplus machines the timing changes, but at best e.g from 30s down to 20s.
Another test for how much time has elapsed e.g.:
for version in /cvmfs/sft.cern.ch/lcg/views/LCG_99/x86_64-centos7-gcc10-opt/setup.sh /cvmfs/sft-nightlies.cern.ch/lcg/views/dev3/latest/x86_64-centos7-gcc9-opt/setup.sh ; do (
source $version;
echo $version;
root --version -q
/usr/bin/time python3 -c "import ROOT; ROOT.gSystem.CompileMacro('~tnanut/public/Stephan/RooThreshold.cpp', 'fO')" 2>&1 | grep user.*system;
/usr/bin/time python3 -c "import ROOT; ROOT.gSystem.CompileMacro('~tnanut/public/Stephan/RooThreshold.cpp', 'fO')" 2>&1 | grep user.*system;
/usr/bin/time python3 -c "import ROOT; ROOT.gSystem.CompileMacro('~tnanut/public/Stephan/RooThreshold.cpp', 'O')" 2>&1 | grep user.*system)
doneOutput:
/cvmfs/sft.cern.ch/lcg/views/LCG_99/x86_64-centos7-gcc10-opt/setup.sh
ROOT Version: 6.22/06
Built for linuxx8664gcc on Nov 27 2020, 15:14:08
From tags/v6-22-06@v6-22-06
14.56user 22.74system 2:30.29elapsed 24%CPU (0avgtext+0avgdata 869920maxresident)k
14.52user 21.71system 2:08.49elapsed 28%CPU (0avgtext+0avgdata 870036maxresident)k
14.26user 21.65system 1:13.75elapsed 48%CPU (0avgtext+0avgdata 869908maxresident)k
/cvmfs/sft-nightlies.cern.ch/lcg/views/dev3/latest/x86_64-centos7-gcc9-opt/setup.sh
ROOT Version: 6.25/01
Built for linuxx8664gcc on Apr 01 2021, 03:35:00
From heads/master@v6-25-01-520-g875e8fb
14.66user 24.65system 1:47.89elapsed 36%CPU (0avgtext+0avgdata 936048maxresident)k
14.36user 23.63system 1:15.73elapsed 50%CPU (0avgtext+0avgdata 936036maxresident)k
17.88user 26.28system 10:23.67elapsed 7%CPU (0avgtext+0avgdata 936052maxresident)k
Expected behavior
Once binaries are created, there should be an option for an almost instantaneous run on the next iterations.
To Reproduce
All files are in /afs/cern.ch/user/t/tnanut/public/Stephan/ (neither format is allowed to be attached).
python3 /afs/cern.ch/user/t/tnanut/public/Stephan/testRooThreshold.pySetup
- ROOT version: 6.22/06 and latest nightlies version
- Operating system: lxplus
- How you obtained ROOT:
Nightlies:
source /cvmfs/sft.cern.ch/lcg/views/dev3/latest/x86_64-centos7-gcc9-opt/setup.sh
6.22: through LHCb
/cvmfs/lhcbdev.cern.ch/conda/envs/default/2021-02-03_15-01/linux-64/bin/root
Additional context
I'd be also interested if you know an alternative method how to implement the class from the .cpp file into python, that can provide nearly instantaneous loading on reruns.
Activity
pcanal commentedon Apr 5, 2021
The time spent appears (likely) to be in the new symbol/autoloading search (which would be slower than usual in your case 'thanks' to afs).
hageboeck commentedon Apr 6, 2021
We talked about this with Axel. I assigned it to him.
pcanal commentedon Apr 6, 2021
You can work around the problem by pre-loading the library libRooFitCore:
malatara commentedon Apr 6, 2021
Nice, this works!! Thanks!
hageboeck commentedon Apr 7, 2021
And here's what's going on in terms of system calls.
Good root (6.22, cvmfs):
Nightly master:
[dyld] Do iterate subfolders and other non-regular files.
[dyld] Do iterate subfolders and other non-regular files.
[dyld] Do iterate subfolders and other non-regular files.
vgvassilev commentedon May 13, 2021
I tried to produce a flamegraph but lxplus seems hard for me. Can somebody produce a flamegraph?
hageboeck commentedon May 14, 2021
@Axel-Naumann ☝️
vgvassilev commentedon Oct 1, 2021
ping.
Axel-Naumann commentedon Oct 1, 2021
@vgvassilev note that this is realtime not CPU time. Could you fire up your own VM to see whether this was fixed by your #6969 ?
vgvassilev commentedon Oct 1, 2021
@Axel-Naumann, we did experiment with this when developing the PR. So the performance should be better. We have two options here: a) test it on the same setup as the initial bug (eg afs); b) close the issue as resolved.
Axel-Naumann commentedon Oct 1, 2021
OK so I guess we should try to reproduce on AFS then? What does
mean?
vgvassilev commentedon Oct 1, 2021
I tried to reproduce it on lxplus and I cannot run
perfwhich is required to produce a flamegraph.vgvassilev commentedon Oct 1, 2021
ok, some updates on running the command by hand on lxplus:
source /cvmfs/sft.cern.ch/lcg/views/dev3/latest/x86_64-centos7-gcc9-opt/setup.shThis seems to be an improvement to what @hageboeck saw.
Then:
It looks like the version in the master takes around 10s. It is still a lot more than what it used to be but that is the cost of having more accurate low-level linker symbol resolution system. I assume we could bring this probably closer to the initial timing (eg may get factor 2 speedup) but that will likely come at the cost of introducing more complex, hard-to-debug and hard-to-maintain code.
vgvassilev commentedon Oct 1, 2021
Here is what I get for the provided test:
hageboeck commentedon Oct 1, 2021
I guess the first time you load (and run!) that macro, this is the situation:
If I didn't misread the numbers, it's now as fast as 6.22 used to be, about 30s.
I don't see the additional 10 s that @vgvassilev mentioned?
vgvassilev commentedon Oct 3, 2021
@hageboeck, I am happy with what we have now, should we close this issue?
hageboeck commentedon Oct 18, 2021
Hi @vgvassilev @Axel-Naumann,
I overlooked something. It's only loading the macro, not running it actually.
I get:
30s for compiling first time + loading.
10 - 15s for loading the existing
.so, e.g.From a user perspective, that will feel slow. As a user I would expect this to complete in ~ 2s. I know that this is asking a lot, and it's certainly better than the 2 min that @malatara reported initally, but if you see any way to squeeze a bit more out of it, I would recommend that.
I leave it to you three if you are happy to close this issue.
guitargeek commentedon Dec 18, 2023
Since the reporter of the issue was happy with the solution...
...Vassill too...
...there was radio silence after it...
...and after @hageboeck's last measurements the compile+loading time went from 30s to 10s, and the loading time reduced from 10s to 0.5s, I think we can close this issue 🙂