Query bug 19.1.4

Hello. We are testing CRDB to migrate and found possible bug:
Same query with and without EXPLAIN takes different time to execute.


As you can see query without EXPLAIN executes much faster, but usual query takes 20 seconds.
How it can be debugged?

Hey @OlegSotnikov,

When you run EXPLAIN <QUERY> the time it takes is how long the planner took to generate the query plan. The actual query was not run.

If you’d like the query to run when you run EXPLAIN then you’ll need to run EXPLAIN ANALYZE. This executes a SQL query and returns a physical query plan with execution statistics.

Let me know if you have any other questions.

Thanks,

Ron

Thank you.
How I can debug problem with execution time of simple query at 23 seconds?
2 regions, 1 zone for every region, 3 node for every zone. Regions 60ms away, replicas=5.

Hey @OlegSotnikov,

Could you share your DDL with us for all the tables that are referenced in this query? I tried my best to reproduce this on my end based on the explains you have sent over but it would be more useful to have your DDL. Also, please note, if the row you are updating contains a column referenced by a foreign key constraint and has an ON UPDATE action all of the dependent rows will also be updated, which could cause the query to take longer.

Thanks

This is my table:
CREATE TABLE users (
id INT8 NOT NULL DEFAULT unique_rowid(),
phone VARCHAR NULL,
email VARCHAR(255) NULL,
first_name VARCHAR(255) NULL,
last_name VARCHAR(250) NULL,
password VARCHAR(255) NULL,
country_id INT8 NULL,
is_active BOOL NOT NULL DEFAULT true,
two_factor_key VARCHAR(12) NULL,
created_at TIMESTAMPTZ NOT NULL,
deleted BOOL NOT NULL DEFAULT false,
updated_at TIMESTAMPTZ NULL,
email_confirmation_expires_at TIMESTAMPTZ NULL,
sms_confirmation_expires_at TIMESTAMPTZ NULL,
email_confirmation_code VARCHAR(1024) NULL,
sms_confirmation_code VARCHAR(32) NULL,
email_confirmed BOOL NOT NULL DEFAULT false,
phone_confirmed BOOL NOT NULL DEFAULT false,
avatar_file_id INT8 NULL,
last_seen_at TIMESTAMPTZ NULL,
is_seeded BOOL NOT NULL DEFAULT false,
blocked BOOL NULL DEFAULT false,
CONSTRAINT users_pk PRIMARY KEY (id ASC),
UNIQUE INDEX users_email_key (email ASC),
UNIQUE INDEX users_phone_key (phone ASC),
CONSTRAINT users_avatar_file_id_fkey FOREIGN KEY (avatar_file_id) REFERENCES files (id),
INDEX users_auto_index_users_avatar_file_id_fkey (avatar_file_id ASC),
CONSTRAINT users_fk0 FOREIGN KEY (country_id) REFERENCES countries (id),
INDEX users_auto_index_users_fk0 (country_id ASC),
FAMILY “primary” (id, phone, email, first_name, last_name, password, country_id, is_active, two_factor_key, created_at, deleted, updated_at, email_confirmation_expires_at, sms_confirmation_expires_at, email_confirmation_code, sms_confirmation_code, email_confirmed, phone_confirmed, avatar_file_id, last_seen_at, is_seeded, blocked)
)

And statements details


Thank you for your help!

Hi @OlegSotnikov,

Could you run EXPLAIN ANALYZE <QUERY> and send us the output of that?

Thanks

root@127.0.0.1:26257/defaultdb> EXPLAIN ANALYZE UPDATE feebme.users SET last_seen_at=now() WHERE id=3;
automatic | url
±----------±-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
false | https://cockroachdb.github.io/distsqlplan/decode.html#eJyUkc-K2zAQh-99imF6aWGKPUr_6qQeesghbUh8avFBtYZgcCQjyaQl-LH6An2yIvvQ3YVdshfDzHzfjPnpij44-WrPklD_QMaWcIyhk5RCLK0V2LpfqGvC3o9TLu2WsAtRUF8x93kQ1NjYn4McxDqJVY2ETrLth2XtGPuzjb_NlCQmJDyO1icN1eZNtaleIuFBvJOowTCBUQRmQ2DeEph3BOY9gflAYD4SmE8EhuvyKSQXlAvLBeZCc8G58FwELoYqhlp2KwIfLq9ea62b7e7Lsfm82zffkTCGS4Io1mlgJEzZDgPk_iwalPr7J2E7E4Yp_w8gZXsS1DzT7SENobMDdGHyGeqK78X02AH1nAMHSWPwSW7aXM8tobiTrC-dwhQ72cfQLWfW8tviLQ0nKa9TXoutX0flB-_K_KSsHsjt_OJfAAAA___MTcY5
(1 row)

Time: 9.49876534s

Hey @OlegSotnikov,

Based on this, that update shouldn’t take that long.

Are you running any other transactions to that table? Or is this the only one? Could you maybe set a trace and rerun the query and send over the trace results.

We have docs on how to set up a trace here.

Thanks