Showing posts with label bugs. Show all posts
Showing posts with label bugs. Show all posts

Friday, August 01, 2025

OverIter Cur Deleted

gSuneido has had a long standing assertion failure that happened maybe once a month which equates to about once per million user hours. We tried multiple times but were never able to recreate it.

I’ll try to explain the scenario. Indexes are stored in the database file as btrees. While the database is running, index updates are buffered. An Overlay consists of the base btree plus layers of updates. When a transaction commits it adds an ixbuf layer to the Overlay’s that it updated. Background threads merge the layers and update the btree. OverIter handles iterating over an Overlay. It merges iterators for each layer. This is fundamentally straightforward but as always, the devil is in the details. The ixbuf layers from the transactions include updates and deletes as well as additions. So the merging has to combine these. For example, combining an add followed by several updates. The final piece of the puzzle is that concurrent modifications can occur during iteration.

"OverIter Cur deleted" means that the current value of the iterator is marked as deleted. This should never happen. The iterator is designed to skip deleted records.

The error occurred again recently and I decided to see what Claude (Sonnet 4) could do with it. It kept saying "now I see the problem", but when I'd tell it to write a test to make it happen it couldn't. It became obvious it wasn't going to spot the bug by just looking at the code so I got it writing tests. It wrote a lot of them, and they all passed. That was actually kind of nice since it meant the code was fairly robust. I wouldn't have been surprised if other bugs had showed up with the intense testing.

Finally, it wrote a random stress test that caused the assertion failure. I was cautiously optimistic. Sadly, it turned out it was generating invalid test data and that was what was triggering the assertion failure. Once I corrected the data generation, then the test passed. It was possible that the bug was actually leading to bad data which was leading to the assertion failure but that seemed unlikely since bad data would cause other problems.

Back to the drawing board. I continued extending the test to cover more scenarios. Eventually I managed to recreate the error with legitimate data and actions. After that it was a matter of extracting one failing case from the random test. Claude added print statements, looked at the result, and wrote a test for that specific sequence.

Once I had a relatively simple failing test, Claude claimed to find the bug right away. I was skeptical since it had claimed to find the bug many times already. I worked on extending the test to cover more of the scenarios. Sure enough, it started failing again. Claude came up with another fix. But the test kept failing. The proposed changes would fix certain cases but break other cases. No combination of the “fixes” solved all the problems.

Eventually Claude proposed rewriting one of the key functions. I was even more skeptical but the code looked reasonable and it was simpler and clearer than the old code. It wasn't very efficient but it wasn't hard to tell Claude how to optimize it. But it still didn’t fix all the problems. I dug into the other “fix” and realized it was on the right track but wasn’t quite complete. A little back and forth came up with a solution here as well. And finally I had a version of the code that passed all the tests.

I am cautiously optimistic. By this point I think the tests are fairly comprehensive. And I understand the fixes and they make sense.

As I've come to expect, my results with Claude were mixed. It definitely did some of the grunt work of writing tests. And I have to give it credit for giving up on some of my old code and writing a simpler, more correct version. But it also came up with several incorrect, or at least incomplete, fixes.

I started this thinking I'd spend a few hours playing with AI. It ended up being my main project for a week. Even though it was rare enough that it wasn't really a problem, I'm glad I finally fixed it. (I hope!)

Friday, April 10, 2020

Sometimes Bugs Are Easy

Finding a bug can be a long frustrating process. Those are the ones I tend to write about. But occasionally the stars (and the tools) align and it goes quickly and easily. I figured I'd write about one of those for a change.

I released (internally) a new version of gSuneido. Users soon found a bug that hadn't been in the previous version. It had been about two weeks and roughly 40 commits since the last version.

Thank goodness for version control. It's long ago, thankfully, but there was a time when we programmed without any version control. The bad old days. Of course, my memory was better back then.

The bug was easy to recreate, which made it easy to manually bisect my Git versions and find the commit that introduced the bug. A good reminder of the efficiency of binary search.

The offending commit only changed a single file, so that simplified things. There were a lot of changes within that file, but they were independent. So I could again manually bisect the changes and quickly find the one with the bug.

And to top it off, the fix was easy.

Wednesday, March 11, 2020

Go Bug

Go 1.14 came out recently. I updated without really thinking about it, expecting a painless experience like all the other versions. I rebuilt gSuneido (the Go version of Suneido), ran it, and ... it crashed, with an unfamiliar internal Go error.

At first I just thought the build hadn't worked properly or I had a mix of versions. Or maybe Go hadn't installed quite right.

But re-installing and re-building didn't solve the problem. It still crashed. Annoyingly, all my tests passed. On the positive side (at least in terms of debugging) it crashed consistently, every time, the same way. And if I built exactly the same source code with the previous version (1.13.8) it worked fine.

