Alfredo Krieg's DBA blog - Oracle ACE: Testing user calls

In the performance tuning world specially talking about Response Time Analysis (RTA), user calls is often used as a workload metric; however this instance statistic was not yet completely clear.

When this metric is incremented?, How this metric is instrumented?, Why sometimes user calls is less with the same SQL statement?; these were some questions rounding my mind.

My friend Craig Shallahamer did a great post in his blog “A Wider View” related to user calls (http://shallahamer-orapub.blogspot.mx/2010/05/understanding-user-calls.html), however looking into Tanel Poder’s blog today everything got clear.

Let’s start tracing an Oracle session using trace events ‘10046’ & ‘10051’.

Event ‘10051’ will trace OPI calls, more information (http://blog.tanelpoder.com/2011/03/20/lobread-sql-trace-entry-in-oracle-11-2/), what are OPI calls?, well as per Oracle documentation:

Oracle Program Interface (OPI)

A networking layer responsible for responding to each of the possible messages sent by OCI. For example, an OCI request to fetch 25 rows would have an OPI response to return the 25 rows once they have been fetched.

Let’s do it!

SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

ALTER SESSION SET EVENTS '10051 TRACE NAME CONTEXT FOREVER, LEVEL 12';

Session altered.

SQL>

Session altered.

SQL> SELECT TRACEFILE FROM V$PROCESS WHERE ADDR =(SELECT PADDR FROM V$SESSION WHERE SID=49);

TRACEFILE

--------------------------------------------------------------------------------

/u01/app/oracle/diag/rdbms/rac/RAC1/trace/RAC1_ora_5393.trc

In another window open the trace file using tail –f in order to monitor the trace execution. Now let’s issue a small query:

SQL> select * from dual;

SQL>

Here’s the output of the trace file:

*** 2013-08-05 21:42:15.721

WAIT #3: nam='SQL*Net message from client' ela= 342028978 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1375756935721909

OPI CALL: type=105 argc= 2 cursor= 0 name=Cursor close all

CLOSE #3:c=0,e=18,dep=0,type=0,tim=1375756935722017

OPI CALL: type=94 argc=28 cursor= 0 name=V8 Bundled Exec

WAIT #1: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375756935722368

WAIT #1: nam='ges message buffer allocation' ela= 0 pool=0 request=1 allocated=0 obj#=-1 tim=1375756935722448

WAIT #1: nam='library cache lock' ela= 568 handle address=1287268616 lock address=1263092292 100*mode+namespace=65538 obj#=-1 tim=1375756935723089

WAIT #1: nam='ges message buffer allocation' ela= 1 pool=0 request=1 allocated=0 obj#=-1 tim=1375756935723137

WAIT #1: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375756935723205

WAIT #1: nam='library cache pin' ela= 473 handle address=1287268616 pin address=1263092428 100*mode+namespace=65538 obj#=-1 tim=1375756935723815

=====================

PARSING IN CURSOR #4 len=210 dep=1 uid=0 oct=3 lid=0 tim=1375756935724353 hv=864012087 ad='4cb562e8' sqlid='96g93hntrzjtr'

select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2

END OF STMT

PARSE #4:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1375756935724351

BINDS #4:

Bind#0

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

kxsbbbfp=0040a79c bln=22 avl=03 flg=05

value=116

Bind#1

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

kxsbbbfp=0040a778 bln=24 avl=02 flg=05

value=1

EXEC #4:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1375756935724524

FETCH #4:c=0,e=51,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=1375756935724594

STAT #4 id=1 cnt=1 pid=0 pos=1 obj=424 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=0 us)'

STAT #4 id=2 cnt=1 pid=1 pos=1 obj=426 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=0 us)'

CLOSE #4:c=0,e=40,dep=1,type=3,tim=1375756935724660

=====================

PARSING IN CURSOR #1 len=18 dep=0 uid=0 oct=3 lid=0 tim=1375756935725402 hv=942515969 ad='4b5c8e54' sqlid='a5ks9fhw2v9s1'

select * from dual

END OF STMT

PARSE #1:c=3999,e=3334,p=0,cr=3,cu=0,mis=1,r=0,dep=0,og=1,plh=272002086,tim=1375756935725401

EXEC #1:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1375756935725457

WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1375756935725480

WAIT #1: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375756935725627

WAIT #1: nam='gc cr grant 2-way' ela= 1035 p1=1 p2=928 p3=4 obj#=116 tim=1375756935726935

WAIT #1: nam='db file sequential read' ela= 634 file#=1 block#=928 blocks=1 obj#=116 tim=1375756935737381

WAIT #1: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=116 tim=1375756935741146

WAIT #1: nam='gc cr grant 2-way' ela= 470 p1=1 p2=929 p3=1 obj#=116 tim=1375756935741693

WAIT #1: nam='db file sequential read' ela= 1312 file#=1 block#=929 blocks=1 obj#=116 tim=1375756935743074

FETCH #1:c=1999,e=17670,p=2,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1375756935743169

STAT #1 id=1 cnt=1 pid=0 pos=1 obj=116 op='TABLE ACCESS FULL DUAL (cr=3 pr=2 pw=0 time=0 us cost=2 size=2 card=1)'

WAIT #1: nam='SQL*Net message from client' ela= 221 driver id=1650815232 #bytes=1 p3=0 obj#=116 tim=1375756935743513

OPI CALL: type= 5 argc= 2 cursor= 1 name=FETCH

FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=272002086,tim=1375756935743579

WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=116 tim=1375756935743629

Snapper shows the below metrics for our session:

SQL> @snapper4 all 5 1 49

Sampling SID 49 with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v4.09 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

SID @INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES

--------------------------------------------------------------------------------------------

49 @1, SYS , STAT, opened cursors cumulative, 1, .2, , , , , 1 per execution

49 @1, SYS , STAT, user calls, 3, .59, , , , , 3 per execution

Now let’s create a dummy table and insert some rows:

SQL> insert into test_user (user_name) select username from dba_users;

36 rows created.

From trace file:

*** 2013-08-05 21:55:34.386

WAIT #1: nam='SQL*Net message from client' ela= 58636486 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1375757734386174

OPI CALL: type=105 argc= 2 cursor= 0 name=Cursor close all

CLOSE #1:c=0,e=15,dep=0,type=0,tim=1375757734386272

OPI CALL: type=94 argc=28 cursor= 0 name=V8 Bundled Exec

=====================

PARSING IN CURSOR #3 len=37 dep=1 uid=0 oct=3 lid=0 tim=1375757734387095 hv=1398610540 ad='4cbf4cb0' sqlid='grwydz59pu6mc'

select text from view$ where rowid=:1

END OF STMT

PARSE #3:c=0,e=375,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=1375757734387093

BINDS #3:

Bind#0

oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00

oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0

kxsbbbfp=1184df90 bln=16 avl=16 flg=05

value=00002068.0000.0001

EXEC #3:c=2000,e=54991,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=3684871272,tim=1375757734442193

FETCH #3:c=0,e=34,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=1375757734442283

STAT #3 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'

CLOSE #3:c=0,e=51,dep=1,type=0,tim=1375757734442357

WAIT #2: nam='ges message buffer allocation' ela= 4 pool=0 request=1 allocated=0 obj#=-1 tim=1375757734443204

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375757734443382

WAIT #2: nam='library cache lock' ela= 549 handle address=1222331724 lock address=1220909652 100*mode+namespace=65538 obj#=-1 tim=1375757734444345

WAIT #2: nam='KJC: Wait for msg sends to complete' ela= 10 msg=1361877012 dest|rcvr=65536 mtype=12 obj#=-1 tim=1375757734444389

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375757734444433

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375757734444564

WAIT #2: nam='library cache pin' ela= 640 handle address=1222331724 pin address=1220909516 100*mode+namespace=65538 obj#=-1 tim=1375757734445329

WAIT #2: nam='KJC: Wait for msg sends to complete' ela= 9 msg=1361877012 dest|rcvr=65536 mtype=12 obj#=-1 tim=1375757734445367

=====================

PARSING IN CURSOR #6 len=210 dep=1 uid=0 oct=3 lid=0 tim=1375757734475342 hv=864012087 ad='4cb562e8' sqlid='96g93hntrzjtr'

END OF STMT

PARSE #6:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1375757734475341

BINDS #6:

Bind#0

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

kxsbbbfp=0040210c bln=22 avl=04 flg=05

value=74760

Bind#1

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

kxsbbbfp=004020e8 bln=24 avl=02 flg=05

value=1

EXEC #6:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1375757734475532

FETCH #6:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=1375757734475567

STAT #6 id=1 cnt=0 pid=0 pos=1 obj=424 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=2 pr=0 pw=0 time=0 us)'

STAT #6 id=2 cnt=0 pid=1 pos=1 obj=426 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=0 us)'

CLOSE #6:c=0,e=1,dep=1,type=3,tim=1375757734475616

=====================

PARSING IN CURSOR #2 len=64 dep=0 uid=0 oct=2 lid=0 tim=1375757734477276 hv=1206268670 ad='48d0a418' sqlid='4x5wmqj3yccry'

insert into test_user (user_name) select username from dba_users

END OF STMT

PARSE #2:c=10999,e=90955,p=0,cr=4,cu=0,mis=1,r=0,dep=0,og=1,plh=3422547789,tim=1375757734477275

WAIT #2: nam='ges message buffer allocation' ela= 5 pool=0 request=1 allocated=0 obj#=74760 tim=1375757734478040

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=74760 tim=1375757734478200

WAIT #2: nam='enq: TM - contention' ela= 616 name|mode=1414332419 object #=74760 table/partition=0 obj#=74760 tim=1375757734478936

WAIT #2: nam='asynch descriptor resize' ela= 4 outstanding #aio=0 current aio limit=384 new aio limit=390 obj#=-1 tim=1375757734486405

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=-1 tim=1375757734486564

WAIT #2: nam='gc cr grant 2-way' ela= 519 p1=1 p2=1976 p3=4 obj#=281 tim=1375757734487242

WAIT #2: nam='db file sequential read' ela= 788 file#=1 block#=1976 blocks=1 obj#=281 tim=1375757734488113

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=281 tim=1375757734488224

WAIT #2: nam='gc cr grant 2-way' ela= 431 p1=1 p2=1977 p3=1 obj#=281 tim=1375757734488790

WAIT #2: nam='db file sequential read' ela= 889 file#=1 block#=1977 blocks=1 obj#=281 tim=1375757734489741

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=281 tim=1375757734491203

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=281 tim=1375757734491352

WAIT #2: nam='enq: HW - contention' ela= 1020 name|mode=1213661190 table space #=0 block=4282248 obj#=281 tim=1375757734492503

WAIT #2: nam='ges message buffer allocation' ela= 2 pool=0 request=1 allocated=0 obj#=281 tim=1375757734492596

WAIT #2: nam='gc current grant 2-way' ela= 422 p1=1 p2=87945 p3=33554433 obj#=74760 tim=1375757734493138

EXEC #2:c=5000,e=15461,p=2,cr=41,cu=7,mis=0,r=36,dep=0,og=1,plh=3422547789,tim=1375757734493365

STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=41 pr=2 pw=0 time=0 us)'

STAT #2 id=2 cnt=36 pid=1 pos=1 obj=0 op='HASH JOIN (cr=40 pr=2 pw=0 time=35 us cost=24 size=1092 card=13)'

STAT #2 id=3 cnt=36 pid=2 pos=1 obj=0 op='HASH JOIN (cr=37 pr=2 pw=0 time=35 us cost=22 size=1053 card=13)'

STAT #2 id=4 cnt=36 pid=3 pos=1 obj=0 op='HASH JOIN (cr=28 pr=2 pw=0 time=35 us cost=17 size=1014 card=13)'

STAT #2 id=5 cnt=36 pid=4 pos=1 obj=0 op='HASH JOIN OUTER (cr=19 pr=2 pw=0 time=140 us cost=13 size=975 card=13)'

STAT #2 id=6 cnt=36 pid=5 pos=1 obj=0 op='HASH JOIN (cr=16 pr=2 pw=0 time=35 us cost=10 size=598 card=13)'

STAT #2 id=7 cnt=36 pid=6 pos=1 obj=0 op='HASH JOIN (cr=13 pr=0 pw=0 time=0 us cost=8 size=572 card=13)'

STAT #2 id=8 cnt=2 pid=7 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=6 pr=0 pw=0 time=3 us cost=4 size=16 card=1)'

STAT #2 id=9 cnt=1 pid=8 pos=1 obj=280 op='TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=8 card=1)'

STAT #2 id=10 cnt=2 pid=8 pos=2 obj=0 op='BUFFER SORT (cr=3 pr=0 pw=0 time=1 us cost=2 size=8 card=1)'

STAT #2 id=11 cnt=2 pid=10 pos=1 obj=280 op='TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=8 card=1)'

STAT #2 id=12 cnt=36 pid=7 pos=2 obj=22 op='TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=0 us cost=3 size=1008 card=36)'

STAT #2 id=13 cnt=2 pid=6 pos=2 obj=281 op='TABLE ACCESS FULL PROFNAME$ (cr=3 pr=2 pw=0 time=1 us cost=2 size=2 card=1)'

STAT #2 id=14 cnt=2 pid=5 pos=2 obj=297 op='TABLE ACCESS FULL RESOURCE_GROUP_MAPPING$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=29 card=1)'

STAT #2 id=15 cnt=7 pid=4 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=9 pr=0 pw=0 time=48 us cost=4 size=21 card=7)'

STAT #2 id=16 cnt=7 pid=3 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=9 pr=0 pw=0 time=12 us cost=4 size=21 card=7)'

STAT #2 id=17 cnt=9 pid=2 pos=2 obj=292 op='TABLE ACCESS FULL USER_ASTATUS_MAP (cr=3 pr=0 pw=0 time=8 us cost=2 size=27 card=9)'

WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=74760 tim=1375757734493823

And from Snapper:

SQL> @snapper4 all 10 1 49

Sampling SID 49 with interval 10 seconds, taking 1 snapshots...

-- Session Snapper v4.09 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

SID @INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES

49 @1, SYS , STAT, opened cursors cumulative, 3, .33, , , , , 1 per execution

49 @1, SYS , STAT, user calls, 2, .22, , , , , .67 per execution

Now let’s commit:

SQL> commit;

Commit complete.

SQL>

From trace file:

*** 2013-08-05 22:01:49.281

WAIT #2: nam='SQL*Net message from client' ela= 374787222 driver id=1650815232 #bytes=1 p3=0 obj#=74760 tim=1375758109281068

OPI CALL: type=105 argc= 2 cursor= 0 name=Cursor close all

CLOSE #2:c=0,e=20,dep=0,type=0,tim=1375758109281167

OPI CALL: type=94 argc=28 cursor= 0 name=V8 Bundled Exec

=====================

PARSING IN CURSOR #4 len=6 dep=0 uid=0 oct=44 lid=0 tim=1375758109281299 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y'

commit

END OF STMT

PARSE #4:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1375758109281298

XCTEND rlbk=0, rd_only=0, tim=1375758109281345

EXEC #4:c=0,e=102,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=1375758109281434

WAIT #4: nam='log file sync' ela= 24619 buffer#=4018 sync scn=1381492 p3=0 obj#=74760 tim=1375758109306071

WAIT #4: nam='SQL*Net message to client' ela= 351 driver id=1650815232 #bytes=1 p3=0 obj#=74760 tim=1375758109307375

From Snapper:

SQL> @snapper4 all 6 1 49

Sampling SID 49 with interval 6 seconds, taking 1 snapshots...

-- Session Snapper v4.09 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

SID @INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES

49 @1, SYS , STAT, opened cursors cumulative, 1, .17, , , , , ~ per execution

49 @1, SYS , STAT, user commits, 1, .17, , , , , ~ per execution

49 @1, SYS , STAT, user calls, 2, .34, , , , , ~ per execution

This is just a little example of how OPI CALL is related to user calls metric. You can play and test more scenarios of select statements to see how they are being affected by ARRAYSIZE setting in SqlPlus.

Craig posted a table containing the result of his testing which is having the same results as this test.

SQL	User Calls
Select 1 row	3
Insert	2
Commit	2

Thanks,

Alfredo

Labels: Oracle, Performance, trace, user calls

Alfredo Krieg's DBA blog - Oracle ACE

Monday, August 5, 2013

Testing user calls

0 Comments:

Post a Comment

About Me

Previous Posts