PostgreSQL Question posted in
The official documentation can be found here.

Postgresql – Find the statement currently running in my PL/pgSQL code block

Is there a way to figure out which statement from the block is currently running in Postgres? (Even extra extensions or tracing might be an option)

Below is the quick way to reproduce but in real scenario the block is way more complicated.

do
$$ 
declare
  x int;
  c char;
  d int := 3;
begin
  select pg_sleep(d), 11112 into c, x;
   
  select pg_sleep(d), 11113 into c, x;

  select pg_sleep(d), 11114 into c, x;
end
$$;

pg_stat_statements / pg_stat_activity show only the main block, not specific queries.

Tags:

2

Answers


  1. 0

    The simple solution is to throw in, at positions you want to know …

    RAISE NOTICE 'Starting query 2 ...';

    Obviously only visible for the same session.

    auto_explain

    You can achieve that for all statements without altering the code block using auto_explain. It’s a bit heavy-handed because it also reports the query plan for each. (Very short for the given example, but may get quite verbose for complex queries.) But I am not aware of a simpler way. See:

    Demo:

    test=> SET ROLE postgres;
SET
test=# LOAD 'auto_explain';
LOAD
test=# SET auto_explain.log_nested_statements = ON; -- statements inside code blocks
SET
test=# SET auto_explain.log_min_duration = 1;       -- exclude queries taking < 1 ms
SET
test=# SET client_min_messages TO log;              -- get log msg in client
SET
test=# do
test-# $$ 
test$# declare
test$#   x int;
test$#   c char;
test$#   d int := 2;
test$# begin
test$#   select pg_sleep(d), 1 into c, x;
test$# 
test$#   select pg_sleep(d), 2 into c, x;
test$# 
test$#   select pg_sleep(d), 3 into c, x;
test$# end
test$# $$;
LOG:  statement: do
$$ 
declare
  x int;
  c char;
  d int := 2;
begin
  select pg_sleep(d), 1 into c, x;

  select pg_sleep(d), 2 into c, x;

  select pg_sleep(d), 3 into c, x;
end
$$;
LOG:  duration: 2002.483 ms  plan:
Query Text: select pg_sleep(d), 1
Result  (cost=0.00..0.01 rows=1 width=8)
LOG:  duration: 2002.134 ms  plan:
Query Text: select pg_sleep(d), 2
Result  (cost=0.00..0.01 rows=1 width=8)
LOG:  duration: 2002.423 ms  plan:
Query Text: select pg_sleep(d), 3
Result  (cost=0.00..0.01 rows=1 width=8)
LOG:  duration: 6009.303 ms
DO
test=#
    Login or Signup to reply.
  2. 0

    Technically, you can just flip debug_print_plan on and it’ll do exactly that:

    set debug_print_plan to on;

    Problem is, that’ll keep throwing whole parse trees at you. While those do hold everything about the currently processed statement, I wouldn’t expect anyone to prefer or even tolerate that format if all you wanted was to see a checkpoint, the line it’s on:

    do $$
declare x int;
        c char;
        d int := 1; i int;
begin select pg_sleep(d), 11112 into c, x;
      for i in 1..5 loop
        select pg_sleep(d); select i;  
      end loop;
      select pg_sleep(d), 11114 into c, x;
end $$;

    You can see pg_sleep() only as its oid under :funcid 2626 a few miles into this (this isn’t all it spewed out):

    LOG:  plan:
DETAIL:     {PLANNEDSTMT
   :commandType 1
   :queryId 0
   :hasReturning false
   :hasModifyingCTE false
   :canSetTag true
   :transientPlan false
   :dependsOnRole false
   :parallelModeNeeded false
   :jitFlags 0
   :planTree
      {RESULT
      :startup_cost 0.00
      :total_cost 0.01
      :plan_rows 1
      :plan_width 4
      :parallel_aware false
      :parallel_safe false
      :async_capable false
      :plan_node_id 0
      :targetlist (
         {TARGETENTRY
         :expr
            {CONST
            :consttype 23
            :consttypmod -1
            :constcollid 0
            :constlen 4
            :constbyval true
            :constisnull false
            :location 0
            :constvalue 4 [ 1 0 0 0 0 0 0 0 ]
            }
         :resno 1
         :resname ?column?
         :ressortgroupref 0
         :resorigtbl 0
         :resorigcol 0
         :resjunk false
         }
      )
      :qual <>
      :lefttree <>
      :righttree <>
      :initPlan <>
      :extParam (b)
      :allParam (b)
      :resconstantqual <>
      }
   :rtable (
      {RANGETBLENTRY
      :alias <>
      :eref
         {ALIAS
         :aliasname *RESULT*
         :colnames <>
         }
      :rtekind 8
      :lateral false
      :inh false
      :inFromCl false
      :requiredPerms 0
      :checkAsUser 0
      :selectedCols (b)
      :insertedCols (b)
      :updatedCols (b)
      :extraUpdatedCols (b)
      :securityQuals <>
      }
   )
   :resultRelations <>
   :appendRelations <>
   :subplans <>
   :rewindPlanIDs (b)
   :rowMarks <>
   :relationOids <>
   :invalItems <>
   :paramExecTypes <>
   :utilityStmt <>
   :stmt_location 0
   :stmt_len 0
   }

LOG:  plan:                                                                                                                                                                                                                                                                                                                                                              [384/1854]
DETAIL:     {PLANNEDSTMT
   :commandType 1
   :queryId 0
   :hasReturning false
   :hasModifyingCTE false
   :canSetTag true
   :transientPlan false
   :dependsOnRole false
   :parallelModeNeeded false
   :jitFlags 0
   :planTree
      {RESULT
      :startup_cost 0.00
      :total_cost 0.01
      :plan_rows 1
      :plan_width 8
      :parallel_aware false
      :parallel_safe false
      :async_capable false
      :plan_node_id 0
      :targetlist (
         {TARGETENTRY
         :expr
            {FUNCEXPR
            :funcid 2626
            :funcresulttype 2278
            :funcretset false
            :funcvariadic false
            :funcformat 0
            :funccollid 0
            :inputcollid 0
            :args (
               {CONST
               :consttype 701
               :consttypmod -1
               :constcollid 0
               :constlen 8
               :constbyval true
               :constisnull false
               :location -1
               :constvalue 8 [ 0 0 0 0 0 0 -16 63 ]
               }
            )
            :location 7
            }
         :resno 1
         :resname pg_sleep
         :ressortgroupref 0
         :resorigtbl 0
         :resorigcol 0
         :resjunk false
         }
         {TARGETENTRY
         :expr
            {CONST
            :consttype 23
            :consttypmod -1
            :constcollid 0
            :constlen 4
            :constbyval true
            :constisnull false
            :location 20
            :constvalue 4 [ 104 43 0 0 0 0 0 0 ]
            }
         :resno 2
         :resname ?column?
         :ressortgroupref 0
         :resorigtbl 0
         :resorigcol 0
         :resjunk false
         }
      )
      :qual <>
      :lefttree <>
      :righttree <>
      :initPlan <>
      :extParam (b)
      :allParam (b)
      :resconstantqual <>
      }
   :rtable (
      {RANGETBLENTRY
      :alias <>
      :eref
         {ALIAS
         :aliasname *RESULT*
         :colnames <>
         }
      :rtekind 8
      :lateral false
      :inh false
      :inFromCl false
      :requiredPerms 0
      :checkAsUser 0
      :selectedCols (b)
      :insertedCols (b)
      :updatedCols (b)
      :extraUpdatedCols (b)
      :securityQuals <>
      }
   )
   :resultRelations <>
   :appendRelations <>
   :subplans <>
   :rewindPlanIDs (b)
   :rowMarks <>
   :relationOids <>
   :invalItems <>
   :paramExecTypes <>
   :utilityStmt <>
   :stmt_location 0
   :stmt_len 0
   }

    As already suggested by @Erwin Brandstetter, it’s best to equip your code with RAISE at adequate message levels.

    Login or Signup to reply.
Please signup or login to give your own answer.

Back To Top
Search