[YSQL] Read latencies spike significantly (over 10ms), when there is a large concurrent write workload in the system.

[rthallamko3]

Description

In the presence of writer threads, simple reads in SQLInserts workload (even without indexes), in RF-3 setting takes over 10ms. Once when writer threads complete their job, latency for reads comes down to 2-3ms.

Repro: Setup Rf-3 cluster on a mac, run SqlInserts with 6 write threads [1] and 24 write threads [2]. Notice the spike in read latencies from about 2-3ms to 9-10ms.

[1]

java -jar yb-sample-apps.jar --workload  SqlInserts --nodes 127.0.0.1:5433 --num_threads_write 6
- Read: 0.00 ops/sec (0.00 ms/op), 0 total ops  |  Write: 1332.91 ops/sec (8.88 ms/op), 6670 total ops  |  Uptime: 10025 ms |
- Read: 598.01 ops/sec (6.56 ms/op), 2993 total ops  |  Write: 1289.30 ops/sec (4.65 ms/op), 13123 total ops  |  Uptime: 15030 ms |
- Read: 696.16 ops/sec (2.87 ms/op), 6477 total ops  |  Write: 1331.81 ops/sec (4.50 ms/op), 19788 total ops  |  Uptime: 20035 ms |
- Read: 649.23 ops/sec (3.08 ms/op), 9726 total ops  |  Write: 1221.33 ops/sec (4.91 ms/op), 25900 total ops  |  Uptime: 25039 ms |

[2]

 java -jar yb-sample-apps.jar --workload  SqlInserts --nodes 127.0.0.1:5433 --num_threads_write 24
- Read: 0.00 ops/sec (0.00 ms/op), 0 total ops  |  Write: 1648.15 ops/sec (27.33 ms/op), 8247 total ops  |  Uptime: 10026 ms |
- Read: 136.69 ops/sec (28.54 ms/op), 684 total ops  |  Write: 1786.63 ops/sec (13.43 ms/op), 17187 total ops  |  Uptime: 15030 ms |
- Read: 197.08 ops/sec (10.13 ms/op), 1670 total ops  |  Write: 1973.80 ops/sec (12.15 ms/op), 27062 total ops  |  Uptime: 20033 ms |
- Read: 208.62 ops/sec (9.58 ms/op), 2714 total ops  |  Write: 2160.73 ops/sec (11.11 ms/op), 37875 total ops  |  Uptime: 25038 ms |

[kmuthukk]

@spolitov wrote:

we had logic to avoid picking up read time at LRT layer, for the first query in transaction. I don’t remember details, may be it was done only for YCQL. or may be it is just broken for YSQL. but, as far as I understand, it is the reason for 10ms latency here. We need to fix ysql code, to avoid picking read time in this scenario.

When read time is picked by YSQL layer, it matches clock at that moment - ht2. A moment before that tserver started to replicate write request - ht1. Then read request arrives to tserver, and it should wait until safe time >= read time.

Read time is ht2, and safe time < min not replicated operation. Since ht1 < ht2, we have to wait until this operation is replicated. And replication takes round trip time between nodes.

In multi-region situations since round-trip between nodes to replicate the write request at ht1 can be high.. for example 10ms between east-1 and east-2 AWS regions, this can add about a 10ms additional latency.

For SELECTs that involve single-shard we could optimize this by letting the TServer pick the read-time rather than YSQL layer.

[rkarthik007]

Read time is ht2, and safe time < min not replicated operation. Since ht1 < ht2, we have to wait until this operation is replicated. And replication takes round trip time between nodes.

Assuming above that ht2 is the safe time for any tablet. A few points about this:

1. Even if ht2 > ht1 - there could be cases for a particular key (row or row/col combo) where there may be no updates queued for replication for that row. And the RPC from this query coordinator to that tserver would force the hybrid time of the tserver to at least ht2. Thus, in these cases, even if a new update were to come in, it CANNOT get in with a commit timestamp lower than ht2 - meaning it is safe to serve the read for that particular row at ht2 even if the safe time for the tablet as a whole is lower.
2. The above property can esp be made use of in cases like foreign key checks (where there may be no updates to the parent row), insert-only workloads (where there is no "update" for the row being inserted - even in distributed transaction scenarios where there are indexes on the table), or even in many regular SELECT operations.

The above would yield a huge win in multi-region scenarios, so are probably worth considering.

[andrei-mart]

It may be related to #11477
Both mention big write and read delay, but in #11477 they are issued by the same session, big write and follow up read.

[rthallamko3]

Reran the CassandraKeyValue and SqlInserts workloads against RF-3 single zone deployment cluster.

1. CassandraKeyValue workload with different number of write threads (8,32,64). The increase in the number of write threads didn't necessarily increase the latencies of the reads. It stayed around 1-2ms range.

java -jar yb-sample-apps.jar --workload CassandraKeyValue --nodes 172.150.31.201:9042 --num_threads_write 8

• Read: 16471.17 ops/sec (1.17 ms/op), 82522 total ops | Write: 2977.80 ops/sec (2.59 ms/op), 14893 total ops | Uptime: 5012 ms | maxWrittenKey: 14891 | maxGeneratedKey: 14900 |
• Read: 20108.38 ops/sec (1.19 ms/op), 183094 total ops | Write: 2652.70 ops/sec (3.01 ms/op), 28158 total ops | Uptime: 10013 ms | maxWrittenKey: 28157 | maxGeneratedKey: 28165 |
• Read: 20068.76 ops/sec (1.20 ms/op), 283446 total ops | Write: 2665.03 ops/sec (3.00 ms/op), 41484 total ops | Uptime: 15013 ms | maxWrittenKey: 41480 | maxGeneratedKey: 41491 |
• Read: 20085.04 ops/sec (1.19 ms/op), 383877 total ops | Write: 2635.65 ops/sec (3.03 ms/op), 54663 total ops | Uptime: 20013 ms | maxWrittenKey: 54659 | maxGeneratedKey: 54670 |

