Query Requires More Time to Execute from an Instant Client Connection

12082010

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:

Actions

Information

2 responses

Note, I’ve intentionally tried to avoid the thread to try and not spoil the fun of this exercise.

Question 1:

– “How would you troubleshoot this performance problem? What would you do and not do, and in what order:”

Answer 1:

I think my first step would be to try and retrieve the actual executions plans for the query that runs well and the query that runs badly. I personally wouldn’t vote for using AUTOTRACE as it can report inaccurate results. If I had access to both machines the easiest way to probably do this, as long as the problem is repeatable would probably be to use the following method you identified:

– 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.

Setting STATISTICS_LEVEL to ALL would probably only be useful in situations where you couldn’t get access to and/or run the code manually.

If I didn’t have access to these clients my next step would be to try and probe the V$ views to try and identify the SQL_ID, and CHILD_NUMBER and use DBMS_XPLAN.DISPLAY_CURSOR. If this fails then I would use the following method:

– Enable a 10046 trace at level 12 and process the trace file using TKPROF.

I don’t think a 10046 trace at level 12 and manually reviewing the trace file is useful at the moment because I’m just after the execution plans. If I need to dig into the weeds this may be useful later.

I don’t think generating a STATSPACK/AWR report is useful at the moment because based on the problem description this seems like an issue in particular with the SQL statement and not an instance wide issue that may show up in a STATSPACK/AWR report. There is no complaint of general slowness of the entire system in the problem statement either.

I probably wouldn’t execute the queries on another computer regardless of what client is installed because chances are the client settings on the machine I test on will not be exactly the same as those on the two given in the problem statement.

The 10053 trace may be useful to use if further execution plan analysis is required. Using DBMS_XPLAN.DISPLAY_CURSOR will ALLSTATS generates a lot of information and I may only dig into the 10053 trace file if the execution plans are different and the A-Rows vs E-Rows given in DBMS_XPLAN.DISPLAY_CURSOR didn’t lead me down another path.

I think the network would only be worth investigating if there were significant wait times related to the network displayed in the TKPROF file.

Question 2:

– What would you do if AUTOTRACE and DBMS_XPLAN show the same execution plan, yet the predicate information section is different. For example:

Answer 2:

The immediate tip off here is the existence of “:SYS_B_01.” This tells me that there is most likely a difference in the client configurations between the two, probably related to the CURSOR_SHARING parameter.

This may be a good time to gather as much information about the client configurations as possible to see if there are any other differences. The 10053 trace file may be useful in this case because it may highlight some parameter differences related to the CBO.

Ultimately the issue could be like the Tom Kyte story, “the database is slow when it rains on .” Bind peeking and data distribution issues may be the culprit.

Question 3:

– 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:

Answer 3:

Typically I wouldn’t expect the SQL_ID to be different in this case because the query text is exactly the same. If the CHILD_NUMBER is different then it may be beneficial to compare the PLAN_HASH_VALUE to determine if the execution plans were indeed the same. If they are different it could be do to environmental differences as mentioned above. The slow one may not be using the optimal plan that the well running query was using. If they have the same plan it may be worth digging deeper into the V$SQL_SHARED_CURSOR view to determine why they weren’t shared and continue the investigation there.

If after all this analysis a conclusion isn’t reached it may be worthwhile to backup a level and look at either an ASH report, or even a AWR/STATSPACK report to determine if there were any instance level issues that could have made the execution times different.

For not having visited the OTN thread prior to posting your comment, I would say that you did an excellent job of analyzing the information that I provided and offering a well reasoned method for investigating the problem.

Regarding your answer for #2, I think that my blog article might have been slightly confusing. I intended to state that from within the client session the OP was seeing a descrepany between the predicate information section of the execution plan displayed by AUTOTRACE and the predicate information section of the execution plan displayed by DBMS_XPLAN when also displayed within the client session (the same behavior was noted on in the server-side session also). I believe that you are correct regarding the reason for the difference in the Predicate Information section – CURSOR_SHARING=FORCE in the database instance’s initialization parameters.

In the thread you may note that I suggested a 10046 trace in addition to DBMS_XPLAN. The OP provided an update to the thread shortly after I published this blog article. The update to the thread demonstrates why someone might move quickly to a 10046 trace with TKPROF analysis and then manual analysis.

Hints for Posting Code Sections in Comments

********************
When the spacing of text in a comment section is important for readability (execution plans, PL/SQL blocks, SQL, SQL*Plus output, etc.) please use a <pre> tag before the code section and a </pre> tag after the code section:
<pre>

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;
TODAY
---------
01-MAR-12

</pre>
********************
When posting test case samples, it is much easier for people to reproduce the test case when the SQL*Plus line prefixes are not included - if possible, please remove those line prefixes. This:

SELECT
SYSDATE TODAY
FROM
DUAL;

Is easier to execute in a test case script than this:

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;

********************
Greater than and Less than signs in code sections are often interpretted as HTML formatting commands. Please replace these characters in the code sections with the HTML equivalents for these characters: