kv: write a test for transaction starvation

[petermattis]

[spencerkimball]

We restart serializable transactions whenever they're forced to adjust their time stamps over the course of execution. This occurs because they try to write to keys that were more recently read than the time stamp at which the Txn started. We use a priority system which exponentially bumps a restarted txn's priority, so starvation, even in a situation with a lot of contention, is avoided in log time. Would be great to actually test this though! That test would involve a relatively long running txn...say writing to 100 keys while many other concurrent readers are accessing the same keys. Such a Txn should only restart once according to our current implementation.

The more interesting restart case is a relatively long running Txn trying to write 100 keys with many concurrent writers also contending for same keys. In this case the long running Txn is expected to abort and restart and we expect this to happen log(N) times, where N is the number of concurrent writers.

[cosmicturtlesoup]

I'd be interested in tackling this issue...

[tbg]

@cosmicturtlesoup cool. It's all yours.

[tbg]

via @cosmicturtlesoup:

Large numbers of concurrent txns against a single key on a single node will fail to commit. Small numbers work fine.

For example, 55 concurrent txns finish in just a few seconds, but if the same test is run with 105 concurrent txns, only a small number complete (like 5 or so) and even those take a long time to commit... and then the system fails to commit any further txns and eventually times out.

Tested in both CentOS7 and Ubuntu 15.04. I'm submitting a pull request shortly which demonstrates this issue.

Sample args (test added in pull req):
make acceptance TESTS=TestSingleKeySingleNodeConcurrentTxn TESTFLAGS="-num 3 -numTrans 55 -d 4s -v"

See example for output of a small test which passes and larger test which fails.

It's normal that things will fall into pieces eventually (with any database). The test in #1959 is the definitive worst case: all Txns fighting for a single key. The goal here is more fine-grained: compare the expected performance against the actual one. It's still interesting to see where between 55 and 105 destructive effects creep in, though. That would involve measuring restarts (as suggested in #628) and run times of individual transactions to see if there are any sudden spikes or races emerging.
For starters, could you sample total run time of the test with k=5,10,...,105 concurrent txns? Would be interesting to see that curve.

[cosmicturtlesoup]

Actually, I have code to capture the restart counts but had distilled that out to the simplest change that shows the timeout behavior. I'll add that code back in and report back.

In the meantime, attached are the results for 4 runs of between 5 and 80 or so concurrent txns. As you can see from the numbers, when things run sanely the process finishes in under 30s, but if/once things go bad, they stay bad until the timeout period.

Run4 is of particular note because there was a 5min timeout at 55 and 80 txns but 60/65/70/75 were ok.

The other runs were terminated manually after several minutes of no progress. Run1 chewed up several GB of ram before I stopped the process. The other runs were more well behaved (didn't grow in ram usage much even during the "no progress" phase -- where no progress means no commits over a minute or two).

[cosmicturtlesoup]

@tschottdorf: Question -- I'm exposing the client.Txn.txn to get at the proto.Transaction.Epoch which I understood to be the count of the txn restarts. However, Epoch+1 doesn't always match the number of times the txn closure is called -- there's no obvious pattern as to how much they differ. Should the Epoch count in client.Txn.txn be the number of retries, or am I looking at the wrong Epoch field?

[tbg]

the closure is called again after each restart, but also after each abort. It's going to be most convenient if you start counting the calls, probably no need to distinguish between restarts and aborts (after all, your test only has write/write conflicts and they will always abort someone). That saves you the need to expose any of the internals. If things get slow (and nothing is seriously wrong) then likely transactions just wind up backing off for way too long, to the point where they choke each other to death.
Could you investigate a few individual transaction's traces and present them here? You can get traces via --vmodule=monitor=2. You can grep out transactional traces by grepping for '^t' (or some variation thereof) and then the output can be piped through sort. Then just look at some of the traces that took a long time and post some of them.
One thing that you might want to try is hard-coding a lower initial and maximum backoff in store.go:

var (
    // defaultRangeRetryOptions are default retry options for retrying commands
    // sent to the store's ranges, for WriteTooOld and WriteIntent errors.
    defaultRangeRetryOptions = retry.Options{
        InitialBackoff: 50 * time.Millisecond,
        MaxBackoff:     5 * time.Second,
        Multiplier:     2,
    }

Try 50ms max and initial 5ms and see whether it dramatically improves results.