search

quicksilver / Quicksilver

Quicksilver Project Source
http://qsapp.com
Apache License 2.0
2.73k stars 285 forks source link

Quicksilver hang (while indexing?) #2279

Closed danielcompton closed 2 years ago

danielcompton commented 8 years ago

I've been getting hangs from Quicksilver since upgrading to Sierra. Here's the full gist.

Date/Time:       2016-10-06 08:35:25 +1300
OS Version:      Mac OS X 10.12 (Build 16A320)
Architecture:    x86_64h
Report Version:  25

Data Source:     Stackshots

Command:         Quicksilver
Path:            /Applications/Quicksilver.app/Contents/MacOS/Quicksilver
Version:         1.4.2 (401A)
Parent:          launchd [1]
PID:             533

Event:           hang
Duration:        0.99s (process was unresponsive for 335 seconds before sampling)
Steps:           10 (100ms sampling interval)

Hardware model:  iMac14,2
Active cpus:     8

Fan speed:       1068 rpm

--------------------------------------------------
Timeline format: stacks are sorted chronologically
Use -i and -heavy to re-report with count sorting
--------------------------------------------------

Heaviest stack for the main thread of the target process:
  10  start + 1 (libdyld.dylib + 21077) [0x7fffc05f0255]
  10  NSApplicationMain + 1237 (AppKit + 27274) [0x7fffa9207a8a]
  10  -[NSApplication run] + 926 (AppKit + 245693) [0x7fffa923cfbd]
  10  -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 1637 (AppKit + 7698667) [0x7fffa99588eb]
  10  _DPSNextEvent + 1093 (AppKit + 292341) [0x7fffa92485f5]
  10  _BlockUntilNextEventMatchingListInModeWithFilter + 71 (HIToolbox + 199638) [0x7fffaab51bd6]
  10  ReceiveNextEventCommon + 432 (HIToolbox + 200097) [0x7fffaab51da1]
  10  RunCurrentEventLoopInMode + 240 (HIToolbox + 200556) [0x7fffaab51f6c]
  10  CFRunLoopRunSpecific + 420 (CoreFoundation + 554420) [0x7fffab5b05b4]
  10  __CFRunLoopRun + 1878 (CoreFoundation + 556902) [0x7fffab5b0f66]
  10  __CFRunLoopDoBlocks + 356 (CoreFoundation + 558116) [0x7fffab5b1424]
  10  __CFRUNLOOP_IS_CALLING_OUT_TO_A_BLOCK__ + 12 (CoreFoundation + 684972) [0x7fffab5d03ac]
  10  ___LSScheduleNotificationFunction_block_invoke_2 + 51 (LaunchServices + 104213) [0x7fffac761715]
  10  HIToolboxLSNotificationCallbackAllASNsFunc + 571 (HIToolbox + 631870) [0x7fffaabbb43e]
  10  SendEventToEventTargetWithOptions + 43 (HIToolbox + 33167) [0x7fffaab2918f]
  10  SendEventToEventTargetInternal(OpaqueEventRef*, OpaqueEventTargetRef*, HandlerCallRec*) + 428 (HIToolbox + 33606) [0x7fffaab29346]
  10  DispatchEventToHandlers(EventTargetRec*, OpaqueEventRef*, HandlerCallRec*) + 1708 (HIToolbox + 37077) [0x7fffaab2a0d5]
  10  appTerminated + 176 (QSCore + 242331) [0x10e75229b]
  10  -[NSNotificationCenter postNotificationName:object:userInfo:] + 66 (Foundation + 28899) [0x7fffacf920e3]
  10  _CFXNotificationPost + 604 (CoreFoundation + 367068) [0x7fffab5829dc]
  10  -[_CFXNotificationRegistrar find:object:observer:enumerator:] + 1827 (CoreFoundation + 371107) [0x7fffab5839a3]
  10  ___CFXNotificationPost_block_invoke + 50 (CoreFoundation + 643746) [0x7fffab5c62a2]
  10  _CFXRegistrationPost + 427 (CoreFoundation + 644411) [0x7fffab5c653b]
  10  __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12 (CoreFoundation + 644668) [0x7fffab5c663c]
  10  -[QSProcessMonitor removeProcessWithPSN:] + 337 (QSCore + 245383) [0x10e752e87]
  10  -[NSObject(NSKeyValueObserverNotification) didChangeValueForKey:] + 118 (Foundation + 75062) [0x7fffacf9d536]
  10  NSKeyValueDidChange + 486 (Foundation + 276052) [0x7fffacfce654]
  10  NSKeyValueNotifyObserver + 350 (Foundation + 277949) [0x7fffacfcedbd]
  10  -[QSProcessObjectSource observeValueForKeyPath:ofObject:change:context:] + 110 (QSCore + 253412) [0x10e754de4]
  10  -[QSProcessObjectSource invalidateSelf] + 75 (QSCore + 253506) [0x10e754e42]
  10  -[QSObjectSource invalidateSelf] + 104 (QSCore + 191435) [0x10e745bcb]
  10  -[NSNotificationCenter postNotificationName:object:userInfo:] + 66 (Foundation + 28899) [0x7fffacf920e3]
  10  _CFXNotificationPost + 604 (CoreFoundation + 367068) [0x7fffab5829dc]
  10  -[_CFXNotificationRegistrar find:object:observer:enumerator:] + 1827 (CoreFoundation + 371107) [0x7fffab5839a3]
  10  ___CFXNotificationPost_block_invoke + 50 (CoreFoundation + 643746) [0x7fffab5c62a2]
  10  _CFXRegistrationPost + 427 (CoreFoundation + 644411) [0x7fffab5c653b]
  10  __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12 (CoreFoundation + 644668) [0x7fffab5c663c]
  10  -[QSLibrarian reloadSource:] + 428 (QSCore + 77218) [0x10e729da2]
  10  -[QSCatalogEntry scanForced:] + 403 (QSCore + 27801) [0x10e71dc99]
  10  -[QSCatalogEntry indexIsValid] + 187 (QSCore + 26207) [0x10e71d65f]
  10  _dispatch_barrier_sync_f_slow + 402 (libdispatch.dylib + 54762) [0x7fffc05c55ea]
  10  _dispatch_thread_event_wait_slow + 85 (libdispatch.dylib + 109678) [0x7fffc05d2c6e]
  10  __ulock_wait + 10 (libsystem_kernel.dylib + 107446) [0x7fffc071f3b6]
 *10  hndl_unix_scall64 + 22 (kernel + 696134) [0xffffff80002a9f46]
 *10  unix_syscall64 + 582 (kernel + 6464358) [0xffffff800082a366]
 *10  ulock_wait + 993 (kernel + 5944129) [0xffffff80007ab341]
 *10  thread_block_reason + 222 (kernel + 1111278) [0xffffff800030f4ee]
 *10  ??? (kernel + 1115851) [0xffffff80003106cb]
 *10  machine_switch_context + 206 (kernel + 2118942) [0xffffff800040551e]

Process:         Quicksilver [533]
Path:            /Applications/Quicksilver.app/Contents/MacOS/Quicksilver
Architecture:    x86_64
Parent:          launchd [1]
UID:             503
Task size:       175 MB
CPU Time:        <0.001
Note:            Unresponsive for 335 seconds before sampling
Note:            2 idle work queue threads omitted
skurfer commented 8 years ago

I’ve seen some hangs too, though not this exact one. Thanks for the report.

j3r3miah commented 7 years ago

I'm having lots of hangs with the same stack as @danielcompton:

Sampling process 49627 for 3 seconds with 1 millisecond of run time between samples
Sampling completed, processing symbols...
Analysis of sampling Quicksilver (pid 49627) every 1 millisecond
Process:         Quicksilver [49627]
Path:            /Applications/Quicksilver.app/Contents/MacOS/Quicksilver
Load Address:    0x10dc4c000
Identifier:      com.blacktree.Quicksilver
Version:         1.4.2 (401A)
Code Type:       X86-64
Parent Process:  ??? [1]

Date/Time:       2016-11-11 21:33:11.978 -0800
Launch Time:     2016-11-11 16:22:03.989 -0800
OS Version:      Mac OS X 10.12 (16A323)
Report Version:  7
Analysis Tool:   /usr/bin/sample
----

Call graph:
 2617 Thread_3732905   DispatchQueue_1: com.apple.main-thread  (serial)
 2617 start  (in libdyld.dylib) + 1  [0x7fffc4380255]
 2617 NSApplicationMain  (in AppKit) + 1237  [0x7fffacf97a8a]
 2617 -[NSApplication run]  (in AppKit) + 926  [0x7fffacfccfbd]
 2617 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:]  (in AppKit) + 1637  [0x7fffad6e88eb]
 2617 _DPSNextEvent  (in AppKit) + 1093  [0x7fffacfd85f5]
 2617 _BlockUntilNextEventMatchingListInModeWithFilter  (in HIToolbox) + 71  [0x7fffae8e1bd6]
 2617 ReceiveNextEventCommon  (in HIToolbox) + 184  [0x7fffae8e1ca9]
 2617 RunCurrentEventLoopInMode  (in HIToolbox) + 240  [0x7fffae8e1f6c]
 2617 CFRunLoopRunSpecific  (in CoreFoundation) + 420  [0x7fffaf3405b4]
 2617 __CFRunLoopRun  (in CoreFoundation) + 917  [0x7fffaf340ba5]
 2617 __CFRunLoopDoBlocks  (in CoreFoundation) + 356  [0x7fffaf341424]
 2617 __CFRUNLOOP_IS_CALLING_OUT_TO_A_BLOCK__  (in CoreFoundation) + 12  [0x7fffaf3603ac]
 2617 ___LSScheduleNotificationFunction_block_invoke_2  (in LaunchServices) + 51  [0x7fffb04f1715]
 2617 HIToolboxLSNotificationCallbackAllASNsFunc  (in HIToolbox) + 571  [0x7fffae94b43e]
 2617 SendEventToEventTargetWithOptions  (in HIToolbox) + 43  [0x7fffae8b918f]
 2617 SendEventToEventTargetInternal(OpaqueEventRef*, OpaqueEventTargetRef*, HandlerCallRec*)  (in HIToolbox) + 428  [0x7fffae8b9346]
 2617 DispatchEventToHandlers(EventTargetRec*, OpaqueEventRef*, HandlerCallRec*)  (in HIToolbox) + 1708  [0x7fffae8ba0d5]
 2617 appLaunched  (in QSCore) + 176  [0x10dd731ba]
 2617 -[NSNotificationCenter postNotificationName:object:userInfo:]  (in Foundation) + 66  [0x7fffb0d220e3]
 2617 _CFXNotificationPost  (in CoreFoundation) + 604  [0x7fffaf3129dc]
 2617 -[_CFXNotificationRegistrar find:object:observer:enumerator:]  (in CoreFoundation) + 1827  [0x7fffaf3139a3]
 2617 ___CFXNotificationPost_block_invoke  (in CoreFoundation) + 50  [0x7fffaf3562a2]
 2617 _CFXRegistrationPost  (in CoreFoundation) + 427  [0x7fffaf35653b]
 2617 __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__  (in CoreFoundation) + 12  [0x7fffaf35663c]
 2617 -[QSProcessMonitor addProcessWithPSN:]  (in QSCore) + 393  [0x10dd74074]
 2617 -[NSObject(NSKeyValueObserverNotification) didChangeValueForKey:]  (in Foundation) + 118  [0x7fffb0d2d536]
 2617 NSKeyValueDidChange  (in Foundation) + 486  [0x7fffb0d5e654]
 2617 NSKeyValueNotifyObserver  (in Foundation) + 350  [0x7fffb0d5edbd]
 2617 -[QSProcessObjectSource observeValueForKeyPath:ofObject:change:context:]  (in QSCore) + 110  [0x10dd75de4]
 2617 -[QSProcessObjectSource invalidateSelf]  (in QSCore) + 75  [0x10dd75e42]
 2617 -[QSObjectSource invalidateSelf]  (in QSCore) + 104  [0x10dd66bcb]
 2617 -[NSNotificationCenter postNotificationName:object:userInfo:]  (in Foundation) + 66  [0x7fffb0d220e3]
 2617 _CFXNotificationPost  (in CoreFoundation) + 604  [0x7fffaf3129dc]
 2617 -[_CFXNotificationRegistrar find:object:observer:enumerator:]  (in CoreFoundation) + 1827  [0x7fffaf3139a3]
 2617 ___CFXNotificationPost_block_invoke  (in CoreFoundation) + 50  [0x7fffaf3562a2]
 2617 _CFXRegistrationPost  (in CoreFoundation) + 427  [0x7fffaf35653b]
 2617 __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__  (in CoreFoundation) + 12  [0x7fffaf35663c]
 2617 -[QSLibrarian reloadSource:]  (in QSCore) + 428  [0x10dd4ada2]
 2617 -[QSCatalogEntry scanForced:]  (in QSCore) + 403  [0x10dd3ec99]
 2617 -[QSCatalogEntry indexIsValid]  (in QSCore) + 187  [0x10dd3e65f]
 2617 _dispatch_barrier_sync_f_slow  (in libdispatch.dylib) + 402  [0x7fffc43555ea]
 2617 _dispatch_thread_event_wait_slow  (in libdispatch.dylib) + 85  [0x7fffc4362c6e]
 2617 _dispatch_ulock_wait  (in libdispatch.dylib) + 40  [0x7fffc4362a8e]
 2617 __ulock_wait  (in libsystem_kernel.dylib) + 10  [0x7fffc44af3b6]
skurfer commented 7 years ago

QSProcessObjectSource is updated whenever an application launches or quits. Much more often than most sources, in other words. I think I know what’s happening, but I can’t say why.

If you can reproduce it fairly easily, I could send a custom build with extra logging.

pjrobertson commented 7 years ago

This probably isn't the right fix, and I can't seem to see where the hang is coming from, but it's horrible that all that process scanning is happening on the main thread. We still have an issue that trying to run catalog entry scans on a dedicated thread for that catalog entry can still cause a deadlock, figuring out where it's coming from though is not easy.

Here's my small proposal: https://github.com/quicksilver/Quicksilver/commit/60c98bed167aefb3071ccf4d0e408e2a87858ef6

j3r3miah commented 7 years ago

I'm reproducing several times a day @skurfer... in the minutes to hours timeframe. I'd be happy to capture logs if that'll help. Let me know.

skurfer commented 7 years ago

This probably isn't the right fix, and I can't seem to see where the hang is coming from, but it's horrible that all that process scanning is happening on the main thread.

I assumed the hang was happening when the scanning and checking indexIsValid were happening at the same time (which shouldn’t be possible), but if that’s on a background thread, it shouldn’t lock up the UI, right? So maybe that’s not it. But the only thing happening on the main thread is a quick boolean test, so… No idea.

pjrobertson commented 7 years ago

If you go through the stack trace, it’s the main thread that listening for changes in QSProcessMonitor then instructing the QSCatalogEntry (via NSNotifications) to do some scanning. The only point it gets off the main thread is when dispatch_sync() is called - but of course, since it’s dispatch_sync and not dispatch_async then it’s still the main thread that’s hanging.

I’d suggest building with my changes and getting j3r3miah to test it out.

On 18 Nov 2016, at 06:42, Rob McBroom notifications@github.com wrote:

This probably isn't the right fix, and I can't seem to see where the hang is coming from, but it's horrible that all that process scanning is happening on the main thread.

I assumed the hang was happening when the scanning and checking indexIsValid were happening at the same time (which shouldn’t be possible), but if that’s on a background thread, it shouldn’t lock up the UI, right? So maybe that’s not it. But the only thing happening on the main thread is a quick boolean test, so… No idea.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/quicksilver/Quicksilver/issues/2279#issuecomment-261393408, or mute the thread https://github.com/notifications/unsubscribe-auth/AAJLn9iQG-0ZPVsB3mzwP26UGOh-OOqWks5q_NhqgaJpZM4KQmHF.

skurfer commented 7 years ago

I’d suggest building with my changes and getting j3r3miah to test it out.

OK, see if this is any better @j3r3miah.

https://cl.ly/3K0g151I1h1z

j3r3miah commented 7 years ago

Thanks for the build @skurfer. I'll give it a try but I likely won't have results for you for more than a week, as I've been traveling and noticed the issue hasn't come up once since I left home. I suspect the problem may be related to scanning network volumes (on my home network). Anyway, I'll run the potentially-fixed-build when I'm home in a week and see what happens.

j3r3miah commented 7 years ago

Frustratingly, I'm no longer reproducing the issue with the 1.4.2 so I can't say whether the above change had any impact. I'm not sure what changed.

j3r3miah commented 7 years ago

Btw, https://qsapp.com/download.php is still pointing to 1.4.2

skurfer commented 7 years ago

Btw, https://qsapp.com/download.php is still pointing to 1.4.2

It was marked as a pre-release, but I forgot and updated the text on the download page. I’ll go ahead and make it a real release. Thanks for pointing it out.

skurfer commented 7 years ago

I started seeing QS hang on login pretty reliably yesterday (probably due to other changes I’m running with). It was getting stuck on addProcessWithPSN:, but your fix didn’t help @pjrobertson since it was getting called from appLaunched:. So I reverted your change and instead just wrapped the didChange… and postNotification calls at the end of the add/remove process methods. Opinions?

pjrobertson commented 7 years ago

should NSNotifications be called on anything but the main thread? (edit: yes it's fine to call notifs on a background thread )

The most important thing is to make sure that the receiver (whoever is listening to QSEventNotification and all those KVO bindings) now knows that they're running on a background thread (since if you post from a background thread, the receiver gets that message on the same thread). This could be a problem if for example the receiver of QSEventNotification needs to do something with NSView/the UI which must be run on a foreground thread.

pjrobertson commented 2 years ago

Closing this. @danielcompton If we're still getting hangs on the latest version, then please re-open and we can debug further.