java -jar yb-sample-apps.jar --workload CassandraKeyValue --nodes 172.150.31.201:9042 --num_threads_write 32

• Read: 8947.46 ops/sec (1.50 ms/op), 44832 total ops | Write: 8579.92 ops/sec (3.14 ms/op), 42918 total ops | Uptime: 5013 ms | maxWrittenKey: 42898 | maxGeneratedKey: 42951 |
• Read: 15670.19 ops/sec (1.53 ms/op), 123207 total ops | Write: 7713.35 ops/sec (4.15 ms/op), 81489 total ops | Uptime: 10013 ms | maxWrittenKey: 81476 | maxGeneratedKey: 81520 |
• Read: 15581.30 ops/sec (1.54 ms/op), 201120 total ops | Write: 7902.75 ops/sec (4.05 ms/op), 121005 total ops | Uptime: 15013 ms | maxWrittenKey: 120981 | maxGeneratedKey: 121036 |
• Read: 15316.47 ops/sec (1.57 ms/op), 277707 total ops | Write: 7740.34 ops/sec (4.13 ms/op), 159709 total ops | Uptime: 20014 ms | maxWrittenKey: 159691 | maxGeneratedKey: 159740 |

java -jar yb-sample-apps.jar --workload CassandraKeyValue --nodes 172.150.31.201:9042 --num_threads_write 64

• Read: 3154.49 ops/sec (1.82 ms/op), 15804 total ops | Write: 11675.33 ops/sec (3.74 ms/op), 58393 total ops | Uptime: 5012 ms | maxWrittenKey: 58314 | maxGeneratedKey: 58457 |
• Read: 11698.63 ops/sec (2.05 ms/op), 74315 total ops | Write: 12006.82 ops/sec (5.33 ms/op), 118434 total ops | Uptime: 10012 ms | maxWrittenKey: 118422 | maxGeneratedKey: 118497 |
• Read: 11876.46 ops/sec (2.02 ms/op), 133702 total ops | Write: 11763.15 ops/sec (5.44 ms/op), 177253 total ops | Uptime: 15013 ms | maxWrittenKey: 177242 | maxGeneratedKey: 177316 |
• Read: 11583.13 ops/sec (2.07 ms/op), 191621 total ops | Write: 11886.28 ops/sec (5.38 ms/op), 236688 total ops | Uptime: 20013 ms | maxWrittenKey: 236665 | maxGeneratedKey: 236751 |

2. SqlInserts workload with different number of write threads (8,32,64). The increase in the number of write threads impacted the overall latencies of both reads and writes significantly.

java -jar yb-sample-apps.jar --workload SqlInserts --nodes 172.150.31.201:5433 --num_threads_write 8

• Read: 697.74 ops/sec (2.61 ms/op), 3498 total ops | Write: 2517.03 ops/sec (3.06 ms/op), 12588 total ops | Uptime: 5016 ms |
• Read: 902.53 ops/sec (2.21 ms/op), 8012 total ops | Write: 2897.90 ops/sec (2.76 ms/op), 27080 total ops | Uptime: 10017 ms |
• Read: 900.51 ops/sec (2.22 ms/op), 12515 total ops | Write: 2885.14 ops/sec (2.77 ms/op), 41507 total ops | Uptime: 15017 ms |
• Read: 897.92 ops/sec (2.23 ms/op), 17005 total ops | Write: 2890.75 ops/sec (2.77 ms/op), 55962 total ops | Uptime: 20018 ms |

java -jar yb-sample-apps.jar --workload SqlInserts --nodes 172.150.31.201:5433 --num_threads_write 32

• Read: 129.10 ops/sec (10.40 ms/op), 647 total ops | Write: 3560.01 ops/sec (7.58 ms/op), 17804 total ops | Uptime: 5015 ms |
• Read: 290.09 ops/sec (6.88 ms/op), 2098 total ops | Write: 4307.93 ops/sec (7.43 ms/op), 39349 total ops | Uptime: 10015 ms |
• Read: 296.37 ops/sec (6.75 ms/op), 3580 total ops | Write: 4406.56 ops/sec (7.26 ms/op), 61385 total ops | Uptime: 15016 ms |
• Read: 290.54 ops/sec (6.88 ms/op), 5033 total ops | Write: 4279.90 ops/sec (7.47 ms/op), 82788 total ops | Uptime: 20017 ms |

java -jar yb-sample-apps.jar --workload SqlInserts --nodes 172.150.31.201:5433 --num_threads_write 64

• Read: 14.56 ops/sec (48.04 ms/op), 73 total ops | Write: 2977.45 ops/sec (14.65 ms/op), 14890 total ops | Uptime: 5014 ms |
• Read: 153.16 ops/sec (13.06 ms/op), 839 total ops | Write: 4427.77 ops/sec (14.45 ms/op), 37032 total ops | Uptime: 10015 ms |
• Read: 144.19 ops/sec (13.83 ms/op), 1560 total ops | Write: 4356.59 ops/sec (14.70 ms/op), 58818 total ops | Uptime: 15015 ms |
• Read: 145.98 ops/sec (13.72 ms/op), 2290 total ops | Write: 4131.49 ops/sec (15.49 ms/op), 79477 total ops | Uptime: 20016 ms |

[rthallamko3]

@amitanandaiyer , can you take a stab at it?

[rthallamko3]

#11886 should fix the single tablet latency issues.