Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t2CtB-002SCz-H8 for pgsql-general@arkaria.postgresql.org; Sat, 19 Oct 2024 17:05:17 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1t2Ct8-005CnK-5s for pgsql-general@arkaria.postgresql.org; Sat, 19 Oct 2024 17:05:14 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t2Ct7-005CnC-Pa for pgsql-general@lists.postgresql.org; Sat, 19 Oct 2024 17:05:14 +0000 Received: from mail-ed1-x543.google.com ([2a00:1450:4864:20::543]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1t2Ct4-001va8-Lf for pgsql-general@postgresql.org; Sat, 19 Oct 2024 17:05:13 +0000 Received: by mail-ed1-x543.google.com with SMTP id 4fb4d7f45d1cf-5c9388a00cfso3290845a12.3 for ; Sat, 19 Oct 2024 10:05:10 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1729357509; x=1729962309; darn=postgresql.org; h=to:subject:message-id:date:from:mime-version:from:to:cc:subject :date:message-id:reply-to; bh=A/vszZcFCsXuu7Jvcpx5+B7dIadpKQRQ2OEYG+uUepA=; b=JDN5LkDfjZD/FLaV8WccnrP/Op85MYIktReSsYXdlvbI+MAmkBfNumbAHbIzi2RS6t VvnwKSUpZAAbMYZN/wPhzgXZSGaSIvXapKrHZt8wcWGsSIdMPeNdXC3JeD78fl9ihqXK V3x50v4G0jb0MgIln1ll1oBvYgDhTtt+9suIoJe64BhtlwLrhHWJZnQAVhK+0tTlTpkk AE0o32vAXJaJWKHBREeXbR3witkaw/YQjBqB9xifwBedR7bEzHYmVfdp7OOAOo6LYaBM +Gxq84ErepzqnlQKvTsYajcOXIT4J7IbA8xNY+AE4wsk6EKEdjv5GdDjfjG+KPEoQDrd H2Xw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1729357509; x=1729962309; h=to:subject:message-id:date:from:mime-version:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=A/vszZcFCsXuu7Jvcpx5+B7dIadpKQRQ2OEYG+uUepA=; b=G9iX/gmeAK3iGemJ1RPv3YLTCua6xMlQj4IgiH7iNYirkSJUddFkaNxtrFi+ZlArI5 +fWYCxrDRECWo5atOg2MdozaUqUcKO2GzoquqleaA2F5mIVDav+ZgKx1XePCsHnDWQEb GHR3CQvQf253N9tQ2AoDs45teouu41YZE7XbL12nDuk+P3ueljDfRUciDRjqT6zAMH7i y+3OxW4rxYwSbgb9VJ5uxhuQ3ZnwKTbjjaPhc7uyVrilVF5hKPppIcYYqPTN0q70fI8S kzP8wTrC04GuahIPLDRutXupJK9efBRRa7OqgIsXJ5cYglvvqyeKjjzHF6xT7gIQWEU7 GoSg== X-Gm-Message-State: AOJu0Yy0DP9Thv/Gs9/eFv4MMmEGW1VY/gMlFvOSgxzvdWLO0qqbNrgi 5/P3jaFDla3WeuOmW3gJGuJ9Dk41kqD0ohLMIe7v8kHZoSz79eeMAehg4s8gPSwcsXQXuEyGQqf zdHri798/f+L0uiKTbLw9WLFTXHAEprCMsqY= X-Google-Smtp-Source: AGHT+IGq8DqPphEEF5SaHnmCl3SBNpq1K/qxWYxNVS6La/zmU44/kvmxcavGmfCWStNrhrVFyKg3/wzQzFzCllnhHcc= X-Received: by 2002:a05:6402:348a:b0:5c8:acf3:12c6 with SMTP id 4fb4d7f45d1cf-5ca0ac443c4mr4116527a12.6.1729357508717; Sat, 19 Oct 2024 10:05:08 -0700 (PDT) MIME-Version: 1.0 From: Vijaykumar Jain Date: Sat, 19 Oct 2024 22:34:59 +0530 Message-ID: Subject: explain vs auto_explain To: pgsql-general Content-Type: multipart/alternative; boundary="000000000000ff38bd0624d76bc6" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000ff38bd0624d76bc6 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi, Why does auto_explain have extended flags to support nested statements and triggers whereas explain does not. the objects of concern have the same ownership and access, so it does not even sound like a security thing. or maybe it is just a format/display issue ? i tried to check the doc, there is no explicit mention of differences PostgreSQL: Documentation: 17: F.3. auto_explain =E2=80=94 log execution pl= ans of slow queries /* postgres@ubuntu:/tmp$ cat db1/postgresql.auto.conf | grep -v '^#' port=3D5432 session_preload_libraries =3D auto_explain auto_explain.log_min_duration =3D 0 auto_explain.log_analyze =3D true auto_explain.log_buffers =3D true auto_explain.log_timing =3D true auto_explain.log_verbose =3D on auto_explain.log_triggers =3D on auto_explain.log_nested_statements =3D on postgres@ubuntu:/tmp$ psql -p 5432 demo psql (16.4 (Ubuntu 16.4-0ubuntu0.24.04.1)) Type "help" for help. demo=3D# create table t(col1 int primary key, col2 int); CREATE TABLE demo=3D# create table r(col3 int primary key, col1 int references t(col1) on update cascade on delete cascade); -- foreign table with col1 having no index CREATE TABLE demo=3D# insert into t select x, x from generate_series(1, 1000000) x; INSERT 0 1000000 demo=3D# insert into r select x, (x % 3) + 1 from generate_series(1, 100000) x; -- only 1,2,3 for col1 INSERT 0 100000 demo=3D# begin; BEGIN demo=3D*# explain (analyze,verbose,buffers) delete from t where col1 < 5; -- when we delete from t, it will show it touches r but will not show what plan was used to delete data from r. we need to check the actual plan to figure out why the delete is slow and how to fix it QUERY PLAN ---------------------------------------------------------------------------= -------------------------------------------- Delete on public.t (cost=3D0.42..8.50 rows=3D0 width=3D0) (actual time=3D0.025..0.026 rows=3D0 loops=3D1) Buffers: shared hit=3D13 -> Index Scan using t_pkey on public.t (cost=3D0.42..8.50 rows=3D4 width=3D6) (actual time=3D0.006..0.008 rows=3D4 loops=3D1) Output: ctid Index Cond: (t.col1 < 5) Buffers: shared hit=3D4 Planning: Buffers: shared hit=3D7 Planning Time: 0.083 ms Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey: time=3D46.274 calls=3D4 Execution Time: 46.460 ms (11 rows) demo=3D*# -- note Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey: time=3D46.274 calls=3D4 , it made 4 calls to r demo=3D*# rollback; ROLLBACK demo=3D# \q -------------- why do we not see this via console EXPLAIN, it is still the same PID postgres@ubuntu:/tmp$ less db1.log postgres@ubuntu:/tmp$ tail -20 db1.log 2024-10-05 18:40:26.429 UTC [2260] LOG: duration: 1.087 ms plan: Query Text: DELETE FROM ONLY "public"."r" WHERE $1 OPERATOR(pg_catalog.=3D) "col1" Query Parameters: $1 =3D '4' Delete on public.r (cost=3D0.00..1693.00 rows=3D0 width=3D0) (actual time=3D1.086..1.087 rows=3D0 loops=3D1) Buffers: shared hit=3D443 -> Seq Scan on public.r (cost=3D0.00..1693.00 rows=3D1 width=3D6) (actual time=3D1.086..1.086 rows=3D0 loops=3D1) Output: ctid Filter: (4 =3D r.col1) Buffers: shared hit=3D443 2024-10-05 18:40:26.429 UTC [2260] CONTEXT: SQL statement "DELETE FROM ONLY "public"."r" WHERE $1 OPERATOR(pg_catalog.=3D) "col1"" 2024-10-05 18:40:26.429 UTC [2260] LOG: duration: 46.303 ms plan: Query Text: explain (analyze,verbose,buffers) delete from t where col1 < 5; Delete on public.t (cost=3D0.42..8.50 rows=3D0 width=3D0) (actual time=3D0.025..0.026 rows=3D0 loops=3D1) Buffers: shared hit=3D13 -> Index Scan using t_pkey on public.t (cost=3D0.42..8.50 rows=3D4 width=3D6) (actual time=3D0.006..0.008 rows=3D4 loops=3D1) Output: ctid Index Cond: (t.col1 < 5) Buffers: shared hit=3D4 Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey: time=3D46.274 calls=3D4 */ --=20 Thanks, Vijay Open to work Resume - Vijaykumar Jain --000000000000ff38bd0624d76bc6 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hi,
Why does auto_explain have extended flags to support nested= statements and triggers whereas explain does not.
the objects of= concern have the same ownership and access, so it does not even sound like= a security thing.

or maybe it is just a format/di= splay issue ?=C2=A0
i tried to check the doc, there is no explici= t mention of differences=C2=A0



/*
postgres@ubuntu:/tmp$ cat db1/postgresql.auto.conf | grep -=
v '^#'
port=3D5432
session_preload_libraries =3D auto_explain
auto_explain.log_min_duration =3D 0
auto_explain.log_analyze =3D true
auto_explain.log_buffers =3D true
auto_explain.log_timing =3D true
auto_explain.log_verbose =3D on
auto_explain.log_triggers =3D on
auto_explain.log_nested_statements =3D on
postgres@ubuntu:/tmp$ psql -p 5432 demo
psql (16.4 (Ubuntu 16.4-0ubuntu0.24.04.1))
Type "help" for help.

demo=3D# create table t(col1 int primary key, col2 int);                   =
                                                   CREATE TABLE
demo=3D# create table r(col3 int primary key, col1 int references t(col1) o=
n update cascade on delete cascade); -- foreign table with col1 having no i=
ndex
CREATE TABLE
demo=3D# insert into t select x, x from generate_series(1, 1000000) x;     =
                                                   INSERT 0 1000000
demo=3D# insert into r select x, (x % 3) + 1 from generate_series(1, 100000=
) x; -- only 1,2,3 for col1
INSERT 0 100000
demo=3D# begin;
BEGIN
demo=3D*# explain (analyze,verbose,buffers) delete from t where col1 < 5=
; -- when we delete from t, it will show it touches r but will not show wha=
t plan was used to delete data from r. we need to check the actual plan to =
figure out why the delete is slow and how to fix it
                                                      QUERY PLAN
---------------------------------------------------------------------------=
--------------------------------------------
 Delete on public.t  (cost=3D0.42..8.50 rows=3D0 width=3D0) (actual time=3D=
0.025..0.026 rows=3D0 loops=3D1)
   Buffers: shared hit=3D13
   ->  Index Scan using t_pkey on public.t  (cost=3D0.42..8.50 rows=3D4 =
width=3D6) (actual time=3D0.006..0.008 rows=3D4 loops=3D1)
         Output: ctid
         Index Cond: (t.col1 < 5)
         Buffers: shared hit=3D4
 Planning:
   Buffers: shared hit=3D7
 Planning Time: 0.083 ms
 Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey: time=3D46=
.274 calls=3D4
 Execution Time: 46.460 ms
(11 rows)

demo=3D*# -- note Trigger RI_ConstraintTrigger_a_16475 for constraint r_col=
1_fkey: time=3D46.274 calls=3D4 , it made 4 calls to r
demo=3D*# rollback;
ROLLBACK
demo=3D#
\q

-------------- why do we not see this via console EXPLAIN, it is sti=
ll the same PID
postgres@ubuntu:/tmp$ =
less db1.log=20
postgres@ubuntu:/tmp$ tail -20 db1.log
2024-10-05 18:40:26.429 UTC [2260] LOG:  duration: 1.087 ms  plan:
        Query Text: DELETE FROM ONLY "public"."r" WHERE=
 $1 OPERATOR(pg_catalog.=3D) "col1"
        Query Parameters: $1 =3D '4'
        Delete on public.r  (cost=3D0.00..1693.00 rows=3D0 width=3D0) (actu=
al time=3D1.086..1.087 rows=3D0 loops=3D1)
          Buffers: shared hit=3D443
          ->  Seq Scan on public.r  (cost=3D0.00..1693.00 rows=3D1 width=
=3D6) (actual time=3D1.086..1.086 rows=3D0 loops=3D1)
                Output: ctid
                Filter: (4 =3D r.col1)
                Buffers: shared hit=3D443
2024-10-05 18:40:26.429 UTC [2260] CONTEXT:  SQL statement "DELETE FRO=
M ONLY "public"."r" WHERE $1 OPERATOR(pg_catalog.=3D) &=
quot;col1""
2024-10-05 18:40:26.429 UTC [2260] LOG:  duration: 46.303 ms  plan:
        Query Text: explain (analyze,verbose,buffers) delete from t where c=
ol1 < 5;
        Delete on public.t  (cost=3D0.42..8.50 rows=3D0 width=3D0) (actual =
time=3D0.025..0.026 rows=3D0 loops=3D1)
          Buffers: shared hit=3D13
          ->  Index Scan using t_pkey on public.t  (cost=3D0.42..8.50 ro=
ws=3D4 width=3D6) (actual time=3D0.006..0.008 rows=3D4 loops=3D1)
                Output: ctid
                Index Cond: (t.col1 < 5)
                Buffers: shared hit=3D4
        Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey: ti=
me=3D46.274 calls=3D4

*/

--
Thanks,
Vijay
Open to work
Resume -=C2=A0Vijaykumar Jain
--000000000000ff38bd0624d76bc6--