Sometimes hangs in LLDB

[futuretap]

When debugging my app and printing a large dictionary in LLDB, Xcode hangs with KZLinkedConsole in the backtrace:

886 Thread_10058798   DispatchQueue_1: com.apple.main-thread  (serial)
+ 886 start  (in libdyld.dylib) + 1  [0x7fff852545ad]
+   886 NSApplicationMain  (in AppKit) + 1176  [0x7fff87f73520]
+     886 -[NSApplication run]  (in AppKit) + 682  [0x7fff87ff0fc8]
+       886 -[DVTApplication nextEventMatchingMask:untilDate:inMode:dequeue:]  (in DVTKit) + 247  [0x10b1720c2]
+         886 -[NSApplication _nextEventMatchingEventMask:untilDate:inMode:dequeue:]  (in AppKit) + 454  [0x7fff883c7943]
+           886 _DPSNextEvent  (in AppKit) + 1067  [0x7fff87ffb0ee]
+             886 _BlockUntilNextEventMatchingListInModeWithFilter  (in HIToolbox) + 71  [0x7fff942055af]
+               886 ReceiveNextEventCommon  (in HIToolbox) + 432  [0x7fff9420576f]
+                 886 RunCurrentEventLoopInMode  (in HIToolbox) + 235  [0x7fff94205935]
+                   886 CFRunLoopRunSpecific  (in CoreFoundation) + 296  [0x7fff9621a338]
+                     886 __CFRunLoopRun  (in CoreFoundation) + 1841  [0x7fff9621acd1]
+                       886 __CFRunLoopDoTimers  (in CoreFoundation) + 298  [0x7fff962dde6a]
+                         886 __CFRunLoopDoTimer  (in CoreFoundation) + 1075  [0x7fff9625f853]
+                           886 __CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__  (in CoreFoundation) + 20  [0x7fff9625fbc4]
+                             886 __NSFireDelayedPerform  (in Foundation) + 377  [0x7fff8d66a345]
+                               886 -[IDEConsoleTextView _appendConsoleItemsWaitingToBeAppended]  (in IDEKit) + 120  [0x10be37045]
+                                 886 -[IDEConsoleTextView appendConsoleItemsImmediatelyWithoutScrolling:]  (in IDEKit) + 1004  [0x10c03e8bd]
+                                   886 -[DVTTextStorage endEditing]  (in DVTKit) + 652  [0x10b0630d6]
+                                     886 -[NSTextStorage endEditing]  (in UIFoundation) + 111  [0x7fff90f6b4af]
+                                       886 -[DVTTextStorage processEditing]  (in DVTKit) + 82  [0x10b063414]
+                                         886 -[NSTextStorage processEditing]  (in UIFoundation) + 190  [0x7fff90f6b7da]
+                                           886 -[DVTTextStorage invalidateAttributesInRange:]  (in DVTKit) + 211  [0x10b1a1b3c]
+                                             886 -[DVTTextStorage fixAttributesInRange:]  (in DVTKit) + 719  [0x10b082a1f]
+                                               886 _TToFE15KZLinkedConsoleCSo13NSTextStorage23kz_fixAttributesInRangefS0_FVSC8_NSRangeT_  (in KZLinkedConsole) + 80  [0x1182b8ee0]  NSTextStorage+Extensions.swift:0
+                                                 886 _TFE15KZLinkedConsoleCSo13NSTextStorageP33_071CB34855B3BCA24A9667F3084B0B6519injectLinksIntoLogsfS0_FT_T_  (in KZLinkedConsole) + 357  [0x1182b8205]  NSTextStorage+Extensions.swift:42
+                                                   886 -[NSRegularExpression(NSMatching) matchesInString:options:range:]  (in Foundation) + 159  [0x7fff8d64c4fb]
+                                                     886 -[NSRegularExpression(NSMatching) enumerateMatchesInString:options:range:usingBlock:]  (in Foundation) + 1251  [0x7fff8d64c9f0]
+                                                       886 uregex_findNext  (in libicucore.A.dylib) + 45  [0x7fff8df82459]
+                                                         886 icu::RegexMatcher::find(UErrorCode&)  (in libicucore.A.dylib) + 1419  [0x7fff8e0d3b01]
+                                                           886 icu::RegexMatcher::MatchAt(long long, signed char, UErrorCode&)  (in libicucore.A.dylib) + 12669,12665,...  [0x7fff8df85621,0x7fff8df8561d,...]

The issue is reproducible here and instantly goes away when removing the KZLinkedConsole plugin.

[krzysztofzablocki]

which log format are you using?

[futuretap]

In this project I haven't (yet) changed to a compatible log format. However, it still shouldn't completely freeze Xcode, imo.

To answer your question, the log format looks like this:

2016-01-04 23:03:34:401 MyApp[44534:70b]    (68d46900.0128)-[WMImageCache printCacheStats] mem: 0% (0/72)

I'm using CocoaLumberJack with colors enabled (using the XcodeColors plugin).

[krzysztofzablocki]

@futuretap of course it should not, I'm asking so we can find the issue causing it. Does it only happen on a really long lldb print or even on simpler ones ?

[futuretap]

So far I can reproduce it only on a very long LLDB print. Shorter ones work fine.

[ewanmellor]

@futuretap Does https://github.com/ewanmellor/KZLinkedConsole/tree/async-processing help?

[futuretap]

Indeed, this helps and I can't reproduce the error anymore in my specific case.

[ewanmellor]

I have made PR #20. This is the same code as mentioned just above, rebased onto current master. That PR should fix this issue then.

[futuretap]

While Xcode doesn't hang anymore, it constantly uses 200% CPU. I verified that KZLinkedConsole regex stuff hogs 2 threads in Xcode. The CPU is still hogged when I delete the log (or even when I stop the debug session and close all windows!) which is embarrassing to me. Looks like the parsing job isn't cancelled.

[ewanmellor]

@futuretap It's not doing that for me, and it's a regex so it shouldn't really run forever. Can you get any debugging info? A backtrace like the one at the start of this issue would be really useful. Alternatively, you can run the plugin using Xcode as normal, and it will launch another version of Xcode and you can debug the whole plugin that way. It would be great to know where that thread is spinning.

There is a let DEBUG_LOGGING = false at the top of NSTextStorage+Extensions.swift, and changing that to true will give some useful info.

Also, are you using https://github.com/ewanmellor/KZLinkedConsole/tree/async-processing or PR #20? (Just in case something got screwed up in the merge.)

[futuretap]

I'm using your branch. I tried to let it run at 200% and it eventually finished. But it took like 10 minutes. I admit, the dictionary I printed was a 150 KB JSON with some huge strings. Maybe the Regex can be optimized to only search in the first 100 characters of a line? It seems awfully inefficient. I'm on a tight schedule and can't debug the issue myself, so I've disabled the plugin for now. Have you tried testing with such large data?

[ewanmellor]

OK, well my patch just moves the work to a background thread, it doesn't change how much work gets done. A busy background thread is better than a hung UI thread of course. You're right though that 10 minutes of regexing is an awful lot. Searching only near the start of a line sounds like a good idea.

[ewanmellor]

@futuretap Try https://github.com/ewanmellor/KZLinkedConsole/tree/search-near-start-of-lines

[krzysztofzablocki]

I'm assuming it's fixed now, let me know that's not the case

[calimarkus]

I just ran in an issue (in another project, not LinkedConsole), where icu::RegexMatcher::MatchAt is stuck at 99% CPU... and it was just acting on a 436 character string. It feels like there are bugs in the regex matcher.