perf: excessive not lease holder errors running tpcc

[petermattis]

When starting up tpcc we see a spike in not lease holder errors that eventually settles down to a steady stream that never completely goes away. This was noticed on a cluster running tpcc-10k. I'm not sure if it happens on smaller tpcc datasets. There might be a simple explanation for this (e.g. the cluster has 54k ranges). My simple attempts to ensure that the leaseholder cache is fully populated on each node in the cluster were unable to completely eliminate the errors.

[bdarnell]

The caching in DistSender is not very smart. We're pretty quick to invalidate the cache if we get any error (especially a timeout). So if the cluster is just barely able to handle its load, we might get a timeout, invalidate the cache, and then the next query would have a good chance of a NotLeaseHolderError. I don't think we're setting short deadlines on the TPCC requests themselves, but we do have short deadlines on some internal operations such as liveness updates.

[petermattis]

The not leaseholder errors seem to have decreased over time as the cluster has remained up. They are now down in the 1-2/sec range. So perhaps my efforts to populate the leaseholder cache were failing.

[jordanlewis]

This is what it looks like on TPCC-1000:

[jordanlewis]

Not a great screenshot. This is 1000, 2000, and 3000 next to each other on a cluster that didn't have any splits or partitioning.

[nvanbenschoten]

So perhaps my efforts to populate the leaseholder cache were failing.

What were these efforts exactly?

[petermattis]

What were these efforts exactly?

Running select count(*) on the various tables pointed at the various nodes. But perhaps I need to do that with distsql=off. I know distsql populates the range cache, but perhaps not 100% of the time.

[tbg]

@petermattis what's the appropriate (i.e. smallest) setting in which you think I could repro this?

[petermattis]

@tschottdorf I don't know. I'm going to set up a 3-node cluster for tpcc-1k tonight. I'll point you at it if it repros there. I don't recall seeing this problem at tpcc-2k or tpcc-5k, but I also wasn't paying attention.

[nvanbenschoten]

I set up a TPCC-1 3-node cluster and ran the following on all nodes before applying load:

USE tpcc;
SET DISTSQL = OFF;
SELECT COUNT(*) FROM warehouse;
...
SELECT COUNT(*) FROM order_line;

After doing so, I turned on the loadgen. I saw only one not leaseholder error spike, which amounted to about 8 errors. After this point, I did not see a single error.

One thing I'm curious about is how many nodes were in the cluster that saw this initial spike. @a-robinson, would you expect rebalancing to be less stable on a larger cluster?

Also, doing this experiment brought up an interesting problem. When I tried it initially on a TPCC-5k cluster, it took about half an hour because of the large amount of data that each COUNT(*) needed to fetch. I think it would be worth adding a SQL command to fetch the leaseholder for all ranges in a table and prime the leaseholder cache without needing to actually perform a COUNT(*) and scan anything from disk. This command would probably also have the effect of leasing the table's descriptor, which would help out with #23510. We could then run this on all tables before starting a load generator and avoid any initial performance hit.

[petermattis]

One thing I'm curious about is how many nodes were in the cluster that saw this initial spike.

I saw this on a 24-node cluster. Testing tpcc-2k last night on an 8-node cluster also showed a spike, but it went away quickly.

I think it would be worth adding a SQL command to fetch the leaseholder for all ranges in a table and prime the leaseholder cache without needing to actually perform a COUNT(*) and scan anything from disk. This command would probably also have the effect of leasing the table's descriptor, which would help out with #23510. We could then run this on all tables before starting a load generator and avoid any initial performance hit.

Agreed.

[petermattis]

Moving to 2.1 as I don't think there is anything to do here for 2.0.

[a-robinson]

One thing I'm curious about is how many nodes were in the cluster that saw this initial spike. @a-robinson, would you expect rebalancing to be less stable on a larger cluster?

No, I wouldn't expect it to be any less stable. I wish I had written something down about it, but I half-remember looking at @petermattis's roachprod cluster after he complained about this on slack and not seeing any rebalancing activity.

Moving to 2.1 as I don't think there is anything to do here for 2.0.

Agreed given where we are in the release cycle, but we should be more actively updating the leaseholder cache when a replica successfully serves a request, as alluded to by the discussion on #23601.

[petermattis]

@a-robinson Didn't you fix some bugs related to leaseholder errors? Can this issue be closed?

[a-robinson]

I did fix a couple problems, although I also found a problem that it looks like I never opened an issue for that can cause large spikes of the errors.

During a lease transfer, there can be a period of time in which the old leaseholder redirects requests to the new leaseholder, but the new leaseholder hasn't applied the lease yet and thus redirects requests to the old leaseholder. This can cause requests to ping pong back and forth from the dist sender to one replica then the other, over and over and over. When network latencies are low, this can lead to thousands of not-leaseholder errors.

I managed to grab these verbose logs from logspy while looking into the spikes: https://gist.github.com/a-robinson/eb931e4987219060f3107e6bd371c625

Here's a brief excerpt demonstrating the problem:

I180616 05:52:17.728179 20503404 kv/dist_sender.go:1317  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] error: (err: [NotLeaseHolderError] r55752: replica (n30,s30):5 not lease holder; current lease is repl=(n16,s16):1 seq=0 start=1529128337.569175562,0 epo=9 pro=1529128337.569181772,0) <nil>; trying next peer (n16,s16):1
I180616 05:52:17.767118 20503404 kv/leaseholder_cache.go:97  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] r55752: updating leaseholder: 30
I180616 05:52:17.767203 20503404 kv/dist_sender.go:1317  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] error: (err: [NotLeaseHolderError] r55752: replica (n16,s16):1 not lease holder; current lease is repl=(n30,s30):5 seq=25 start=1529123107.545581542,0 epo=9 pro=1529123107.545589819,0) <nil>; trying next peer (n30,s30):5
I180616 05:52:17.771239 20503404 kv/leaseholder_cache.go:97  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] r55752: updating leaseholder: 16
I180616 05:52:17.771327 20503404 kv/dist_sender.go:1317  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] error: (err: [NotLeaseHolderError] r55752: replica (n30,s30):5 not lease holder; current lease is repl=(n16,s16):1 seq=0 start=1529128337.569175562,0 epo=9 pro=1529128337.569181772,0) <nil>; trying next peer (n16,s16):1
I180616 05:52:17.774656 20503404 kv/leaseholder_cache.go:97  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] r55752: updating leaseholder: 30
I180616 05:52:17.774740 20503404 kv/dist_sender.go:1317  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] error: (err: [NotLeaseHolderError] r55752: replica (n16,s16):1 not lease holder; current lease is repl=(n30,s30):5 seq=25 start=1529123107.545581542,0 epo=9 pro=1529123107.545589819,0) <nil>; trying next peer (n30,s30):5
I180616 05:52:17.841658 20503404 kv/leaseholder_cache.go:97  [client=10.142.0.54:39264,user=root,txn=61557e35,ts=1529128299.977196718,4,n12] r55752: updating leaseholder: 16

The spike of errors:

Proof of a lease transfer happening right around that time on that range:

[nvanbenschoten]

Yeah, this is exactly what I saw in #22837. We'll want to do something about this sometime soon.

[a-robinson]

Alright, I'm going to close this in favor of #22837 then. Thanks @nvanbenschoten.