Wednesday, September 30, 2009

New in Snow Leopard: New Mac OS X DTrace Providers

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.

2 comments:

natevw said...

__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.

Karan said...

I tried this but failed... Do you know how one can add the objc_exception_throw probe in Instruments as a custom instrument?

Thanks!

 
...