Tag Archives: utrace

more systemtap mozilla event loop awareness

Posted on by 
====================                                             ms    #
----- Event Loop:
  nsInputStreamReadyEvent                                      7119   11
----- Input Events:
  nsInputStreamPump                                            7119   11
----- Pump Events:
  thunk:nsNNTPProtocol::QueryInterface(...)                    7119   11

====================                                             ms    #
----- Event Loop:
  nsInputStreamReadyEvent                                      6284   15
  nsTimerEvent                                                  242  123
----- Timers:
  nsUITimerCallback                                             121    2
----- Input Events:
  nsInputStreamPump                                            6284   15
----- Pump Events:
  thunk:nsNNTPProtocol::QueryInterface(...)                    6283   15

As of late, I’ve noticed that Thunderbird has been pegging one of my CPU cores periodically in ways not correlated with gloda activity, the usual scapegoat.  With some enhancements to my systemtap script from last time, I can now see that it apparently takes something like 13 seconds of dominating the event loop to perform the check for new messages in my 26 subscribed news folders on news.mozilla.org.  Yowch.  At least this is on a debug build!

Changes are that we now cover input stream ready events, input pump listeners, and proxied objects (which lets us see what Thunderbird IMAP gets up to).  Also, the output is more concise and only shows things that take at least 100ms of aggregate wall clock time.

Script invocation currently wants to look like this:
sudo stap -v moz-event-loop.stp /path/to/thunderbird/objdir/mozilla/dist/lib/libxpcom_core.so /path/to/thunderbird/objdir/mozilla/dist/bin/components/libnecko.so | ../addrsymfilt.py `pgrep thunderbird-bin`

Using systemtap to figure what your mozilla app’s event loop is up to

Posted on by 
====================                                             ms    #
----- Event Loop:
  nsTimerEvent                                                 1233   31
  nsProxyObjectCallInfo                                          19   44
  nsStreamCopierOB                                                1   48
  nsStreamCopierIB                                                0   18
  nsProxyCallCompletedEvent                                       0   44
  nsProxyReleaseEvent                                             0   27
  nsTransportStatusEvent                                          0   19
  nsSocketEvent                                                   0   18
  nsHttpConnectionMgr::nsConnEvent                                0    1
----- Timers:
  OnBiffTimer(...)                                             1129    3
  nsGlobalWindow::TimerCallback(...)                             70   10
  nsAutoSyncManager::TimerCallback(...)                          29    6
  nsExpirationTracker::TimerCallback(...)                         1    1
  nsIdleService::IdleTimerCallback(...)                           0    5
  nsExpirationTracker::TimerCallback(...)                         0    1
  nsHttpHandler                                                   0    1
  nsUITimerCallback                                               0    2
  imgContainer::sDiscardTimerCallback(...)                        0    1
  nsExpirationTracker::TimerCallback(...)                         0    1

That’s one of the periodic outputs (10 seconds currently) of this systemtap script filtered through this python script to translate addresses to useful symbol names in realtime.  It’s like top for mozilla.

Actual invocation looks like so:
sudo stap -v moz-event-loop.stp /path/to/thunderbird/objdir/mozilla/dist/lib/libxpcom_core.so | ../addrsymfilt.py `pgrep thunderbird-bin`

The giant caveat (and giant hooray for utrace and Fedora having kernels with the utrace patches built-in) is that the magic in here is done dynamically using utrace source line probes.  As such, the probes aren’t resilient in the face of changes to the underlying source files; the current line numbers are targeted at 1.9.2.  There are various in-tree and out-of-tree solutions possible.