Main thread locks during debugging

One of our apps does most of its work in an NSOperation subclass, and most of the work involves sending hundreds of AppleScripts to InDesign. We only send them on the main thread via:


dispatch_sync(dispatch_get_main_queue(), ^{

[self _runAppleScriptWithDict:infoDict];

});


Since upgrading from an old MacBook Pro running 10.10.x and whatever Xcode it could handle to a fairly new one running 10.13..6 and Xcode 10.1, I've been seeing a lot of problems when debugging, stopping at breakpoints, then either stepping or continuing when the next line involves sending an AppleScript on the main thread. The main thread looks like:


#00x00007fff54fefaee in __psynch_rw_wrlock ()
#10x0000000100e109a9 in _pthread_rwlock_lock_wait ()
#20x0000000100e108f0 in _pthread_rwlock_lock_slow ()
#30x00000001005ff39d in enter_stack_in_backtrace_uniquing_table ()
#40x00000001005fb92e in gcd_queue_item_enqueue_hook ()
#50x0000000100dbe085 in _dispatch_introspection_queue_item_enqueue_hook ()
#60x0000000100da5794 in _dispatch_root_queue_push_override ()
#70x00007fff2f051399 in __NSOQSchedule ()
#80x00007fff2f080190 in __addOperations ()
#90x00007fff2b0212f4 in NSPersistentUIEncodingQueueFinishEnqueued ()
#100x00007fff2af92511 in -[NSPersistentUIManager flushAllChanges] ()
#110x00007fff2ad6446c in __48-[NSPersistentUIFlushScheduler initWithHandler:]_block_invoke_2 ()
#120x0000000100d8ed8f in _dispatch_client_callout ()
#130x0000000100da33d2 in _dispatch_continuation_pop ()
#140x0000000100d9148f in _dispatch_source_invoke ()
#150x0000000100d9b053 in _dispatch_main_queue_callback_4CF ()
#160x00007fff2cfabb39 in __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ ()
#170x00007fff2cf6dcda in __CFRunLoopRun ()
#180x00007fff2cf6d033 in CFRunLoopRunSpecific ()
#190x00007fff2c257d96 in RunCurrentEventLoopInMode ()
#200x00007fff2c257b06 in ReceiveNextEventCommon ()
#210x00007fff2c257884 in _BlockUntilNextEventMatchingListInModeWithFilter ()
#220x00007fff2a507a73 in _DPSNextEvent ()
#230x00007fff2ac9de34 in -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] ()
#240x00007fff2a4fc885 in -[NSApplication run] ()
#250x00007fff2a4cba72 in NSApplicationMain ()
#260x00000001000018c2 in main at /Users/rr219379/gitdepot/MMAutomation/main.m:13
#270x00007fff54e9f015 in start ()


And the top of our worker thread looks like:


#00x00007fff54ff015a in __ulock_wait ()
#10x0000000100d9fe92 in _dispatch_ulock_wait ()
#20x0000000100d9ff83 in _dispatch_thread_event_wait_slow ()
#30x0000000100da7604 in _dispatch_sync_wait ()
#40x000000010097b954 in -[AppleScriptHelper runAppleScript:withSubstitutionValues:] at /Users/rr219379/gitdepot/RRDFramework/AppleScriptHelper.m:135
#50x00000001009f823a in -[InDesignHelper _runAppleScript:withSubstitutionValues:forDocID:] at /Users/rr219379/gitdepot/RRDFramework/InDesignHelper.m:4152


I've normalized all our main thread calling to use dispatch_sync (running AppleScripts only uses that one) or dispatch_async instead of a mix of those and performSelectorOnMainThread:withObject: after reading a blog post about race conditions and such when both are used. That didn't magically fix it. It never happens when just running normally, only after stopping at a breakpoint, and not every time.


I've played with all the debugging options in Xcode, the sanitizers and such. No luck. Any other ideas? It's highly annoying to spend a lot of time debugging, almost getting to the root of a problem, and then having to kill it and start all over because Xcode or the OS is hosing up the main thread locking stuff.

Accepted Reply

Consider these frames from your backtrace:

#3 0x00000001005ff39d in enter_stack_in_backtrace_uniquing_table ()
#4 0x00000001005fb92e in gcd_queue_item_enqueue_hook ()
#5 0x0000000100dbe085 in _dispatch_introspection_queue_item_enqueue_hook ()
#6 0x0000000100da5794 in _dispatch_root_queue_push_override ()

Frames 3 and 2 implicates Xcode’s queue backtrace recording subsystem. This is a neat feature that lets you backtrace across Dispatch async calls, but it’s clearly causing problems here.

Fortunately you can disable this using Product > Scheme > Edit Scheme > Run > Options Queue Debugging > “Enable backtrace recording”. Please try that and let us know how you get along.

Also, make sure to file a bug about this. I’m not sure what’s going on here, but the Xcode folks should take a look. It would really help if you could create a cut-down test project that reproduces the problem, but if not you should at least include a sysdiagnose log triggered shortly after encountering it.

Please post your bug number, just for the record.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Replies

Consider these frames from your backtrace:

#3 0x00000001005ff39d in enter_stack_in_backtrace_uniquing_table ()
#4 0x00000001005fb92e in gcd_queue_item_enqueue_hook ()
#5 0x0000000100dbe085 in _dispatch_introspection_queue_item_enqueue_hook ()
#6 0x0000000100da5794 in _dispatch_root_queue_push_override ()

Frames 3 and 2 implicates Xcode’s queue backtrace recording subsystem. This is a neat feature that lets you backtrace across Dispatch async calls, but it’s clearly causing problems here.

Fortunately you can disable this using Product > Scheme > Edit Scheme > Run > Options Queue Debugging > “Enable backtrace recording”. Please try that and let us know how you get along.

Also, make sure to file a bug about this. I’m not sure what’s going on here, but the Xcode folks should take a look. It would really help if you could create a cut-down test project that reproduces the problem, but if not you should at least include a sysdiagnose log triggered shortly after encountering it.

Please post your bug number, just for the record.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Thanks, Quinn! I should've know I could count on you. radar://47630845 with sysdiagnose currently being uploaded.

Thanks for your bug report (r. 47630845).

Did disabling “Enable backtrace recording” help?

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Disabling it seemed to help. I should only need to do that for the app being debugged, not for any of the framework projects included in it, correct?


What does backtrace recording do? I still see the stack in each thread when stopping at a breakpoint, and from the name of that checkbox, I almost assumed I wouldn't.

I should only need to do that for the app being debugged, not for any of the framework projects included in it

Correct. This is a process-wide feature, and thus only the value in the main app’s scheme is relevant.

What does backtrace recording do?

It allows you to backtrace across Dispatch enqueues. Consider this code:

import Dispatch

let q1 = DispatchQueue(label: "BacktraceTest")
let q2 = DispatchQueue(label: "BacktraceTest2")

func f1() {
    q2.async(execute: f2)
}

func f2() {
    q2.async(execute: f3)
}

func f3() {
    fatalError()
}

func main() {
    f1()
    dispatchMain()
}

main()

Set a breakpoint on line 15 and, when you hit the breakpoint, show the debug navigator. If you have backtrace recording disabled, you see this backtrace:

Thread 2 Queue : BacktraceTest2 (serial)
#0  0x00000001000019f8 in f3() at /Users/quinn/Desktop/xxst/xxst/main.swift:15
#1  0x00000001000019dd in thunk for @escaping @callee_guaranteed () -> () ()
#2  0x00007fff5834dd53 in _dispatch_call_block_and_release ()
#3  0x00007fff5834edcf in _dispatch_client_callout ()
#4  0x00007fff58355124 in _dispatch_lane_serial_drain ()
#5  0x00007fff58355bdc in _dispatch_lane_invoke ()
#6  0x00007fff5835e090 in _dispatch_workloop_worker_thread ()
#7  0x00007fff5858e63c in _pthread_wqthread ()
#8  0x00007fff5858e435 in start_wqthread ()

You only see

f3
in the backtrace. A lot of the time you want to know what code enqueued
f3
, but that’s not available because the enqueue operation is async, and thus the enqueue code was not running on this thread’s stack.

If you enable backtrace recording you see this:

Thread 2 Queue : BacktraceTest2 (serial)
#0  0x00000001000019f8 in f3() at /Users/quinn/Desktop/xxst/xxst/main.swift:15
#1  0x00000001000019dd in thunk for @escaping @callee_guaranteed () -> () ()
#2  0x0000000100a466eb in _dispatch_call_block_and_release ()
#3  0x0000000100a477c3 in _dispatch_client_callout ()
#4  0x0000000100a4f9c7 in _dispatch_lane_serial_drain ()
#5  0x0000000100a5087e in _dispatch_lane_invoke ()
#6  0x0000000100a5bf44 in _dispatch_workloop_worker_thread ()
#7  0x0000000100ac2078 in _pthread_wqthread ()
#8  0x0000000100ac1e71 in start_wqthread ()
Enqueued from BacktraceTest2 (Thread 2) Queue : BacktraceTest2 (serial)
#0  0x0000000100a4cac2 in dispatch_async ()
#1  0x0000000100020e2e in OS_dispatch_queue.async(group:qos:flags:execute:) ()
#2  0x000000010000198c in f2() at /Users/quinn/Desktop/xxst/xxst/main.swift:11
#3  0x00000001000019dd in thunk for @escaping @callee_guaranteed () -> () ()
#4  0x0000000100a466eb in _dispatch_call_block_and_release ()
#5  0x0000000100a477c3 in _dispatch_client_callout ()
#6  0x0000000100a4f9c7 in _dispatch_lane_serial_drain ()
#7  0x0000000100a5087e in _dispatch_lane_invoke ()
#8  0x0000000100a5bf44 in _dispatch_workloop_worker_thread ()
#9  0x0000000100ac2078 in _pthread_wqthread ()
#10 0x0000000100ac1e71 in start_wqthread ()

Now you get the backtrace for both

f3
and
f2
, because Xcode’s debugging infrastructure has recorded the backtrace of the code that enqueued
f3
.

Note It’s weird that we don’t see a third block showing

f1
enqueuing
f2
on the main thread. I’ve filed a bug about that (r. 47696894).

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Apple says "DUPLICATE OF 31662531", which is still open (if I'm reading their email correctly).