Spawning lots of short lived threads when initialising `MSACCrashes` instance

Question

Spawning lots of short lived threads when initialising `MSACCrashes` instance

Closed this issue 6 months ago · 16 comments

Description

When MSACCrashes instance is created, ms_crashes_log_buffer_size buffer files are created in - [MSACCrashes setupLogBuffer] via dispatch_group_async and + [MSACUtility createFileAtPathComponent:withData:atomically:forceOverwrite:]. The issue is that MSACUtility synchronises its file creation and so it leads to spawning (of in the worst case scenario ms_crashes_log_buffer_size) short lived threads.

Provided the nature of the SDK, the mentioned instance is created during the process bootstrapping, and creation of these threads puts an extra pressure on the runtime which may lead to crashes.

Repro Steps

Please list the steps used to reproduce your issue.

Create any iOS project and add the AppCenter SDK (for instance using Swift Package Manager)
Initiate creation of the service for crashes using the following line:

AppCenterCrashes.AppCenter.start(withAppSecret: "12345", services: [Crashes.self])

Make breakpoint on a statement right before that and observe a number of threads

or alternatively create a breakpoint for start_wqthread as below and observe the burst of thread creations:

Notice: If there is no mentioned initialisation, the situation is different:

Details

Which SDK version are you using?
All available versions
Which OS version did you experience the issue on?
All iOS (and apparently macOS versions)
Which Xcode version did you build the app with?
Xcode 14.2
Which Cocoapods version are you using (run pod --version)?
n/a
What device version did you see this error on? Were you using an emulator or a physical device?
All supported models
What language are you using?
- Objective C
- Swift
What third party libraries are you using?
none
Please enable verbose logging for your app using MSAppCenter.setLogLevel(.verbose) before your call to MSAppCenter.start(...) for Swift, or [MSAppCenter setLogLevel:MSLogLevelVerbose] before [MSAppCenter start: ...] for Objective C and include the logs here:

2023-08-29 21:47:48.300519+0200 TestAppCenter[86745:24896836] [AppCenter] VERBOSE: -[MSACDelegateForwarder addTraceBlock:]_block_invoke_2/88 Start buffering traces.
2023-08-29 21:47:48.300575+0200 TestAppCenter[86745:24896836] [AppCenter] DEBUG: -[MSACDelegateForwarder setEnabledFromPlistForKey:]_block_invoke/278 Delegate forwarder for info.plist key 'AppCenterAppDelegateForwarderEnabled' enabled. It may use swizzling.
2023-08-29 21:47:48.300619+0200 TestAppCenter[86745:24896836] [AppCenter] VERBOSE: +[MSACDelegateForwarder flushTraceBuffer]/106 Stop buffering traces, flushed.
2023-08-29 21:47:48.301330+0200 TestAppCenter[86745:24896836] [AppCenter] DEBUG: -[MSACSessionContext init]/42 1 session(s) in the history.
2023-08-29 21:47:48.302546+0200 TestAppCenter[86745:24896836] [AppCenter] VERBOSE: -[MSACSessionContext setSessionId:]/66 Stored new session with id:(null) and timestamp: 2023-08-29 19:47:48 +0000.
2023-08-29 21:47:48.302631+0200 TestAppCenter[86745:24896836] [AppCenter] DEBUG: -[MSACUserIdContext init]/54 1 userId(s) in the history.
2023-08-29 21:47:48.311865+0200 TestAppCenter[86745:24896836] [AppCenter] INFO: -[MSACHttpClient networkStateChanged:]/202 Internet connection is up.
2023-08-29 21:47:48.312257+0200 TestAppCenter[86745:24896836] [AppCenter] INFO: -[MSACHttpClient networkStateChanged:]/202 Internet connection is up.
2023-08-29 21:47:48.312308+0200 TestAppCenter[86745:24896836] [AppCenter] INFO: -[MSACHttpClient networkStateChanged:]/202 Internet connection is up.
2023-08-29 21:47:48.312365+0200 TestAppCenter[86745:24896836] [AppCenter] DEBUG: -[MSACDBStorage initWithSchema:version:filename:]_block_invoke/38 SQLite global configuration successfully updated.
2023-08-29 21:47:48.322786+0200 TestAppCenter[86745:24896842] [AppCenter] INFO: -[MSACAppCenter configureWithAppSecret:transmissionTargetToken:fromApplication:]/354 App Center SDK configured successfully.
2023-08-29 21:47:48.322893+0200 TestAppCenter[86745:24896842] [AppCenter] VERBOSE: -[MSACAppCenter startServices:withAppSecret:transmissionTargetToken:fromApplication:]/380 Start services MSACCrashes from an application
2023-08-29 21:47:48.325746+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] DEBUG: -[MSACCrashes configureCrashReporterWithUncaughtExceptionHandlerEnabled:]/709 EnableUncaughtExceptionHandler is set to YES
2023-08-29 21:47:48.325853+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] VERBOSE: -[MSACCrashes configureCrashReporterWithUncaughtExceptionHandlerEnabled:]/719 Enabled Mach exception handler.
2023-08-29 21:47:48.333153+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] WARNING: -[MSACCrashes configureCrashReporterWithUncaughtExceptionHandlerEnabled:]/734 Detecting crashes is NOT enabled due to running the app with a debugger attached.
2023-08-29 21:47:48.335023+0200 TestAppCenter[86745:24896852] [Client] Updating selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.343461+0200 TestAppCenter[86745:24896591] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.343839+0200 TestAppCenter[86745:24896591] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.343921+0200 TestAppCenter[86745:24896852] [Client] Updating selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.344502+0200 TestAppCenter[86745:24896591] [Client] Synchronous remote object proxy returned error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.344532+0200 TestAppCenter[86745:24896852] [Client] Updating selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.349994+0200 TestAppCenter[86745:24896852] [Client] Updating selectors failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.350068+0200 TestAppCenter[86745:24896852] [Client] Updating selectors after delegate addition failed with: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process." UserInfo={NSDebugDescription=The connection to service named com.apple.commcenter.coretelephony.xpc was invalidated: failed at lookup with error 3 - No such process.}
2023-08-29 21:47:48.351163+0200 TestAppCenter[86745:24896852] [AppCenter] VERBOSE: -[MSACSessionContext clearSessionHistoryAndKeepCurrentSession:]/88 Cleared old sessions.
2023-08-29 21:47:48.351484+0200 TestAppCenter[86745:24896852] [AppCenter] VERBOSE: -[MSACUserIdContext clearUserIdHistory]/125 Cleared old userIds while keeping current userId.
2023-08-29 21:47:48.351590+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] INFO: -[MSACCrashes applyEnabledState:]/454 Crashes service has been enabled but the service cannot detect crashes due to running the application with a debugger attached.
2023-08-29 21:47:48.357895+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] VERBOSE: -[MSACCrashes startWithChannelGroup:appSecret:transmissionTargetToken:fromApplication:]/501 Started crash service.
2023-08-29 21:47:48.358104+0200 TestAppCenter[86745:24896852] [AppCenterCrashes] VERBOSE: -[MSACCrashes channel:didPrepareLog:internalId:flags:]/584 Storing a log to Crashes Buffer: (sid: (null), type: startService)

Answer 1 · 2023-09-01T14:42:10.000Z

@vmagaziy,

Thanks for sharing this report. It does seem a bit odd, and we'll look into it. We'll get back to you with an update soon.

Answer 2 · 2023-09-01T17:07:56.000Z

@DmitriyKirakosyan, the easiest way to see that is to introduce an artificial delay in + [MSACUtility createFileAtPathComponent:withData:atomically:forceOverwrite:], so all 60 (ms_crashes_log_buffer_size) threads could be seen altogether:

Answer 3 · 2023-09-18T19:17:24.000Z

@vmagaziy, thank you for your patience.

I've investigated this issue. These threads are used for setting up the log buffer, which ensures that no analytics data is lost if the app crashes. This functionality was introduced in this GitHub pull request. Initially, the buffer size was set to 20, but it was later increased to 60.

When the AppCenter SDK starts, it initializes the buffer and attempts to create an empty file for each buffer item. These threads are responsible for creating the file if it doesn't already exist. Therefore, during the first app launch, they would create 60 files, but subsequent launches would not create additional files, so the threads won't have much impact.

Although there are many threads dispatched when AppCenter starts, they are generally lightweight, except during the first launch, and shouldn't significantly affect your app's performance. Have you noticed any performance issues in your app related to this SDK's behavior?

