Monthly Archives: April 2009

displaying execution traces on a SIMILE timeline

Posted on by

chronimoz-timeline-1

chroniquery can now output JSON for display using the SIMILE timeline widget.  And I am finally done trying to figure out what was going wrong.  Click the pictures to experience the timeline sensation for yourself.

Related interesting things:

  • Supports a fancy if specific constraint mechanism.  For example, PrepareAndDispatch is only displayed in the context of nsTimerImpl::Fire using the following line in the config file:
[func@PrepareAndDispatch]
only_show_if=backtrace,4,nsTimerImpl::Fire
  • Supports displaying arguments in the title using the config file.  For example, displaying the observer service’s topic (plus putting it in its own band and giving it a nice prefix):
[class@nsObserverService]
prefixAlias=Obs:
band=context
list_args=aTopic
  • We actually get the dump() output by logging where _IO_fputs shows up.  We constrain its output by adding an extensible (if currently somewhat specialized) argument-based constraint.
  • Things in red are red because their return codes were exceptional, per my last blog post.  Things in other colors are that way because of the config file.
  • The bubbles that show up when you click on things tell you the return value and arguments for the call in question.  We could include a backtrace, but they are expensive to compute (currently), so I don’t.
  • All layout is using the timeline widget’s layout.  There is no correspondence between stack depth and anything else.

chronimoz-timeline-2

An important limitation is that all functions displayed here were explicitly chosen for display.  Some form of automated mechanism could be used, but unless chronicle-query starts caching more things, it would be really slow.  Here’s the command-line used for the above:

chron-xpc mozrun-9022.db jsontrace -t 1 -f nsObserverService::NotifyObservers -f nsThread::ProcessNextEvent -f nsTimerImpl::Fire -f nsMsgSearchSession::NotifyListenersDone -f nsMsgDBFolder::Shutdown  -f nsMsgLocalMailFolder::AddMessage -f nsMsgDatabase::Open -f nsMsgDatabase::ForceClosed -f nsMsgLocalMailFolder::GetDatabaseWithReparse -f nsMsgDBFolder::OnAnnouncerGoingAway -f nsMsgDBFolder::AddSubfolder -f nsMsgSearchOfflineMail::OpenSummaryFile -f nsMsgSearchSession::TimerCallback -f nsMsgSearchSession::TimeSlice -f nsMsgSearchSession::TimeSliceSerial -f nsMsgSearchScopeTerm::TimeSlice -f nsMsgXFVirtualFolderDBView::Open -f nsMsgXFVirtualFolderDBView::OnNewSearch -f nsMsgXFVirtualFolderDBView::OnSearchDone  -f js_GC -f PrepareAndDispatch -f nsMsgLocalMailFolder::UpdateFolder -f _IO_fputs

understanding where unit tests go wrong with object diffs

Posted on by

chronimoz-diff-1

In our last chroniquery adventure, we used roc‘s chronicle-recorder to trace the execution of an xpcshell unit test and chroniquery (repo info) to use that trace to help us understand what was happening in some particularly confusing C-ish code.  Actually, we’re doing that this time too, but the bag of tricks now contains additional tricks.

The exciting things happening in the screenshot above, in order of increasing awesomeness:

  • The argument list is exposing out-parameters (via a heuristic though, it doesn’t know the XPCOM details.)  ex: “*folderInfo: 0x0” used to be “folderInfo: some pointer to hold an out-parameter that leaves us none the wiser.”
  • Chronifer now sees through ‘this’-adjusting trampolines/wrappers.  Previously, function calls might be hidden because the stack pointer change that chronicle uses to determine function calls jumped to the trampoline whose bytecode was not associated with the actual function being called, and so would potentially be assumed to be boring.  The trampoline would modify rdi then perform a trivial jump (it could have just fallen through) into the function proper, which the existing trampoline detector would not notice.  (That detector only would notice an instant jump of more than 128 bytes; intended for dynamic linking indirection purposes.)
  • Pretty printers allow us to translate nsresult error codes to strings, display the strings referenced by nsString/nsCString instead of the raw structure (mData/mLength/mFlags), pierce nsCOMPtr’s, etc.
  • Pretty printers allow us to detect exceptional values and show them in red!  For example, that NS_ERROR_INVALID_POINTER is red because the nsresult pretty printer’s is_exceptional method returned True because the error bit was high.
  • The configuration method that lets us say what directories/files/classes/functions are interesting/boring has been augmented to let us specify arguments and the sub-fields of arguments to dump.  For example, in the above screenshot, we have added “dump_this=True” to the section labeled “[class@nsMsgLocalMailFolder]”.  As a result, any time a method is called on nsMsgLocalMailFolder, we dump the contents of its ‘this’.  If we only wanted a few fields from “this”, we could have used “dump_this=mPath,mIsServer,mName,mURI” instead.  You can see the end of a full object dump at the top of the screenshot.
  • The object dump output is diffed against the result of previous calls.  This is why we have that text in yellow.  The first entire GetDBFolderInfoAndDB call you see on the screen is a succesful call (no red!) diffed against a previous successful call.  Mainly we see the name-derived things changing and things we expect to be distinct (file path, database).  Then we have an error case, with a few things we probably would not have noticed if we were doing this by hand.  I was somewhat surprised that mHaveParsedURI, the reference count, and m_numOfflineMsgLines showed up.  The others are not entirely shocking, but it’s useful to have them all there.  Without the diff, we would be looking at 65 lines of attribute values, and that is with us already benefitting from the pretty printers.

Exciting possibilities opened by enhancements here:

  • The pretty printers and internal cleanups/refactoring make it feasible to express complicated data-based constraints simply.  For example, with a tractable amount of work I could opt to only see calls on the folder named “gabba3” using the constraint “mURI == ‘mailbox://nobody@Local%20Folders/gabba0′”.  This could be made particularly efficient if we make an assumption that the attribute is invariant once observed and then allow us to key off the pointer/memory region.
  • Code-sharing of pretty printers between my chroniquery code and my archer gdb plugins.
  • Now that archer-gdb has python inferior control, potential use of archer-gdb as an alternate back-end to chroniquery.
  • It would be neat to be able to expose chroniquery’s functionality via a web interface so that things could be expanded/drilled down without having to re-run things.  This would also help offset the non-trivial startup costs to chronicle-recorder’s own chronicle-query.  (Although arguably the startup time is nothing compared to the inefficiency of all the work chronicle-query does for a call and throws away when the next call pretty much wants that same data.)

gaudily syntax-highlighted code listings in (archer) gdb

Posted on by

pyglist sl command output

Gaudily syntax-highlighted code listing in gdb joins the gaudy gdb plugin family!  (Other members include gaudily colorized backtraces, which you can also see in the bottom of the screenshot.)  This, of course, requires gdb with python crammed inside.  It might require one crammed a few months ago too; I haven’t updated my archer-gdb repo for at least that long.

The “sl” plugin uses Pygments for the syntax highlighting.  Although pygments has a 256 color terminal formatter (woo!), I ended up using my pyflam module because it did not support my need to color the background of the current line without doing something convoluted.  (I would have had to create a filter that did its own line-counting and created background-color-styled token variant of every token on the desired line.)  Also, it didn’t do line numbers.

The color theme is based off the “fruity” color theme.  Much of the gaudy comes from a filter I added that tries to do various Mozilla C++-aware code styling things by recognizing naming patterns of Name tokens.  Before you complain about the colors hurting your brain, remember that this is the alternative:

not-pyglist, standard list command

That’s right.  It’s like looking at static.  You can barely make anything out.  And imagine if it was more than just the 10 lines “list” gives you.

Anywho, the repo is here: http://hg.mozilla.org/users/bugmail_asutherland.org/pythongdb-gaudy/

The README tells you what to do.  For complete-ness, and because I went to all the effort to write documentation for the command, here is what it does!

