sql: statement timings in transactions are suspicious

[piyush-singh]

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

[jordanlewis]

@piyush-singh thanks for writing this up! It's missing one crucial measurement that I was trying to explain in person - you included the timings as reported by the SQL shell (which just measures the time until response was finished from the server) for the implicit txn, but not for the explicit txn. Can you include those timings? In particular, the crucial measurement is whether the select within the transaction returns quickly or slowly, and whether the commit statement returns quickly or slowly.

Thank you!

[piyush-singh]

No problem - so when running the explicit transaction, I only get a single timing if I don't have results returned for each statement:

root@localhost:26257/test> begin;
Now adding input for a multi-line SQL transaction client-side (smart_prompt enabled).
Press Enter two times to send the SQL text collected so far to the server, or Ctrl+C to cancel.
You can also use \show to display the statements entered so far.
                        -> insert into b values (1,1);
                        -> select * from b;
                        -> commit;
  a | b  
+---+---+
  1 | 1  
(1 row)

Time: 972.120879ms

If I execute the statements one at a time, I see:

begin;
Now adding input for a multi-line SQL transaction client-side (smart_prompt enabled).
Press Enter two times to send the SQL text collected so far to the server, or Ctrl+C to cancel.
You can also use \show to display the statements entered so far.
                        -> insert into d values (1,1);
                        -> 
INSERT 1

Time: 757.001271ms

root@localhost:26257/test  OPEN> select * from d;
  a | b  
+---+---+
  1 | 1  
(1 row)

Time: 822.218µs

root@localhost:26257/test  OPEN> commit;
COMMIT

Time: 73.486123ms

One thing I wonder about this second set of timings is whether entering these slowly, manually impacts the timings vs executing them rapidly programmatically (without waiting to type them out in between). Perhaps if replication is able to take place while I'm typing it might impact reporting latencies?

[RaduBerinde]

What is "overhead" in the latency breakdown referring to?

[piyush-singh]

Overhead is a catch-all bucket as I understand it. Essentially we subtract the parse, plan, and run latencies from the overall latency and the remainder is just stuck under the overhead label.

[knz]

When executing this via an implicit txn, I see the statement executing much faster:

There is additional complexity in the SQL code with explicit transactions. We'd need some advanced investigation, but I would not be surprised if it was truly slower.
For example, explicit txns do not benefit from the "1PC optimization" available to standalone statements. That alone cuts down many network roundtrips in a multi-node cluster.

Overhead is a catch-all bucket as I understand it. Essentially we subtract the parse, plan, and run latencies from the overall latency and the remainder is just stuck under the overhead label.

Correct (I wrote that code). It ensures that the sum of latencies balances out. It also attracts our attention to measurement bugs if the overhead every gets too large compared to other things.

[nvanbenschoten]

@piyush-singh Is it possible that the leaseholder for the table descriptors or namespaces were remote and that the latency was due to lookups in these metadata tables? That would be consistent with your finding that the latency was attributed to "planning". It would also explain why the first access of table b in the transaction was significantly slower than later accesses because these lookups are cached.

[nvanbenschoten]

It would also explain this:

(side note: why is the second run so much faster?)

[andy-kimball]

It's "expected" that the 1st planning time will be very large, because we have to fetch sql schema in order to plan. In fact, even subsequent planning times can be large, because you might hit different gateway nodes, and each node then has to fetch schema.

[solongordon]

There could be more than one issue at play here but it looks to me like our latency accounting is just plain wrong when multiple statements are submitted in a single request. The execution time of the earlier statements is counted as "Overhead" in the later statements. This affects both implicit and explicit transactions.

SQL:

root@:26257/defaultdb> select pg_sleep(2); select 1;

WebUI:

I'll look into how to fix the accounting for this in conn_executor.

[rafiss]

@solongordon will sync up with the Observability team and move ownership over to them.

[awoods187]

@jordanlewis can we get this on the next milestone?

[daniel-crlabs]

Another customer has reached out to us with this same issue:

We seem to be processing the individual in 3ms. However, when we look at the Admin UI, we see an "overhead" of 2.3s

While analyzing the trace statement, it clearly indicates the statements take less than 400ms to complete

[awoods187]

cc @maryliag @kevin-v-ngo

[maryliag]

From Solon's last comments, the solution for this will be just "stop displaying this "overhead" on the statement details page"?
Or a combination will another fix? Since Daniel's comment indicates there is also an issue with "overall"