Eclipse Bug

This one had me puzzled for a while. I went to run some jSuneido code in Eclipse and I got a weird verifyError i.e. something wrong with the byte code. Probably just a glitch, a corrupted file or something. I recompiled the code. Same error. Meanwhile, all the jUnit tests (running all the time through Infinitest) were passing fine. And when I built the final jar, it worked fine as well.

Maybe my Eclipse or my configuration was messed up. I connected to my office machine and tried it there. And got the same error.

The problem was, I couldn't remember when this last worked. I've been mostly working in Go on gSuneido. I've made the occasional minor changes in jSuneido but probably didn't try to run anything inside Eclipse.

Maybe it was a Java 14 issue? Eclipse isn't very good at supporting the latest version of Java. Currently you have to install a patch to get Java 14 support. So I installed Java 13 and tried again with that. Same error.

I tried reinstalling Eclipse (2020-03). Didn't help. I tried installing the previous version of Eclipse (2019-12). Still no good.

I have to admit I was getting quite frustrated by this point. I'd had several computer issues in the last few days and I didn't need yet another one. I even considered switching IDE's. I installed JetBrains intelliJ (I have a license for all their products) and it had no problem running the code.  But I struggled just to get that far with intelliJ. It's quite an investment to learn an IDE and I didn't really want to start over. Especially when I'm not doing much Java development these days.

I narrowed it down to a problem with the Eclipse Java compiler (they have their own, separate from the JDK). If I compiled with the JDK it was fine, but if I compiled with Eclipse, it wouldn't work inside Eclipse or outside.

I vaguely remembered that I had fallen a bit behind with Eclipse and had jumped over the previous version (2019-12). So I installed 2019-09. And it worked! Finally!

By this point I was fairly sure it was an Eclipse Java compiler bug. I searched the Eclipse bug database (and the web) but couldn't find anything related.

I figured I should report a bug, but was, as usual, hesitant. There are lots of Eclipse users, why was I the only one to run into this? Was it something I was doing wrong? (Although in that case, why did the JDK work fine?) It sounds silly, but I was afraid of looking stupid in public.

I decided if I could create a simple example that reproduced the issue, then I'd file a bug. Luckily, by then I had a good idea of the issue and it wasn't hard to make the example.

Basically the bug came from the equivalent of:

MyFunc(condition ? derived1() : derived2())

derived1 and derived2 returned private classes with a common public parent (all from another package).

The type of the ?: expression should be the common public parent. But in the Eclipse bytecode it was Object (basically an unknown type). For some reason it wasn't looking past the private classes to see the common public parent. Curiously, if I assigned the ?: expression to a variable of the parent type, it handled that fine. Or if I rewrote the ?: as an if-else it was also fine. Using javap to look at the bytecode I could see the JDK stack map showed the correct parent type, but the Eclipse stack map showed Object.

I posted the bug and the next morning I saw:

I will investigate. Reproduced with your example.
Thanks! Great test case. This is really helpful

It was good to see it was valid. Later comments confirmed the bug and that the fix was trivial and would go into future versions.

Concurrency is Hard episode n+1

For almost a year a bug has been haunting me. Once every few thousand server startups, the server would hang. It wasn't totally frozen - the server monitor web page was still running and the server would still accept connections (but not service them). Simply restarting would fix it. There was no discernible pattern, customers got it at random and there didn't seem to be anything in common between them.

At first we wrote it off to bad hardware or server glitches. But it continued to happen a little too consistently for that to be the cause.

It was hard to pinpoint exactly when it started since we didn't pick up on it right away. But we knew the rough time frame. So I could look at version control and see what changes I'd made. But nothing seemed like it could cause it. I could have rolled back changes, but most of them were bug fixes so I wasn't keen to do that. And for all we knew it could have been a Windows update or a Java update or changes to the application code that triggered it.

Once we recognized we had a problem, my first thought was that it was some kind of deadlock during the startup sequence. No problem, Java has ThreadMXBean findDeadlockedThreads. It worked great when I forced deadlocks. I scheduled it to run five minutes after startup. It didn't find anything. I scheduled it to run every five minutes. Still didn't find anything. So either it wasn't a deadlock, or the deadlock detection wasn't working. In other words, no progress.

It seems terrible that we had this bug for almost a year. I did work on it, and many hours in total, but it was never really urgent. An individual customer might get it once every six months and they simply had to restart. So there wasn't a lot of external pressure to fix it. It certainly "bugged" me but with no clues it was hard to even know what to try.

I studied the code. I rewrote large sections. I ran the ThreadSafe static analysis tool on it. We added logging in numerous places.

We did stress testing to try and make it happen, although it's hard to "stress test" server startup. All we could do is repeatedly start and stop the server. Of course, it never happened when we did this.

What I really needed was to examine a hung system with a debugger (e.g. jvisualvm). But we only install a JRE on our customers servers, not the full JDK. If it happened consistently on one customer we could have installed the JDK on their server but it didn't. Towards the end I was starting to think about installing the JDK on all our customers. I would have been happy even to make the bug worse so it happened more frequently. At least then I'd have a chance of getting it under the microscope.

Looking at the Java documentation I found you could debug core dumps. So next time we got a chance to access a hung server, we forced a core dump. But we're using a launcher to run as a Windows service, and the launcher meant the debugging tools didn't recognize the core dump. So much for that idea.