The crash call stack had some references to defer. (Go's equivalent to try-finally.) And one of the big improvements in Go 1.14 was to ... defer. That was very suspicious, but I wasn't quite ready to blame the crash on Go yet.

One big question was "why me?". (In this kind of situation it is actually a valid question.) If it was a bug in Go why weren't other people running into it? I'm not that much of a unique snowflake. Yet, despite searching the Go issues and the web in general, I couldn't find anyone reporting a similar issue. However, it was possible that I was (ab)using panic/defer/recover in a way other people aren't. For better or worse, the Suneido language has exceptions (like Java and C++). And the easiest way for me to implement exceptions was to use panic/defer/recover. Go strongly discourages this kind of thing. I'm pretty sure Go true believers would regard what I was doing as an abomination. (Another reason I was reluctant to submit a bug report.)

The win32 interface in gSuneido uses unsafe and C code, so that was the first thing to be suspicious of. It was quite possible there was a bug in that code that hadn't surfaced before. Or perhaps an unintentional dependency on some internal feature that had inadvertently changed in 1.14.

Thankfully, it didn't take long to recreate the problem without running any of the win32 interface. Which also allowed me to recreate it on Mac OS X.

The issue seemed to be related to defer, recover, and re-panic'ing. (equivalent to catching and re-throwing an exception in other languages) But strangely it seemed to require one sequence of defer/recover/panic first, and then a second sequence would crash. It was as if the first sequence was corrupting something or leaving something behind that caused the second sequence to crash. 

At this point, after several days of debugging, I was starting to lean towards a bug in Go 1.14. I was hesitant to submit a bug report because I didn't have a small example to reproduce the problem. So based on what I'd discovered so far I tried to create a standalone test case. In retrospect, I think I was close, but none of my test programs would crash.

I decided to submit the bug anyway. At least if anyone else ran into it, there would be something to find when they searched. And maybe someone would have some suggestions on how to debug it further.

crash on 1.14 with unexpected return pc, fatal error: unknown caller pc

I got some responses right away which was nice. One of the first suggestions was to try building with -gcflags=-N which turns off various optimizations, including the new defer handling. Confusingly, it still crashed. Which seemed to indicate it wasn't the defer changes. Luckily at that point the author of the defer changes, Dan Scales, offered to help debug it. I was able to come up with a package of files to allow him to recreate the crash. It wasn't a small example, it was the whole Suneido source code, but at least he could reproduce the crash. It turned out that -gcflags=-N did actually fix the problem. The catch was that setting that flag didn't force recompilation, so I was still running old code. I should have used -gcflags="all=-N". (These "internal" options aren't well documented.)

So Dan confirmed that the bug was in was his changes, and he quickly came up with a fix.
He also suggested a workaround. The defer optimizations didn't kick in if the defer was in a loop. So I could put a one iteration loop around the relevant defer's. (That seems a little odd - I would have thought the compiler would optimize away one iteration loops. Maybe that happens in a later stage.) The question was which defer's. At first I only added the workaround to defer's that re-panic'ed. But it still crashed sometimes (albeit less often). I ended up adding the workaround to all the defer's with recovers and that seemed to fix the problem.

One of the problems is that this is happening in gSuneido's byte code interpreter. So it's impossible to statically determine which code might call which code, which is what's critical to this bug.

I was hoping that the fix would be cherry picked and back ported to 1.14.1 rather than having to wait for 1.15 which is six months away. Thankfully, it looks like that is going to happen.

I was impressed by the response of the Go team/community. They took my bug report seriously and gave me good feedback. No one hassled me about my lack of a small example or my abuse of panic/defer/recover. And the problem was rapidly tracked down and fixed. You can't ask for much more than that. (I also had a good experience with the other bug I've reported and was fixed - 35492)

Tuesday, January 07, 2020

Recurring Nightmares

gSuneido has been coming along nicely. It's solid enough that it has replaced cSuneido for my personal use. Of course, there are still issues but I'm gradually cleaning them up.

cSuneido has a Windows COM/OLE interface that we primarily use for the Windows browser control. I used go-ole to implement this in gSuneido. I wasn't completely happy with taking a dependency on a small project that wasn't very active, but the code was fairly straightforward and I knew I could write my own if I needed to.

go-ole worked well and I thought that area was complete. But when I got other people testing gSuneido more issues came up. Ctrl+C (copy) in a browser window crashed. Some links crashed. Passing an empty string caused a later crash.

I spent several days trying to debug the problems. The crashes were access violations inside Windows which meant you don't have a lot of insight into what's happening. Windows is a very large black box.

Working on a previous issue I had wondered if it would be better to isolate the COM/OLE interface the same way I had isolated the DLL interface. (see gSuneido Roller Coaster) I'd actually started implementing this but abandoned it when I solved the bug another way.

These COM/OLE bugs were somewhat different from the DLL issues - more reproducible and less random. But they also had a lot of similarities. I suspected there were some threading issues but I don't understand COM/OLE threading well enough to be sure.

Searching on the web I found more issues with interfacing between Go and Windows. Often they caused crashes. Go's threading model, garbage collection, and stack movement do not play well with Windows. As I've come to know, it's a dangerous area to work in. Note: This is not really a flaw with Go itself. If you stick to straight Go you won't run into these problems. It's only a problem when you have "unsafe" code calling external Windows stuff. Unfortunately, that's what I'm doing.

I decided to finish isolating the COM/OLE interface. It was a bit of a gamble since I had no idea if it would solve the problems. But it didn't seem like it would take too long and I didn't have a lot of other ideas.

