If you used Leopard and DTrace, then came to Snow Leopard there is a big treat for you (if you haven't used DTrace you can read my previous article Debugging Cocoa With DTrace Guide, go on read it and come back here... I'll wait), on Leopard on any given run I ran dtrace -l | wc -l I got about 23,000 probes on average. On Snow Leopard anytime I do the probe count I get about 66,000 (76,000 right before publishing with a lot of apps running) probes on average. So what's with the almost 3x increase in probes? Did Apple pull overtime and add a lot of DTrace probes to Mac OS X? Yes and no.
Yes in that now there are many more DTrace Mac OS X Specific Providers in Mac OS X 10.6 Snow Leopard than there were in 10.5 Leopard. Since there are many more providers they attach to each process that's applicable to them, and with all the processes running on your system you can see why your probe count has skyrocketed. It appears that Apple has made into providers what you previously had to get at by knowing the right methods to trace in the right libraries,etc, thus making tracing a particular aspect of an app or the whole OS easier.
Objective-C Runtime
//objc_runtime 24509 objc_runtime32972 libobjc.A.dylib objc_exception_rethrow objc_exception_rethrow 24510 objc_runtime32972 libobjc.A.dylib objc_exception_throw objc_exception_throw
Objective-C now has it's own provider for the (apparent) sole purpose of making Objective-C exceptions easy to catch. So you could run a script and catch all exception backtraces like so...
sh-3.2# dtrace -n 'objc_runtime$target:::objc_exception_throw { ustack(); }' -p 35467
dtrace: description 'objc_runtime$target:::objc_exception_throw ' matched 1 probe
CPU ID FUNCTION:NAME
1 90573 objc_exception_throw:objc_exception_throw
libobjc.A.dylib`objc_exception_throw+0xb4
CoreFoundation`+[NSException raise:format:arguments:]+0x67
CoreFoundation`+[NSException raise:format:]+0x94
Foundation`-[NSCFArray insertObject:atIndex:]+0x77
CocoaPlugin`IBWrapIndex+0x3a5f
CocoaPlugin`IBCounterpartTable+0xe3
CocoaPlugin`IBCounterpartTable+0x130
AppKit`-[NSToolbarView(_ItemDragAndDropSupport) dstDraggingDepositedAtPoint:draggingInfo:]+0x227
AppKit`NSCoreDragReceiveProc+0x328
HIServices`DoDropMessage+0x63
HIServices`SendDropMessage+0x1f
HIServices`DragInApplication+0x1c6
HIServices`CoreDragStartDragging+0x27a
AppKit`-[NSCoreDragManager _dragUntilMouseUp:accepted:]+0x2fb
AppKit`-[NSCoreDragManager dragImage:fromWindow:at:offset:event:pasteboard:source:slideBack:]+0x63a
AppKit`-[NSWindow(NSDrag) dragImage:at:offset:event:pasteboard:source:slideBack:]+0x92
CocoaPlugin`IBCounterpartTable+0x6e06
CocoaPlugin`IBCounterpartTable+0x4433
InterfaceBuilderKit`-[IBEditorWindowController interceptEvent:]+0x5ca
InterfaceBuilderKit`-[IBViewEditorWindowController interceptEvent:]+0xc2
1 90573 objc_exception_throw:objc_exception_throw
libobjc.A.dylib`objc_exception_throw+0xb4
CoreFoundation`-[NSException raise]+0x9
AppKit`NSCoreDragReceiveProc+0x5fe
HIServices`DoDropMessage+0x63
HIServices`SendDropMessage+0x1f
HIServices`DragInApplication+0x1c6
HIServices`CoreDragStartDragging+0x27a
AppKit`-[NSCoreDragManager _dragUntilMouseUp:accepted:]+0x2fb
AppKit`-[NSCoreDragManager dragImage:fromWindow:at:offset:event:pasteboard:source:slideBack:]+0x63a
AppKit`-[NSWindow(NSDrag) dragImage:at:offset:event:pasteboard:source:slideBack:]+0x92
CocoaPlugin`IBCounterpartTable+0x6e06
CocoaPlugin`IBCounterpartTable+0x4433
InterfaceBuilderKit`-[IBEditorWindowController interceptEvent:]+0x5ca
InterfaceBuilderKit`-[IBViewEditorWindowController interceptEvent:]+0xc2
InterfaceBuilderKit`-[IBEditableWindow sendEvent:]+0x34
AppKit`-[NSApplication sendEvent:]+0x126d
Interface Builder`0x1000038ad
AppKit`-[NSApplication run]+0x1da
AppKit`NSApplicationMain+0x16c
Interface Builder`0x1000016a5
1 90573 objc_exception_throw:objc_exception_throw
libobjc.A.dylib`objc_exception_throw+0xb4
CoreFoundation`-[NSException raise]+0x9
AppKit`-[NSCoreDragManager _dragUntilMouseUp:accepted:]+0x33e
AppKit`-[NSCoreDragManager dragImage:fromWindow:at:offset:event:pasteboard:source:slideBack:]+0x63a
AppKit`-[NSWindow(NSDrag) dragImage:at:offset:event:pasteboard:source:slideBack:]+0x92
CocoaPlugin`IBCounterpartTable+0x6e06
CocoaPlugin`IBCounterpartTable+0x4433
InterfaceBuilderKit`-[IBEditorWindowController interceptEvent:]+0x5ca
InterfaceBuilderKit`-[IBViewEditorWindowController interceptEvent:]+0xc2
InterfaceBuilderKit`-[IBEditableWindow sendEvent:]+0x34
AppKit`-[NSApplication sendEvent:]+0x126d
Interface Builder`0x1000038ad
AppKit`-[NSApplication run]+0x1da
AppKit`NSApplicationMain+0x16c
Interface Builder`0x1000016a5
Interface Builder`0x100001634
Interface Builder`0x2
dtrace: pid 35467 has exited
This is a crash I got when adding a flexible space item to BWSelectableToolbar in Interface Builder.
OpenCL
//OpenCL Probes 21304 opencl_api32981 OpenCL _CLQueueDeallocate commandqueuedeallocate 21305 opencl_api32981 OpenCL _CLContextDeallocate contextdeallocate 21306 opencl_api32981 OpenCL _CLEventDeallocate eventdeallocate 21307 opencl_api32981 OpenCL _CLKernelDeallocate kerneldeallocate 21308 opencl_api32981 OpenCL _CLMemDeallocate memdeallocate 21309 opencl_api32981 OpenCL _CLProgramDeallocate programdeallocate 21310 opencl_api32981 OpenCL clWaitForEvent waitforevent
Of course, OpenCL being a new technology in Snow Leopard has probes, all of the probes seen above appear to be for dealloc'ing items and 1 probe where OpenCL is waiting on events. I honestly have not gotten around to playing with OpenCL yet, but I expect to toy around with it and see what it's capable of sometime.
Cocoa Autorelease Provider
//Cocoa Autorelease Provider 22445 Cocoa_Autorelease32978 CoreFoundation _CFAutoreleasePoolAddObject autorelease 22446 Cocoa_Autorelease32978 CoreFoundation __NSAutoreleaseFreedObject error_freed_object 22447 Cocoa_Autorelease32978 CoreFoundation __NSAutoreleaseNoPool error_no_pool 22448 Cocoa_Autorelease32978 CoreFoundation _CFAutoreleasePoolPop pool_pop_end 22449 Cocoa_Autorelease32978 CoreFoundation _CFAutoreleasePoolPop pool_pop_start 22450 Cocoa_Autorelease32978 CoreFoundation _CFAutoreleasePoolPush pool_push
The Cocoa Autorelease provider is a great example of Apple adding a new provider that essentially makes it easier to grasp onto something that was already present in Mac OS X, but again you sort of had to know where to latch onto. It makes seeing the activity around Creating/Releasing NSAutoReleasePool objects and the objects you add to these pools easier. I picked on MarsEdit (which I am using to write this article) to see how this provider worked.
sh-3.2# dtrace -n 'Cocoa_Autorelease$target::: { ustack(); }' -p 38071
dtrace: description 'Cocoa_Autorelease$target::: ' matched 6 probes
0 30720 _CFAutoreleasePoolPush:pool_push
CoreFoundation`_CFAutoreleasePoolPush+0xbe
Foundation`-[NSAutoreleasePool init]+0x16
AppKit`-[NSApplication run]+0x2e7
AppKit`NSApplicationMain+0x23e
MarsEdit`_start+0xd8
MarsEdit`start+0x29
MarsEdit`0x2
...
CPU ID FUNCTION:NAME
0 30715 _CFAutoreleasePoolAddObject:autorelease
CoreFoundation`_CFAutoreleasePoolAddObject+0x185
CoreFoundation`-[NSObject(NSObject) autorelease]+0x1a
AppKit`-[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]+0x16b
AppKit`-[NSApplication run]+0x335
AppKit`NSApplicationMain+0x23e
MarsEdit`_start+0xd8
MarsEdit`start+0x29
MarsEdit`0x2
..
0 30719 _CFAutoreleasePoolPop:pool_pop_start
CoreFoundation`_CFAutoreleasePoolPop+0x93
Foundation`NSPopAutoreleasePool+0x189
Foundation`-[NSAutoreleasePool drain]+0x82
AppKit`-[NSApplication run]+0x3f5
AppKit`NSApplicationMain+0x23e
MarsEdit`_start+0xd8
MarsEdit`start+0x29
MarsEdit`0x2
...
0 30718 _CFAutoreleasePoolPop:pool_pop_end
CoreFoundation`_CFAutoreleasePoolPop+0x1d5
Foundation`NSPopAutoreleasePool+0x189
Foundation`-[NSAutoreleasePool drain]+0x82
AppKit`-[NSApplication run]+0x3f5
AppKit`NSApplicationMain+0x23e
MarsEdit`_start+0xd8
MarsEdit`start+0x29
MarsEdit`0x2
I haven't yet seen the error_freed_object probe triggered, and I honestly don't know what would trigger it. All the documentation says is that the Cocoa Autorelease probes should be obvious where they are triggered and all of them except for the error_freed_object probe are obvious. I asked online what would trigger it and got back no responses. All I know is that the documentation should explain what this probe does better. I have had many hypothesizes about what could trigger it, but no amount of intentionally badly written code appears to trigger it. If you do find out what triggers it, please let me know.
Update: natevw seems to have solved it and now I know why it was never triggered
"__NSAutoreleaseFreedObject (error_freed_object) is similar to NSZombieEnabled. It tries to detect when an object that is already freed is being released by an autorelease pool. But unlinke NSZombie, it does not cause objects to hang around. So the memory could have been reused in the meantime.
Pre-10.6, you needed to set +[NSAutoreleasePool enableFreedObjectCheck:] to enable this. See NSDebug.h for more details and many other helpful goodies."
Garbage Collection
The garbage collection provider is technically nothing new, you could trace garbage collection before, but it's been made into it's own provider to make tracing garbage collection activities easier.
garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::collect] collection_begin garbage_collection32978 libauto.dylib ... [auto_collect_internal] collection_begin garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::process_local_garbage] collection_end garbage_collection32978 libauto.dylib ... [auto_collect_internal] collection_end garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::collect] collection_phase_begin garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::scavenge_local] collection_phase_begin garbage_collection32978 libauto.dylib ... [Auto::Zone::collect] collection_phase_begin garbage_collection32978 libauto.dylib ... [auto_collect_internal] collection_phase_begin garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::collect] collection_phase_end garbage_collection32978 libauto.dylib ... [Auto::ThreadLocalCollector::scavenge_local] collection_phase_end garbage_collection32978 libauto.dylib ... [Auto::Zone::collect] collection_phase_end garbage_collection32978 libauto.dylib ... [auto_collect_internal] collection_phase_end
QuickLookDaemon
If you care about QuickLook and how long it's spending on various tasks there are some new interesting probes. I've chopped the list down a bit for the sake of brevity here.
21402 QuickLookDaemon32981 quicklookd __-[QLDiskCacheQueryOperation main]_block_invoke_2 disk_cache_thumbnail_found 21403 QuickLookDaemon32981 quicklookd _QLServerGetThumbnail dispatch_end 21404 QuickLookDaemon32981 quicklookd _QLServerGetThumbnail dispatch_start 21405 QuickLookDaemon32981 quicklookd -[_QLCacheThread serverIsIdle] idle_signal 21406 QuickLookDaemon32981 quicklookd -[QLMemoryCacheQueryOperation main] memory_cache_query_end 21407 QuickLookDaemon32981 quicklookd -[QLMemoryCacheQueryOperation main] memory_cache_query_start 21408 QuickLookDaemon32981 quicklookd -[QLMemoryCache addThumbnailData:] memory_cache_thumbnail_data_added 21409 QuickLookDaemon32981 quicklookd -[QLMemoryCacheQueryOperation main] memory_cache_thumbnail_found 21410 QuickLookDaemon32981 quicklookd __-[_QLServerThread serverWork]_block_invoke_4 saved_memory 21411 QuickLookDaemon32981 quicklookd -[_QLServerThread _dispatchThumbnailRequest:] thumbnail_generator_end 21412 QuickLookDaemon32981 quicklookd -[_QLServerThread _dispatchThumbnailRequest:] thumbnail_generator_start 21413 QuickLookDaemon32981 quicklookd -[QLManage run] waitfordtrace 21414 QuickLookDaemon32981 quicklookd -[_QLCacheThread serverIsWorking] work_signal
QLThumbnail
Along with the QuickLookDaemon there is a QLThumbnail provider...
29567 QLThumbnail32898 QuickLook QLThumbnailCancel cancel 29568 QLThumbnail32898 QuickLook QLThumbnailCreate create 29569 QLThumbnail32898 QuickLook _QLThumbnailEndProcess end_generate 29570 QLThumbnail32898 QuickLook _QLThumbnailCFFinalize finalized 29571 QLThumbnail32898 QuickLook _QLThumbnailSetThumbnailWithBitmapData generated 29572 QLThumbnail32898 QuickLook _QLThumbnailRequestDispatch generated_but_empty 29573 QLThumbnail32898 QuickLook _QLThumbnailSendQuery start_generate
Core Image
Core Image has been made into a provider for tracing kernel compiling, loading the kernels, tracing when contexts are created, etc.
26349 CoreImage32970 QuartzCore fe_kernel_compile coreImage_Kernel_Compile 26350 CoreImage32970 QuartzCore fe_gl_load_programs coreImage_Kernel_ProgramLoad 26351 CoreImage32970 QuartzCore fe_context_cl_new coreImage_OpenCL_Context_Created 26352 CoreImage32970 QuartzCore fe_cl_load_kernel coreImage_OpenCL_Kernel_Loaded 26353 CoreImage32970 QuartzCore fe_accel_read_bitmap coreImage_Readback_Image
JavaScript Core
Now you can easily see when JavaScript Core is doing it's garbage collection...
//JavaScriptCore 29562 JavaScriptCore32898 JavaScriptCore ... [JSC::Heap::collect] gc-begin 29563 JavaScriptCore32898 JavaScriptCore ... [JSC::Heap::collect] gc-end 29564 JavaScriptCore32898 JavaScriptCore ... [JSC::Heap::collect] gc-marked 29565 JavaScriptCore32898 JavaScriptCore ... [JSC::ProfileGenerator::didExecute] profile-did_execute 29566 JavaScriptCore32898 JavaScriptCore ... [JSC::ProfileGenerator::willExecute] profile-will_execute
Conclusion
There are many more new providers that I haven't even listed here, that will be interesting to various people, but I wanted to take you on a quick tour on what's new in Mac OS X from a DTrace perspective. If I can I will try and show some interesting things we can accomplish with these probes down the line. Overall I am glad Apple is really starting to put DTrace to good use from a native technology point of view, in that we no longer have to be just stuck looking through library calls and can now refer to a native Mac OS X provider that makes writing scripts and tracing our apps and the OS easier.
__NSAutoreleaseFreedObject (error_freed_object) is similar to NSZombieEnabled. It tries to detect when an object that is already freed is being released by an autorelease pool. But unlinke NSZombie, it does not cause objects to hang around. So the memory could have been reused in the meantime.
ReplyDeletePre-10.6, you needed to set +[NSAutoreleasePool enableFreedObjectCheck:] to enable this. See NSDebug.h for more details and many other helpful goodies.
I tried this but failed... Do you know how one can add the objc_exception_throw probe in Instruments as a custom instrument?
ReplyDeleteThanks!