Archives

Uncategorized — Comments Off on measuring power usage with power gadget and joulemeter
24
Feb 15

measuring power usage with power gadget and joulemeter

In the continuing evaluation of how Firefox’s energy usage might be measured and improved, I looked at two programs, Microsoft Research’s Joulemeter and Intel’s Power Gadget.

As you might expect, Joulemeter only works on Windows. Joulemeter is advertised as “a software tool that estimates the power consumption of your computer.” Estimates for the power usage of individual components (CPU/monitor/disk/”base”) are provided while you’re running the tool. (No, I’m not sure what “base” is, either. Perhaps things like wifi?) A calibration step is required for trying to measure anything. I’m not entirely sure what the calibration step does, but since you’re required to be running on battery, I presume that it somehow obtains statistics about how your battery drains, and then apportions power drain between the individual components. Desktop computers can use a WattsUp power meter in lieu of running off battery. Statistics about individual apps are also obtainable, though only power draw based on CPU usage is measured (estimated). CSV logfiles can be captured for later analysis, taking samples every second or so.

Power Gadget is cross-platform, and despite some dire comments on the download page above, I’ve had no trouble running it on Windows 7 and OS X Yosemite (though I do have older CPUs in both of those machines). It works by sampling energy counters maintained by the processor itself to estimate energy usage. As a side benefit, it also keeps track of the frequency and temperature of your CPU. While the default mode of operation is to draw pretty graphs detailing this information in a window, Power Gadget can also log detailed statistics to a CSV file of your choice, taking samples every ~100ms. The CSV file also logs the power consumption of all “packages” (i.e. CPU sockets) on your system.

I like Power Gadget more than Joulemeter: Power Gadget is cross-platform, captures more detailed statistics, and seems a little more straightforward in explaining how power usage is measured.

Roberto Vitillo and Joel Maher wrote a tool called energia that compares energy usage between different browsers on pre-selected sets of pages; Power Gadget is one of the tools that can be used for gathering energy statistics. I think this sort of tool is the primary use case of Power Gadget in diagnosing power problems: it helps you see whether you might be using too much power, but it doesn’t provide insight into why you’re using that power. Taking logs along with running a sampling-based stack profiler and then attempting to correlate the two might assist in providing insight, but it’s not obvious to me that stacks of where you’re spending CPU time are necessarily correlated with power usage. One might have turned on discrete graphics in a laptop, or high-resolution timers on Windows, for instance, but that wouldn’t necessarily be reflected in a CPU profile. Perhaps sampling something different (if that’s possible) would correlate better.

Uncategorized — 1 Comment
20
Feb 15

finding races in Firefox with ThreadSanitizer

We use a fair number of automated tools for memory errors (AddressSanitizer/Leak Sanitizer for use-after-free and buffer overflows; custom leak checking on refcounted objects; Valgrind tests and Julian Seward’s mochitests on Valgrind periodic testing), but we do very little in terms of checking for data races between threads.  As more and more components of the browser use threads in earnest (parts of the JavaScript engine, including the GC; graphics; networking; Web features like indexedDB, workers, and WebRTC; I have probably left out some others), preventing and/or fixing data races become more and more important as a way of ensuring both correctness and stability. One of my goals this quarter is running mochitests and reftests with ThreadSanitizer (TSan), reporting any races that it finds, and either fixing some of them myself or convincing other people to fix them.

What is a data race? Informally, data races occur when two different threads operate on the same location in memory without any synchronization between the threads. So if you do:

*ptr = 1;

in one thread and:

if (*ptr == 1) {
...
}

in another thread (without locks or similar), that’s a data race. It’s not guaranteed that the second thread will see the value written by the first thread, and if the code was written with that assumption, things can (and usually do) work as expected, but can also go badly wrong. When things do go badly wrong, it can be extremely frustrating to find the actual problem, because the problems don’t typically show up at the point where the data race happened. Of course, since the bug is dependent on caches and timing issues, the problem doesn’t always reproduce on a developer’s machine, either. You can see one of Chromium’s experiences with data races producing a common crash, and it took them nearly three months to find a fix. TSan told them exactly where to look. Google has written blog posts about their experiences using TSan with Chromium and more generally with other software they develop, including Go and their own internal tools.

When faced with evidence of a data race, people sometimes say, “well, int/long/pointer accesses are atomic, so it’s OK.” This is decidedly not true, at least not in the sense that writes to memory locations of such types are immediately visible to all threads. People sometimes try using volatile to fix the problem; that doesn’t work either (volatile says nothing about concurrent accesses between threads, or visibility of operations to other threads). Even if you think your data race is benign–that it can’t cause problems–you might be surprised at what can go wrong with benign data races. Hans Boehm, who led the effort to define the C++ memory model, has written a paper describing why there is no such thing as a benign data race at the C/C++ language level. Data races are always real bugs and are explicitly undefined behavior according to the C++ standard.

I’m not the first person to try using TSan on Firefox inside Mozilla; Christian Holler started filing bugs about races detected by TSan over a year ago.  So far, I’ve filed about 30 bugs from running “interesting” groups of mochitests: mostly mochitests under dom/ and layout/. That doesn’t sound like that many, and there are a couple reasons for that. One is that the same races tend to get reported over and over again. I’ve applied some local fixes to silence some of the really obnoxious races, but you still have to sort through the same races to find the interesting ones. (I should probably spend quality time setting up suppression files, but I’ve avoided doing that thus far for the fear of inadvertently silencing other races that I haven’t seen/reported before.) Test runs are also slow (about 10x slower than a non-TSan run), and it’s fairly common for the browser to simply hang during testing. I’ve been able to fiddle around with the mochitest harness to increase timeouts or the number of timeouts permitted, but that makes tests go even slower, as tests that do timeout take longer and longer to do so.

Fortunately, people have been responsive to the bugs I’ve filed; Honza Bambas, Valentin Gosu, and Patrick McManus on the networking side of things; Terrence Cole, Jon Coppeard, Andrew McCreight, and Shu-yu Guo on the JavaScript side of things; and Milan Sreckovic on the graphics side of things have all been fixing bugs and/or helping analyze what’s going wrong as they’ve been filed.

If you want to try out TSan locally, there’s an excellent introduction to using TSan on MDN.  I strongly recommend following the instructions for building your own, local clang; my experiences have shown that the released versions of clang don’t always work (at least with Firefox) when trying to use TSan. If you find new bugs in your favorite piece of code, please file a bug, CC me, and make it block bug 929478.

Uncategorized — 1 Comment
27
Jan 15

examples of poor API design, 1/N – pldhash functions

The other day in the #content IRC channel:

<bz> I have learned so many things about how to not define APIs in my work with Mozilla code ;)
<bz> (probably lots more to learn, though)

I, too, am still learning a lot about what makes a good API. Like a lot of other things, it’s easier to point out poor API design than to describe examples of good API design, and that’s what this blog post is about. In particular, the venerable XPCOM datastructure PLDHashTable has been undergoing a number of changes lately, all aimed at bringing it up to date. (The question of why we have our own implementations of things that exist in the C++ standard library is for a separate blog post.)

The whole effort started with noticing that PL_DHashTableOperate is not a well-structured API. It’s necessary to quote some more of the API surface to fully understand what’s going on here:

typedef enum PLDHashOperator {
    PL_DHASH_LOOKUP = 0,        /* lookup entry */
    PL_DHASH_ADD = 1,           /* add entry */
    PL_DHASH_REMOVE = 2,        /* remove entry, or enumerator says remove */
    PL_DHASH_NEXT = 0,          /* enumerator says continue */
    PL_DHASH_STOP = 1           /* enumerator says stop */
} PLDHashOperator;

typedef PLDHashOperator
(* PLDHashEnumerator)(PLDHashTable *table, PLDHashEntryHdr *hdr, uint32_t number,
                      void *arg);

uint32_t
PL_DHashTableEnumerate(PLDHashTable *table, PLDHashEnumerator etor, void *arg);

PLDHashEntryHdr*
PL_DHashTableOperate(PLDHashTable* table, const void* key, PLDHashOperator op);

(PL_DHashTableOperate no longer exists in the tree due to other cleanup bugs; the above is approximately what it looked like at the end of 2014.)

There are several problems with the above slice of the API:

  • PL_DHashTableOperate(table, key, PL_DHASH_ADD) is a long way to spell what should have been named PL_DHashTableAdd(table, key)
  • There’s another problem with the above: it’s making a runtime decision (based on the value of op) about what should have been a compile-time decision: this particular call will always and forever be an add operation. We shouldn’t have the (admittedly small) runtime overhead of dispatching on op. It’s worth noting that compiling with LTO and a quality inliner will remove that runtime overhead, but we might as well structure the code so non-LTO compiles benefit and the code at callsites reads better.
  • Given the above definitions, you can say PL_DHashTableOperate(table, key, PL_DHASH_STOP) and nothing will complain. The PL_DHASH_NEXT and PL_DHASH_STOP values are really only for a function of type PLDHashEnumerator to return, but nothing about the above definition enforces that in any way. Similarly, you can return PL_DHASH_LOOKUP from a PLDHashEnumerator function, which is nonsensical.
  • The requirement to always return a PLDHashEntryHdr* from PL_DHashTableOperate means doing a PL_DHASH_REMOVE has to return something; it happens to return nullptr always, but it really should return void. In a similar fashion, PL_DHASH_LOOKUP always returns a non-nullptr pointer (!); one has to check PL_DHASH_ENTRY_IS_{FREE,BUSY} on the returned value. The typical style for an API like this would be to return nullptr if an entry for the given key didn’t exist, and a non-nullptr pointer if such an entry did. The free-ness or busy-ness of a given entry should be a property entirely internal to the hashtable implementation (it’s possible that some scenarios could be slightly more efficient with direct access to the busy-ness of an entry).

We might infer corresponding properties of a good API from each of the above issues:

  • Entry points for the API produce readable code.
  • The API doesn’t enforce unnecessary overhead.
  • The API makes it impossible to talk about nonsensical things.
  • It is always reasonably clear what return values from API functions describe.

Fixing the first two bulleted issues, above, was the subject of bug 1118024, done by Michael Pruett. Once that was done, we really didn’t need PL_DHashTableOperate, and removing PL_DHashTableOperate and related code was done in bug 1121202 and bug 1124920 by Michael Pruett and Nicholas Nethercote, respectively. Fixing the unusual return convention of PL_DHashTableLookup is being done in bug 1124973 by Nicholas Nethercote. Maybe once all this gets done, we can move away from C-style PL_DHashTable* functions to C++ methods on PLDHashTable itself!

Next time we’ll talk about the actual contents of a PL_DHashTable and how improvements have been made there, too.

Uncategorized — 1 Comment
07
Jan 15

profiling for wakeups on osx

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.  Roberto Vitillo already did a bit of exploration in this space last year.  Ideally, what would come out of my research would be some sort of event counter that we could hook into the Gecko Profiler.  Failing that, it would at least be good to document what is possible for power profiling on each of our supported platforms.

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

$ sudo powermetrics

at a Terminal prompt and you will periodically (every five seconds by default) see a large amount of information concerning power usage printed.  The default data sources that powermetrics draws from includes things like detailed C-state usage for all available processors.  For my purposes, I’m just interested in what applications are waking up most frequently.  powermetrics supports limiting its data sources with the –samplers switch:

$ sudo powermetrics --samplers tasks

will just display interesting information on all currently running tasks in the system.  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:

$ sudo powermetrics --samplers tasks --show-process-energy

The numbers from powermetrics 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.

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.  The easiest way I know of for finding that information is to use dtrace:

$ sudo dtrace -n 'mach_kernel::wakeup { @[ustack()] = count(); }'

It’s worth breaking down what’s going on in the above.

  1. The mach_kernel::wakeup bit selects a probe point in dtrace parlance.  mach_kernel is the “module name” and wakeup is the “probe name”.  You can see a complete list of probes by running sudo dtrace -l.
  2. The bits between the braces are the actions to run when the probe point is hit.  In our example, we’re counting unique stack traces when wakeups occur; ustack is short for “user stack”, i.e. the stack of the userspace program executing.

(dtrace is a pretty snazzy tool; it’s worth checking out Brendan Gregg’s DTrace Tools or FreeBSD’s DTrace tutorial if you’re at all interested by the above script.)

Running the above on my system for several seconds gives stack traces like the following:

              libsystem_kernel.dylib`mach_msg_trap+0xa
              CoreFoundation`CFRunLoopWakeUp+0xab
              XUL`nsAppShell::ScheduleNativeEventCallback()+0x3c
              XUL`non-virtual thunk to nsBaseAppShell::OnDispatchedEvent(nsIThreadInternal*)+0x26
              XUL`nsThread::PutEvent(nsIRunnable*, nsThread::nsNestedEventTarget*)+0x95
              XUL`nsTimerImpl::PostTimerEvent(already_AddRefed)+0x229
              XUL`TimerThread::Run()+0x283
              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8
              XUL`NS_ProcessNextEvent(nsIThread*, bool)+0x35
              XUL`mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)+0x11b
              XUL`MessageLoop::Run()+0x4d
              XUL`nsThread::ThreadFunc(void*)+0x15b
              libnss3.dylib`_pt_root+0xda
              libsystem_pthread.dylib`_pthread_body+0x83
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd
               90

              libsystem_kernel.dylib`__psynch_cvsignal+0xa
              libnss3.dylib`pt_PostNotifies+0xb8
              libnss3.dylib`PR_Unlock+0x4e
              XUL`nsTimerImpl::InitCommon(unsigned int, unsigned int)+0x1f7
              XUL`mozilla::PreciseRefreshDriverTimer::ScheduleNextTick(mozilla::TimeStamp)+0x215
              XUL`mozilla::RefreshDriverTimer::Tick()+0x35
              XUL`nsTimerImpl::Fire()+0x3e5
              XUL`nsTimerEvent::Run()+0xf9
              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8
              XUL`NS_ProcessPendingEvents(nsIThread*, unsigned int)+0x51
              XUL`nsBaseAppShell::NativeEventCallback()+0x77
              XUL`nsAppShell::ProcessGeckoEvents(void*)+0x132
              CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__+0x11
              CoreFoundation`__CFRunLoopDoSources0+0x10d
              CoreFoundation`__CFRunLoopRun+0x39f
              CoreFoundation`CFRunLoopRunSpecific+0x128
              HIToolbox`RunCurrentEventLoopInMode+0xeb
              HIToolbox`ReceiveNextEventCommon+0x1af
              HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter+0x47
              AppKit`_DPSNextEvent+0x3c4
              154

              libsystem_kernel.dylib`mach_msg_trap+0xa
              CoreGraphics`_CGSEventAppUnresponsiveStatus+0x79
              CoreGraphics`CGSEventAppUnresponsiveStatus+0x38
              CoreGraphics`CGSEventIsAppUnresponsive+0x13
              Activity Monitor`0x000000010e918bd1+0xa76
              Activity Monitor`0x000000010e9038c8+0x141
              libsysmon.dylib`sysmon_table_apply+0x28
              Activity Monitor`0x000000010e9032df+0x231
              Activity Monitor`0x000000010e90a156+0x192
              libdispatch.dylib`_dispatch_client_callout+0x8
              libdispatch.dylib`_dispatch_barrier_sync_f_invoke+0x39
              Activity Monitor`0x000000010e90a09b+0x91
              libsysmon.dylib`__sysmon_request_execute_block_invoke_2+0xe0
              libxpc.dylib`_xpc_connection_call_event_handler+0x3a
              libxpc.dylib`_xpc_connection_mach_event+0x76d
              libdispatch.dylib`_dispatch_client_callout4+0x9
              libdispatch.dylib`_dispatch_mach_msg_invoke+0x1bd
              libdispatch.dylib`_dispatch_queue_drain+0x23b
              libdispatch.dylib`_dispatch_mach_invoke+0xe8
              libdispatch.dylib`_dispatch_queue_drain+0x23b
              176

              libsystem_kernel.dylib`mach_msg_trap+0xa
              CoreFoundation`CFRunLoopWakeUp+0xab
              XUL`nsAppShell::ScheduleNativeEventCallback()+0x3c
              XUL`non-virtual thunk to nsBaseAppShell::OnDispatchedEvent(nsIThreadInternal*)+0x26
              XUL`nsThread::PutEvent(nsIRunnable*, nsThread::nsNestedEventTarget*)+0x95
              XUL`nsTimerImpl::PostTimerEvent(already_AddRefed)+0x229
              XUL`TimerThread::Run()+0x283
              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3d8
              XUL`NS_ProcessNextEvent(nsIThread*, bool)+0x35
              XUL`mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)+0xac
              XUL`MessageLoop::Run()+0x4d
              XUL`nsThread::ThreadFunc(void*)+0x15b
              libnss3.dylib`_pt_root+0xda
              libsystem_pthread.dylib`_pthread_body+0x83
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd
              177

              libsystem_kernel.dylib`__psynch_cvbroad+0xa
              libnss3.dylib`PR_Interrupt+0x37
              XUL`mozilla::HangMonitor::NotifyActivity(mozilla::HangMonitor::ActivityType)+0xe0
              XUL`nsThread::ProcessNextEvent(bool, bool*)+0x3ce
              XUL`NS_ProcessPendingEvents(nsIThread*, unsigned int)+0x51
              XUL`nsBaseAppShell::NativeEventCallback()+0x77
              XUL`nsAppShell::ProcessGeckoEvents(void*)+0x132
              CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__+0x11
              CoreFoundation`__CFRunLoopDoSources0+0x10d
              CoreFoundation`__CFRunLoopRun+0x39f
              CoreFoundation`CFRunLoopRunSpecific+0x128
              HIToolbox`RunCurrentEventLoopInMode+0xeb
              HIToolbox`ReceiveNextEventCommon+0x1af
              HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter+0x47
              AppKit`_DPSNextEvent+0x3c4
              AppKit`-[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]+0xc2
              XUL`-[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]+0x56
              AppKit`-[NSApplication run]+0x252
              XUL`nsAppShell::Run()+0xfd
              XUL`nsAppStartup::Run()+0x29
              201

              libsystem_kernel.dylib`mach_msg_overwrite_trap+0xa
              CoreGraphics`CGXRunOneServicesPass+0x282
              CoreGraphics`CGXServer+0x347
              WindowServer`DYLD-STUB$$CGXServer
              libdyld.dylib`start+0x1
              WindowServer`0x2
              219

You can see that timers going off in Firefox are a major source of wakeups (those are the stacks with TimerThread::Run() in them).

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.  Figuring that puzzle out will help solve problems like frequently waking up when animating images with CSS.

Newer Entries →