[DocDB] Delayed read request execution

[andrei-mart]

Jira Link: DB-716

Description

Observed occasional failures of the TestPgReadTimeout.java test.
The purpose of the test is to make sure that long running aggregate requests do not fail (#4692). The test reduces the session timeout, then enters a loop which inserts bunch of rows into a table and counts them immediately after that. The loop continues until counting takes much longer than the timeout.
Below are the logs from a failed test:

$ egrep 'TestPgReadTimeout\.java|pgsql_operation\.cc' org.yb.pgsql.TestPgReadTimeout-output.txt
2022-02-12 01:21:51,001 (Time-limited test) [INFO - org.yb.pgsql.TestPgReadTimeout.testReadTimeout(TestPgReadTimeout.java:93)] Loaded 10000 rows
ts1|pid16475|:20792 I0212 01:21:52.254496 16525 pgsql_operation.cc:938] Started iterator
ts1|pid16475|:20792 I0212 01:21:52.255218 16525 pgsql_operation.cc:989] Stopped iterator after 1 matches, 0 rows fetched
ts1|pid16475|:20792 I0212 01:21:52.255239 16525 pgsql_operation.cc:991] Deadline is exceeded
ts1|pid16475|:20792 I0212 01:21:52.256888 16526 pgsql_operation.cc:938] Started iterator
ts1|pid16475|:20792 I0212 01:21:52.884389 16526 pgsql_operation.cc:989] Stopped iterator after 9999 matches, 0 rows fetched
ts1|pid16475|:20792 I0212 01:21:52.884429 16526 pgsql_operation.cc:991] Deadline is not exceeded
2022-02-12 01:21:52,894 (Time-limited test) [INFO - org.yb.pgsql.TestPgReadTimeout.testReadTimeout(TestPgReadTimeout.java:98)] SELECT count(*) FROM readtimeouttest; took 1893ms
2022-02-12 01:22:04,345 (Time-limited test) [INFO - org.yb.pgsql.TestPgReadTimeout.testReadTimeout(TestPgReadTimeout.java:93)] Loaded 25356 rows
ts1|pid16475|:20792 I0212 01:22:06.359221 16520 pgsql_operation.cc:938] Started iterator
ts1|pid16475|:20792 I0212 01:22:06.359743 16520 pgsql_operation.cc:989] Stopped iterator after 1 matches, 0 rows fetched
ts1|pid16475|:20792 I0212 01:22:06.359767 16520 pgsql_operation.cc:991] Deadline is exceeded
	at org.yb.pgsql.TestPgReadTimeout.testReadTimeout(TestPgReadTimeout.java:96)

Session timeout is 2s, so read is supposed to respond after 1s (1000ms before timeout is the default).
On the first iteration 10000 rows are inserted, there is a log about that at 01:21:51,001, and SELECT count(*) is issued immediately after that. However execution is started 1.253s later. Deadline is already over at this point, so response is returned after the first row is read. The follow up request starts iterating immediately and completes table scan in 0.63s.
Based on the query timing the test estimates that 25356 more rows are needed to reach desired query time, and those rows loaded on the second iteration by 01:22:04,345. Following read starts 2.014s later, and at that point not only it is over the deadline, but the session is already timed out.

[rthallamko3]

@arybochkin , This looks similar to the other tablet-splitting issue assigned to you.

[rthallamko3]

Recent trends indicate that the test is no longer failing.