Re: compute_query_id - Mailing list pgsql-general

On Thu, 17 Jun 2021 at 20:20, Julien Rouhaud <rjuju123@gmail.com> wrote:
>
> On Thu, Jun 17, 2021 at 08:09:54PM +0530, Vijaykumar Jain wrote:
> > how is the compute_query_id actually calculated?
>
> > why does it show 0 in logs for random sql queries.
> > log_line_prefix = '%Q :'
> > 0 :LOG:  statement: select * from pg_stat_activity;
>
> It means that you haven't enabled it:
>
> 2021-06-17 22:46:16.231 CST [11246] queryid=0 LOG:  duration: 4.971 ms  statement: select * from pg_stat_activity ;
> 2021-06-17 22:46:25.383 CST [11246] queryid=0 LOG:  duration: 0.284 ms  statement: set compute_query_id = on;
> 2021-06-17 22:46:28.744 CST [11246] queryid=941978042436931562 LOG:  duration: 1.725 ms  statement: select * from
pg_stat_activity;
 
>

 psql test
psql (14beta1)
Type "help" for help.

test=# show log_line_prefix;
        log_line_prefix
--------------------------------
 [timestamp=%t] [query_id=%Q] :
(1 row)

test=# show compute_query_id;
 compute_query_id
------------------
 on
(1 row)

test=# show log_statement;
 log_statement
---------------
 all
(1 row)

test=# select query_id, query, pid from pg_stat_activity where pid =
pg_backend_pid();
-[ RECORD 1 ]-----------------------------------------------------------------------------
query_id | -4293879703199833131
query    | select query_id, query, pid from pg_stat_activity where pid
= pg_backend_pid();
pid      | 2640


from the logs, i get the id for some queries, but not all
[timestamp=2021-06-17 20:37:59 IST] [query_id=488416992746849793]
:ERROR:  relation "t" already exists
[timestamp=2021-06-17 20:37:59 IST] [query_id=488416992746849793]
:STATEMENT:  create table t(id int);
[timestamp=2021-06-17 20:38:22 IST] [query_id=0] :LOG:  statement:
prepare qq(int) as select count(1) from t where id = $1;
[timestamp=2021-06-17 20:38:29 IST] [query_id=0] :LOG:  statement:
execute qq(1);
[timestamp=2021-06-17 20:38:29 IST] [query_id=0] :DETAIL:  prepare:
prepare qq(int) as select count(1) from t where id = $1;
[timestamp=2021-06-17 20:38:32 IST] [query_id=0] :LOG:  statement:
execute qq(2);
[timestamp=2021-06-17 20:38:32 IST] [query_id=0] :DETAIL:  prepare:
prepare qq(int) as select count(1) from t where id = $1;
[timestamp=2021-06-17 20:39:25 IST] [query_id=0] :LOG:  statement:
select query_id, query, pid from pg_stat_activity where pid = 0;
[timestamp=2021-06-17 20:40:36 IST] [query_id=0] :LOG:  statement:
select count(1) from t;
[timestamp=2021-06-17 20:40:47 IST] [query_id=0] :LOG:  statement:
select count(1) from t where id < 100;

test=# explain (analyze,verbose) select * from t where id <
floor((random() * 100)::int);
                                                        QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------
 Append  (cost=0.00..3.10 rows=3 width=4) (actual time=0.009..0.014
rows=3 loops=1)
....
 Query Identifier: 1051405225525186795
 Planning Time: 0.090 ms
 Execution Time: 0.030 ms
(13 rows)

test=# select query_id, query, pid from pg_stat_activity where pid =
pg_backend_pid();
       query_id       |                                      query
                                 | pid
----------------------+---------------------------------------------------------------------------------+------
 -4293879703199833131 | select query_id, query, pid from
pg_stat_activity where pid = pg_backend_pid(); | 2671
(1 row)

but in logs
[timestamp=2021-06-17 20:46:47 IST] [query_id=0] :LOG:  statement:
explain select query_id, query, pid from pg_stat_activity where pid =
pg_backend_pid();
[timestamp=2021-06-17 20:46:54 IST] [query_id=0] :LOG:  statement:
explain select query_id, query, pid from pg_stat_activity where pid >
100;
[timestamp=2021-06-17 20:46:58 IST] [query_id=0] :LOG:  statement:
explain analyze select query_id, query, pid from pg_stat_activity
where pid > 100;
[timestamp=2021-06-17 20:47:25 IST] [query_id=0] :LOG:  statement:
explain analyze select * from t where id <  floor((random() *
100)::int);
[timestamp=2021-06-17 20:48:16 IST] [query_id=0] :LOG:  statement:
explain (analyze,verbose) select * from t where id <  floor((random()
* 100)::int);
[timestamp=2021-06-17 20:48:38 IST] [query_id=0] :LOG:  statement:
select query_id, query, pid from pg_stat_activity where pid =
pg_backend_pid();

not sure, if i am missing something obvious?

> I'm not sure that I understand that question.  The pid will identify a backend,
> and that backend can execute 0, 1 or a lot of different queries.  The query_id
> will uniquely identify statements after some normalization and removing the
> constant parts (so for instance "select 1;" and "Select 2  ;" will have the
> same identifier).  Having only that information in the log can be useful on its
> own, but you usually get way more benefit using additional modules like
> pg_stat_statements.

Thanks, that helps, but I still do not see them in logs.


************************************* corrects myself
..... ok now it works, when i set log_min_duration_statement =0 to log
all statements.

test=# show log_min_duration_statement;
 log_min_duration_statement
----------------------------
 0
(1 row)

test=# explain (analyze,verbose) select * from t where id <
floor((random() * 100)::int);
                                                        QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------
 Append  (cost=0.00..3.10 rows=3 width=4) (actual time=0.018..0.022
rows=3 loops=1)
   ->  Seq Scan on public.t0 t_1  (cost=0.00..1.03 rows=1 width=4)
(actual time=0.018..0.018 rows=1 loops=1)
         Output: t_1.id
         Filter: ((t_1.id)::double precision < floor((((random() *
'100'::double precision))::integer)::double precision))
   ->  Seq Scan on public.t1 t_2  (cost=0.00..1.03 rows=1 width=4)
(actual time=0.001..0.002 rows=1 loops=1)
         Output: t_2.id
         Filter: ((t_2.id)::double precision < floor((((random() *
'100'::double precision))::integer)::double precision))
   ->  Seq Scan on public.t2 t_3  (cost=0.00..1.03 rows=1 width=4)
(actual time=0.001..0.001 rows=1 loops=1)
         Output: t_3.id
         Filter: ((t_3.id)::double precision < floor((((random() *
'100'::double precision))::integer)::double precision))
 Query Identifier: 1051405225525186795
 Planning Time: 0.353 ms
 Execution Time: 0.034 ms
(13 rows)

test=# select query_id, query, pid from pg_stat_activity where pid =
pg_backend_pid();
       query_id       |                                      query
                                 | pid
----------------------+---------------------------------------------------------------------------------+------
 -4293879703199833131 | select query_id, query, pid from
pg_stat_activity where pid = pg_backend_pid(); | 2777
(1 row)


[timestamp=2021-06-17 20:54:12 IST] [query_id=-1477439429101745134]
:LOG:  duration: 0.040 ms  statement: show log_min_duration_statement;
[timestamp=2021-06-17 20:54:16 IST] [query_id=1308619569072270555]
:LOG:  duration: 0.882 ms  statement: explain (analyze,verbose) select
* from t where id <  floor((random() * 100)::int);
[timestamp=2021-06-17 20:54:19 IST] [query_id=-4293879703199833131]
:LOG:  duration: 1.201 ms  statement: select query_id, query, pid from
pg_stat_activity where pid = pg_backend_pid();


all good, Julien.

-- 
Thanks,
Vijay
Mumbai, India