#coding:utf-8 """ ID: issue-7086 ISSUE: 7086 TITLE: PSQL and SQL profiler NOTES: [21.02.2023] pzotov Test verifies only example from doc/sql.extensions/README.profiler.md More complex checks will be implementer later. Checked on 5.0.0.958 SS/CS. """ import os import pytest from firebird.qa import * # Output contains lot of data with concrete values for attachment_id, timestamps etc. # We have to check only presense of such lines and ignore these values: ptn_list = [ 'ATTACHMENT_ID' ,'START_TIMESTAMP' ,'FINISH_TIMESTAMP' ,'SQL_TEXT' ,'LINE_NUM' ,'COLUMN_NUM' ,'MIN_ELAPSED_TIME' ,'MAX_ELAPSED_TIME' ,'TOTAL_ELAPSED_TIME' ,'AVG_ELAPSED_TIME' ,'STATEMENT_ID' ,'OPEN_MIN_ELAPSED_TIME' ,'OPEN_MAX_ELAPSED_TIME' ,'OPEN_TOTAL_ELAPSED_TIME' ,'OPEN_AVG_ELAPSED_TIME' ,'FETCH_COUNTER' ,'FETCH_MIN_ELAPSED_TIME' ,'FETCH_MAX_ELAPSED_TIME' ,'FETCH_TOTAL_ELAPSED_TIME' ,'FETCH_AVG_ELAPSED_TIME' ,'OPEN_FETCH_TOTAL_ELAPSED_TIME' ,'REQUEST_ID' ,'STATEMENT_ID' ,'CALLER_REQUEST_ID' ,'START_TIMESTAMP' ,'FINISH_TIMESTAMP' ,'TOTAL_ELAPSED_TIME' ] sub_list = [ (x+' .*', x) for x in ptn_list ] substitutions = [ ('[ \t]+', ' ') ] + sub_list db = db_factory() test_script = f""" set list on; create table tab ( id integer not null, val integer not null ); set term ^; create or alter function mult(p1 integer, p2 integer) returns integer as begin return p1 * p2; end^ create or alter procedure ins as declare n integer = 1; begin while (n <= 1000) do begin if (mod(n, 2) = 1) then insert into tab values (:n, mult(:n, 2)); n = n + 1; end end^ set term ;^ -- ###################################### -- ### Start profiling, session 1 ### -- ###################################### select rdb$profiler.start_session('profile session 1') from rdb$database; set term ^; execute block as begin execute procedure ins; delete from tab; end^ set term ;^ -- ###################################### -- ### Finish profiling session 1 ### -- ###################################### execute procedure rdb$profiler.finish_session(true); execute procedure ins; -- ###################################### -- ### Start profiling, session 2 ### -- ###################################### select rdb$profiler.start_session('profile session 2') from rdb$database; out {os.devnull}; select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val); out; -- ###################################### -- ### Finish profiling session 2 ### -- ###################################### execute procedure rdb$profiler.finish_session(true); -- Data analysis commit; set transaction read committed; set count on; -- ############################## select '--- [ 1: plg$prof_sessions ] ---' as msg ,s.* from plg$prof_sessions s order by profile_id ; -- ############################## select '--- [ 2: plg$prof_psql_stats_view ] ---' as msg ,p.profile_id ,p.statement_type ,p.sql_text ,p.line_num ,p.column_num ,p.counter ,p.min_elapsed_time ,p.max_elapsed_time ,p.total_elapsed_time ,p.avg_elapsed_time from plg$prof_psql_stats_view p order by p.profile_id, p.statement_id, p.line_num, p.column_num ; -- ############################## select '--- [ 3: plg$prof_record_source_stats_view ] ---' as msg ,p.profile_id ,p.statement_id ,p.statement_type ,p.package_name ,p.routine_name ,p.parent_statement_id ,p.parent_statement_type ,p.parent_routine_name ,p.sql_text ,p.cursor_id ,p.cursor_name ,p.cursor_line_num ,p.cursor_column_num ,p.record_source_id ,p.parent_record_source_id ,p.access_path ,p.open_counter ,p.open_min_elapsed_time ,p.open_max_elapsed_time ,p.open_total_elapsed_time ,p.open_avg_elapsed_time ,p.fetch_counter ,p.fetch_min_elapsed_time ,p.fetch_max_elapsed_time ,p.fetch_total_elapsed_time ,p.fetch_avg_elapsed_time ,p.open_fetch_total_elapsed_time from plg$prof_record_source_stats_view p order by p.profile_id, p.statement_id ; -- ############################## select '--- [ 4: plg$prof_requests ] ---' as msg ,q.profile_id ,q.request_id ,q.statement_id ,q.caller_request_id ,q.start_timestamp ,q.finish_timestamp ,q.total_elapsed_time from plg$prof_requests q join plg$prof_sessions s on s.profile_id = q.profile_id and s.description = 'profile session 1' order by q.profile_id, q.statement_id, q.request_id ; -- ############################## select -- pstat.* '--- [ 5: plg$prof_psql_stats join plg$prof_sessions ] ---' as msg ,t.profile_id ,t.request_id ,t.line_num ,t.column_num ,t.statement_id ,t.counter ,t.min_elapsed_time ,t.max_elapsed_time ,t.total_elapsed_time from plg$prof_psql_stats t join plg$prof_sessions s on s.profile_id = t.profile_id and s.description = 'profile session 1' order by t.profile_id, t.statement_id, t.request_id, t.line_num, t.column_num ; -- ############################## select '--- [ 6: plg$prof_record_source_stats ] ---' as msg ,t.profile_id ,t.request_id ,t.cursor_id ,t.record_source_id ,t.statement_id ,t.open_counter ,t.open_min_elapsed_time ,t.open_max_elapsed_time ,t.open_total_elapsed_time ,t.fetch_counter ,t.fetch_min_elapsed_time ,t.fetch_max_elapsed_time ,t.fetch_total_elapsed_time from plg$prof_record_source_stats t join plg$prof_sessions s on s.profile_id = t.profile_id and s.description = 'profile session 2' order by t.profile_id, t.statement_id, t.request_id, t.cursor_id, t.record_source_id ; """ act = isql_act('db', test_script, substitutions = substitutions) expected_stdout = """ START_SESSION 1 START_SESSION 2 MSG --- [ 1: plg$prof_sessions ] --- PROFILE_ID 1 ATTACHMENT_ID USER_NAME SYSDBA DESCRIPTION profile session 1 START_TIMESTAMP FINISH_TIMESTAMP MSG --- [ 1: plg$prof_sessions ] --- PROFILE_ID 2 ATTACHMENT_ID USER_NAME SYSDBA DESCRIPTION profile session 2 START_TIMESTAMP FINISH_TIMESTAMP Records affected: 2 MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE BLOCK SQL_TEXT execute block as begin execute procedure ins; delete from tab; end LINE_NUM COLUMN_NUM COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE BLOCK SQL_TEXT execute block as begin execute procedure ins; delete from tab; end LINE_NUM COLUMN_NUM COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE PROCEDURE SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE PROCEDURE SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 1001 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE PROCEDURE SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 1000 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE PROCEDURE SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 500 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE PROCEDURE SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 1000 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME MSG --- [ 2: plg$prof_psql_stats_view ] --- PROFILE_ID 1 STATEMENT_TYPE FUNCTION SQL_TEXT LINE_NUM COLUMN_NUM COUNTER 500 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME AVG_ELAPSED_TIME Records affected: 8 MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 1 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select rdb$profiler.start_session('profile session 1') from rdb$database CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 2 PARENT_RECORD_SOURCE_ID 1 ACCESS_PATH 84:1 -> Table "RDB$DATABASE" Full Scan OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 1 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select rdb$profiler.start_session('profile session 1') from rdb$database CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 1 PARENT_RECORD_SOURCE_ID ACCESS_PATH 84:0 Select Expression OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 1 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT execute block as begin execute procedure ins; delete from tab; end CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 2 PARENT_RECORD_SOURCE_ID 1 ACCESS_PATH 84:3 -> Table "TAB" Full Scan OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 1 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT execute block as begin execute procedure ins; delete from tab; end CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 1 PARENT_RECORD_SOURCE_ID ACCESS_PATH 84:2 Select Expression (line 5, column 9) OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select rdb$profiler.start_session('profile session 2') from rdb$database CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 2 PARENT_RECORD_SOURCE_ID 1 ACCESS_PATH 84:5 -> Table "RDB$DATABASE" Full Scan OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select rdb$profiler.start_session('profile session 2') from rdb$database CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 1 PARENT_RECORD_SOURCE_ID ACCESS_PATH 84:4 Select Expression OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 2 PARENT_RECORD_SOURCE_ID 1 ACCESS_PATH 84:7 -> Sort (record length: 44, key length: 12) OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 3 PARENT_RECORD_SOURCE_ID 2 ACCESS_PATH 84:8 -> Aggregate OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 4 PARENT_RECORD_SOURCE_ID 3 ACCESS_PATH 84:9 -> Sort (record length: 44, key length: 8) OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 5 PARENT_RECORD_SOURCE_ID 4 ACCESS_PATH 84:a -> Filter OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 6 PARENT_RECORD_SOURCE_ID 5 ACCESS_PATH 84:b -> Table "TAB" Full Scan OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME MSG --- [ 3: plg$prof_record_source_stats_view ] --- PROFILE_ID 2 STATEMENT_ID STATEMENT_TYPE BLOCK PACKAGE_NAME ROUTINE_NAME PARENT_STATEMENT_ID PARENT_STATEMENT_TYPE PARENT_ROUTINE_NAME SQL_TEXT select mod(id, 5), sum(val) from tab where id <= 50 group by mod(id, 5) order by sum(val) CURSOR_ID 1 CURSOR_NAME CURSOR_LINE_NUM CURSOR_COLUMN_NUM RECORD_SOURCE_ID 1 PARENT_RECORD_SOURCE_ID ACCESS_PATH 84:6 Select Expression OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME OPEN_AVG_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME FETCH_AVG_ELAPSED_TIME OPEN_FETCH_TOTAL_ELAPSED_TIME Records affected: 12 MSG --- [ 4: plg$prof_requests ] --- PROFILE_ID 1 REQUEST_ID STATEMENT_ID CALLER_REQUEST_ID START_TIMESTAMP FINISH_TIMESTAMP TOTAL_ELAPSED_TIME MSG --- [ 4: plg$prof_requests ] --- PROFILE_ID 1 REQUEST_ID STATEMENT_ID CALLER_REQUEST_ID START_TIMESTAMP FINISH_TIMESTAMP TOTAL_ELAPSED_TIME MSG --- [ 4: plg$prof_requests ] --- PROFILE_ID 1 REQUEST_ID STATEMENT_ID CALLER_REQUEST_ID START_TIMESTAMP FINISH_TIMESTAMP TOTAL_ELAPSED_TIME MSG --- [ 4: plg$prof_requests ] --- PROFILE_ID 1 REQUEST_ID STATEMENT_ID CALLER_REQUEST_ID START_TIMESTAMP FINISH_TIMESTAMP TOTAL_ELAPSED_TIME MSG --- [ 4: plg$prof_requests ] --- PROFILE_ID 1 REQUEST_ID STATEMENT_ID CALLER_REQUEST_ID START_TIMESTAMP FINISH_TIMESTAMP TOTAL_ELAPSED_TIME Records affected: 5 MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1001 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1000 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 500 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 1000 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME MSG --- [ 5: plg$prof_psql_stats join plg$prof_sessions ] --- PROFILE_ID 1 REQUEST_ID LINE_NUM COLUMN_NUM STATEMENT_ID COUNTER 500 MIN_ELAPSED_TIME MAX_ELAPSED_TIME TOTAL_ELAPSED_TIME Records affected: 8 MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 1 STATEMENT_ID OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 2 STATEMENT_ID OPEN_COUNTER 0 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 1 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 2 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 3 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 4 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 5 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME MSG --- [ 6: plg$prof_record_source_stats ] --- PROFILE_ID 2 REQUEST_ID CURSOR_ID 1 RECORD_SOURCE_ID 6 STATEMENT_ID OPEN_COUNTER 1 OPEN_MIN_ELAPSED_TIME OPEN_MAX_ELAPSED_TIME OPEN_TOTAL_ELAPSED_TIME FETCH_COUNTER FETCH_MIN_ELAPSED_TIME FETCH_MAX_ELAPSED_TIME FETCH_TOTAL_ELAPSED_TIME Records affected: 8 """ @pytest.mark.version('>=5.0') def test_1(act: Action): act.expected_stdout = expected_stdout act.execute(combine_output = True) assert act.clean_stdout == act.clean_expected_stdout