Slow loading of libCore.so on OSX El Capitan

Hi,
I just upgraded my macbook to El Capitan, recompiled everything, and since then ROOT and all executables I built linking the ROOT libraries take a long time to run. After some debugging I discovered that the linker spends 30s on loading libCore.so
I built a small executable to test this problem, I’m attaching the code and the output I get.
I’m running El Capitan OSX 10.11.6 on a Early 2011 MacBook Pro, ROOT v6-04-08, Apple LLVM version 7.0.2 (clang-700.1.81).

The output I get when enabling DYLD debug variables

export DYLD_PRINT_LIBRARIES=1 export DYLD_PRINT_APIS=1 export DYLD_PRINT_STATISTICS=1
is in log.txt. Basically after the call

dlsym(0xfffffffffffffffe, usedToIdentifyRootClingByDlSym)

it’s stuck for 30s before proceeding to the various dladdr calls.
The linker statistics show that all of the 30s are spent loading libCore.so

total time: 30.1 seconds (100.0%) total images loaded: 200 (175 from dyld shared cache) total segments mapped: 72, into 8930 pages with 358 pages pre-fetched total images loading time: 13.39 milliseconds (0.0%) total dtrace DOF registration time: 0.09 milliseconds (0.0%) total rebase fixups: 108,113 total rebase fixups time: 1.67 milliseconds (0.0%) total binding fixups: 49,294 total binding fixups time: 4.77 milliseconds (0.0%) total weak binding fixups time: 3.48 milliseconds (0.0%) total bindings lazily fixed up: 0 of 0 total initializer time: 30.0 seconds (99.9%) libSystem.B.dylib : 5.73 milliseconds (0.0%) libc++.1.dylib : 0.02 milliseconds (0.0%) CoreFoundation : 0.49 milliseconds (0.0%) CFNetwork : 0.02 milliseconds (0.0%) vImage : 0.00 milliseconds (0.0%) Kerberos : 0.31 milliseconds (0.0%) libGLImage.dylib : 0.08 milliseconds (0.0%) libFosl_dynamic.dylib : 0.01 milliseconds (0.0%) libCore.so : 30.0 seconds (99.8%) libMathCore.so : 0.81 milliseconds (0.0%) libMatrix.so : 0.51 milliseconds (0.0%) libHist.so : 0.94 milliseconds (0.0%) libThread.so : 0.33 milliseconds (0.0%) libRIO.so : 0.40 milliseconds (0.0%) libGraf.so : 0.40 milliseconds (0.0%) libGpad.so : 0.29 milliseconds (0.0%) libGui.so : 0.99 milliseconds (0.0%) libcrypto.1.0.0.dylib : 0.03 milliseconds (0.0%) libNet.so : 0.38 milliseconds (0.0%) libGraf3d.so : 0.34 milliseconds (0.0%) libTree.so : 0.48 milliseconds (0.0%) libRint.so : 0.20 milliseconds (0.0%) libPostscript.so : 0.24 milliseconds (0.0%) libPhysics.so : 0.21 milliseconds (0.0%) libTreePlayer.so : 0.45 milliseconds (0.0%) libMLP.so : 0.19 milliseconds (0.0%) libMinuit.so : 0.20 milliseconds (0.0%) libXMLIO.so : 0.21 milliseconds (0.0%) libTMVA.so : 0.82 milliseconds (0.0%) test_ROOT : 0.01 milliseconds (0.0%)

I’m really puzzled and I would be very grateful if someone will help me fix this issue. Otherwise I’ll revert back to Yosemite from a recent backup…
log.txt (67.7 KB)
test.zip (4.99 KB)

Hi,

we do quite many things during the time accounted to the load of libCore, e.g. reading rootmaps, initialising the typesystem, reading part of the pch.
I do not see this behaviour. Can you check if root 6.08 features the same runtime performance?

Cheers,
Danilo

Hi,

Right - but this is the dynamic loader, so that’s really only about symbols.