It only took me a day or two to replace go-ole with my own interface. But ... it didn't work. I kept getting DISP_E_TYPEMISMATCH and CTL_E_INVALIDPROPERTYVALUE. I had basically ported my cSuneido implementation which I knew worked. cSuneido is 32 bit whereas gSuneido is 64 bit, but that didn't seem to be the problem. I also had the go-ole code as an example. I spent a whole day trying to figure out why it didn't work. I added logging to all three implementations and they looked identical.

Finally I realized that the IDispatch Invoke arguments need to be in reverse order. The way I'd added the logging had hidden this and I'd only been looking at the values of the arguments. A day's worth of time wasted!

Once I made that trivial but crucial fix, it all started working.

And even better, the original weird bugs and crashes were gone :-)

So my hunch was right and my gamble paid off (this time). And as a side bonus, I no longer have a dependency on an external library.

Tuesday, October 22, 2019

gSuneido Roller Coaster

One of the questions with the Go version of Suneido (gSuneido) was the Windows UI interface. In the long run I'm hoping to switch to a browser based front end, but that's a long term project and I would like to replace cSuneido sooner than that. One option is to implement cSuneido's general purpose DLL interface. But this involved some ugly low level code (even some assembler) that I didn't really want to port. Another option was to use Go's syscall facilities to write the specific Win32 functions that we needed. I did a quick check on how many functions we needed to open the IDE. It was about 100. I knew the final number would be higher, but it seemed reasonable to hand write that many. One advantage of doing this is that it moved the "unsafe" code from Suneido to Go, which seemed safer.

Of course, it took much longer than I expected to write (and debug) the interface functions. There were about 300 in the end. (It's not just the functions, it's converting to and from all the structs involved as well.) I definitely had a few doubts whether this was the right approach. In retrospect, I'm pretty sure I could have ported the general purpose interface in less time. It was also a bit depressing knowing that if/when we got the browser interface finished, then this code would all be thrown out. If I was to do it again, I might write a tool that would take the cSuneido definitions and generate Go language definitions.

But finally I got near to complete and I could actually run the Suneido GUI. That felt pretty good.

Except there were intermittent crashes. I didn't worry about it too much at first. This kind of low level unsafe code can easily crash if you have bugs. But even after I cleaned up the majority of the bugs, it was still crashing. It worked most of the time, so I didn't think it was blatant errors in the code. I spent days trying to track it down. Of course, like many elusive bugs, it almost never crashed in the debugger.

My first thought was something related to garbage collection. But disabling garbage collection didn't help.

Another possibility was stack movement. Because Go supports high numbers of goroutines, they start out with relatively small stacks, which grow as necessary. This is a tricky process because you have local variables on the stack, and pointers between them, all of which have to be adjusted when the stack is moved. I couldn't figure out how to debug this. There was no way to turn it off, and no way to trace when it happened. I tried to detect it by storing the address of a stack value in an integer where it wouldn't get adjusted. But this didn't seem to work and I never did figure out why. (Part of the problem is that unlike C(++), in Go you don't control whether things are on the stack or the heap. That's all handled automatically by the compiler. It's quite possible that my value was ending on the heap and therefore useless for detecting stack movement.)

Needless to say, this was another low point. For starters, all that work for nothing - it was useless if it crashed randomly. And secondly, what now? If I couldn't reliably interface with the Windows GUI from Go, then the only other option I could see was to write the GUI interface in a separate C(++) program and use some kind of interprocess communication. Presumably that would work, but it would be ugly.

It might seem odd that something so objective and abstract would involve so much emotion like elation and depression. But software development (at least so far) is a human activity, and human are nothing if not subjective and emotional.