One of the problems with Java's "synchronized" keyword is that you can't put any timeouts on it. So towards the end I was considering replacing all my uses of synchronized with explicit locks with timeouts. At least then deadlocks would time out and give me a clue where they were happening. In retrospect, this would have worked to locate where the problem was.

One of the problems was the slow turnaround. After making a change to jSuneido we would run it internally for at least a week. Then we'd roll it out to beta customers, and then finally to the rest of the customers. Then we had to wait for several days to see if the problem reoccured. So after each change I'd have to wait several weeks to see if it made a difference. Of course, there was nothing stopping me from continuing to work on the problem during this time, but the natural inclination was to want to wait and see if the change had worked.

One pattern we noticed was that it seemed to be related to requests to the HTTP server during startup. We weren't aware of that last time we stress tested so I thought it might be something to try. So I set up a server to restart every minute and arranged for a constant stream of HTTP requests. It ran all day without a hiccup. I normally shut down my computer at night. But that was only about 500 restarts, not really enough to have a good chance of detecting something that only happens every few thousand times. What the heck, I left it running overnight.

When I went to check it in the morning I had no expectation of finding anything other than it happily running. So it took me a minute of staring at the screen to realize it had hung! Eureka! Funny to be so excited about managing to hang your software!

I was almost afraid to touch it, for fear of disturbing the hung process. I fired up jvisualvm and did a thread dump. As I'd expected from the beginning, it was a deadlock. Two threads each owning a lock that the other wants.

And still the deadlock detection didn't show anything. I realized the reason was that one of the threads was not waiting on a lock, it was "parked" in Guava cache code. The code it was in was documented as "thread safe". As Inigo says in The Princess Bride, "You keep using that word. I do not think it means what you think it means."

I briefly entertained the (attractive) thought that the deadlock was in the Guava code and not my fault. That would have been nice, although harder to get fixed. But unfortunately it was quite obvious from the thread dump that it was my code that was at fault, despite the one thread being parked in Guava code.

The problem, and one of the lessons from this bug, is that code that calls a user supplied function is never truly thread safe because you can't control what that function does. That's also one of the problems with "functional" code, it is not amenable to static analysis.

In hindsight I realize that ThreadMXBean also has dumpAllThreads. I might have been able to write code to detect when the server hung and dumped the threads automatically. That would have given me the information I needed to solve this. Of course, I had no way to know that before now.

When I started rewriting Suneido from C++ to Java one of the big reasons was that we needed a multi-threaded server, and I thought Java had good concurrency support. But what it has is locks and shared state, which we've come to realize is not a great way to handle concurrency. Even back then I knew that, and I tried hard to minimize locking (which also helps performance) by keeping state thread contained and using immutable data. But I still used a certain amount of locking and concurrent data structures (which commonly use locking). And it's mostly worked out pretty well - jSuneido hasn't had a lot of concurrency problems. However, it's a bit like the lack of safety and garbage collection in C++, if you're careful you can get away with it, but sooner or later it's going to catch you.

When is a PriorityQueue Not Ordered?

aka When does a final field change?

Background

jSuneido limits how long a database update transaction can be active. This is because active update transactions consume resources.

Read-only transactions consume little resources and are not limited. (This is a benefit of the append-only database structure.)

There are two parts to the limiting. If an update transaction commits and it was active more than a certain amount of time (currently 5 seconds) then a warning is logged but otherwise the transaction completes normally.

A separate process runs periodically (currently once per second) and any update transactions that have been active for too long (default 10 seconds) are aborted. A PriorityQueue is used for this so that only the longest running update transaction needs to be looked at.

Problem

Recently I noticed that some of our customers were getting the warning, but the duration given was well over the abort limit. That should have been impossible - the transactions should have been aborted before they reached that point. My first thought was that I had "broken" it with some recent change. But going back through the logs it looked like this had been happening for quite a while.

Searching the logs, I found that there were some transactions getting aborted due to duration, so that part of the code was working at least some of the time.

I added some debugging and found that the problem was that PriorityQueue peek was not returning the oldest transaction. That seemed impossible since by definition PriorityQueue peek returns the smallest element.

I checked my comparator but it was simple and seemed correct. I wrote some equivalent test code and it worked fine.

I started searching on the internet to see if anyone else had run into similar problems. Sure enough they had, but the reason was that they had been modifying the elements after inserting them. (Similar to problems if you modify elements after inserting into hash tables.)

But the field I was ordering by was final so it couldn't be modified.

Or could it? A final field still has to get set at some point. Sure enough, I was inserting the transactions into the queue in the super constructor, which ran before the field was initialized. So the queue insertion was always seeing a value of zero and the order was undefined. Argh!

(Java normally prevents this kind of problem, but I was casting to a derived class in code called by a base class constructor. Moral of the story - avoid tricky code!)

In case you're wondering, I had tested. But it worked when testing since I would only have a single active transaction, and the order was irrelevant.

It was an easy fix to reorganize the code slightly to ensure the queue insertion was done after the field was initialized. (Although that splits what used to be a single synchronized method into two, which makes me nervous about concurrency problems. I think it's ok, hopefully it won't be the subject of a future blog post!)