August 12, 2010
An interesting thread appeared on the OTN forums a couple of days ago where the original poster demonstrated that a simple query that executed in 0.12 seconds from a SQL*Plus session on the server required 1 minute and 54.19 seconds on a client that was connected using Oracle’s Instant Client. The simple query looked like this:
select mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
How would you troubleshoot this performance problem? What would you do and not do, and in what order:
- Create a Statspack or AWR report.
- Review an ADDM report.
- Execute the SQL statement multiple times in each environment to limit differences due to the effects of buffer caching.
- Execute the SQL statement from another computer that is also using the Oracle Instance Client.
- Execute the SQL statement from another computer that is using the regular Oracle Client.
- Perform an AUTOTRACE to see the execution plan along with the number of reads from the buffer cache and the number of physical reads.
- Execute the query at the client and server, specifying the GATHER_PLAN_STATISTICS hint and then examine the execution plan using DBMS_XPLAN.DISPLAY_CURSOR.
- Set the STATISTICS_LEVEL to ALL for both client and display an execution plan with DBMS_XPLAN.DISPLAY_CURSOR.
- Enable a 10046 trace at level 12 and process the trace file using TKPROF.
- Enable a 10046 trace at level 12 and manually review the trace file.
- Review a 10053 trace for the SQL statement executed on the client-side and server-side.
- Verify that the NLS settings are the same for the client-side and server-side sessions.
- Review the data captured by ASH.
- Investigate the network connection.
- Pass along the problem to someone more familiar with troubleshooting performance problems.
- Say “that’s just the way it works,” then duck and cover.
——
What would you do if AUTOTRACE and DBMS_XPLAN show the same execution plan, yet the predicate information section is different. For example:
Autotrace:
Predicate Information (identified by operation id):
---------------------------------------------------
5 - filter("LASTINSTUSERALIAS"='2221')
8 - access("LASTINSTUSERALIAS"='2221')
10 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
12 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
14 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
16 - filter("USERALIAS"='2221')
18 - filter("USERALIAS"='2221')
20 - access("USERALIAS"='2221')
22 - access("USERALIAS"='2221')
24 - access("USERALIAS"='2221')
26 - filter("USERALIAS" IS NOT NULL AND "USERALIAS"='2221')
28 - access("USERALIAS"='2221')
30 - access("USERALIAS"='2221')
32 - access("USERALIAS"='2221')
34 - access("USERALIAS"='2221')
36 - access("USERALIAS"='2221')
38 - access("USERALIAS"='2221')
40 - access("USERALIAS"='2221')
42 - access("USERALIAS"='2221')
44 - filter("USERALIAS"='2221')
46 - filter("USERALIAS"='2221')
DBMS_XPLAN:
Predicate Information (identified by operation id):
---------------------------------------------------
5 - filter("LASTINSTUSERALIAS"=:SYS_B_1)
8 - access("LASTINSTUSERALIAS"=:SYS_B_1)
10 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
12 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
14 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
16 - filter("USERALIAS"=:SYS_B_1)
18 - filter("USERALIAS"=:SYS_B_1)
20 - access("USERALIAS"=:SYS_B_1)
22 - access("USERALIAS"=:SYS_B_1)
24 - access("USERALIAS"=:SYS_B_1)
26 - filter(("USERALIAS" IS NOT NULL AND "USERALIAS"=:SYS_B_1))
28 - access("USERALIAS"=:SYS_B_1)
30 - access("USERALIAS"=:SYS_B_1)
32 - access("USERALIAS"=:SYS_B_1)
34 - access("USERALIAS"=:SYS_B_1)
36 - access("USERALIAS"=:SYS_B_1)
38 - access("USERALIAS"=:SYS_B_1)
40 - access("USERALIAS"=:SYS_B_1)
42 - access("USERALIAS"=:SYS_B_1)
44 - filter("USERALIAS"=:SYS_B_1)
46 - filter("USERALIAS"=:SYS_B_1)
——
What if you executed the following script on the client-side and server-side and found that the SQL_ID and or CHILD_NUMBER displayed were different for the client and server executions:
ALTER SESSION SET STATISTICS_LEVEL='TYPICAL';
SET AUTOTRACE OFF
SET SERVEROUTPUT OFF
SET TIMING OFF
SET LINESIZE 160
SET PAGESIZE 1000
select /*+ GATHER_PLAN_STATISTICS */ mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
select /*+ GATHER_PLAN_STATISTICS */ mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
SELECT
*
FROM
TABLE(DBMS_XPLAN.DISPLAY_CURSOR('NULL,NULL,'ALLSTATS LAST'));
——
There are several interesting replies in the OTN message thread, including a very helpful response by Randolf Geist.
Recent Comments