Fun and games with assembly

This is a problem that came up during my research. Suppose I have a function foo whose assembly looks like the following:

foo:
  mov global($rip), %rax
  mov (%rax), %rax
  retq

Are the following two lines of code equivalent?

  /* defines somewhere */
  int val;
  extern int foo(void);
  /* actual code */
  asm("callq foo" : "=a"(val));
  val = foo();

The answer, as you might guess by the fact that I'm writing this post, is "no." The reason why is a lot more complex. In the case that caused me endless toil and grief, the function foo is not located in the same executable as the caller; it is in an external library file. Now, the platform ABI allows functions to clobber a fair number of registers which callers must assume are unusable. If the loader needs to perform work when calling a global relocated function, then it is a good idea to use those registers where possible, since you don't need to bother saving those values. When the asm construct is invoked, we've declared that only the return register is clobbered, so the compiler is free to store some values over the call. When the function call is direct and doesn't need to go through the GOT or anything similar, this is perfectly fine and works as one would expect. But if you need to invoke the loader when calling through the GOT, then you now have registers whose values have suddenly mysteriously changed on you when calling a function which doesn't (appear to) use them. Hope you have more fun debugging those cases than I did!

Achievement Unlocked: Use 100GB of memory in a single process

I discovered that the compiler I was using last night managed to run out of memory while compiling some code. This was on our research group's server which has a whopping 128GB of memory. And by "ran out of memory", I literally watched in top as clang went from dozens of megabytes of memory to 120GB of memory, evict everything from the cache and thrash swap like crazy before the out-of-memory killer decided it ought to go.

What was I doing? No, I wasn't linking the source code to the universe; I was merely compiling a file in the Spec 2006 benchmarks. And this wasn't anything large--only 3700 lines of code or so in a single C++ file. And the pass that wasn't dying wasn't some horribly written pass that leaked memory like a leaky bucket. Indeed, LLVM tends to get you to free memory too quickly, judging by how many times I've chased down memory corruption. If you don't believe me, the offending code was this:

    Code = CloneBasicBlock(CodeOrig, ValMap, "", F, NULL);
    for (II = Code->begin(), EE = Code->end(); II != EE; ++II) {
      if (!isa(II))
        RemapInstruction(II, ValMap, RF_IgnoreMissingEntries);
    }

For those of you who don't know what the code is doing, it roughly amounts to this: make a copy of a basic block of a function, and then tell all of the instructions to use the new instructions instead. On some programs, though, this simple instruction seems to have compelled the code to eat up gigabytes of memory.

Fortunately, I am now proud to announce that I have reduced my memory consumption by 99%… with a one-line fix. So I guess I should get the achievement for "Fix the Memory Leak" as well?

How bugs get fixed

