Skip to Main Content
  • Questions

  • pl/sql code debugging - long running block

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question.

Asked: March 28, 2017 - 12:20 pm UTC

Last updated: April 08, 2017 - 5:19 am UTC

Version: 11.2.0.4

Viewed 1000+ times

You Asked

hi - our developers have a package that they are running within a begin... end block. They are telling us that this block seems to run for a very long time. this is the only thing that is running in the database and using over 90% of cpu. we ran the AWR and ASH reports but they only tell us that this block is the top event which we already know. we want to get more info as in which line in the package is running long. is there a way to get that information ?

Thanks.

and Connor said...

One plan of attack could be

a) Look at v$session.sql_id - see what exact SQL it is running
b) query v$sql for that sql_id, it will show you where in the block it originated from.

A full example here on my blog

https://connormcdonald.wordpress.com/2016/01/20/problematic-sql-plsql-is-your-friend/

Alternatively, take the package and add some calls to dbms_application_info, eg

SQL> create or replace
  2  procedure P is
  3  begin
  4    dbms_application_info.set_action('Start');
  5
  6    -- simulate a 5 second activity
  7    dbms_lock.sleep(5);
  8
  9    dbms_application_info.set_action('Step 2');
 10
 11    -- simulate a 5 second activity
 12    dbms_lock.sleep(5);
 13
 14    dbms_application_info.set_action('Step 2');
 15
 16    -- simulate a 5 second activity
 17    dbms_lock.sleep(5);
 18
 19    dbms_application_info.set_action('Step 2');
 20
 21    -- simulate a 5 second activity
 22    dbms_lock.sleep(5);
 23  end;
 24  /

Procedure created.

SQL>
SQL> exec P
[running]

--
-- then from another session I can see its status
--
SQL> select action
  2  from   v$session
  3  where  status = 'ACTIVE'
  4  and    username = 'MCDONAC';

ACTION
-------------------------------------------------


SQL>
SQL> /

ACTION
-------------------------------------------------

Start

SQL> /

ACTION
-------------------------------------------------

Step 2

SQL> /

ACTION
-------------------------------------------------

Step 3



dbms_application_info has no impact on transactions, and is very fast

SQL> set timing on
SQL> begin
  2  for i in 1 .. 1000000 loop
  3    dbms_application_info.set_action('Step 2');
  4  end loop;
  5  end;
  6  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.02


So around 1,000,000 calls per second on my laptop

Rating

  (3 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

A reader, March 29, 2017 - 11:44 am UTC

Thanks for the response.I tried looking at the sql_id from v$session. I got the sql_id of the entire pl/sql block.

BEGIN

CNV_PKG.SetArrayFetchSize(2000);
truncutil.truncate_table(<tablename>);

truncutil.truncate_table(<table2>);

CNV_PKG.proc1;

proc2;

END;

in this block, I cant find out which line is causing the issue.
Connor McDonald
March 30, 2017 - 12:33 am UTC

Think of your plsql as:

begin
  [does some plsql code]

  [runs some more sql]

  [does some plsql code]

  [runs some more sql]

  [does some plsql code]

  [runs some more sql]
end;


If you query v$session and the SQL_ID points to SQL, then your block is running some SQL at the moment. If its the SQL_ID of the block itself, its in the plsql part of the code.

Two comments...

J. Laurindo Chiappa, March 29, 2017 - 12:58 pm UTC

Hello, 'a reader' - let me give to you 2 obs :

a. there is no such thing as 'sql_id of the entire pl/sql block' : each distinct SQL present in the PL/SQL block will receive a distinct sql_id... Of course, non-distinct SQLs already present in SQL cache will share one sql_id

b. I recommend that you use the basic instrumentation technique provided by Connor (I prefer to use the CLIENT_INFO column due to the larger size) , so your PL/SQL block will turn into :
BEGIN
   --
   dbms_application_info.set_client_info('starting setarraysize @' || to_char(sysdate, 'HH24:MI:SS'));
   CNV_PKG.SetArrayFetchSize(2000);
   --
   dbms_application_info.set_client_info('starting trunc#1 @' || to_char(sysdate, 'HH24:MI:SS'));
   truncutil.truncate_table(<tablename>);
   --
   dbms_application_info.set_client_info('starting trunc#2 @' || to_char(sysdate, 'HH24:MI:SS'));
   truncutil.truncate_table(<table2>);
   --
   dbms_application_info.set_client_info('starting proc1 @' || to_char(sysdate, 'HH24:MI:SS'));
   CNV_PKG.proc1;
   --
   dbms_application_info.set_client_info('starting proc2 @' || to_char(sysdate, 'HH24:MI:SS'));
   proc2;
END;


And in another session connected to the database with any client tool, repeteadly query :

select client_info, otherusefulcolumnsinv$session FROM v$session where client_info is not null;

(replace V$ with GV$ if using RAC...
)
With this you will discover the main culprit : after that, do the same instrumentation inside the slow procedure, until you find the culprit command... It can be, maybe, the TRUNCATE command in the truncate_table procedure, or any other SQL command in proc1 OR proc2....

Regards,

J. Laurindo Chiappa
Connor McDonald
March 30, 2017 - 12:31 am UTC

nice input

instrumenting is production code

Mathias, April 07, 2017 - 12:19 pm UTC

...and PLEASE treat the dbms_application_info code as production code. That is, do not remove and do not turn it off. It should always run and it should be specific enough to tell you what is going on even when looked at on database level.

Not having this be part of production code is throwing away some of the best things you can do for yourself and your application. I'd even go as far as to say that code that isn't instrumented is not ready for production. Production lever quality code requires it to be well instrumented.
Connor McDonald
April 08, 2017 - 5:19 am UTC

Indeed.
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library