{"id":385,"date":"2015-01-07T12:25:26","date_gmt":"2015-01-07T17:25:26","guid":{"rendered":"http:\/\/blog.mozilla.org\/nfroyd\/?p=385"},"modified":"2015-01-07T12:25:26","modified_gmt":"2015-01-07T17:25:26","slug":"profiling-for-wakeups-on-osx","status":"publish","type":"post","link":"https:\/\/blog.mozilla.org\/nfroyd\/2015\/01\/07\/profiling-for-wakeups-on-osx\/","title":{"rendered":"profiling for wakeups on osx"},"content":{"rendered":"

One of my Q1 goals is to investigate what can be done for cross-platform power profiling, in service of the Firefox Platform’s Project Candle.\u00a0 Roberto Vitillo already did a bit of exploration in this space<\/a> last year.\u00a0 Ideally, what would come out of my research would be some sort of event counter that we could hook into the Gecko Profiler.\u00a0 Failing that, it would at least be good to document what is possible for power profiling on each of our supported platforms.<\/p>\n

The only power profiling tool I was at all familiar with was powertop<\/a>. I thought I’d start by figuring out if there was any rough equivalent on OS X.\u00a0 Turns out there is; it’s called powermetrics<\/a>.\u00a0 You can simply run:<\/p>\n

$ sudo powermetrics\r\n<\/pre>\n
at a Terminal prompt and you will periodically (every five seconds by default) see a large amount of information concerning power usage printed.\u00a0 The default data sources that powermetrics draws from includes things like detailed C-state<\/a> usage for all available processors.\u00a0 For my purposes, I’m just interested in what applications are waking up most frequently.\u00a0 powermetrics supports limiting its data sources with the –samplers switch:<\/p>\n
$ sudo powermetrics --samplers tasks\r\n<\/pre>\n
will just display interesting information on all currently running tasks in the system.\u00a0 You might think of it as a more detailed version of Activity Monitor’s Energy tab, and indeed, you can convince powermetrics to output the “Energy Impact” number found in Activity Monitor:<\/p>\n
$ sudo powermetrics --samplers tasks --show-process-energy\r\n<\/pre>\n
The numbers from powermetrics<\/code> don’t match up exactly with the numbers from Activity Monitor; I’m guessing that the impact of kernel_task (seen in powermetrics) is somehow spread among applications calling into the kernel by Activity Monitor. Or Activity Monitor is aggregating energy usage over a longer time period than every five seconds.<\/p>\n
Knowing that your application is waking up rather often is helpful (Firefox is waking up ~once a second while I’m writing this), but even more helpful is where the wakeups are coming from.\u00a0 The easiest way I know of for finding that information is to use dtrace<\/a>:<\/p>\n
$ sudo dtrace -n 'mach_kernel::wakeup { @[ustack()] = count(); }'\r\n<\/pre>\n
It’s worth breaking down what’s going on in the above.<\/p>\n
    \n
  1. The mach_kernel::wakeup<\/code> bit selects a probe point in dtrace parlance.\u00a0 mach_kernel<\/code> is the “module name” and wakeup<\/code> is the “probe name”.\u00a0 You can see a complete list of probes by running sudo dtrace -l<\/code>.<\/li>\n
  2. The bits between the braces are the actions to run when the probe point is hit.\u00a0 In our example, we’re counting unique stack traces when wakeups occur; ustack<\/code> is short for “user stack”, i.e. the stack of the userspace program executing.<\/li>\n<\/ol>\n
    (dtrace is a pretty snazzy tool; it’s worth checking out Brendan Gregg’s DTrace Tools<\/a> or FreeBSD’s DTrace tutorial<\/a> if you’re at all interested by the above script.)<\/p>\n
    Running the above on my system for several seconds gives stack traces like the following:<\/p>\n
                  libsystem_kernel.dylib`mach_msg_trap+0xa\r\n              CoreFoundation`CFRunLoopWakeUp+0xab\r\n              XUL`nsAppShell::ScheduleNativeEventCallback()+0x3c\r\n              XUL`non-virtual thunk to nsBaseAppShell::OnDispatchedEvent(nsIThreadInternal*)+0x26\r\n              XUL`nsThread::PutEvent(nsIRunnable*, nsThread::nsNestedEventTarget*)+0x95\r\n              XUL`nsTimerImpl::PostTimerEvent(already_AddRefed)+0x229\r\n              XUL`TimerThread::Run()+0x283\r\n              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8\r\n              XUL`NS_ProcessNextEvent(nsIThread*, bool)+0x35\r\n              XUL`mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)+0x11b\r\n              XUL`MessageLoop::Run()+0x4d\r\n              XUL`nsThread::ThreadFunc(void*)+0x15b\r\n              libnss3.dylib`_pt_root+0xda\r\n              libsystem_pthread.dylib`_pthread_body+0x83\r\n              libsystem_pthread.dylib`_pthread_body\r\n              libsystem_pthread.dylib`thread_start+0xd\r\n               90\r\n\r\n              libsystem_kernel.dylib`__psynch_cvsignal+0xa\r\n              libnss3.dylib`pt_PostNotifies+0xb8\r\n              libnss3.dylib`PR_Unlock+0x4e\r\n              XUL`nsTimerImpl::InitCommon(unsigned int, unsigned int)+0x1f7\r\n              XUL`mozilla::PreciseRefreshDriverTimer::ScheduleNextTick(mozilla::TimeStamp)+0x215\r\n              XUL`mozilla::RefreshDriverTimer::Tick()+0x35\r\n              XUL`nsTimerImpl::Fire()+0x3e5\r\n              XUL`nsTimerEvent::Run()+0xf9\r\n              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8\r\n              XUL`NS_ProcessPendingEvents(nsIThread*, unsigned int)+0x51\r\n              XUL`nsBaseAppShell::NativeEventCallback()+0x77\r\n              XUL`nsAppShell::ProcessGeckoEvents(void*)+0x132\r\n              CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__+0x11\r\n              CoreFoundation`__CFRunLoopDoSources0+0x10d\r\n              CoreFoundation`__CFRunLoopRun+0x39f\r\n              CoreFoundation`CFRunLoopRunSpecific+0x128\r\n              HIToolbox`RunCurrentEventLoopInMode+0xeb\r\n              HIToolbox`ReceiveNextEventCommon+0x1af\r\n              HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter+0x47\r\n              AppKit`_DPSNextEvent+0x3c4\r\n              154\r\n\r\n              libsystem_kernel.dylib`mach_msg_trap+0xa\r\n              CoreGraphics`_CGSEventAppUnresponsiveStatus+0x79\r\n              CoreGraphics`CGSEventAppUnresponsiveStatus+0x38\r\n              CoreGraphics`CGSEventIsAppUnresponsive+0x13\r\n              Activity Monitor`0x000000010e918bd1+0xa76\r\n              Activity Monitor`0x000000010e9038c8+0x141\r\n              libsysmon.dylib`sysmon_table_apply+0x28\r\n              Activity Monitor`0x000000010e9032df+0x231\r\n              Activity Monitor`0x000000010e90a156+0x192\r\n              libdispatch.dylib`_dispatch_client_callout+0x8\r\n              libdispatch.dylib`_dispatch_barrier_sync_f_invoke+0x39\r\n              Activity Monitor`0x000000010e90a09b+0x91\r\n              libsysmon.dylib`__sysmon_request_execute_block_invoke_2+0xe0\r\n              libxpc.dylib`_xpc_connection_call_event_handler+0x3a\r\n              libxpc.dylib`_xpc_connection_mach_event+0x76d\r\n              libdispatch.dylib`_dispatch_client_callout4+0x9\r\n              libdispatch.dylib`_dispatch_mach_msg_invoke+0x1bd\r\n              libdispatch.dylib`_dispatch_queue_drain+0x23b\r\n              libdispatch.dylib`_dispatch_mach_invoke+0xe8\r\n              libdispatch.dylib`_dispatch_queue_drain+0x23b\r\n              176\r\n\r\n              libsystem_kernel.dylib`mach_msg_trap+0xa\r\n              CoreFoundation`CFRunLoopWakeUp+0xab\r\n              XUL`nsAppShell::ScheduleNativeEventCallback()+0x3c\r\n              XUL`non-virtual thunk to nsBaseAppShell::OnDispatchedEvent(nsIThreadInternal*)+0x26\r\n              XUL`nsThread::PutEvent(nsIRunnable*, nsThread::nsNestedEventTarget*)+0x95\r\n              XUL`nsTimerImpl::PostTimerEvent(already_AddRefed)+0x229\r\n              XUL`TimerThread::Run()+0x283\r\n              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8\r\n              XUL`NS_ProcessNextEvent(nsIThread*, bool)+0x35\r\n              XUL`mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)+0xac\r\n              XUL`MessageLoop::Run()+0x4d\r\n              XUL`nsThread::ThreadFunc(void*)+0x15b\r\n              libnss3.dylib`_pt_root+0xda\r\n              libsystem_pthread.dylib`_pthread_body+0x83\r\n              libsystem_pthread.dylib`_pthread_body\r\n              libsystem_pthread.dylib`thread_start+0xd\r\n              177\r\n\r\n              libsystem_kernel.dylib`__psynch_cvbroad+0xa\r\n              libnss3.dylib`PR_Interrupt+0x37\r\n              XUL`mozilla::HangMonitor::NotifyActivity(mozilla::HangMonitor::ActivityType)+0xe0\r\n              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3ce\r\n              XUL`NS_ProcessPendingEvents(nsIThread*, unsigned int)+0x51\r\n              XUL`nsBaseAppShell::NativeEventCallback()+0x77\r\n              XUL`nsAppShell::ProcessGeckoEvents(void*)+0x132\r\n              CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__+0x11\r\n              CoreFoundation`__CFRunLoopDoSources0+0x10d\r\n              CoreFoundation`__CFRunLoopRun+0x39f\r\n              CoreFoundation`CFRunLoopRunSpecific+0x128\r\n              HIToolbox`RunCurrentEventLoopInMode+0xeb\r\n              HIToolbox`ReceiveNextEventCommon+0x1af\r\n              HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter+0x47\r\n              AppKit`_DPSNextEvent+0x3c4\r\n              AppKit`-[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]+0xc2\r\n              XUL`-[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]+0x56\r\n              AppKit`-[NSApplication run]+0x252\r\n              XUL`nsAppShell::Run()+0xfd\r\n              XUL`nsAppStartup::Run()+0x29\r\n              201\r\n\r\n              libsystem_kernel.dylib`mach_msg_overwrite_trap+0xa\r\n              CoreGraphics`CGXRunOneServicesPass+0x282\r\n              CoreGraphics`CGXServer+0x347\r\n              WindowServer`DYLD-STUB$$CGXServer\r\n              libdyld.dylib`start+0x1\r\n              WindowServer`0x2\r\n              219\r\n<\/pre>\n
    You can see that timers going off in Firefox are a major source of wakeups (those are the stacks with TimerThread::Run()<\/code> in them).<\/p>\n
    Even with stacks causing wakeups, it’s not always obvious what sequence of events leads to those wakeups; this is especially true in the e10s era, where a particular stack ending in an IPC message send might only give you half of the picture.\u00a0 Figuring that puzzle out will help solve problems like frequently waking up when animating images with CSS<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"
    One of my Q1 goals is to investigate what can be done for cross-platform power profiling, in service of the Firefox Platform’s Project Candle.\u00a0 Roberto Vitillo already did a bit of exploration in this space last year.\u00a0 Ideally, what would come out of my research would be some sort of event counter that we could […]<\/p>\n","protected":false},"author":320,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[72425,780,5,924],"_links":{"self":[{"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/posts\/385"}],"collection":[{"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/users\/320"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/comments?post=385"}],"version-history":[{"count":0,"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/posts\/385\/revisions"}],"wp:attachment":[{"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/media?parent=385"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/categories?post=385"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.mozilla.org\/nfroyd\/wp-json\/wp\/v2\/tags?post=385"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}