Recently, I have had the misfortuneopportunity to fix bug 695309. This bug is perhaps a good exemplar of why "obvious" bugs take weeks or months to fix; it is also a good example of why just reporting that a bug occurs for the filer is insufficient to fix. In the hope that others might find this useful, I will explain in a fake liveblogging format how I fixed the bug (fake because I'm writing most of these entries well after they happened).

October 20

There's a bug that "Thunderbird sometimes marks entire newsgroups as unread" in my email. Time to open up the bug report… reported in version 8… I'm pretty sure I've seen this once or twice before, so I don't think it's just a "the news server borked itself" issue. Time to file it away until when I have more time.

November 12

Another comment reminded me that I have this tab open. I've definitely seen it a few times, but I need to remember to keep Thunderbird open with logging enabled to figure out what's going on. It's reported as being a regression from version 8, when I checked in a slew of the NNTP URI parsing patches, so that seems like a probable target to look at. The question is why URI parsing would be causing an intermittent problem instead of a constant issue?

December 3

Some NNTP logs. Nothing is obviously amiss (not terribly unexpected, since logging either tends to drown you in useless information or omit the things you really want to know). Note after the fact: the NNTP logs in fact contain the smoking gun; it's just that the poster trimmed it out.

December 6

Bienvenu comments that no developer has seen the problem; this isn't true, as I have seen it (but just taken to avoiding it as much as possible). At some point in time, I figured out that the issue could be avoided by shutting down Thunderbird before putting my laptop to sleep. After being prodded over IRC, I finally sat down and attempted to debug it. The working thesis is that the problem is that newsrc files are getting corrupted, so I faithfully save several copies of the newsrc for confirmation. The msf files are also generally good candidates, but since other flags are untouched, it's highly unlikely in this bug.

I successfully trigger the bug once. The reports are mixed: the newsrc didn't get trashed as expected at first, but later it did. However, there is a brief window of time after the bug happens which allows you to fix it, if you shut down Thunderbird. Knowing what I now know, this is because the newsrc file is written out on a timer, so the newly-all-unread messages wouldn't have been saved to disk to show the bug. Since I always think of what to log after the fact, I try to trigger it a few more times.

None of the later tests are quite so successful as the first one. It does start to dawn on me that the bug probably has two parts. There is a first step that puts the group into a pre-bug situation; a second step actually produces the symptoms of the bug. Omniscient addendum: the first step is where the bug happens; the second step is just the delay in getting the bug to occur. I report my findings, and subsequent comments all but confirm my hypothesis for a necessary component.

December 12

This bug seems to be happening for me only when I don't want it to happen. I thought of more things to test earlier, and had them ready to copy-paste into my error console to try to find a smoking gun. This test confirms that the fault originates with the newsrcLine (so something reset that); more investigation leads to only one truly likely scenario to cause this to happen. At this point, I am all but convinced that the bug happens in two parts. All of the debugging needs to focus on when the first part happens; the symptoms (everything being marked read) are a result of Thunderbird attempting to repair the damage that had already been done. Since most people are going to try to report based on when they see the problems, I'm probably not going to get anything useful.

December 13

Hey, I found it again. Tests confirm that the high water number was first set to 0. This means either we have memory corruption or we are setting the value incorrectly initially. Looking at the code, this is set from a call to sscanf. A simple test indicates that I can set the input value to 0 if I don't have it scan a number. Now all I need to do is figure out network traffic that can cause this. Time to try to trigger it with xpcshell tests. And then get frustrated because I still can't do it reliably.

December 18

With Wireshark (logging on Windows is rather annoying), I finally can track down the network traffic of interest. It turns out that we are off-by-one in terms of responses. This really should be enough to get xpcshell to report the error. However, it also means I probably should finally give up and go for the NNTP logs again to catch the error: it is painfully obvious that the problem is that the internal state is futzed up. This also means that other various newly-reported issues (more frequent auth failures, various alerts like "Not in a newsgroup", etc.) are pretty much confirmed to be the same bug.

January 9

I finally buckled down and turned my very old hackish code for NSPR log management into an extension. This means that I don't have to futz with environment variables on Windows, and it also gives me an easy way to trim down my log size (since unlike environment variables, I can stop logging). I test and finally get the NNTP log of interest.

Now that I have a log, I can try to work backwards and figure out how this bug happens. The failure is easily ascribable to somehow thinking we've already opened the socket when we open a socket; this much I have known for almost a month (the Wireshark told me). What the NNTP log gives me is a more fine-grained ability to try to trace the code after-the-fact to figure out where the bug is.

Working backwards from the log

NNTP logs helpfully record the address of the the NNTP protocol object when emitting output, so the best place to start is from the first line of that object. Since the numbers are hard to read, so I replace the addresses with a more obvious string like "evil." The next state was set to SEND_FIRST_NNTP_COMMAND—that clearly should be NNTP_LOGIN_RESPONSE, so let's see why it might be skipped. The latter is set if m_socketIsOpen is false, so perhaps someone could open a socket if it isn't set.

This variable is set only by nsMsgProtocol, specifically the LoadUrl method. So who might call that? Still nothing out of the ordinary is popping out at me, so it's time to return to the logs (A particularly astute developer might be able to find out the bug without returning to the log here, but I doubt most people would come up with the final flash of insight yet).

To figure out the problem, it's important (to me, at least) to set out the time frames. The natural sequence of events for a connection is to be created, connected to the server, and then go through several iterations of running URLs. Is this bad connection a new connection or an old one (since I started the log after TB started up, I can't guarantee that this is truly a new connection)? Thunderbird stupidly (but helpfully, in this case) tells me when the connection is created, since we get a log message of "creating" in the constructor. Since this message doesn't appear, it's being reused.

