I had a bizarre slow loading problem with a Mac app. Before reaching main, while loading the libraries, the process stalls for about 20 seconds. By adding DYLD_PRINT_STATISTICS=1 to the environment variables, I can get the dynamic linker to print statistics about loading, which reveals this ridiculous delay in initializing libSystem.B.dylib:
Total pre-main time: 22.6 seconds (100.0%)
dylib loading time: 167.96 milliseconds (0.7%)
rebase/binding time: 15.58 milliseconds (0.0%)
ObjC setup time: 15.36 milliseconds (0.0%)
initializer time: 22.4 seconds (99.1%)
slowest intializers :
libSystem.B.dylib : 22.4 seconds (98.9%)
Stopping the process during that time (which is easy, you have a 20 second window to do it) reveals this backtrace that looks like an initializer is waiting for some response from an XPC service:
|
Binary |
Function |
| 0 |
libsystem_kernel.dylib |
mach_msg_trap |
| 1 |
libsystem_kernel.dylib |
mach_msg |
| 2 |
libxpc.dylib |
xpc_pipe_routine |
| 3 |
libsystem_secinit.dylib |
_libsecinit_send_request |
| 4 |
libsystem_secinit.dylib |
_libsecinit_setup_secinitd_client |
| 5 |
libsystem_secinit.dylib |
_libsecinit_initialize_once |
| 6 |
libdispatch.dylib |
_dispatch_client_callout |
| 7 |
libdispatch.dylib |
dispatch_once_f |
| 8 |
libSystem.B.dylib |
libSystem_initializer |
| 9 |
dyld |
ImageLoaderMachO::doModInitFunctions |
| 10 |
dyld |
ImageLoaderMachO::doInitialization |
| 11 |
dyld |
ImageLoader::recursiveInitialization |
| 12 |
dyld |
ImageLoader::recursiveInitialization |
| 13 |
dyld |
ImageLoader::processInitializers |
| 14 |
dyld |
ImageLoader::runInitializers |
| 15 |
dyld |
dyld::initializeMainExecutable |
| 16 |
dyld |
dyld::_main |
| 17 |
dyld |
dyldbootstrap::start |
| 18 |
dyld |
_dyld_start |
Inspecting the stack trace, it appears libsystem_secinit is responsible for the XPC request.
Meanwhile, looking at the console, I see about a thousand of identical messages like this one every time I launch the app:
secinitd: MacOS error: -67050
Obviously the secinitd deamon is doing a job on behalf of the libsystem_secinit library and something fails… a thousand times!
So far so good, but what does this error mean? A quick search for error -67050 says errSecCSReqFailed, or “The code failed to satisfy one of the code requirements.”
Even though it doesn’t really say “code signing” anywhere, this message is reminiscent of code signing issues since it talks about “code requirements”. This feeling is somewhat amplified by the name “secinit” that looks like a shorthand for “security” and “initialization”.
The app’s code is signed by Xcode at build time, so it should be fine. But opening it with RB App Checker Lite reveals a peculiarity: “The application was signed by an unidentified entity (this is unusual).” What does that mean? Does it have something to do with the current issue?
Meanwhile, I tested the app on other computers. It ran fine everywhere with no delay at startup. Even on my development machine, if I ran the app in another user account everything was fine. It definitely had something to do with my user account.
Not really knowing where to start looking, I changed the bundle ID of the app. Oh, now it launches instantly! Going back to the old bundle ID, the 20-second loading problem comes back. So it is somehow linked to the bundle ID.
Now I know I need to look for something that has the bundle ID in my user account. My first stop is the “~/Library/Containers” folder. Every sandboxed app automatically get a container where it can put its files and settings, and the container’s name is the app’s bundle ID. I move the app’s container folder away and relaunch, and… oh, it’s fast again!
That container definitely has something to do with the problem. So I restore the old container and look for something suspicious inside. There’s not much in there beside mostly empty folders and symlinks. But there’s a Container.plist file at the root of the container that looks interesting.
Inside Container.plist, there’s a Version number and there’s an Identity array. That Identity array has 7313 data items in it. Each item is different, but they all look somewhat like this:
<fade0c00 00000048 00000001 00000007 00000008 00000014
8254e67a 5efbb500 2eef7741 b8bc6054 18cc5224 00000008
00000014 d025ece1 ac627aae 27d047b0 deaa1450 6563b718>
I don’t know exactly what they are, but looking at containers for other apps I can see one, two, or three identities at most. Never something in the thousands. That’s suspicious.
I delete the Identity array and run the app again. And it loads fast. And a new identity also appears in Container.plist without me doing anything beside launching the app. Running the app a second time does not make a new identity appear. But then I tried build and run from Xcode: a new identity would appear. If every time I build and run a new identity appears, that’d explain the huge number.
Here’s my guess at what’s happening. The identity corresponds to whoever signed the app, something linked to the signing certificate. Upon launching the app, the sandbox adds that identity to Container.plist (unless the identity is already there) to keep track of who ran with this container. Now, remember RB App Checker Lite seeing the app as signed by an “unidentified entity”? Perhaps this translates somehow as a new identity every time the app is built.
Once the array is bloated with too many identities, the secinitd daemon becomes very slow at whatever it is doing. By the repeated errors to “errSecCSReqFailed” on the console, I’d adventure a guess at saying it reverifies the app signature for each and every identity found in Container.plist. It’d make sense that recomputing the checksum 7313 times would take more than 20 seconds and spill thousands of MacOS error: -67050 to the system console.
Knowing that I can periodically clean the Container.plist, while reassuring, is not very satisfactory. What is causing this signature issue the first place?
After looking at all the build settings for this project, I ended up noticing signing was not enabled for the test bundle target that contains all the unit tests.
I enabled signing for the test bundle. Doing this makes RB App Checker Lite see a proper signing identity for the app. Building and running the app a couple times is no longer adding a new identity every time. So problem solved!
Why would secinitd add a new identity every time the app is built though? Something must change for the identity to change, right? I believe it happens because I have a script bumping the build number every time I build. Disabling this script (keeping the build number the same for every build) stops new identities from appearing. This seems to confirm that identities are dependent on the build number when the signature is from an “unidentified entity”.
Note that having about 7313 identities in Container.plist will slow things down regardless of whether your build number is the same or not, or your signature is form an “unidentified entity” or not. So it’s still important to cleanup Container.plist to get normal loading times again after fixing this signing problem. Here’s the final times:
Total pre-main time: 307.72 milliseconds (100.0%)
dylib loading time: 157.79 milliseconds (51.2%)
rebase/binding time: 2.66 milliseconds (0.8%)
ObjC setup time: 9.39 milliseconds (3.0%)
initializer time: 137.63 milliseconds (44.7%)
slowest intializers :
libSystem.B.dylib : 123.46 milliseconds (40.1%)
307.72 milliseconds is a 7344 % improvement over 22.6 seconds!
(This is on macOS High Sierra. I haven’t tested if Mojave still exhibit this problem.)
