Spindump analysis instructions?

Question

I have a collection of spindumps focused on an app that need to be analyzed, however I'm not sure precisely how to analyze these. I've seen some other developers who are able to quickly parse these either mentally or with software and come back to me with details on where hangs are coming to play and so forth and I'm hoping to understand how to properly analyze these.

Where does one go to properly analyze spindumps?

Answer 1

Generally:

• with a crash report, you get a stack trace
• with spindumps, you get multiple stack traces over a period of time together.

There are two cases in which you might want to examine a spindump:

1. an infinite loop, probably calling the same function over and over
2. deadlock.

The first case can be seen from the spindump by many calls to the same function over and over. A good thing to use in such situations is Activity Monitor – take sample of a hung process there and you can view it in several useful ways, hiding unimportant frames, etc.

The second case can be viewed by different threads waiting on locks at the same time.

Here is a little example:

+ 2663 start  (in MyApp) + 52  [0x100001bb4]
+   2663 main  (in MyApp) + 39  [0x100001be7]  main.m:65
+     2663 NSApplicationMain  (in AppKit) + 869  [0x7fff8ea27cb6]
+       2663 -[NSApplication run]  (in AppKit) + 517  [0x7fff8ea83283]
+         2663 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]  (in AppKit) + 128  [0x7fff8ea8bed2]
+           2663 _DPSNextEvent  (in AppKit) + 685  [0x7fff8ea8c613]
+             2663 BlockUntilNextEventMatchingListInMode  (in HIToolbox) + 62  [0x7fff8dd53cd3]
+               2663 ReceiveNextEventCommon  (in HIToolbox) + 356  [0x7fff8dd53e42]
+                 2663 RunCurrentEventLoopInMode  (in HIToolbox) + 209  [0x7fff8dd540a4]
+                   2663 CFRunLoopRunSpecific  (in CoreFoundation) + 290  [0x7fff95dec6b2]
+                     2557 __CFRunLoopRun  (in CoreFoundation) + 1078  [0x7fff95decee6]
+                     ! 2556 __CFRunLoopServiceMachPort  (in CoreFoundation) + 195  [0x7fff95de7803]
+                     ! : 2556 mach_msg  (in libsystem_kernel.dylib) + 70  [0x7fff93630c42]
+                     ! :   2556 mach_msg_trap  (in libsystem_kernel.dylib) + 10  [0x7fff93631686]
+                     ! 1 __CFRunLoopServiceMachPort  (in CoreFoundation) + 199  [0x7fff95de7807]
+                     97 __CFRunLoopRun  (in CoreFoundation) + 728  [0x7fff95decd88]
+                     ! 97 __CFRunLoopDoObservers  (in CoreFoundation) + 369  [0x7fff95e11921]
+                     !   97 __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__  (in CoreFoundation) + 23  [0x7fff95e119b7]
+                     !     97 __83-[NSWindow _postWindowNeedsDisplayOrLayoutOrUpdateConstraintsUnlessPostingDisabled]_block_invoke_01208  (in AppKit) + 46  [0x7fff8f05a971]
+                     !       90 _handleWindowNeedsDisplayOrLayoutOrUpdateConstraints  (in AppKit) + 738  [0x7fff8ea8f2ac]
+                     !       : 89 -[NSView displayIfNeeded]  (in AppKit) + 1830  [0x7fff8ea8fd73]

What this tells me, is that MyApp has gone through main, etc. and finally got into a function CFRunLoopRunSpecific, then __CFRunLoopRun – from there (2557) it called __CFRunLoopServiceMachPort, which called mach_msg and got into a trap at mach_msg_trap (calling a syscall) – when it got back, the stack trace returned to CFRunLoopRunSpecific, where __CFRunLoopRun was called, which then calls __CFRunLoopDoObservers, and so on.

Note that this isn't a spindump of any hanging process - you can sample this way any running process and view what functions were called during that sample. An infinite loop, however, will have a repeating calls to some function over and over again - there will be the same call tree over and over again. Of course, this can mean a simple for cycle, but that's where you can examine, if the for cycle isn't for some reason infinite. Unfortunately, these spin dumps are usually quite long, depending on what function you are calling, so it may take some time to examine

The + sign at the beginning of the row simply indicates a beginning of a line - lines without the + sign indicate a beginning of a new thread. The ! and : signs make a line, so it's easier for you to see subsequent calls - i.e. which calls are at the same level. Further, | character can be also used.

The numbers mean how long the app spent in that particular call - they are in the number of samples. The sampling works that the sampled app gets suspended every few millisecond and the stack frame is examined of each thread. If the app is still in the same function, the function gets +1.