Wait—that message is there, tucked just underneath the lines that tell me LoadUrl is run. As I am often wont to do, I announce my revelation to IRC: "< jcranmer> bienvenu: please slap me". The code for the constructor is pretty simple, but there is one little function call that ends up causing the problem. If I tell you the exact revision that caused the regression (specifically, the first hunk of that the patch), can you find the regression? Click me if you can't

Reproducing the bug

Now that I know the exact sequence of events to cause the bug, I can write a test to reliably reproduce the bug. I can also explain why the symptoms occur. First, a connection's socket dies, but it doesn't fail the timeout check in mailnews code, so it remains in the cache. Next, the server schedules a URL on the connection, which promptly dies. If there are many more URLs to be run (when we're doing, say, a timed update), then we have several elements in the queue waiting to be processed. Now, we attempt to run a new URL; with no connections available in the cache, we now create a new connection and run the new URL on that. Since the queue is not empty, the SetIsBusy(false) call ends up pulling a queued URL and setting up the state (including opening up the connection) and running that. Then the constructor finishes, and the new URL for which the connection was constructed is used to initialize it. Since the connection is by now open, the code moves straight to the run-my-URL part of the state machine, which misinterprets the login response as the answer to the command it just sent. This ends up leading to all of the various badness subsequently observed.

The description of these events is pretty complicated. A condensed version is added to the test I constructed to get this to happen, which is called, fittingly enough, test_bug695309.js. I am not going to try to come up with a better name, as I think most people might agree that this is where naming tests after bug numbers is most desirable. Naturally, the code to actually trigger this is complicated: I started with code to trigger just the unread effect, and then switched to monitoring the highwater mark instead (one less download of messages). I need to fill up the connection cache and then figure out how to kill the connections (restarting the server seems to do an adequate job). After that, I need to run enough URLs to cause the connections to queue, and then trigger a load of the folder in question at precisely the right moment. All of these requires paying careful attention to what happens synchronously and what does not, and it all relies on knowing the precise steps of what will happen as a result of each action. Any of a small number of changes I could make in the future is probably going to "break" the test, in that it will cease to test anything meaningful.

Postmortem on fixing it

I'm sure some people might look at this bug and ask several questions. Let me try to anticipate some of them and answer them.

Why did the reviewers fail to notice this change?

This bug is a result of the confluence of several changes. In the beginning, SetIsBusy was mostly a no-op, so calling it from the constructor was safe. Then the URL queue was added, and SetIsBusy was used to indicate that the connection was ready to receive a new URL from the queue. This turned it into a time bomb, since the code was correct only because the server was null in the constructor and the queue should have been empty during connection construction anyways. The final change was moving initialization of the server, which triggered the time bomb. But even then, it triggered the bomb only in a rather abnormal circumstance. At no time would the code have failed any automated tests or any of the "does your patch work" tests that a reviewer normally goes through: robustness during connection interruption is both sufficiently difficult to test and rare enough that it generally doesn't get tested.

Why did this bug take so long to track down?

The time since December 1 is truly a result of lack of time: I have had maybe 1 good week to work on anything due to outside factors. There are two, maybe three, people in active participation with Mozilla who know this code well, and out of those, only one was able to somewhat reliably reproduce it (specifically, the one with the least amount of time on his hands). I could have relied on others to gather the information I needed, but my previous efforts in QA have taught me that getting people to give you necessary information is often very difficult, especially when the information collectable at the obvious point in time is completely useless. I realize in retrospect that there were some more technically inclined people in the bug (at which point in time I was already devoting as much attention as I felt I could spare on the bug anyways). The bug is also particularly pernicious in that the most valuable information is that which is gathered before any visible symptoms occur; it was after I figured out how to discover that the bug was going to occur that I could track it down further.

Will the fix be backported to more stable branches?

At this stage, I am looking at two fixes: the small one-liner that fixes the specific bug, and the larger patch which fixes the larger issue of "the NNTP URL connection queue is a ticking time bomb". The former I would definitely like to see backported to aurora and beta (and possibly release if there are plans for another one before the next uplift), and I can't see any reason a small patch on the most-highly-voted TB bug filed since 01-01-2011 would get rejected (it is the newest bug to have more than 5 votes, and the next largest has 1/3 less and is almost twice as old).

Why is this bug so hard to reproduce?

If you think to the cause of the bug, it is that it is passing a check in a function that is always called. It therefore seems like this bug should be triggered a majority of the time, and not an undependable minority. As I alluded to earlier, the problem is that this also has to interact with a buggy pending URL queue management system. In short, most of the time, this queue will be empty during the initial, buggy call; with a poor timing of events (less likely to happen on most developers' computers, in short), the queue will cease to be empty and cause the problem. Indeed, when crafting my test for reproduction, I discovered that letting the event loop spin in one particular location (after killing connections) would fail to trigger the bug. In the real world, that is one of the places where the event loop is most liable to spinning for the longest.

2011 LLVM Developers' Meeting

This feels a bit late to be talking about the 2011 LLVM Developers' Meeting (seeing as how it happened almost exactly a month ago), but since the slides have been put up over the past week and the talks were only put up on Youtube this week, I suppose I can finally back notes up with links and not talk so abstractly.

Of the talks I went to, I think by far the most interesting one was Doug Gregor's talk on Extending Clang. It covered various extension points in Clang and some of their capabilities with simple examples. It also ended in what might be impolitely titled "Where Extending Clang Sucks" and what was politely titled "Help Wanted." This boils down to "plugins are hard to use" and "one-off rewriters are hard to write". Indeed, I think the refrain of problematic architecture for further tools was repeated in more than a few presentations: Clang has the information you want and need, but squeezing the information out is inordinately difficult.

What was probably the most popular talk was Chandler Carruth's talk on Clang MapReduce—Automatic C++ Refactoring at Google Scale (his slides appear to not yet be posted). From what I recall, the more interesting parts of the talk are closer to the end. He had a discussion on developing a language for semantic queries to identify code that needs to be replaced (the example query was essentially "find all calls to Foo::get()"); the previous things people have tried are regexes (C++ is not syntactically regular, it's recursively enumerable), XPath (unfortunately, ASTs, despite their name, aren't exactly tree structures), and pattern matching ASTs (not always sufficient textual clues). The team's idea was to use a matcher library on "AST" values as predicates. He also spoke a bit about some of the efforts they did on using Clang with Chromium.

There is a point brought up in Chandler's talk that I want to reiterate. One of the problems with writing refactoring tools (or static analysis tools in general) is in getting people to trust that they work. For any sufficiently large codebase—millions of lines of code or more—it is fairly certain that the project will run up against the nasty edge cases in parsing tools. If a tool is intended to run mostly automated analysis on such code, it is impossible for anyone to be able to look at the output and ensure complete correctness. However, most sufficiently large codebases come with massive testsuites to help people believe their code is correct; if the same parser is capable of producing code that passes the entire testsuite, then one only needs to trust that the analysis is done correctly, a much smaller task. Without such a capability, no one would be willing to trust the analysis; in other words, any parser which is not capable of then generating code is never going to be trusted as a basis for further work, at least, not if you are looking at million-line projects.

Speaking of Chromium and Clang, there was talk on this too. As I am sure most of my audience is well aware, Chromium uses Clang for several of its buildbots (and all of its recent Mac development); I wish Mozilla could get Clang to be a tier 2 or tier 1 platform for Mac and Linux. As for why they prefer it, the brief rundown is this: better diagnostics, faster, smaller object sizes, they can write a style checker, and they can build better tools off of it (like AddressSanitizer, which, unsurprisingly, itself had a talk). Again, there were the complaints: building the rewriter proved to be difficult a task (notice a trend here?). Incidentally, I also attended the AddressSanitizer talk, but I'm getting tired of copying down notes of talks, so I'll let those slides and the video speak for themselves.

Finally, I did give a talk on DXR. It seemed to be well-received; I had a few people coming up to me later in the day thanking me for the talk and asking more questions about DXR. Something I did discover when giving it, though, is just how difficult giving a talk really is. I had specific notes on the slides written in my notebook, only to discover that I wasn't able to gracefully retreat to the podium and read the notes long enough to figure out what to say next. If you're wondering what I forgot to mention in the talk, it's mostly a more coherent explanation during the undead demo.

How I got involved with Mozilla

My journey to become a contributor to Mozilla started during the summer of 2007, which was when I started very heavily using Thunderbird. The initial impetus is probably best traced to this thread in a newsgroup: a long, semi-flame war. I wanted to excise the flame war portions from the rest of the thread, so I filed bug 392404 (the first bug I ever filed!). That bug was marked as a duplicate of bug 11054.

At that time, I had a fair amount of free time (this was around the time my summer internship ended but before school started). I downloaded the source code to Thunderbird and then built it, only to discover that every time I built it, it crashed in a linker. After bugging people about it on IRC, I learned that I needed a swap file, and I finally managed to get a successful build. Then, having had programming experience, I decided just to fix the bug myself. I honestly can't remember for certain, but I believe I built the original patch without much aide from people on IRC--it was only the inability to build that I had needed to ask for help.

I do remember that I needed guidance on how to get a patch committed. This being mailnews code around the time that Mozilla Messaging was being set up, the pool of potential reviewers and superreviewers was rather slim. I had been advised that David Bienvenu and Scott McGregor were my best candidates for review. Unfortunately, around this time, Scott had cut off all work with Mozilla; after two months of not getting any response from him whatsoever, I switched to another reviewer.

While I was waiting for the patch to be reviewed, I recall Dan Mosedale talking about bug 132340 indirectly; later, when I asked if there was a fix that people would be interested in, that bug was what I was pointed towards. This patch took about two months and four review cycles to be accepted, but it eventually satisfied my reviewer and superreviewer and became my first contribution to Mozilla. That first patch I worked on? It turned out to be significantly more complicated than I first appreciated and finally was closed 9 months after I started work on it. After bug 132340, I started getting more and more involved with Mozilla development and have been a contributor since then.

Public Service Announcement #2

A brief note to all application and operating system developers:

Failure to respond to a prompt does not indicate accession to perform the actions that would otherwise occur. Especially if those actions have a high risk of losing my data. So I would like to thank you (whichever product is responsible for my most recent undesired restart) for completely obliterating my class notes. At the very least, you did not destroy all of my research too, just a day's worth.

Not-so-random mozilla-central factoids

Back when I was looking at reducing disk usage of running DXR, I used the sizes of the generated CSV files to make a rough estimate of how many times the average line of mozilla-central needs to be parsed and compiled (the answer is around 20). Now, having just respun a build of mozilla-central with the newest version of DXR, I have a larger database with some fairly accurate statistics of its size. This all started when I wondered what our most common function name was, so I decided to make a list of factoids (it's also a chance to refresh my SQL memory). All of the statistics come from a build of Firefox today on Linux x86-64 with debug and tests disabled.

Notes on accuracy

DXR tries as hard as possible to correlate data back to the original source code, and it is very likely that it can get itself confused in some weird circumstances. I don't yet have a good idea of where all of the buggy cases are, but I am aware of some broad strokes. Pretty much all information that deals with references is likely missing large swathes of the codebase. Information about callers only counts explicit calls (i.e, call expressions). The most accurate data I have is the macro information and the least accurate is information involving a templated class in almost any fashion. I also suspect that scope information is malformed in a non-empty set of cases, and I'm pretty sure that the number of global objects in any count is overcounted.

Type statistics

I count in mozilla-central just 33,555 distinct types. Of these, we have 13,648 typedefs, 6,523 structs, 6,470 classes, 5,147 enums, 1,410 interfaces, and 357 unions. Of all of these, 13,740 types are nested in another in some fashion, and another 4,524 types are templated. I'm not counting separate template instantiations as new types, but I am counting specializations individually.

Then there's the inheritance. I found 7,715 direct inheritance relations, all but a handful of which (around 200) are public. These relations account for 2,317 distinct base classes and 6,157 distinct subclasses. Naturally, some types are inherited much more than others. The winner, by a factor of 6, is nsISupports, having a whopping 3,156 implementations. Pickle and IPC::Message tie for second place with 501 implementations each; nsIRunnable takes 4th place at 282 implementations. The 5th place goes to nsXPCOMCycleParticipant (242). Rounding out the top 10 are nsIDOMElement (226), nsRunnable (224), nsScriptObjectTracer (209), nsSupportsWeakReference (154), and nsIObserver with 144. Subclass relationships involving templates are not counted, which may bump a few classes up into this list.

Macros

There are 42,457 distinct definitions of macros to produce 38,045 distinct names. Of these, 30,475 look like variables and 7,647 look like functions, which implies that 77 macros take on both depending on how they got defined.

How about calling them? I count just 482,142 macro invocations, so each macro is being invoked about 12 times on average. But... 20,628 of our macros are never used (or almost 48.6% of them), so the average is closer to 25 times. Of course, some macros really get used. Here are the top 5:

Count	Macro name
23,109	nsnull
22,941	PR_FALSE
20,139	NS_OK
13,154	NS_IMETHOD
13,138	NS_IMETHODIMP

Functions

There are 137,903 functions in mozilla-central. Of these, there are 68,867 having a distinct name. Of these, I found 33,693 in the global scope, and 8,943 that were a member of a class. Directly templated functions comprise about 2,291 functions. Just for fun, I found that there are 774 functions named exactly "Init" and a further 1,681 that begin with "Init" (case-insensitively in the last case).

In terms of calling these functions, I found 291,598 distinct edges in the callgraph (this is definitely an underestimate, since I am missing a large number of cases). For my usage, a callgraph is not a traditional directed graph but rather a hypergraph, where each edge goes from a single head to a set of nodes in the tail. These comprise 85,144 distinct callers and 67,098 distinct targets. Of the targets, I found 51,590 distinct functions being called statically, 13,274 distinct virtual functions invoked, and 2,234 distinct function pointers or pointers-to-member-functions being called. If I break it up by calls, 246,086 of the calls are static function calls, 41,770 virtual function calls, and 3,742 function pointer calls. I want to emphasize here that information pertaining to templates, in particular nsCOMPtr is completely missing, so a lot of calls to nsISupport's methods are missing, which is going to horribly skew the statistics.

Counting the function pointers, we have 65 pointers-to-member-functions and around 1700-1800 function pointers (those numbers do not add up to what I should get above, but I'm not sure who's in error here). I count about 19,721 virtual functions that I generated target information for (a subset of all virtual functions), and 65,761 implementations of those virtual functions, so the average virtual function has about 3.4 implementations. In addition, I found about 981 of these virtual functions were also called statically.

Now I'm sure, having mentioned it earlier, that you too are now wondering what the most common function name in mozilla-central is. The answer should be pretty obvious when you consider the most heavily-implemented class. And the winners are...

Count	Function name
1,687	Release
1,680	AddRef
1,600	GetIID
1,587	QueryInterface
774	Init
659	operator=
549	Log
517	Read
506	Write
396	GetType

The top 4 methods are related to XPCOM; the famed Init method is a mere 5th place. Of interesting note is that there are 659 assignment operators; I'm guessing some of these may be default copy constructors implemented for non-POD classes.

Variables

There's not much to say here. We have some 623,237 variables of some kind. Most of these, naturally, are local variables or parameters: 516,627, to be precise. We additionally have 82,008 members of some compound type, and 24,602 global variables. Some interesting statistics would be to compute the number of variables whose names defy our naming convention or the number of static constructors that need to be run before startup, but that data is harder to compute.

Warnings

I count 5,283 reported warnings for mozilla-central. Of these, 1,608 are warning about the use of non-virtual destructors with virtual functions. Another 940 warn about our use of mismatched enumeration types. There are 1,348 warnings of unused things. Finally, there are 1,551 warnings about use of extensions, leaving 466 "miscellaneous warnings".

Build statistics

The final set of statistics I have is mere size statistics for the build information. There are about 8,581,746 non-empty lines of text comprising some 320MiB of data. These are organized into about 51,469 files, including 1,469 files of generated files in the build directory. My output SQLite file was 464MiB, easily comprising around 3.5 million rows of data. We also have about 38MiB of binary files (like PNGs) in the source tree. Almost 15MiB of the generated included files were produced, comprising around 354,893 non-empty lines of text.

I think the best way to summarize this data is "mozilla-central is a massive codebase." It also goes to show you why just looking at source code without compiling is a bad idea: around 3-5% of our source code actually isn't in the source tree to begin with but is instead automatically created at compile time.