[flaky test] org.yb.pgsql.TestPgRegressFeature.testPgRegressFeature

[bmatican]

Jira Link: DB-1008

Description

https://detective-gcp.dev.yugabyte.com/stability/test?branch=master&build_type=all&class=org.yb.pgsql.TestPgRegressFeature&name=testPgRegressFeature&platform=all

[myang2021]

There are two types of errors:

(1) Create database timed out
(2) Query error: Restart read required

For (1), the error only appeared in debug build, samples:

ts1|pid4892|:27485 W0907 02:06:21.790311  4929 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:47425 => 127.212.99.145:27485 (request call id 53) took 57375ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:07:12.885120  4930 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:47425 => 127.212.99.145:27485 (request call id 80) took 47181ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:11:01.036902  8142 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 59) took 45512ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:12:00.640125  7352 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 91) took 50357ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:12:59.858043  7345 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 104) took 58888ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:13:51.610272  7346 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 118) took 51351ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:14:53.788679  7347 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 131) took 60007ms (client timeout 60000ms).
ts1|pid4892|:27485 W0907 02:15:59.452118  7352 yb_rpc.cc:392] Call yb.tserver.PgClientService.CreateDatabase 127.212.99.145:37149 => 127.212.99.145:27485 (request call id 145) took 60004ms (client timeout 60000ms).

Note the last 2 has timed out, the others are not very far from the 60000ms timeout threshold. Because debug build runs slower than release build, we should increase the timeout limit from 60000ms to say 120000ms. We already do the same for asan/tsan build types (rpc timeout limit is increased 3 times to 180000ms).

[myang2021]

For the second type of error. Following is what I have found.

After looking into several failed instances, I extracted a test case that can reproduce the
bug in repeated runs:

create table atacc1 (test int not null);
alter table atacc1 alter column test drop not null;
insert into atacc1 values (null);
alter table atacc1 alter test set not null; -- statement A1
ERROR:  column "test" contains null values
delete from atacc1;
alter table atacc1 alter test set not null; -- statement A2
ERROR:  Query error: Restart read required at: { read: { days: 19249 time: 19:27:45.787447 }
local_limit: { days: 19249 time: 19:27:45.787447 } global_limit: <min> in_txn_limit: <max>
serial_no: 0 }

Notice that the statement alter table atacc1 alter test set not null is executed twice. The first
execution (A1) we see an expected ERROR. However for the second execution (A2) the Restart read required ERROR is unexpected. It is caused by a race condition that is described below.

When executing statement A1, a ddl transaction is started at the tserver side. Next PG needs to
verify that the table atacc1 does not contain any null values and therefore PG runs a sequential
scan of the table atacc1. During the sequential scan, YB makes Perform RPC calls to tserver. YB
has an optimization called pre-fetching: before returning the current batch of rows to PG layer,
another Perform RPC is issued to fetch the next batch of rows. This optimization can speed up the
scan process: while PG layer is verifying the rows already fetched, the next batch of rows are
fetched concurrently.

Because the table atacc1 does have null value, the verification failed and statement A1 is aborted
before all the batches are fetched. As part of that, the ddl transaction is also aborted via a
FinishTransaction RPC with ABORT argument from PG to tserver. Once tserver receives
FinishTransaction with ABORT argument, it will clear it from the ddl session and then abort the
ddl transaction. The relevant code:

  const auto txn_value = std::move(txn);
  Session(kind)->SetTransaction(nullptr);

and

  VLOG_WITH_PREFIX_AND_FUNC(2)
      << "ddl: " << req.ddl_mode() << ", txn: " << txn_value->id() << ", abort";
  txn_value->Abort();

There is a race condition between the pre-fetching Perform RPC and the FinishTransaction RPC
because pre-fetching is done asynchronously in a different thread of the PG process.

(1) If tserver receives Perform first, the next FinishTransaction will properly clear the ddl
transaction from the ddl session and abort the ddl transaction as shown above. This is the common
case.
(2) If tserver receives FinishTransaction first, it leads to the unexpected Restart read required error for the following reason.

After FinishTransaction terminates the ddl transaction of statement A1, the pre-fetching
Perform RPC (which belonged to the just terminated ddl transaction of statement A1) arrived. It
will re-establish a new ddl transaction because it has ddl_mode in its PgPerformOptionsPB set to
true. This newly created ddl transaction gets a readpoint T1 when executing the Perform operation.
Following that, statement delete from atacc1 is executed which causes a write to table atacct
with a commit time of T2. Note that T1 < T2. Then at tserver side the statement A2 will reuse the
newly created ddl transaction with readpoint T1 for the execution of A2. Because T1 < T2, in docdb
DocRowwiseIterator::RestartReadHt returns T2 instead of HybridTime::kInvalid, eventually leading
to the "Restart read required` error:

  if (max_seen_ht.is_valid() && max_seen_ht > db_iter_->read_time().read) {
    VLOG(4) << "Restart read: " << max_seen_ht << ", original: " << db_iter_->read_time();
    return max_seen_ht;
  }
  return HybridTime::kInvalid;

For non-ddl transaction, we have used txn_serial_no to detect PG/tserver transaction mismatch
and abort the previous transaction. For ddl transaction, we do not use txn_serial_no.

We can add a similar ddl_txn_serial_no to detect PG/tserver ddl transaction mismatch and
abort the previous ddl transaction.