I’ve been working on writing some prototype code for a CouchDB layer have finally gotten far enough to start analyzing various requests at the transaction tracing level. I’ve come across a somewhat curious behavior that I’m having trouble understanding based on my reading of the commit protocols in FoundationDB.
The following gantt chart shows seven total transactions. The first transaction is a single doc write. The second transaction is a two document write. Then there are five write transactions spawned in parallel that each write five documents.
My question has to do with the way that the commits are ending at different times. With five document writes across five parallel transactions I’m seeing each commit ending about 1-2ms after the previous. Tweaking that test to write fifty documents (i.e., 250 total) across five transactions extends that smear to something along the lines of 5-10ms between commit finish times.
I’m not particularly concerned about the absolute values on timing here as this is just a trace against a local dev server. What I’m finding curious though is that according to the versionstamps that are written as part of the parallel transactions I am getting multiple transactions into a single batch. My understanding is that proxies will batch transactions which are then submitted to resolvers and eventually the transaction logs. Given that, I would have expected to see any transactions that were part of the same batch to have a response from the proxy at roughly the same time rather than what appears to have been some sort of serialization of each commit.
Granted it’s also conceivable that even though transactions move through the system in a batch the transaction logs end up making each transaction durable individually which could explain what I’m seeing. But based on my shallow understanding of the process it was surprising enough I figured I’d ask for help understanding whatever I’m missing.