2013-12-16

Instrumentation still needed

Recently I received an email with an simple content:
"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