"It" is slow again :-)The email explained a package to be slow.
Ok, I started with my "not enough information" reply and an email conversation began.
We are still not ready to identify the problem, but as there is no code instrumentation in place I tried to identify what's possible with
v$active_session_history (ASH).To do so, I created 2 Packages:
P1 and P2. P1 has a procedure DO_IT and a function SLEEP, which burns CPU for approximately x seconds. P2 only has a function SLEEP, which also burns CPU for approximately x seconds and then calls P1.SLEEP again. P1.DO_IT has a simple sql which calls P1.SLEEP and P2.SLEEP. My code is properly instrumented using DBMS_APPLICATION_INFO.set_module in the code and dbms_session.set_identifier to identify one specific execution - to compare it's value to the information already available in v$active_session_history.Here the packages:
CREATE OR REPLACE
PACKAGE P1
IS
PROCEDURE DO_IT(SEC IN NUMBER);
FUNCTION SLEEP(SEC IN NUMBER)
RETURN NUMBER;
END;
/
CREATE OR REPLACE
PACKAGE P2
IS
FUNCTION SLEEP(SEC IN NUMBER)
RETURN NUMBER;
END;
/
CREATE OR REPLACE PACKAGE BODY P1
IS
PROCEDURE DO_IT(SEC IN NUMBER)
IS
r NUMBER;
BEGIN
DBMS_APPLICATION_INFO.set_module(module_name => 'P1',
action_name => 'DO_IT');
dbms_output.put_line('++P1.DO_IT++');
SELECT P2.SLEEP(SEC) into r
FROM DUAL
WHERE P1.SLEEP(SEC) > 1;
dbms_output.put_line('--P1.DO_IT--');
DBMS_APPLICATION_INFO.set_module(module_name => 'blaaa',
action_name => 'blaaa');
END DO_IT;
FUNCTION SLEEP(SEC IN NUMBER)
RETURN NUMBER
IS
C NUMBER := 0;
now DATE := SYSDATE;
BEGIN
DBMS_APPLICATION_INFO.set_module(module_name => 'P1',
action_name => 'SLEEP');
dbms_output.put_line('++P1.SLEEP++');
LOOP
C := C + 1;
EXIT WHEN now + (SEC * (1/86400)) <= SYSDATE;
END LOOP;
dbms_output.put_line('--P1.SLEEP--');
DBMS_APPLICATION_INFO.set_module(module_name => 'blaaa',
action_name => 'blaaa');
RETURN C;
END SLEEP;
END;
/
CREATE OR REPLACE
PACKAGE BODY P2
IS
FUNCTION SLEEP(SEC IN NUMBER)
RETURN NUMBER
IS
C NUMBER := 0;
D NUMBER := 0;
now DATE := SYSDATE;
BEGIN
DBMS_APPLICATION_INFO.set_module(module_name => 'P2',
action_name => 'SLEEP');
dbms_output.put_line('++P2.SLEEP++');
LOOP
C := C + 1;
EXIT WHEN now + (SEC * (1/86400)) <= SYSDATE;
END LOOP;
SELECT P1.SLEEP(SEC) into D
FROM DUAL;
C := C + D;
dbms_output.put_line('--P2.SLEEP--');
DBMS_APPLICATION_INFO.set_module(module_name => 'blaaa',
action_name => 'blaaa');
RETURN C;
END SLEEP;
END;
/
I started the testcase with a simple
set serveroutput on exec dbms_session.set_identifier(client_id => 'berx testcase ' || to_char(sysdate, 'YYYY-MM-DD HH24:MI:SS') ); exec p1.do_it(5); exec dbms_session.set_identifier(client_id => 'berx testcase ' || to_char(sysdate, 'YYYY-MM-DD HH24:MI:SS') ); exec p1.do_it(5); exec dbms_session.set_identifier(client_id => 'blaaa');
And immediately afterwards I checked for sql_id, top_level_sql_id, action, module, client_id, plsql_entry_object_id, plsql_entry_subprogram_id, plsql_object and plsql_subprogram_id
select SESSION_ID,
sql_id,
( SELECT max( substr( sql_text , 1, 40 )) FROM v$sql sq WHERE sq.sql_id = ash.sql_id ) AS sql_text,
TOP_LEVEL_SQL_ID,
( SELECT max( substr( sql_text , 1, 40 )) FROM v$sql sq WHERE sq.sql_id = ash.top_level_sql_id ) AS top_level_sql_text,
action,
module,
client_id
, ( SELECT object_name FROM dba_procedures WHERE object_id = plsql_entry_object_id AND subprogram_id = 0) AS plsql_entry_object
, ( SELECT procedure_name FROM dba_procedures WHERE object_id = plsql_entry_object_id AND subprogram_id = plsql_entry_subprogram_id) AS plsql_entry_subprogram
, ( SELECT object_name FROM dba_procedures WHERE object_id = plsql_object_id AND subprogram_id = 0) AS plsql_object
, ( SELECT procedure_name FROM dba_procedures WHERE object_id = plsql_object_id AND subprogram_id = PLSQL_SUBPROGRAM_ID) AS plsql_subprogram
from v$active_session_history ash
where SAMPLE_TIME > sysdate - 1/(24*60)
and session_id = SYS_CONTEXT('USERENV','SID')
order by SAMPLE_TIME asc;
Here is the result (please excuse the wide list).
ST SESSION_ID SQL_ID SQL_TEXT TOP_LEVEL_SQL_ID TOP_LEVEL_SQL_TEXT ACTION MODULE CLIENT_ID PLSQL_ENTRY_OBJECT PLSQL_ENTRY_SUBPROGRAM PLSQL_OBJECT PLSQL_SUBPROGRAM ------------------- ---------- ------------- ---------------------------------------- ---------------- ---------------------------------------- ---------- ---------- ----------------------------------- ------------------------------ ------------------------------ --------------- ---------------- 2013-12-14 22:24:00 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:01 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:02 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT P1 SLEEP 2013-12-14 22:24:03 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT P1 SLEEP 2013-12-14 22:24:04 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:05 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:06 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:07 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:00 P1 DO_IT P2 SLEEP 2013-12-14 22:24:08 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:09 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:00 P1 DO_IT P2 SLEEP 2013-12-14 22:24:10 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:11 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT P1 SLEEP 2013-12-14 22:24:12 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:13 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT P1 SLEEP 2013-12-14 22:24:14 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:00 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:15 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:16 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:17 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:18 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 2013-12-14 22:24:19 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:20 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:15 P1 DO_IT P2 SLEEP 2013-12-14 22:24:21 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:15 P1 DO_IT P2 SLEEP 2013-12-14 22:24:22 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:15 P1 DO_IT STANDARD SYSDATE 2013-12-14 22:24:23 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:15 P1 DO_IT P2 SLEEP 2013-12-14 22:24:24 160 cqd77zbnpa79n SELECT P2.SLEEP(:B1 ) FROM DUAL WHERE P1 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P2 berx testcase 2013-12-14 22:24:15 P1 DO_IT P2 SLEEP 2013-12-14 22:24:25 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 2013-12-14 22:24:26 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 2013-12-14 22:24:27 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 2013-12-14 22:24:28 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 2013-12-14 22:24:29 160 cc9hp65m5aq6s SELECT P1.SLEEP(:B1 ) FROM DUAL 1ahw2g5n38js5 BEGIN p1.do_it(5); END; SLEEP P1 berx testcase 2013-12-14 22:24:15 P1 DO_IT P1 SLEEP 30 rows selected
So my findings here:
- TOP_LEVEL_SQL_ID is the same all the time. That's good, as I have a valid anchor on the top most layer.
- there is nothing similar to SQL_EXEC_ID for the TOP_LEVEL_SQL_ID. So I can not distinguish the 2 runs of P1.DO_IT.
- PLSQL_OBJECT.PLSQL_SUBPROGRAM does not always reflect the current application module, as also internal code (as SYSDATE) is shown there. ACTION and MODULE are more reliable.
- Only with ASH I don't see any general way to identify the runtime of sub-TOP_LEVEL SQLs or PLSQL_SUBPROGRAMs.
- The most complete picture from ASH is only given with proper instrumentation
- If you need the full insight about the stack of SQL and PL/SQL calls, you need to trace the session. This again works like a charm with ACTION and MODULE set and
DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE
