[YSQL] Insert throughput drops by ~3x with a "GENERATED ALWAYS AS IDENTITY" column in the table schema.

[sonalsagarwal]

Jira Link: DB-11735

Description

Steps to reproduce:

CREATE TABLE test_table (id int8 GENERATED ALWAYS AS IDENTITY NOT NULL, k text primary key, v TEXT);
CREATE TABLE test_table (id int8 NOT NULL, k text primary key, v TEXT);

Inserted rows in the tables with 100 threads for 5 mins.

Results :

1 column with "GENERATED ALWAYS AS IDENTITY"  :  throughput => 20k and CPU Util => 80%
without "GENERATED ALWAYS AS IDENTITY"  : throughput => 57k and CPU Util => 70%

Cluster details : 3-node RF3 1AZ m6i.4xlarge
Please refer attached metrics screenshot for the 2 runs.

Issue Type

kind/bug

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

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

[FranckPachot]

The default cache is 100 (set by --ysql_sequence_cache_minval) so with this throughput it's still hitting the sequence 200 times per second. You can increase the cache:

CREATE TABLE test_table (id int8 GENERATED ALWAYS AS IDENTITY (cache 1000)  NOT NULL, k text primary key, v TEXT);

[sonalsagarwal]

We tried increasing cache (1000 / 10000 / 1000000), but didn't see any difference in the latency or throughput.

[FranckPachot]

@sonalsagarwal do you use prepared statement or is it planned each time? I've seen recently that during the planning phase it reads dependencies from the catalog (which is in yb-master so network call)

[FranckPachot]

I confirm that there generated always as identity has bad performance compared to bigserial or sequence.
I've run 6 concurrent insert workloads on 2024.1:

• bigint generated always as identity, simple and prepared
• bigserial, simple and prepared
• bigint and inserting with nextval from a sequence, simple and prepared
  And gathered wait event sampling with the new ASH
  YSQL:
  
  TServer:
  

With bigint generated always as identity a lot of time is spent on TServer "Raft_WaitingForReplication" and YSQL waits on it ("StorageFlush"). Non-prepared has some waits on "CatalogRead"

The sequence spends most of its time in YSQL "QueryProcessing" and very little in TServer.

This is what I've run for the workload above:

drop sequence s;
drop table if exists demo;
create table demo ( id bigint generated always as identity primary key, value int) ;
\! echo "insert into demo(value)     values(0);              " | pgbench -M simple   -c 30 -nf /dev/stdin -t 10000
\! sleep 30
\! echo "insert into demo(value)     values(0);              " | pgbench -M prepared -c 30 -nf /dev/stdin -t 10000
\! sleep 120
drop table if exists demo;
create table demo ( id bigserial                           primary key, value int) ;
\! echo "insert into demo(value)     values(0);              " | pgbench -M simple   -c 30 -nf /dev/stdin -t 10000
\! sleep 30
\! echo "insert into demo(value)     values(0);              " | pgbench -M prepared -c 30 -nf /dev/stdin -t 10000
\! sleep 120
drop table if exists demo;
create sequence s;
create table demo ( id bigint                              primary key, value int) ;
\! echo "insert into demo(id, value) values (0,nextval('s'));" | pgbench -M simple   -c 30 -nf /dev/stdin -t 10000
\! sleep 30
\! echo "insert into demo(id, value) values (0,nextval('s'));" | pgbench -M prepared -c 30 -nf /dev/stdin -t 10000
\! sleep 120

[FranckPachot]

Apparently, the difference is that, without secondary indexes, bigserial uses fast-path but generated is transactional:

Write operation with generated:

yugabyte=# 2024-06-22 21:50:28.337 UTC [386] LOG:  statement: execute ins;
2024-06-22 21:50:28.337 UTC [386] DETAIL:  prepare: prepare ins as insert into demo(value) values(0);
I0622 21:50:28.341383   386 pg_session.cc:281] Session id 2: Buffering operation: ...
I0622 21:50:28.342567   386 pg_session.cc:653] Session id 2: Flushing buffered operations, using transactional session (num ops: 1)
I0622 21:50:28.345868   386 pg_client.cc:487] Session id 2: Committing transaction

Write operation with bigserial:

yugabyte=# 2024-06-22 21:51:11.206 UTC [386] LOG:  statement: execute ins;
2024-06-22 21:51:11.206 UTC [386] DETAIL:  prepare: prepare ins as insert into demo(value) values(0);
I0622 21:51:11.206781   386 pg_session.cc:318] Session id 2: Applying operation: ...
I0622 21:51:11.206837   386 pg_session.cc:345] Session id 2: Flushing collected operations, using session type: kRegular num ops: 1