PL Profiler Report for Overview debug tools
PL/pgSQL Call Graph
List of functions detailed below
Top 10 functions (by self_time)
Function public.long_running_function_1() oid=34486 (show)
self_time = 21,024,384 µs
total_time = 21,026,319 µs
public.long_running_function_1 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
3 |
21026319 |
7009328 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
3 |
905 |
374 |
PERFORM raise_msg('long_running_function. Stage 1/3...'); |
4 |
3 |
6006563 |
2002470 |
PERFORM pg_sleep(2); |
5 |
0 |
0 |
0 |
|
6 |
3 |
473 |
169 |
PERFORM raise_msg('long_running_function. Stage 2/3...'); |
7 |
3 |
9009628 |
3003393 |
PERFORM pg_sleep(3); |
8 |
0 |
0 |
0 |
|
9 |
3 |
514 |
199 |
PERFORM raise_msg('long_running_function. Stage 3/3...'); |
10 |
3 |
6007128 |
2002464 |
PERFORM pg_sleep(2); |
11 |
0 |
0 |
0 |
|
12 |
3 |
1100 |
789 |
PERFORM raise_msg('long_running_function. Done.'); |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.long_running_function_2() oid=34487 (show)
self_time = 14,014,506 µs
total_time = 14,014,506 µs
public.long_running_function_2 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
2 |
14014506 |
7007551 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
2 |
51 |
43 |
NOTIFY dbg, 'long_running_function. Stage 1/3...'; |
4 |
2 |
4002931 |
2001849 |
PERFORM pg_sleep(2); |
5 |
0 |
0 |
0 |
|
6 |
2 |
107 |
94 |
NOTIFY dbg, 'long_running_function. Stage 2/3...'; |
7 |
2 |
6006509 |
3003313 |
PERFORM pg_sleep(3); |
8 |
0 |
0 |
0 |
|
9 |
2 |
110 |
97 |
NOTIFY dbg, 'long_running_function. Stage 3/3...'; |
10 |
2 |
4004671 |
2002337 |
PERFORM pg_sleep(2); |
11 |
0 |
0 |
0 |
|
12 |
2 |
112 |
99 |
NOTIFY dbg, 'long_running_function. Done.'; |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.listen_trace() oid=35054 (show)
self_time = 7,018,721 µs
total_time = 7,018,721 µs
public.listen_trace |
(channel text) |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
7018721 |
7018721 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
DECLARE |
3 |
0 |
0 |
0 |
payload text; |
4 |
0 |
0 |
0 |
ts text; |
5 |
0 |
0 |
0 |
BEGIN |
6 |
1 |
7018717 |
7018717 |
LOOP |
7 |
4 |
7017602 |
2999599 |
PERFORM dbms_pipe.receive_message(channel); |
8 |
4 |
162 |
130 |
payload := dbms_pipe.unpack_message_text(); |
9 |
4 |
26 |
19 |
ts := dbms_pipe.unpack_message_text(); |
10 |
4 |
758 |
587 |
RAISE NOTICE '%: %', ts, payload; |
11 |
0 |
0 |
0 |
|
12 |
4 |
161 |
127 |
EXIT WHEN lower(payload) = 'stop'; |
13 |
0 |
0 |
0 |
END LOOP; |
14 |
0 |
0 |
0 |
END; |
15 |
0 |
0 |
0 |
|
Function public.long_running_function() oid=34484 (show)
self_time = 7,010,146 µs
total_time = 7,010,146 µs
public.long_running_function |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
7010146 |
7010146 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
1 |
22 |
22 |
RAISE NOTICE 'long_running_function. Stage 1/3...'; |
4 |
1 |
2003946 |
2003946 |
PERFORM pg_sleep(2); |
5 |
0 |
0 |
0 |
|
6 |
1 |
48 |
48 |
RAISE NOTICE 'long_running_function. Stage 2/3...'; |
7 |
1 |
3003480 |
3003480 |
PERFORM pg_sleep(3); |
8 |
0 |
0 |
0 |
|
9 |
1 |
50 |
50 |
RAISE NOTICE 'long_running_function. Stage 3/3...'; |
10 |
1 |
2002547 |
2002547 |
PERFORM pg_sleep(2); |
11 |
0 |
0 |
0 |
|
12 |
1 |
48 |
48 |
RAISE NOTICE 'long_running_function. Done.'; |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.long_running_function_3() oid=35055 (show)
self_time = 7,007,918 µs
total_time = 7,009,141 µs
public.long_running_function_3 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
7009141 |
7009141 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
1 |
1019 |
1019 |
PERFORM trace('dbg', 'long_running_function. Stage 1/3...'); |
4 |
1 |
2002381 |
2002381 |
PERFORM pg_sleep(2); |
5 |
0 |
0 |
0 |
|
6 |
1 |
285 |
285 |
PERFORM trace('dbg', 'long_running_function. Stage 2/3...'); |
7 |
1 |
3002587 |
3002587 |
PERFORM pg_sleep(3); |
8 |
0 |
0 |
0 |
|
9 |
1 |
294 |
294 |
PERFORM trace('dbg', 'long_running_function. Stage 3/3...'); |
10 |
1 |
2002304 |
2002304 |
PERFORM pg_sleep(2); |
11 |
0 |
0 |
0 |
|
12 |
1 |
269 |
269 |
PERFORM trace('dbg', 'stop'); |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.long_running_function_4() oid=35056 (show)
self_time = 7,006,058 µs
total_time = 7,006,058 µs
public.long_running_function_4 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
7006058 |
7006058 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
1 |
70 |
70 |
set local application_name = "long_running_function. Stage 1/3..."; |
4 |
1 |
2002338 |
2002338 |
PERFORM pg_sleep(2); |
5 |
0 |
0 |
0 |
|
6 |
1 |
112 |
112 |
set local application_name = "long_running_function. Stage 2/3..."; |
7 |
1 |
3002825 |
3002825 |
PERFORM pg_sleep(3); |
8 |
0 |
0 |
0 |
|
9 |
1 |
120 |
120 |
set local application_name = "long_running_function. Stage 3/3..."; |
10 |
1 |
2000482 |
2000482 |
PERFORM pg_sleep(2); |
11 |
0 |
0 |
0 |
|
12 |
1 |
105 |
105 |
set local application_name = "long_running_function. Done."; |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.long_running_function_7() oid=35136 (show)
self_time = 6,007,902 µs
total_time = 6,009,154 µs
public.long_running_function_7 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
6009154 |
6009154 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
1 |
1119 |
1119 |
PERFORM write_file('long_running_function. Stage 1/3...'); |
4 |
1 |
1001267 |
1001267 |
PERFORM pg_sleep(1); |
5 |
0 |
0 |
0 |
|
6 |
1 |
311 |
311 |
PERFORM write_file('long_running_function. Stage 2/3...'); |
7 |
1 |
2002570 |
2002570 |
PERFORM pg_sleep(2); |
8 |
0 |
0 |
0 |
|
9 |
1 |
320 |
320 |
PERFORM write_file('long_running_function. Stage 3/3...'); |
10 |
1 |
3003257 |
3003257 |
PERFORM pg_sleep(3); |
11 |
0 |
0 |
0 |
|
12 |
1 |
307 |
307 |
PERFORM write_file('long_running_function. Done.'); |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.long_running_function_5() oid=35113 (show)
self_time = 6,005,519 µs
total_time = 6,036,542 µs
public.long_running_function_5 |
() |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
1 |
6036542 |
6036542 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
1 |
5731 |
5731 |
PERFORM write_log('long_running_function. Stage 1/3...'); |
4 |
1 |
1001348 |
1001348 |
PERFORM pg_sleep(1); |
5 |
0 |
0 |
0 |
|
6 |
1 |
8785 |
8785 |
PERFORM write_log('long_running_function. Stage 2/3...'); |
7 |
1 |
2002321 |
2002321 |
PERFORM pg_sleep(2); |
8 |
0 |
0 |
0 |
|
9 |
1 |
8512 |
8512 |
PERFORM write_log('long_running_function. Stage 3/3...'); |
10 |
1 |
3001213 |
3001213 |
PERFORM pg_sleep(3); |
11 |
0 |
0 |
0 |
|
12 |
1 |
8627 |
8627 |
PERFORM write_log('long_running_function. Done.'); |
13 |
0 |
0 |
0 |
END; |
14 |
0 |
0 |
0 |
|
Function public.write_log() oid=35112 (show)
self_time = 31,023 µs
total_time = 31,023 µs
public.write_log |
(message text) |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
4 |
31023 |
8629 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
DECLARE |
3 |
0 |
0 |
0 |
cmd text; |
4 |
0 |
0 |
0 |
BEGIN |
5 |
4 |
11843 |
3006 |
PERFORM dblink_connect('dbname=' || current_database()); |
6 |
0 |
0 |
0 |
|
7 |
4 |
313 |
255 |
cmd := 'INSERT INTO log (username, ts, message) VALUES (' || |
8 |
0 |
0 |
0 |
quote_literal(user) || ', ' || |
9 |
0 |
0 |
0 |
quote_literal(clock_timestamp()::text) || '::timestamp, ' || |
10 |
0 |
0 |
0 |
quote_literal(write_log.message) || ')'; |
11 |
4 |
18524 |
5582 |
PERFORM dblink_exec (cmd); |
12 |
0 |
0 |
0 |
|
13 |
4 |
320 |
165 |
PERFORM dblink_disconnect(); |
14 |
0 |
0 |
0 |
END; |
15 |
0 |
0 |
0 |
|
Function public.raise_msg() oid=34485 (show)
self_time = 1,935 µs
total_time = 1,935 µs
public.raise_msg |
(message text) |
RETURNS void
|
| Line |
exec_count |
total_time |
longest_time |
Source Code |
0 |
12 |
1935 |
717 |
-- Function Totals |
1 |
0 |
0 |
0 |
|
2 |
0 |
0 |
0 |
BEGIN |
3 |
12 |
1900 |
712 |
CASE current_setting('app.raise_level') |
4 |
0 |
0 |
0 |
WHEN 'NONE' THEN |
5 |
0 |
0 |
0 |
NULL; |
6 |
0 |
0 |
0 |
WHEN 'NOTICE' THEN |
7 |
4 |
349 |
155 |
RAISE NOTICE '% % %', user, clock_timestamp(), message; |
8 |
0 |
0 |
0 |
WHEN 'DEBUG' THEN |
9 |
0 |
0 |
0 |
RAISE DEBUG '% % %', user, clock_timestamp(), message; |
10 |
0 |
0 |
0 |
WHEN 'LOG' THEN |
11 |
4 |
1036 |
690 |
RAISE LOG '% % %', user, clock_timestamp(), message; |
12 |
0 |
0 |
0 |
WHEN 'INFO' THEN |
13 |
0 |
0 |
0 |
RAISE INFO '% % %', user, clock_timestamp(), message; |
14 |
0 |
0 |
0 |
WHEN 'WARNING' THEN |
15 |
0 |
0 |
0 |
RAISE WARNING '% % %', user, clock_timestamp(), message; |
16 |
0 |
0 |
0 |
ELSE |
17 |
0 |
0 |
0 |
NULL; |
18 |
0 |
0 |
0 |
END CASE; |
19 |
0 |
0 |
0 |
END; |
20 |
0 |
0 |
0 |
|