-
Notifications
You must be signed in to change notification settings - Fork 4.1k
sql: statement timings in transactions are suspicious #40675
Description
Describe the problem
Roko noted that we had a customer with unexpected latencies in their Admin UI. The customers' latencies were different when measured from their client compared to the latencies in the UI. Roko and I did a simple experiment to determine whether wrapping statements in txns was impacting timings for the statements. It seems that we are inaccurately reporting latencies in the below situation.
To Reproduce
Setup steps:
roachprod create $CLUSTER -n 3 --geo
roachprod stage $CLUSTER release v19.1.4
roachprod start $CLUSTER
roachprod sql $CLUSTER:1
SQL:
create database test;
use test;
create table b(a int, b int);
show experimental_ranges from table b; # (confirm I'm connected to the leaseholder as gateway)
begin;
insert into b values (1,1);
select * from b;
commit;
When I check the UI, I see the read took 800+ ms despite being connected to the leaseholder as my gateway node:

This is unexpected. When executing this via an implicit txn, I see the statement executing much faster:
root@localhost:26257/test> select * from b;
a | b
+---+---+
1 | 1
(1 row)
Time: 362.221301ms
root@localhost:26257/test> select * from b;
a | b
+---+---+
1 | 1
(1 row)
Time: 793.702µs
(side note: why is the second run so much faster?)
Subsequent executions yield some strange results in other ways. I see that latencies for the planning phase on the insert are extremely high (this is also true on the read, but closer to 100ms instead of 400+):

It is unclear why the timings for the reads is so different inside of vs outside of transactions. cc @rkruze and @jordanlewis as we spoke about this in person.
gz#8246