Prints a syntax-highlighted source listing.  Currently limited to only
work based on the current debug frame and position.

By default, the 11 lines before the current position and 8 lines after are
displayed.  A line context is saved between command invocations if the current
source line does not change.

Arguments when used in a new context:
  (none)  Shows the 11 lines before the current position and 8 lines after.
  N       Shows the N/2 lines befores the current position and N/2 lines after.
  -N      Shows the N lines before the current position and 8 lines after.
  +N      Shows the 11 lines before the current position and N lines after.
  M N     Shows the M lines before the current position and N lines after.

Arguments in an existing context:
  (none)  Shows the 20 lines after the last-shown lines.
  -       Shows the 20 lines preceding the last-shown lines.
  N       Shows the N lines after the last-shown lines.
  -N      Shows the N lines preceding the last-shown lines.
  M N     Shows the M last lines of the last-shown lines and N lines after the
            last-shown lines.

Arguments regardless of context
  @A,B    Shows lines A through B.

thunderbird, gloda, exptoolbar, protovis, paninaro, oh oh oh

Posted on by

exptoolbar-protovis-gloda-256

Thunderbird.  With the global database, gloda.  Using the exptoolbar extension.  Using the protovis javascript visualization library.  For reals!  Not a prank!  Just grab the most recent XPI or grab the repo.  And be using a nightly (beta 2 might work?)

What you are looking at:

  • The exptoolbar search results page, augmented with a visualization.
  • Each conversation with search results gets its own wedge.
    • Wedges can be distinguished because of the alternating background colors.
    • Conversations that you sent a message to will have a red shading to them.  The examples may be somewhat misleading because the account where a lot of my sent mail ends up is not part of the profile used to create the screenshots.
  • Each message is placed in its conversation wedge…
    • The radius is based on the ‘age’ of the message using a log-ish scale.  Interpolation is actually linear at each level (one day, one week, one month, three months, one year, 5 years, ‘forever’.)
    • The angular placement within the wedge is based on the author of the message.  Across all wedges the placement is the same.  This helps ‘bursty’ parts of conversations (which are extremely likely) be made more obvious, while also helping to provide some understanding of conversation dynamics.
  • Message shapes are determined by whether the message is starred (diamond), sent by a ‘popular’ contact (circle), or an unpopular one (cross).  The use of popularity is a temporary measure because current gloda in trunk does not cache address-book lookups, and they are expensive.  Once the new gloda search code lands with those changes, we can rely on the existence of an address book entry.  (Starring a contact using the new message reader adds them to your address book.)
  • Message opacity is determined by whether the message is a ‘hit’ or not.  All messages in a conversation are eventually retrieved, though initially we only have the hits.
  • Message color is determined by applied tags (using the closest tango color for the first tag), or whether the message is starred (closest tango color to yellow, where I think I had removed the yellow tango colors for some unknown reason, so we get green I guess).  It’s grey if the message has no tag or star.
  • The subject of the conversation is displayed in the wedge.

exptoolbar-protovis-seek-thunderbird-256

Things that are happy:

Things that are sad (aka caveats):

  • It would probably be better if the visualization was not radar-inspired.  Besides the perceptual reasons, the subjects are harder to read than they would be in an equivalent linear-styled visualization.
  • The visualization is not interactive.  protovis officially has no interaction support yet, but if you look in the (only available minified?) source, it’s almost there.  It might be entirely there, but it didn’t work for me immediately after a quick reading of the (indented) source.
  • There is some low probability failure that occurs during the visualization updating as gloda backfills the message collections.  If it happens on the last update, you can end up with a half-built visualization.  Re-running the search will generally resolve the issue.
  • The visualization does a pretty solid job of taking up all the screen real estate and has no way to be disabled, so you have to scroll past it every time.

Future work:

  • Interactivity.
  • Perhaps showing the gravatars for the people involved in a conversation at the outer rim of the wedge, positioning them based on the author positioning we determined.
  • Perhaps lose the radar motif.
  • Your thoughts / patches!