Query Requires More Time to Execute from an Instant Client Connection

12 08 2010

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.








Follow

Get every new post delivered to your Inbox.

Join 144 other followers