[DocDB] YCQL scan by indexed column can take longer than client timeout and cause a log spew

[ttyusupov]

Jira Link: DB-8015

Description

This could be reproduced with the following test on GCP n1-standard-4 1-node local cluster with release build at commit 0cbfb04:

./bin/yb-ctl start

CREATE KEYSPACE ks;
USE ks;
CREATE TABLE test_table (key INT PRIMARY KEY, category INT, value INT) WITH transactions = { 'enabled' : true };
CREATE INDEX category_idx ON test_table (category) WITH TABLETS = 2;

python3 -c "for i in range(0, 1000000): print(i, ',', 0, ',', i);" | ./bin/ycqlsh -e "COPY ks.test_table(key, category, value) from STDIN";

./bin/yb-ctl restart --tserver_flags 'client_read_write_timeout_ms=4000,rpc_slow_query_threshold_ms=4000'

time ./bin/ycqlsh -e "PAGING OFF; select * from ks.test_table where category=0;"

Actual result:

time ./bin/ycqlsh -e "PAGING OFF; select * from ks.test_table where category=0;"
<stdin>:1:OperationTimedOut: errors={'127.0.0.1': 'Client request timeout. See Session.execute[_async](timeout)'}, last_host=127.0.0.1

real	0m10.605s
user	0m0.404s
sys	0m0.076s

W0920 18:59:02.334851 249960 cql_rpc.cc:335] CQL Call from 127.0.0.1:57058, stream id: 2 took 25781ms. Details:
W0920 18:59:02.334957 249960 cql_rpc.cc:338] cql_details {
  type: "QUERY"
  call_details {
    sql_string: "select * from ks.test_table where category=0;"
  }
}

Also a lot of the following error messages in logs:

I0920 18:58:42.527166 249960 client_master_rpc.cc:77] 0x00000000022a9398 -> GetTableLocations { table_name: ks.test_table, table_id: 6cc26701215d4dd49bff3681cb4a8892, partition_start_key: hash_code: NaN, partition_list_version: 0, request_no: 13, num_attempts: 1 }: Failed: Timed out (yb/client/meta_cache.cc:816): Timed out after deadline expired, passed: 0.000s
I0920 18:58:42.527400 249960 client_master_rpc.cc:77] 0x00000000022a9398 -> GetTableLocations { table_name: ks.test_table, table_id: 6cc26701215d4dd49bff3681cb4a8892, partition_start_key: hash_code: NaN, partition_list_version: 0, request_no: 14, num_attempts: 1 }: Failed: Timed out (yb/client/meta_cache.cc:816): Timed out after deadline expired, passed: 0.000s
...
I0920 18:59:00.661993 249960 client_master_rpc.cc:77] 0x00000000022a9e18 -> GetTableLocations { table_name: ks.test_table, table_id: 6cc26701215d4dd49bff3681cb4a8892, partition_start_key: hash_code: NaN, partition_list_version: 0, request_no: 1000011, num_attempts: 1 }: Failed: Timed out (yb/client/meta_cache.cc:816): Timed out after deadline expired, passed: 0.000s
I0920 18:59:00.662026 249960 client_master_rpc.cc:77] 0x00000000022a9e18 -> GetTableLocations { table_name: ks.test_table, table_id: 6cc26701215d4dd49bff3681cb4a8892, partition_start_key: hash_code: NaN, partition_list_version: 0, request_no: 1000012, num_attempts: 1 }: Failed: Timed out (yb/client/meta_cache.cc:816): Timed out after deadline expired, passed: 0.000s

Warning: Please confirm that this issue does not contain any sensitive information

• I confirm this issue does not contain any sensitive information.

[ttyusupov]

Here is what happens:

1. select * from ks.test_table where category=0 is executed, it is important that there is an index on category column, so index scan is performed.
2. YCQL sets the deadline to now + client_read_write_timeout_ms (4 seconds in the example above).
3. Index tablet lookup is requested from MetaCache and first GetTableLocations RPC is sent to master and response is returned quickly.
4. YCQL sends Read RPC to the index tablet leader with the timeout calculated based on deadline determined in step 2.
5. Index tablet leader starts scan, but there are 1M records with category = 0 and index tablet scan is completed around or after the timeout, but before hitting deadline is detected at tserver side (there is a some granularity in detecting deadline).
6. CQL receives answer from index tablet leader after deadline, but before Connection::CleanupExpirationQueue is executed, so index tablet scan is not timed out at YCQLProxy/YBClient side.
   Connection::CleanupExpirationQueue is executed by timer at FLAGS_rpc_connection_timeout_ms (60 seconds by default) granularity and also when we send outgoing call on the same connection.
7. CQL is preparing Read operations from the main table based on keys received and adding these operations to YBSession which adds them to Batcher. Batcher is doing loop over these 1M operations and asks MetaCache to determine tablet for each one.
8. Since we’ve already hit deadline at this step, MetaCache gets error Timed out after deadline expired even before sending GetTableLocations RPC to the master.
9. Tablet lookup for each of 1M+ operations is failing with the same Timed out after deadline expired and every error is logged by client_master_rpc.cc.
10. Due to log spew from step 10 we have a longer CQL call execution time.

Important factor here is that paging is off or page size is big enough, so index table page scan takes around or a little more than YCQL request timeout.

[ttyusupov]

Lower priority follow-up issue for YCQL: #19252