If we do want to eliminate these threads, one potential solution would be to check if the file exists first before opening a thread.

Answer 4 · 2023-09-20T07:05:22.000Z

Yes, the increase to 60 was done back in 2019 and it hasn't affected us for all this time. However, since we started using async/await in our project for setting up various services at the launch time to boost the app readiness, this started contributing to the number of threads, and despite the fact Task does not lead to the burst of threads in contrast to GCD queue (despite the claims it should not), in combination it leads to the before mentioned crashes.

We introduced a workaround by starting (and further accessing) App Center crashes on a serial bg queue with a lower priority, but it does not fix the issue in general, just mitigates the issue.

I opened a PR which allows to reduce a number of threads for setting up the log buffer #2507, it allows to set the limitation and use operation queue API in tests to make sure the buffer is set up. Can you please have a look, the limitation to 5 concurrent operation is just a rough guess, it may be increased to 10 or 20.

Answer 5 · 2023-09-20T09:24:43.000Z

I might have the same issue with a macOS app. The app crashes during setup (AppCenter.start) while setting up the buffer.

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
MSACCrashesBufferedLog::MSACCrashesBufferedLog(NSString*, NSData*) (MSACCrashesBufferedLog.hpp:31)
-[MSACCrashes setupLogBuffer]

Im my case, it already crashes with the first thread that calls: MSACUtility(File) createFileAtPathComponent:withData:atomically:forceOverwrite: instead of 60.

The interesting thing is, that I can not reproduce this issue at all, but it's 100% reproducible on a customers Macbook (macOS 11.6).

Answer 6 · 2023-09-20T09:29:51.000Z

macOS should not have such limitation for a number of simultaneous threads, so this is highly unlikely that the mentioned crash happens because of exhausting of resources (runtime pressure). On iOS we observe crashes at random places, while we see lots of threads being spawned.

Answer 7 · 2023-09-25T08:25:03.000Z

Seeing it in our macOS app too. Indeed, macOS 11 seems to suffer for some reason. Not seen on other OSes.

Answer 8 · 2023-10-09T14:41:44.000Z

@lrrrs @drewmccormack I think the crashes you are seeing have a different cause. According to the Xcode 15 Release Notes, "Linking > Known Issues":

Binaries using symbols with a weak definition crash at runtime on iOS 14/macOS 12 or older. This impacts primarily C++ projects due to their extensive use of weak symbols. (114813650) (FB13097713)
Workaround: Bump the minimum deployment target to iOS 15, macOS 12, watchOS 8 or tvOS 15, or add -Wl,-ld_classic to the OTHER_LDFLAGS build setting.

And in fact, the crashing line for me is msACCrashesLogBuffer[i] = MSACCrashesBufferedLog(path, nil);, which calls an (overloaded) constructor of the MSACCrashesBufferedLog C++ class. My suspicion is that this causing the weak definition crash mentioned above.

I am in the process of building my app with the Xcode 15.1 beta which is claimed to contain a fix for this issue.

/cc @vmagaziy

Answer 9 · 2023-10-09T14:42:33.000Z

@vmagaziy please see the reply I just posted; maybe this is the actual reason for the crash you are seeing as well.

Answer 10 · 2023-10-09T14:45:30.000Z

@MrMage This is not the case in our scenario moreover we've seen these crashes with apps built using Xcode 14

Answer 11 · 2023-10-10T11:50:06.000Z

@lrrrs FYI, the crash really is fixed when linking using Xcode 15.1 beta. @drewmccormack, this might also apply to the crash you are seeing.

Answer 12 · 2023-10-17T09:28:53.000Z

@DmitriyKirakosyan -- when is it supposed to be released if it's closed? 5.0.4 release does not include these changes for some reason.

Answer 13 · 2023-10-18T14:51:31.000Z

Hi @vmagaziy, we are going to release these changes along with our planned next release.

Answer 14 · 2023-10-18T15:06:40.000Z

Thanks, @MikhailSuendukov -- sorry for bothering as I thought it would be done in 5.0.4. Any expectations re: 5.0.5?

Answer 15 · 2023-10-18T15:16:58.000Z

@vmagaziy Next release is planned at the end of this quarter.

Answer 16 · 2024-05-15T14:53:45.000Z

Version 5.0.5, which includes the fix, has been released.