Skip to main content
Question

Effective way to track INSERT process

  • December 20, 2019
  • 3 replies
  • 11 views

TomYork1986

Hello,
I try to find the effective way to track INSERT process. Sometimes INSERT statements can take too long to execute. It'd be great to have a possibility to track them.
I understand that the EE operators counters are what I need, but there is no detailed information about the underlying EE processes. Therefore, it's difficult to understand which counters should be used.

3 replies

mosheg
Forum|alt.badge.img+2
  • Participating Frequently
  • December 21, 2019

The following script example shows the step differences between two INSERT statements.

DROP TABLE my_table_xyz CASCADE;

CREATE TABLE my_table_xyz
(
    time_id timestamp NOT NULL DEFAULT CURRENT_TIME(0)::timestamp - randomint(730)/9,
    myuuid varchar(36)
)
PARTITION BY (date(my_table_xyz.time_id));

PROFILE INSERT /* +LABEL(test_insert_1) */ INTO my_table_xyz (myuuid) VALUES ('12345F8D-12C3-41F2-B175-E36E91B67890');
COMMIT;

\echo 'Generating 10k rows for INSERT..'
\set GEN_ROWS 10000
PROFILE INSERT /* +LABEL(test_insert_100) */ INTO my_table_xyz (myuuid)
with myrows as (select UUID_GENERATE() as myuuid
from ( select 1 from ( select now() as se union all select now()
+ :GEN_ROWS - 1 as se) a timeseries ts as '1 day' over (order by se)) b)
select myuuid 
from myrows;
COMMIT;

SELECT request_label, transaction_id, statement_id, request_duration_ms
FROM   query_requests
WHERE  request_label ilike 'test_insert_%' AND SUCCESS
ORDER BY start_timestamp DESC
LIMIT 2;
  request_label  |  transaction_id   | statement_id | request_duration_ms 
-----------------+-------------------+--------------+---------------------
 test_insert_100 | 45035996273730393 |            1 |                  70
 test_insert_1   | 45035996273730385 |            1 |                  13
(2 rows)

\set trxid 45035996273730393
\set stmtid 1
\echo 'test_insert_100'
SELECT execution_step, sum(completion_time - time) as elapsed
FROM v_internal.dc_query_executions 
WHERE   transaction_id=:trxid AND 
        statement_id=:stmtid 
GROUP BY 1
ORDER BY 2 DESC;

test_insert_100
        execution_step         |     elapsed     
-------------------------------+-----------------
 ExecutePlan                   | 00:00:00.06311
 BeforePlan                    | 00:00:00.003658
 PreparePlan                   | 00:00:00.002045
 BeforePlan:AnalyzeRewrite     | 00:00:00.001745
 Plan                          | 00:00:00.001704
 CompilePlan                   | 00:00:00.001172
 CompilePlan:EEpreexecute      | 00:00:00.001114
 PreparePlan:EEcompile         | 00:00:00.000849
 PreparePlan:TunePlanResources | 00:00:00.000843
 PreparePlan:LocalPlan         | 00:00:00.000201
 LoadVirtualTableRows          | 00:00:00.000062
 CompilePlan:ReserveResources  | 00:00:00.000023
 PreparePlan:TakeTableLocks    | 00:00:00.000003
(13 rows)

\set trxid 45035996273730385
\set stmtid 1
\echo 'test_insert_1'
SELECT execution_step, sum(completion_time - time) as elapsed
FROM v_internal.dc_query_executions 
WHERE   transaction_id=:trxid AND 
        statement_id=:stmtid 
GROUP BY 1
ORDER BY 2 DESC;

test_insert_1
        execution_step         |     elapsed     
-------------------------------+-----------------
 BeforePlan                    | 00:00:00.035631
 ExecutePlan                   | 00:00:00.003215
 Plan                          | 00:00:00.002682
 PreparePlan                   | 00:00:00.001723
 BeforePlan:AnalyzeRewrite     | 00:00:00.001241
 CompilePlan                   | 00:00:00.00092
 CompilePlan:EEpreexecute      | 00:00:00.000865
 PreparePlan:EEcompile         | 00:00:00.000451
 PreparePlan:TunePlanResources | 00:00:00.00032
 PreparePlan:LocalPlan         | 00:00:00.000191
 BeforePlan:Parser             | 00:00:00.000056
 CompilePlan:ReserveResources  | 00:00:00.000025
 PreparePlan:TakeTableLocks    | 00:00:00.000003
(13 rows)

TomYork1986
  • Author
  • New Participant
  • December 23, 2019

Thanks for the answer, but that's not exactly what I'm trying to find. I want to get an output like this:
+++++
Rows to proceed:
Rows proceeded:


mosheg
Forum|alt.badge.img+2
  • Participating Frequently
  • December 23, 2019

select output_rows
from query_consumption
where LABEL='The_INSERT_Label';
-- OR --
with my_insert as (
select transaction_id,statement_id
from query_requests
where REQUEST_LABEL = 'The_Insert_Label'
-- OR add: and is_executing
)
select
eep.node_name, eep.operator_name, eep.counter_value
from execution_engine_profiles eep, my_insert mi
where
eep.transaction_id = mi.transaction_id
and eep.statement_id = mi.statement_id
and counter_name='rows produced'
and operator_name='NewEENode'
order by 1;