SQL with bind vars is very slow in toad

Toad for Oracle
1

Hi all,

when we run an SQL with bind variables in Toad for ORACLE (tried 13.2.0.258 and 12.6.0.53) on different computers with different ORACLE Connectors (12-19) on a ORACLE DB 12.2.0.1,
it is so horrible slow (up to 7 minutes).

When i run the same SQL (same SQL_ID) with the same binding in SQL Developer, SQL Plus or Quest SQL Optimizer (tried 8.x and 9.x) i have the result in 0.1 - 0.3 seconds.

The SQL retrieve 1-300 rows, and also an another bind variable has no effect.

Tracing is disabled in Toad.

Any ideas?

Thank you

BR
J

PS: Script runner seams to have the same issue (but only if i use the TSR Option --> Scripts --> Show Script Grids)
PPS: static SQL in Toad is fast with 240 ms

SOLUTION

Toad Datagrid --> Right Click --> Restore desktop defaults

After doing that SQL is as fast as in other tools (240ms).

2

After you restore desktop default, and the query runs fast, is there something you can change in Toad to make the query start going slowly again?

3

So far i was not able to reproduce.

Maybe in Toad V 9/10 i saved an layout, and maybe there was a problem with migrating it through the versions till 13.

4

I don't know why this would affect SQL execution but I'm glad you got it solved. Let us know if you discover a way to make the problem return.

5

Hi John,

unfortunately my problem is back... SQL with BindVar is ******* SLOW in Toad

I reinstalled Toad for ORACLE 13.2.0.258 (64 bit) and removed all Toad files, i only imported my connections, i reinstalled the Oracle Client (19c) but the situation stay the same.

Tests with the same binding

Slow:
Toad for ORACLE (10 secs, 8 Rows)

BUG:
Toad Script Runner (400 ms, 0 Rows)

FAST:
SQLPlus, SQLDeveloper, Quest SQL Optimizer (100 ms, 8 rows)

SQL in ( SQLDeveloper, Quest SQL Optimizer, Toad for ORACLE):

select column1, column2
from table1 t1, table2 t2
where t1.id = t2.t1_id
and t1.search_column like :bind_var;

Apps ask for bind_var (VARCHAR2, IN) ==> blabla

SQL in (SQLPlus, Toad Script Runner):

var bind_var varchar2(100) = 'blabla'

select column1, column2
from table1 t1, table2 t2
where t1.id = t2.t1_id
and t1.search_column like :bind_var;

How does Toad execute SQLs with BindVariables?

Any Ideas?

Thank you
BR

6

I can repeat the bug where Toad Script Runner does not set the variables that way. You can set them in TSR like this:

var abc varchar2(100);

exec :abc := '123';

select :abc from dual;

unfortunately, I don't know why your SQL is executing slowly when you run it from Toad. Toad does not execute SQL. Oracle does. Toad sends the SQL to Oracle using the OCI. We create bind variables using OCI commands.

Maybe a trace of the session both from SQL*Plus and Toad will reveal something.

ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
then your sql statement

then to turn tracing off:
ALTER SESSION SET EVENTS '10046 trace name context forever, level 0';

Now, go find your trace files on the server. The next SQL will tell you which folder to look in.

select name, value
from v$diag_info
where name = 'Diag Trace'

I'll send you my email address in a private message. You can email the trace files to me and I'll take a look.

7

The only difference I see in there is the bind variable size. In SQL*Plus you define it as 120. Toad just takes the actual size (in this case 59).

You can see it in this data (This is from the Toad file. See that mxlc=59?):

 Bind#0
  oacdty=01 mxl=128(59) mxlc=59 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000010 frm=01 csi=31 siz=128 off=0
  kxsbbbfp=121060850  bln=128  avl=59  flg=05
  value="-501-4822301-16719901-16720101-16102501-25982701-27887301-%"

I don't know why that would make a difference (and maybe it isn't making the difference).
Another thing that I thought of is the OCI Fetch size. In SQL*Plus, this is called ARRAY SIZE and defaults to 25. Toad determines an optimal value and adjusts it for each SQL statement (Normally 500, but as row size increases, the array size decreases).

You can override this behavior in Toad in Options -> Oracle -> General. Set "OCI Array Buffer Size" to manual and put in 25. I don't know if this will affect the perforamance of this SQL but I do know that if you have a fetch with lots of rows, changing the settings will make fetches take longer.

You can also try setting array size to 500 in SQL*Plus and see if it worsens behavior there.

8

Hi John,

i tried both:

SQLPlus with ARRAY SIZE 500/1000
and Toad with 25/50

with no effect.

Also the definition of the variable 59 or 100 has no effect.

9

It's very strange. Oracle even assigns the same SQLID when the query is run from Toad vs SQL*Plus. So Oracle knows that it is the same SQL when run from 2 different applications. But some reason it chooses a different execution plan when it is run from Toad.

I wish I had an answer for you. Maybe Oracle support can tell you something using those 2 trace files.

10

Evening Gents,

Have a look in v$sqlPlan for the different plans. You can use the sql_id to query the view.

If you are suffering from different plans for the same sql, with binds, then welcome to my world! So am Ibut not yet on 19c.

V$shared_cursor should show how many child cursors have been created for your sql_id and, usually, the reason why.

There are bugs in the new adaptive cursor sharing, vheck support for your version. We have similar problems and have had to pin a good plan in memory to stop oracle choosing the bad plans.

I'm also happy to look at the trace files if no-one objects, and if I can be useful?

HTH

Cheers,
Norm. [TeamT]

11

I was hoping we'd get your attention. Trace files sent. :smiley:

12

We are on 12.2.0.1

v$sql_shared_cursor

REASON_NOT_SHARED CURSORS
OPTIMIZER_MISMATCH 11
BIND_LENGTH_UPGRADEABLE 2
STATS_ROW_MISMATCH 2
USER_BIND_PEEK_MISMATCH 1

I can also share the full detail of both mentioned views with you Norm/John.

PS: when i run the SQL in the Script Runner (and assign the bind var as you mentioned John) it is also constant slow

13

I believe this SQL will show you the differences in optimizer variables. Just plug in the session ID from the Toad session and again from a SQL*Plus session.

select sid, id, name, value, isdefault
from   V$SES_OPTIMIZER_ENV
where sid = ...
order by id

I checked a SQL*Plus session vs a Toad session and I am getting identical values (even using a different Oracle client) but perhaps yours will be different.

You can find your session id with: select distinct sid from v$mystat;

14

My values/isdefault are 100 % equal.

15

I've looked at your trace files. In the Toad one, 72 seconds was spent gathering dynamic stats. Then a further 8 seconds but that was common to sqlplus, so is discounted.

In the output from v$shared_cursor, I see 11 optimiser mismatches. Interesting given that you are seeing 100% the same. Could be a bug, could be other sessions since database startup. But your child cursor dud not have the same optimiser environment in 11 different ways. (You appear to have 16 different child cursors for this one sql_id).

User_bind_peek_mismatch is telling me that this query has been run previously, with a bind that doesnt give the same execution plan. For better or worse? Who knows! Given your testing is using the same bind, this must be left over from another test or run with a bind value that pulls more or less data back.

Stats_row_mismatch says that stats have changed so a new child cursor, and potentially, execution plan, has been created.

If v$shared_cursor still has data for your sql_id, what if anything is in the REASON colum. It might be helpful.

Cheers,
Norm. [TeamT]

16

I forgot to mention, one trace shows nested loops while the other shows hash joins. One, if I remember, shows full scans while the other is a PK scan. (Why scan the pk, it's unique!).

I'm suffering this problrm at work. We have a few SRs raised against adaptive cursor sharing - unresolved at the moment. I have a colleague who is pinning good plans in the sga to stop the bad plans being used. So far, so good. All from the same app, not two different ones like your problem.

Oh, you have polling for dbms_output turned on in Toad. That will also affect your run time, perhaps. Not to the extent you are seeing though.

Cheers,
Norm. [TeamT]

17

Hi Norm. / John,

i ran the v$sql_shared_cursor again:

REASON_NOT_SHARED CURSORS SQL_IDS
ROLL_INVALID_MISMATCH 2 0
STATS_ROW_MISMATCH 2 0
OPTIMIZER_MISMATCH 1 0
PURGED_CURSOR 1 0
USER_BIND_PEEK_MISMATCH 1 0

V$SES_OPTIMIZER_ENV is identical.

I saw that both tests (SQLPLUS vs TOAD/QSR) was with the same SQL_ID but with different childs 4 and 5.

But i don't understand why the Optimizer choose which one.

If it is helpfull i can share the new tracefiles and also the V$SQL_SHARED_CURSOR to you.

Thank you for your support :+1:

18

Roll_invalid_mismatch means that new stats have been gathered and existing cursors have been invalidated. This happens at "some random point in the next 5 hours", by default, from the stats gather time.

Purged_cursor is when someone or something changed on the underlying table(s) - alter table perhaps.

Sometimes the REASON column in v$shared_cursor has useful information about why the child cursor was created. Not always though. Have a looksee - it might be helpful.

I'll happily look at your trace files etc, thanks. Send them to toad at dunbar-it dot co dot uk. Thanks.

Cheers,
Norm. [TeamT]

19

Files are sent.

Thank you Norm. :+1:

20

Afternoon Johann,

@JOHN: For information.

See attached file. It contains an analysis text file, and a couple of
HTML files showing the code actually executed in your trace files, with
all the binds replaced by the actual text.

SQL Plus did a straight PARSE-EXEC-FETCH-CLOSE with a good plan. Toad
too executed the good plan, once, but on two other occasions, it
executed the bad plan. Toad seems to run a couple of extra PARSE-CLOSE
operations too. This seems a bit strange to me, maybe John knows why? It
might be so that Toad can determine type and size of the required bind
variables so that the user can be prompted for values at run time? (I'm
guessing, but that's what Perl and Java does.)

The text file basically walks through the trace files extracting the
relevant details. I can see why Toad's execution takes much longer,
there's a HASH JOIN with million plus blocks being read (from UNDO it
seems) which happens twice in the Toad trace, SQL Plus doesn't have this
operation. Mind you, the execution plan in Johann's original file, shows
that this step never actually took place! The trace file says otherwise.

I would love to say it's a bug, but I cannot think of any kind of bug
which would always run SQL Plus quickly and never Toad. Unless Oracle
are doing something underhand - which I'm not offering as a serious
possibility!

The good plans read 8 rows from BATCHES using an index lookup, the bad
plan does a full scan of 13,478,003 rows. Given that the one, singular
bind variable is identical in each case, the optimiser should know to
use an index lookup!

Anyway, there's more in the analysis.txt file in the attached zip file.
I'm afraid I don't have a good reason for the problem.

@Johann, do you see this problem with other (simpler?) SQL statements on
the same database? How about on other databases?

Does SQL*Plus have any startup files that execute? perhaps changing the
optimiser environment, etc? How about Toad?

Can you tell I'm grasping at straws? :frowning:

Cheers,
Norm. [TeamT]

(Attachment TraceFiles.html.zip is missing)