We have been trying to hide the clang + llvm symbols as much as possible; I cannot remember whether that’s the case for v6.04, though. So indeed, as Danilo suggested, it would be great to know if an install of v6.08 shows the same behavior.

I still have to address the symbol visibility warnings we now get in 6.08 and the master. That should help - if I actually manage to hide these symbols…

Cheers, Axel.

[quote=“dpiparo”]Hi,

we do quite many things during the time accounted to the load of libCore, e.g. reading rootmaps, initialising the typesystem, reading part of the pch.
I do not see this behaviour. Can you check if root 6.08 features the same runtime performance?

Cheers,
Danilo[/quote]

Hi Danilo,
it’s the first thing I tried after posting on the forum. Unfortunately it still takes 30s to load libCore even with version 6.08/00.

total initializer time: 30.1 seconds (99.9%) libSystem.B.dylib : 13.15 milliseconds (0.0%) libc++.1.dylib : 0.02 milliseconds (0.0%) CoreFoundation : 0.56 milliseconds (0.0%) CFNetwork : 0.01 milliseconds (0.0%) vImage : 0.01 milliseconds (0.0%) Kerberos : 0.34 milliseconds (0.0%) libGLImage.dylib : 0.15 milliseconds (0.0%) libFosl_dynamic.dylib : 0.02 milliseconds (0.0%) libCore.so : 30.0 seconds (99.5%) libMathCore.so : 6.77 milliseconds (0.0%) libMatrix.so : 5.29 milliseconds (0.0%) libHist.so : 8.76 milliseconds (0.0%) libThread.so : 1.16 milliseconds (0.0%) libRIO.so : 4.96 milliseconds (0.0%) libGraf.so : 5.14 milliseconds (0.0%) libGpad.so : 3.57 milliseconds (0.0%) libGui.so : 9.00 milliseconds (0.0%) libcrypto.1.0.0.dylib : 0.79 milliseconds (0.0%) libNet.so : 4.24 milliseconds (0.0%) libGraf3d.so : 5.16 milliseconds (0.0%) libTree.so : 6.15 milliseconds (0.0%) libRint.so : 1.21 milliseconds (0.0%) libPostscript.so : 2.72 milliseconds (0.0%) libPhysics.so : 2.34 milliseconds (0.0%) libTreePlayer.so : 5.47 milliseconds (0.0%) libMLP.so : 1.27 milliseconds (0.0%) libMinuit.so : 1.89 milliseconds (0.0%) libXMLIO.so : 2.00 milliseconds (0.0%) libTMVA.so : 14.39 milliseconds (0.0%) test_ROOT : 0.01 milliseconds (0.0%) total symbol trie searches: 5832 total symbol table binary searches: 0 total images defining weak symbols: 26 total images using weak symbols: 75
I’m starting to think it has to be related in some misconfiguration by my side, since before the upgrade it was quite fast. On top of that 30 seconds is quite a suspicious amount of time. Also updating XCode and disabling crsutils didn’t help. This is so far beyond my expertise I don’t even know where to look.

If it helps narrowing down the problem, I see the same anomalous loading time for libXrdUtils.2.dylib testing a more complex program

Hi,

I just realized: this is likely caused by static initialization.

Which in turn might be the interpreter initialization and that might be triggering file lookups.

Something else we saw in the past was broken resolvers (DNS) that caused enormous delays. We need to resolve the hostname to initialize the TUUID / TProcessID.

A profile on a debug build would help.

Cheers, Axel.

I just thought it might be useful to know, it was the DNS fault. My home router arbitrarily appends a strange domain name to all devices connected to it. With wireshark I was able to see that during the loading of libCore a auto-dns probe with the wrong hostname (due to the wrong domain) would result in a 30s timeout before the library was loaded.
Resetting the domains fixed this, but it’s a precaution I have to take every single time I connect to my home network.

Cheers,
Valerio

2 Likes
2 Likes

Should be fixed in the master. Could someone confirm?