One thing that puzzled me was that I knew there were several other Go projects that interfaced with the Windows GUI. (Like https://github.com/lxn/win and walk) Why didn't they have this problem? I started searching and soon found this issue:

don't use Go heap for MSG
It's not entirely clear to me what's going on here, and I'm only
half-certain that this fixes the issue, due to it being somewhat hard to
reproduce ... While this might point to deeper Go runtime issues, we
just work around this here by allocating the variable using GlobalAlloc.
At the very least, I haven't been able to reproduce the bug after
applying this patch.

Following the links and looking at the related issues it sounded very much like what I was seeing. I applied their fix/workaround and sure enough the crashes went away, accompanied by feelings of relief and joy.

Part of the problem/complexity is that the way the Windows GUI works, there are nested callbacks and DLL/sycalls. i.e. Windows calls application code which calls Windows code which calls application code, and so on. On top of that, Go syscalls and callbacks do a complicated dance to switch between Go stacks and syscall stacks, and attempt to protect non-Go code from garbage collection and stack movement. It's not at all surprising that there would be ugly corner cases.

Well, my happiness lasted all of a day before I had another crash. Hmmm... was that the old problem still there, or something else? I crossed my fingers that it was something unrelated. There's a fine line between wishful thinking and having a positive attitude. Sadly, the crashes kept happening and it became obvious the problem wasn't solved.

But the lxn/walk issue had seemed so similar. And the fix had certainly reduced the number of crashes. If the issue was passing pointers to stack values, then I was doing this in a lot more places than just the message loop MSG. Whereas the lxn win/walk code always took the pointers as arguments rather than declaring them locally. (Of course, I didn't figure this out quite as step by step as it sounds. There was a lot of frowning and frustration first. )

I tried changing a few of the common crash sites to avoid anything Go might put on the stack. That reduced crashes even further. Of course, once the crashes get rare, it becomes very difficult to know whether you've fixed anything or not. It always seems to work at first. Just when you're ready to declare success, then it crashes again.

It seemed like I was on the right track, so I took the plunge and changed all the functions to allocate temporary values on my own "heap/stack". This was a bit of a gamble since it was a lot of changes (several days work) with no guarantee it would help.

But the gamble seemed to pay off. No more crashes! I was a happy camper.

I soon had more or less the whole IDE working. There were numerous little glitches but they were mostly easy to fix. Until one glitch that was more problematic. I happened to try dragging some text within an editor window, and it didn't work. At first I thought the drop was failing since the text didn't appear at the destination. But I soon realized it was getting inserted at the very beginning or end of the text, instead of where I was trying to drop it. I couldn't remember how drag and drop worked so I had to do a little digging. At this point I was still assuming it was just some minor error in one of the functions. But it wasn't anything obvious. I narrowed it down to a couple of notification callbacks (EN_CHANGE or SCEN_MODIFIED). If those callbacks did anything significant then the drop would go to the wrong place. It didn't seem to matter what they did. I never did narrow it down to whether it was call stack or heap usage.

The problem was, this was a bit of a dead end. Inserting seemingly harmless, irrelevant code in between Windows and Scintilla (the editor control) caused drag and drop to fail. I looked at the Scintilla code but it didn't seem to be doing anything unusual or suspicious.

I spent another couple of days on this issue until I admitted defeat. Again, there seemed to be something going wrong in the depths of Go's complex syscall / concurrent garbage collection / stack movement. In theory I should submit a Go bug report. But, understandably, they'd want a small example that consistently reproduced the problem. And I don't have anything close to that. I have a large system that crashes rarely.

Another low point. Now what? Such a small symptom, but there's no such thing as minor corruption, it's a bit like a little bit pregnant.

Back to my previous idea of a separate GUI process written in C. Probably the fastest interprocess communication would be shared memory. But you'd still need some kind of synchronization. It still seemed ugly.

Did I really need a separate process? I want some isolation, but maybe I can do that within a single process. Go has a facility for incorporating C code in your Go program (Cgo). What if the C GUI code ran in a separate OS thread, but still within the same process? That would separate the Windows GUI code from all the Go issues of concurrent garbage collection and stack movement. But you wouldn't have the overhead and complexity of a separate process and interprocess communications. And you could, of course, share memory. (carefully!)

But you still need synchronization. When the Go side made a call to the C side, it would need to wait for the result. Similarly when the C side made a callback to the Go side, it would need to wait for the result. One option was to use a Windows synchronization facility. That would mean a syscall on the Go side. The other option was to use a Go synchronization facility, which would mean a callback from the C side. I decided it made more sense to use Go synchronization because I suspected that would play better with the Go scheduler and concurrency.

One way to handle the synchronization was to use Go channels. If it was pure Go code I might have gone that way. But with C involved it looked like sync.Cond would be simpler. When I searched for how to use sync.Cond, what I found was an issue where someone suggested the documentation needed to be improved. I wouldn't have thought that would be at all contentious. But  it seems some of the Go team doesn't like sync.Cond and don't think people should use it, and therefore don't want the documentation improved. Personally,  I question the logic of that. It seems like poor documentation just increases the chances of people misusing it. I appreciate the Go team and I'm grateful for all they've done, but sometimes there seems like a bit of a "we know better" attitude. (Of course, most of the time, I have no doubt they do indeed know better.) Another example is the refusal to supply a goroutine ID or any kind of goroutine local storage, again because "it might be abused". And yet internally, they use goroutine ID's. I'm just an ignorant bystander, but it seems like a bit of a double standard to me.

Despite the poor documentation (and with the help of Stack Overflow)  I figured out how to use sync.Cond. Whether I used it appropriately is a question someone else can debate. No doubt some people would say I should be using channels instead.

Using Cgo turned out to be fairly straightforward. It requires GCC so I installed Mingw64. I decided to stick to C rather than use C++. For the small amount of code I had to write, it seemed simpler and therefore safer. It took a few tries to get the synchronization working properly. The code wasn't complex, but as with all concurrency, the devil is in the details.

Thankfully, it didn't require a lot of changes to my existing Go code. I basically just swapped out the syscall and callback facilities.

Of course, it was another gamble to implement a whole approach on the basis of not much more than a gut feeling it should work. And gut feelings are notoriously unreliable in software development. But it only took a day or two to implement, and I was back to running the the Suneido IDE. And the moment of truth - would drag and drop work now? It did! By this point my reaction was more sigh of relief than elation.

Are there other bugs lurking? Almost certainly. But I'm cautiously optimistic that I've solved the crashing and corruption. The only thing talking to Windows is now a single C thread (with a regular dedicated fixed stack and no garbage collection or even heap allocation) which is a very tried and true setup. You can't get much more basic than that. The only interaction is C calling a Go function to signal and wait. No stack or heap pointers are shared between the two sides. Go's concurrent garbage collection and stack movement can work totally independently of the C thread. And as a bonus, it's more efficient to run the message loop in C with no Go syscall overhead.

I was all ready to post this, but I was a little nervous because I really hadn't tested much. I didn't want to declare victory and then find another problem. Of course, there were always going to be "other problems".

So I did some more testing and it seemed a little sluggish. At first I didn't pay much attention - there's so much background stuff going on in our computers these days that can affect speed. But it didn't go away. I did a quick benchmark of a simple Windows call and got 70 us per call. That seemed high but I wasn't sure. I checked cSuneido and it was 2 us. Ouch. Maybe it was just Go syscall overhead? (i.e. can I blame someone else?) No, directly from go it was .3 us.  My guess is that there is some kind of bad interaction with sync.Cond, but I don't really know.

Another downer, just when I thought I'd won. C'est la vie. The obvious alternative (that I had considered earlier) was to use Windows synchronization. Luckily Windows condition variables and critical sections were similar enough to Go sync.Cond that it didn't take long to switch.

I didn't actually hold my breath when I ran the benchmark, but I mentally had my fingers crossed. And it worked - now it was 1 us per call, better than cSuneido. And the IDE no longer felt sluggish.

I've been running this version for a couple of days, and it seems that this chapter of the saga is over, so I will post this and move on to other bugs.

Friday, August 04, 2017

[[nodiscard]]

I was reviewing some of my cSuneido C++ code and I noticed that I was ignoring the return value from a function, which meant that a variable might not be set. The function looked like:

bool int_if_num(int* pi);

I recalled reading about the new (C++17) [[nodiscard]] attribute which should catch this kind of error. I added the attribute to the function:

[[nodiscard]] bool int_if_num(int* pi);

I thought it was supported in Visual Studio but it turned out that it's "coming soon" in the next release.

But I also had Clang which does support it, and sure enough it caught the error:

error: ignoring return value of function declared with 'nodiscard' attribute

(I thought there might be more instances, but this was the only one.)

The nice thing about this kind of feature is that it's fine if it doesn't have universal support. I commonly compile with GCC and Clang in addition to Visual Studio because they each catch different issues.

[Afterward - reading the code more carefully, I found that I was initializing the variable prior to the call so it wasn't a problem after all. But that relied on the function not modifying the value unless it succeeded, which could change, and then there would be a problem. So it was still worth fixing the code.]

Tuesday, September 22, 2015

A Bug Hunter's Life

I recently spent two weeks tracking down a single bug. Needless to say, it was a frustrating process. Like most such things, what made it difficult was not a single problem, it was a whole cascade of errors, including many during the debugging process. I like to think I'm fairly organized and methodical, especially when working on a tough bug. I take notes on what I'm doing, what my assumptions are, what I've tried, what the results were. And yet I still managed to make multiple major mistakes and go a long way down the wrong paths based on false assumptions I should have questioned much sooner.

It started with a customer getting a corrupted database. Most of the time this is from hardware issues or crashing. But this one appeared to be caused by a bug in the code.

It wasn't easy to look into because all I had was the corrupt database, with no clues as to how it might have gotten that way. Thankfully, jSuneido's append-only database means that the database itself forms a kind of log. Based on that I could see that two transactions had committed conflicting updates - something that the whole transaction system is designed to prevent.

It seemed a pretty safe bet that this was a concurrency related issue - my least favorite kind of bug :-( I wasn't surprised that I couldn't make it happen. With roughly 1000 systems running 24x7 this was the only case I was aware of. So my sole sources of information were that database and the code itself.

In order to detect conflicts at commit time (jSuneido uses optimistic concurrency control) you need to know the outstanding overlapping update transactions (i.e. ones that had started after this one and had not completed yet). Perhaps the bug was in determining this set of transactions? I wrote a completely new implementation of this code and used it to cross-check.

We deployed this version to our customers and pretty quickly started to get lots of errors. But only a couple were from the new cross-check. The rest were from code I hadn't touched. And yet they quite clearly started when the new version was deployed. Strange.

The errors indicated that sometimes when it went to complete a transaction it would be missing from the list of outstanding ones. Again, this shouldn't be possible. That would explain why the overlapping set would be wrong, so it made a certain amount of sense. I spent days studying the code and trying (unsuccessfully) to figure out how it was happening.

This turned out to be completely off track - it was a just problem with my new cross checking code.

The stack traces showed a transaction commit that turned into an abort. That happens if an update transaction doesn't end up doing any updates. So I wrote a bunch of tests with those kinds of transactions in the mix, but they all worked fine. If nothing else, the code was getting reviewed and tested pretty heavily.

Finally, after wasting days on this, I realized there was another way for a commit to turn into an abort. The relevant part of the code looked like:

try {
     // commit stuff
} finally {
     abortIfNotComplete();
}

What was happening was that an exception during the commit stuff would get overridden (and lost) if there was an error in abortIfNotComplete(). So I wasn't seeing the original error at all. And the reason that the transaction was missing from the list was that it had got far enough into the commit to remove it.

I'm not sure why I wrote it using finally. In hindsight it was obviously a bad idea. I rewrote it like:

try {
     // commit stuff
} catch (Throwable e) {
     try {
          abortIfNotComplete();
     } catch (Throwable e2) {
          e.addSuppressed(e2);
          throw e;
     }

addSuppressed was added in Java 7. It is used, for example, in try-with-resources for exceptions when closing after another exception.

Part of the reason I didn't realize which path was being taken in the code was that I didn't have line numbers in the stack traces.  That was because in the Ant build task "debuglevel=vars" had been added. The intent had been to increase the amount of debugging information. But because of the way Ant and the Java -g option work, this had actually meant only variable information. I changed it to "debug=true" which becomes "-g" which means all debug information (file, line, and vars). Once this change percolated through and I started to get stack traces with line numbers, then I could see which path was being taken in the code.

One big step forward was when I was finally able to recreate the bug. Running random updates (of certain kinds) in a bunch of threads would encounter the bug within a few seconds. It wasn't the ideal recreation because the bug would occur buried within a lot of other activity, so it still wasn't possible to determine exactly what was happening.

I couldn't be 100% sure that what I was able to recreate was the same bug, but the end result was more or less identical - two transactions deleting the same record. But confusingly, the errors that I saw were about duplicate records being output, leading me to spend a bunch of time looking at the output code.

A huge mistake that I made repeatedly, without realizing it, was that I was building one variation of the jSuneido jar, and then testing with a different out of date one. So I wasn't actually testing with the changes I was making. This was because, for faster turnaround, I wasn't running a full build, I was just building the main jar that we deploy. But I was testing using the jar with Win32 support so I could use the IDE. This explained the totally baffling behavior where the debugging output that I was 100% certain should be triggered didn't appear at all. Which confused me and made me think I was totally wrong in my ideas about what was happening.

This mistake cost me about 4 days. I actually had the bug fixed, but it kept happening because I was testing with the old jar. Of course, since the bug still happened I assumed that I had not located it yet and I went looking for it in other places where, of course, I didn't find it.

Even worse, I thought my method of recreating the bug was quite "fragile". For instance, it would not happen running in the Eclipse debugger. Coming from C and C++, I didn't find that too surprising. And although Java should be more predicable, there would still be timing and threading differences which could affect concurrency. But I was totally wrong - the reason I couldn't recreate it within Eclipse was that I was running the latest code, which had the fix. Arghhh!

The actual bug and fix are obvious in hindsight. Throughout the long process I suspected that would be the likely result. But that didn't make it any easier, in fact it made it even more frustrating.

jSuneido's database uses optimistic concurrency. That means concurrent transactions proceed independently without any locking. Then when it comes time to commit, they verify that nothing has happened that would conflict. For example, they might find that another transaction has output a duplicate key. In which case the transaction will abort due to the conflict. Or it might find that another transaction has deleted a key that we also deleted. And that's where the bug was. I had made the assumption (back when I wrote this code) that it was ok if two concurrent transactions deleted the same key. After all, the end result is the same. And it's still serializable (i.e. the result is as if the transactions had happened one after another instead of concurrently).

The problem is not the deletes by themselves. If that was all the transactions were doing, my logic was correct. But transactions aren't that simple. They perform other actions based on whether the delete succeeded. For example, deleting an old version of a record and outputting a new version.  If you allow two transactions to think they deleted the old version, then they will, incorrectly, both output a new version. (leading to the duplicate outputs I was seeing)

All I had to do to fix the bug was to make duplicate deletes a conflict, like I already did with duplicate outputs. Two weeks for one line of code. How's that for productivity.

One interesting part of this whole adventure was that although it was a concurrency bug, it wasn't the kind of subtle interaction problem that I really fear. It was, in hindsight, a fairly clear, obvious issue.




Monday, January 05, 2015

Safety First

I recently fixed a long standing (many years) bug in the C++ implementation of Suneido. A friend remarked how you'd wish that after this long all the bugs would have been found. Of course, it doesn't take much code to provide room for bugs to lurk.

The problem that was reported was that if you created one thread inside another that cSuneido would crash. It seemed to happen quite consistently and predictably. That was from the IDE. If you ran the same code without the IDE it worked fine. Or if you played around a bit in the IDE first, it would also work fine.

cSuneido "threads" aren't real threads. They are Windows "fibers" - more like coroutines. They don't actually run concurrently, but they allow cooperative multi-tasking. The big advantage is that since you control when the task switching happens and can do it at "safe" points in the code, you don't have to worry about low level concurrency issues. The downside is that you can't take advantage of multiple cpu's. But this was implemented at a time when no one had multiple cpu's and Moore's Law was still happily improving single cpu performance.

Suneido's C++ fiber code had a std::vector of fibers. It also had a main fiber, separate from the vector. The current fiber was a reference (pointer) to either the main fiber or an element of the vector.

Even from that minimal description you could probably guess the problem. Vector implementations normally grow by allocating a new larger array, copying over the data, and throwing out the smaller old array. So adding an element to a vector invalidates any references to its content. So the current fiber reference would be pointing to stale data. (It wouldn't actually be a dangling pointer because cSuneido uses garbage collection.) The reference to stale data could cause an "impossible" situation that would lead to a fatal error. (So the problem was nothing to do with creating one fiber inside another, it was simply that creating two fibers in that sequence happened to be one way to expose the bug.)

The problem was rare because it required a specific sequence of events. First, the vector had to grow. Which is why if you played around first (and expanded the vector) it wouldn't happen. Second, the stale reference had to be used in such a way that it caused a problem. Since the data would normally be identical the stale reference wouldn't matter. And the next fiber switch would update it to a valid value so the stale reference wouldn't hang around.

Actually, I think there was at least one more potential problem scenario. When fibers ended they were removed from the vector. This probably wouldn't cause a reallocation (many implementations never shrink the array) but it would invalidate any references after that item. You'd either end up with a reference to the wrong item or past the end of the array.

I'm a little embarrassed to discover such a long standing blatant mistake, and a newbie mistake at that. All the times I've looked at that code and I never picked up on it. Ouch.

But to me the real moral of the story is "don't use unsafe languages". Interestingly, this bug was not a memory management issue since cSuneido (unlike almost all C++ programs) uses garbage collection. It's just a result of C++ allowing unsafe raw pointers/references.

C++ fans would tell you that modern C++ has plenty of high level features that are "safe". But the point is that it still has lots of unsafe features. (And AFAIK there is no way to enforce use of a "safe" subset. And C++ continues to resist "real" garbage collection.) I would much rather work in a language like Java or Go (or others) that just don't allow unsafe code of this nature, and eliminate a whole class of problems. Figuring out my high level issues is challenging enough without worrying about unsafe low level issues.

Wednesday, March 26, 2014

B-tree Range Estimation

One of the trickier issues to deal with in Suneido is when the database query optimizer picks what seems like a poor strategy. One of the difficulties is that these issues are usually data dependant - so you need to do the debugging on a large database.

Suneido's query optimizer is fairly straightforward, but even on relatively simple queries there are a lot of possible strategies and it can be quite hard to understand the end results.

We had an issue recently with jSuneido where the sort could be satisfied by an index, but the strategy it chose was reading by a different index and then sorting (with a temporary index).

It wasn't hard to discover that it thought reading by the other index was enough faster to justify the temporary index. The problem was it was wrong.

It came down to the the btree range estimation. It was estimating the same key range quite differently for the two indexes, where they should have been exactly the same.

One of the important choices in query optimization is which indexes to use. To help with this, Suneido uses the index B-trees to estimate how "selective" a given range of index keys is, i.e. what fraction of the records does a range include. Because the query optimizer looks at lots of possible strategies (combinatorial explosion) you want this estimation to be fast. You don't want to read the entire index.

Strangely, I used the identical approach on both cSuneido and jSuneido, but they ended up choosing different strategies for the same data.

The code was doing a lookup on the "from" and "to" keys, estimating the position of the key from the path down the tree. Because a single path down the tree only looks at a few nodes out of a potentially large number, it has to assume that the rest of the tree is balanced and node sizes are "average".

It didn't take long to discover a rather blatent bug in both jSuneido and cSuneido. I was averaging the node sizes of the "from" search and the "to" search in order to get a better idea of the average node size on each level. But I wasn't adjusting the position within the node. For example, if the "from" search went through position 5 of a node of size 10, and the "to" search went through position 25 of a node of size 30, when I average the node sizes it now thought the "to" search went through position 25 of a node of size 20 - obviously wrong. On the positive side, if the node sizes don't vary too much then it doesn't have a big affect.

One reason why this bug hadn't surfaced yet is that the exact estimates aren't that important since the optimizer is just comparing whether different indexes are better or worse, not what the absolute numbers are.

That bug was easy enough to fix, and I came up with a much simpler way to write the code, but I still wasn't getting very accurate results. I started running the numbers through a spreadsheet to try to see what was wrong with my calculations.

After banging my head against the wall for a long time I finally realized that the problem was that the trees were actually not very balanced. A B-tree only guarantees that the tree is balanced in terms of height i.e. all the branches are the same length. It does not guarantee that each branch of the tree leads to the same number of keys. Most B-tree allow nodes to vary between half empty and full. When a node gets full it is split into two half full nodes.

However, if you add keys in order, this leads to most nodes only being half full. So Suneido uses a common optimization to split unevenly if a node gets full by adding on the end. In the "worst" case (in terms of balance) this leads to the root of the tree having a left branch that is full, and a right branch that has a single key. That is exactly what my data looked like in the "bad" case, but I hadn't realized the significance.

Side note - this optimization applies more to B-trees that use fixed node sizes, like cSuneido. jSuneido's append-only database uses variable sized nodes, so space wastage isn't an issue. However, you still want to keep the branching high to minimize the height of the tree.

My solution was for the estimation code to look at the sizes of all the nodes on the first and second level of the tree (root and one level below), rather than assume they were all the same average size. This doesn't handle the tree being unbalanced below there, but the lower levels of the tree have less of an effect on the final result. Finally I got some results that were at least in the right ballpark, and good enough so that jSuneido now chooses the "correct" strategy.

Maybe I've been spoiled by Java, but the unsafe nature of C++ scares me. I made a stupid bug in the cSuneido changes that wrote one past the end of an array. This passed all the unit tests, but gave some strange random errors later on. In this case it wasn't hard to find the problem, but it makes me wonder.

As usual the code is in version control on SourceForge.

Thursday, January 23, 2014

jSuneido Network Bug

beetle

Our installations run a scheduler as a client. (On jSuneido this could probably just be a thread on the server, but cSuneido is single threaded.)

On Windows, when we shut down the server, the scheduler will exit. On Linux the scheduler would hang.

I narrowed it down to a simple test case (on OS X, which seemed to behave like Linux)
  1. start the server
  2. start a client REPL
  3. from the client,execute: ServerEval("Exit")
  4. server exits
  5. client hangs (on Linux but not on Windows)
Strangely, if you killed the server (with Ctrl+C) then the client would get an exception instead of hanging.

I assumed that the client was blocking when it tried to read the response from the ServerEval (which never came because the server had terminated). And that on Linux, for some reason, it didn't recognize the socket was closed when it was blocked reading, although that didn't make a lot of sense.

I ran the client in the debugger and when it was hung, I paused it to see where it was. Sure enough it was in the socket read.

I searched the web trying to find anything related. There wasn't much, which was surprising. Most problems like this are documented by someone. 

But I did notice some of the code examples were checking the return value from channel.read and I wasn't. The documentation said read returns -1 when "the channel has reached end-of-stream". That didn't sound like channel closed to me, but it seemed like I should be checking it anyway.

And that was the problem. It wasn't actually blocking on the read, the read was returning -1, but I was looping until I read all the data, and that's what was hanging it.

To verify, I restored the code, made it hang, and checked the CPU usage - sure enough the client Java was at 100% (because it was in a tight loop calling channel.read over and over).

I'm still not sure why killing the server behaves differently from exiting normally. I guess the socket gets closed differently. (i.e. gracefully or not)

In hindsight it seems like an obvious bug in my code (not checking the return value). I think what threw me off was that it worked fine in Windows. Java is usually pretty good at hiding operating system differences, but not in this case.

Friday, May 03, 2013

An Amusing Bug

I recently realized that the block form of Suneido's string.Replace was a more efficient way to "map" over strings.

As I mentioned in my recent post on String Building Internals, I also discovered cSuneido's string.Replace didn't handle nul's. I fixed this problem and we sent out the new suneido.exe to our beta customers.

And we started to get support calls that PDF attachments weren't being sent properly. Sure enough it was the new version of Base64.Encode that used string.Replace.

But I had tests, and we had also tested manually and it worked fine. We got one of the problem files from a customer and sure enough it failed.

Digging into it, I could see that it was only encoding part of the file. That seemed a bit like the previous nul problem, which led me in the wrong direction for a while.

More testing revealed it was encoding the first 39996 characters of the file. That seemed like an odd number. My first thought was that it was in the general vicinity of SHORT_MAX or 32767. When I first wrote the C++ version of Suneido I was still trying to use short int's when possible. This has led to a number of issues since SHORT_MAX isn't very big in modern terms. But the relevant code wasn't using any short int's.

But I noticed a magic number of 9999 in the code. Base64 encode outputs groups of 4 characters. 4 x 9999 - 39996. Aha!

string.Replace takes an optional argument for how many replacements to do. Usually, you either want 1 or all. When not specified, the count was defaulting to 9999. For "normal" usage, that's plenty. But when using replace to map large strings, it obviously isn't.

I changed it to INT_MAX and that fixed the problem. Out of curiosity  I went and checked the jSuneido code. (It did not have the same issue.) Frustratingly, it already had INTMAX. I don't think I foresaw this issue when I ported the code, it probably just bugged me to have a magic number.

I'm not sure why this strikes me as amusing. It just seems funny that the "bug" was not something obscure, just a badly chosen limit, that no doubt seemed entirely reasonable at the time.

Wednesday, June 17, 2009

Mac OS X Hangs from Lightroom

More often than I'd like lately, when I import photos into Lightroom (from an SD card in a USB reader) it hangs my whole Mac.

I can understand how Lightroom could crash, but I'm a little baffled that it manages to freeze the whole operating system. You get the spinning beachball and you can't to anything - can't switch apps, can't pull down menus, can't do Ctrl + Eject to shutdown.

At first I thought it was because I would start to view photos while it was still downloading, so I quit doing that, but it's still happening.

The strange thing is that Lightroom is normally very stable. It doesn't crash or hang when I'm working in it, no matter what I do. I suspect this is more of an OS bug, or at least a bad interaction between the app and the OS.

This seems to have become a problem recently, perhaps related to either Lightroom updates, or OS X updates, or both. (That's one of the downsides of all these automatic updates.)

I wonder whether it has someting to do with importing directly from the SD card through USB. Not that that is an excuse for the OS to die, but I could see where there would be some low level device stuff going on. Maybe I should copy the files to the Mac and then import from there. Although that's quite a bit more hassle since Lightroom auto-detects memory cards and goes straight to Import. However, I think you can set up Lightroom to "watch" a directory, so maybe I could do that and copy to that directory.