SQLDeveloper VAR NUMBER

Just been tearing my hair out on some unexpected SQL behaviour in SQL Developer.
Eventually I managed to get to the root cause of the problem as illustrated below.
There is a silent failure which can cause unexpected results from your SQL.

SQL*Plus:

SQL> var ps number
SQL> exec :ps := 4001644945;

PL/SQL procedure successfully completed.

SQL> select :ps from dual;

       :PS
----------
4001644945

SQL>

SQL Developer v3.2 and v4.0 via “Run As Script(F5)”:

var ps number
exec :ps := 4001644945;
select :ps from dual;

anonymous block completed
       :PS
----------
         0 

Looks like SQL Developer is running into an integer problem and silently “dealing” with it.

var ps number
exec :ps := 2147483647
select :ps from dual;
exec :ps := 2147483648
select :ps from dual;

anonymous block completed
       :PS
----------
2147483647 

anonymous block completed
       :PS
----------
         0 

No such problem when you do a Run (F9) and use the bind dialog.
One to watch out for if you do a lot of sql execution via var like me.
Think I’ve seen it before. Think I might even have blogged about it before!

SQL Developer 3 and Timestamp Conversion

I shouldn’t be using an old version of SQL Developer like v3 (3.2.10.09) anyway but… cut a long story short … I am.
I’ve also got v4 which doesn’t display the same problem

Just pointing out an oddity whilst investigating something for someone:

with x as 
(select to_date('28-MAR-2015 01:30','DD-MON-YYYY HH24:MI') dt1
 ,      to_date('29-MAR-2015 01:30','DD-MON-YYYY HH24:MI') dt2
 from   dual)
select sessiontimezone
,      dt2 "date"
,      cast(dt2 as timestamp) "timestamp"
,      to_Char(cast(dt2 as timestamp),'DD-MON-YYYY HH24:MI') "string"
from   x;

Run as Script (F5):

SESSIONTIMEZONE date               timestamp                       string                   
--------------- ------------------ ------------------------------- -----------------
Europe/London   29-MAR-2015 01:30  29-MAR6-2015 01.30.00.000000000 29-MAR-2015 01:30

Run Statement (F9):

Europe/London   29-MAR-2015 01:30   29-MAR-2015 02.30.00.000000000 29-MAR-2015 01:30

Spot the oddity in column “timestamp” in the “Run Statement (F9)” output.

There is something dodgy going on related to timestamp display.

Colleagues in other regions have not had the same problem so I wonder if some environment variable is/isn’t getting passed along for one of these tool/driver code paths.

I’ve seen dodgy timestamp behaviour before when trying to run dbms_xplan.display_cursor(null,null) in SQL Developer and getting the plan not of my target statement but of some timestamp lookup somewhere – either tool or driver.

For example, if I run the statement above together with a dbms_xplan select but this time via “Run As Script (F5)”, e.g.

with x as 
(select to_date('28-MAR-2015 01:30','DD-MON-YYYY HH24:MI') dt1
 ,      to_date('29-MAR-2015 01:30','DD-MON-YYYY HH24:MI') dt2
 from   dual)
select sessiontimezone
,      dt2 "date"
,      cast(dt2 as timestamp) "timestamp"
,      to_Char(cast(dt2 as timestamp),'DD-MON-YYYY HH24:MI') "string"
from   x;

select * from table(dbms_xplan.display_cursor(null,null));

Then apparently my last run script (the meaning of the first null parameter to display_cursor) is:

SQL_ID  0gzt83m5pxufx, child number 0 
------------------------------------- 
/*+ NO_SQL_TRANSLATION */SELECT VALUE FROM V$NLS_PARAMETERS WHERE PARAMETER = 'NLS_TIMESTAMP_FORMAT' 
 
Plan hash value: 1805486652 
 
-------------------------------------------------------------------------- 
| Id  | Operation        | Name             | Rows  | Bytes | Cost (%CPU)| 
-------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT |                  |       |       |     1 (100)| 
|*  1 |  FIXED TABLE FULL| X$NLS_PARAMETERS |     1 |    31 |     0   (0)| 
-------------------------------------------------------------------------- 
 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
 
   1 - filter(("PARAMETER"='NLS_TIMESTAMP_FORMAT' AND 
              "PARAMETER"<>'NLS_SPECIAL_CHARS' AND "INST_ID"=USERENV('INSTANCE')))

Unfortunately, this could all largely be irrelevant to the OP’s question which was why does the following code return the wrong result:

select CAST(FROM_TZ( TO_TIMESTAMP('29-MAR-15 16:30:00','DD-MON-YY HH24:MI:SS') , TO_CHAR('Australia/Sydney')) AT TIME ZONE 'America/New_York' AS timestamp)
from dual;
29-MAR-2015 02.30.00.000000000

But if we run this:

select CAST(FROM_TZ( TO_TIMESTAMP('29-MAR-15 16:30:00','DD-MON-YY HH24:MI:SS') , TO_CHAR('Australia/Sydney')) AT TIME ZONE 'America/New_York' AS timestamp)
,      to_char(CAST(FROM_TZ( TO_TIMESTAMP('29-MAR-15 16:30:00','DD-MON-YY HH24:MI:SS') , TO_CHAR('Australia/Sydney')) AT TIME ZONE 'America/New_York' AS timestamp),'DD-MON-YYYY HH24:MI')
from dual;
29-MAR-2015 02.30.00.000000000	29-MAR-2015 01:30

Then perhaps it suggests that this is just this tool or jdbc error and not something related to DST timezone data files, etc?

Also, there’s something about timestamps with (local) time zones which always causes trouble and which you’re forced to relearn every time… maybe it’s just me?

SQL Developer: Viewing Trace Files

Just a quick plug for looking at raw sql trace files via SQL Developer.

There is a nice Tree View:
sqldev_trace

Which can be expanded:
sqldev_trace_expand

Also summary view of statistics, filterable:
sqldev_trace_stats

And a list view, filterable and orderable:

sqldev_trace_list

Some sort of right click summary for binds/waits might be a nice addition.

Real time sql monitoring – bulk bound statement

Moving through some observations of an ongoing investigation tackling the easiest ones first.

Previously I observed the slow execution of a recursive delete of statistics history but coming not from MMON but from a number of application processes which should have only been calculating stats for their own partitions.

Statement was sql id 9v9n97qj8z1dg:

	
delete /*+ dynamic_sampling(4) */
from sys.wri$_optstat_histhead_history
where savtime < :1
and rownum <= NVL(:2, rownum);

From the real time sql monitoring output of a single execution (DBMS_SQLTUNE.REPORT_SQL_MONITOR EXEC_ID parameter) , I observed that EXECS was greater than 1 and so the A-Rows was much larger than I expected for a statement which was deliberately restricting the number of rows affected by a ROWNUM predicate.

Reminder:

SQL Plan Monitoring Details (Plan Hash Value=2348801730)
=======================================================================================================================================================================================================
| Id   |            Operation             |             Name              |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Activity |            Activity Detail            |
|      |                                  |                               | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |              (# samples)              |
=======================================================================================================================================================================================================
|    0 | DELETE STATEMENT                 |                               |         |       |     50262 |   +101 |  1423 |        1 |      |       |          |                                       |
|    1 |   DELETE                         | WRI$_OPTSTAT_HISTHEAD_HISTORY |         |       |     50361 |     +2 |  1423 |        1 |      |       |    29.74 | enq: TX - row lock contention (14630) |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | buffer busy waits (231)               |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (82)                              |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | resmgr:cpu quantum (5)                |
|    2 |    COUNT                         |                               |         |       |     50262 |   +101 |  1423 |      14M |      |       |     0.00 | Cpu (1)                               |
|    3 |     FILTER                       |                               |         |       |     50266 |    +97 |  1423 |      14M |      |       |    30.14 | Cpu (15146)                           |
|    4 |      TABLE ACCESS BY INDEX ROWID | WRI$_OPTSTAT_HISTHEAD_HISTORY |      6M | 23218 |     50253 |   +100 |  1423 |       4G |   22 | 176KB |    23.17 | buffer busy waits (18)                |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (11627)                           |
| -> 5 |       INDEX RANGE SCAN           | I_WRI$_OPTSTAT_HH_ST          |    990K |  5827 |     50264 |   +101 |  1423 |       4G |   41 | 328KB |    16.94 | buffer busy waits (3)                 |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (8332)                            |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | resmgr:cpu quantum (180)              |
=======================================================================================================================================================================================================
   3 - filter(ROWNUM<=NVL(:2,ROWNUM))
   5 - access("WRI$_OPTSTAT_HISTHEAD_HISTORY"."SYS_NC00024$"<SYS_EXTRACT_UTC(:1))

Initially I was stumped by the fact that A-Rows in steps 2-3 was greater than the ROWNUM predicate restriction (10000) but that was before I noticed the number of EXECS and EXECS * 10000 = 14M so was this a report of a bulk/batched statement?

So, this is just an illustration that such a bulk bound statement will produce an output as per above.

Create a table with a few rows to slow things down:

drop table t3;

create table t3
as
with x as
(select rownum col1
 from   dual
 connect by level <= 1000)
select x1.col1
,      rpad('X',100,'X') col2
from   x x1, x x2;

Then run an update with FORALL to bulk bind:

declare
 v1 sys.odcinumberlist := sys.odcinumberlist();
begin
 for i in 1 .. 1000
 loop
     v1.extend();
     v1(i) := i;
 end loop;
 forall i in 1 .. v1.count
   update /*+ monitor domtest */ t3
   set    col2 = rpad('Y',100,'Y')
   where  col1 = v1(i);
 commit;
end;
/

Hunt down my SQL execution and get RTSM output of statement.

V$SQL reports this as one execution updating 1M rows.

select executions, rows_processed, elapsed_time/1000/1000, sql_text from v$sql where sql_id = '3tkqtzjyaa02g';

EXECUTIONS ROWS_PROCESSED ELAPSED_TIME/1000/1000 SQL_TEXT
---------- -------------- ---------------------- ------------------------------------------------------------------------------
         1        1000000             109.596429 UPDATE /*+ monitor domtest */ T3 SET COL2 = RPAD('Y',100,'Y') WHERE COL1 = :B1

RTSM reports it as 1044 (!?) executions and doesn’t seem to deal with the number of rows updated.
We only get the bind for the initial bind – not unexpected.

select dbms_sqltune.report_sql_monitor('3tkqtzjyaa02g',sql_exec_id => '16777216') from dual;
SQL Monitoring Report

SQL Text
------------------------------
UPDATE /*+ monitor domtest */ T3 SET COL2 = RPAD('Y',100,'Y') WHERE COL1 = :B1

Global Information
------------------------------
 Status              :  DONE                 
 Instance ID         :  1                    
 SQL ID              :  3tkqtzjyaa02g        
 SQL Execution ID    :  16777216             
 Execution Started   :  02/26/2015 13:25:29  
 First Refresh Time  :  02/26/2015 13:25:29  
 Last Refresh Time   :  02/26/2015 13:27:19  
 Duration            :  110s                 
 Module/Action       :  SQL Developer/-      
 Service             :  SYS$USERS            
 Program             :  SQL Developer        

Binds
========================================================================================================================
| Name | Position |  Type  |                                           Value                                           |
========================================================================================================================
| :B1  |        1 | NUMBER | 1                                                                                         |
========================================================================================================================

Global Stats
=========================================
| Elapsed |   Cpu   |  Other   | Buffer |
| Time(s) | Time(s) | Waits(s) |  Gets  |
=========================================
|     110 |     109 |     0.16 |    16M |
=========================================

SQL Plan Monitoring Details (Plan Hash Value=669554690)
==========================================================================================================================
| Id |      Operation       | Name |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|    |                      |      | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
==========================================================================================================================
|  0 | UPDATE STATEMENT     |      |         |      |           |        |  1044 |          |          |                 |
|  1 |   UPDATE             | T3   |         |      |       109 |     +2 |  1044 |        0 |     0.92 | Cpu (1)         |
|  2 |    TABLE ACCESS FULL | T3   |     171 | 3409 |       110 |     +1 |  1044 |       1M |    99.08 | Cpu (108)       |
==========================================================================================================================

By contrast a non-bulk bound FOR LOOP statement would register as 1000 executions in V$SQL and each a separate SQL_EXEC_ID.

However this does nothing to address the concern about what the heck is going on such that application processes executing gather_table_stats for a particular partition would each end up running this bulk indiscriminate cleanup script… heading that way next.

COUNT STOPKEY – NVL

Yesterday I mentioned issues with a recursive delete operation on statistics history.

This is a quick illustration of the last points I made on that post regarding the lack of a COUNT STOPKEY optimisation because of the use of NVL.

COUNT STOPKEY is an optimisation which allows processing to stop once the target number of rows has been reached.

For example:

create table t1 as select * from dba_objects;

alter session set statistics_level = all;

var rn number
exec :rn := 10;

select *
from   t1
where  rownum <= :rn
and    mod(object_id,5) = 0;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

Plan hash value: 3836375644

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |     10 |00:00:00.01 |       4 | 
|*  1 |  COUNT STOPKEY     |      |      1 |        |     10 |00:00:00.01 |       4 |
|*  2 |   TABLE ACCESS FULL| T1   |      1 |  26148 |     10 |00:00:00.01 |       4 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(ROWNUM<=:RN)
   2 - filter(MOD("OBJECT_ID",5)=0) 

COUNT STOPKEY kicks in after we have fetched the relevant rows and stops any unnecessary further execution – note in particular A-Rows & Buffers for STEP 2

However, if we use NVL around our ROWNUM limitation, then this optimisation is prevented.

var rn number
exec :rn := 10;

select *
from   t1
where  rownum <= nvl(:rn,rownum)
and    mod(object_id,5) = 0;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

Plan hash value: 624922415

--------------------------------------------------------------------------------------
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |      1 |        |     10 |00:00:00.09 |    2310 |
|   1 |  COUNT              |      |      1 |        |     10 |00:00:00.09 |    2310 |
|*  2 |   FILTER            |      |      1 |        |     10 |00:00:00.09 |    2310 |
|*  3 |    TABLE ACCESS FULL| T1   |      1 |  26148 |  29630 |00:00:00.08 |    2310 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(ROWNUM<=NVL(:RN,ROWNUM))
   3 - filter(MOD("OBJECT_ID",5)=0)

Understanding vs Resolution – Statistics History Cleanup

Today I helped resolve a problem quickly but to the detriment of my understanding of exactly what was going on and why.

And as part of the quicker resolution, I had to destroy the evidence which would have helped understand better.

So… now need to go back and figure it out if I have time to model it properly, etc.

Here’s what little I know so far.

What happened was that there were a number of application sessions experiencing slowness and contention when executing a recursive stats history cleanup statement.

Verified via ASH that this recursive delete was somehow being called by app ETL code (TOP_LEVEL_SQL_ID, PLSQL_ENTRY_OBJECT_ID & USER_ID columns), four of them each running slow statement and also because of that nature of the statement below and being blocked by mode 6 TX locks from the leading execution.

Version is 11.2.0.3

Statement was sql id 9v9n97qj8z1dg:

delete /*+ dynamic_sampling(4) */ 
from sys.wri$_optstat_histhead_history 
where savtime < :1 
and rownum <= NVL(:2, rownum);

First up, resolution was quick and easy according to, by a quirk of coincidence, my last post:
https://orastory.wordpress.com/2015/02/16/dbms_stats-purge_stats/

We just got rid of all the statistics history using the magic PURGE_ALL truncate flag.
The history is of limited usefulness day-to-day anyway.

The slowness was holding up ETL jobs which were just trying to calculate stats for their own partition.

I was brought into the situation towards the end of the situation but here’s an illustration of the slowness:

SQL Text
------------------------------
delete /*+ dynamic_sampling(4) */ from sys.wri$_optstat_histhead_history where savtime < :1 and rownum <= NVL(:2, rownum)

Global Information
------------------------------
 Status              :  EXECUTING               
 Instance ID         :  1                       
 SQL ID              :  9v9n97qj8z1dg           
 SQL Execution ID    :  16777249                
 Execution Started   :  02/24/2015 19:11:25     
 First Refresh Time  :  02/24/2015 19:13:06     
 Last Refresh Time   :  02/25/2015 09:10:35     
 Duration            :  50351s                  
 Module/Action       :  JDBC Thin Client/-      
 Program             :  JDBC Thin Client        

Binds
========================================================================================================================
| Name | Position |  Type  |                                           Value                                           |
========================================================================================================================
| :2   |        2 | NUMBER | 10000                                                                                     |
========================================================================================================================

Global Stats
===============================================================================================
| Elapsed |   Cpu   |    IO    | Application | Concurrency |  Other   | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) |  Gets  | Reqs | Bytes |
===============================================================================================
|   50359 |   35199 |     0.16 |       14669 |         254 |      237 |     1G |   63 | 504KB |
===============================================================================================

SQL Plan Monitoring Details (Plan Hash Value=2348801730)
=======================================================================================================================================================================================================
| Id   |            Operation             |             Name              |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Activity |            Activity Detail            |
|      |                                  |                               | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |              (# samples)              |
=======================================================================================================================================================================================================
|    0 | DELETE STATEMENT                 |                               |         |       |     50262 |   +101 |  1423 |        1 |      |       |          |                                       |
|    1 |   DELETE                         | WRI$_OPTSTAT_HISTHEAD_HISTORY |         |       |     50361 |     +2 |  1423 |        1 |      |       |    29.74 | enq: TX - row lock contention (14630) |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | buffer busy waits (231)               |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (82)                              |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | resmgr:cpu quantum (5)                |
|    2 |    COUNT                         |                               |         |       |     50262 |   +101 |  1423 |      14M |      |       |     0.00 | Cpu (1)                               |
|    3 |     FILTER                       |                               |         |       |     50266 |    +97 |  1423 |      14M |      |       |    30.14 | Cpu (15146)                           |
|    4 |      TABLE ACCESS BY INDEX ROWID | WRI$_OPTSTAT_HISTHEAD_HISTORY |      6M | 23218 |     50253 |   +100 |  1423 |       4G |   22 | 176KB |    23.17 | buffer busy waits (18)                |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (11627)                           |
| -> 5 |       INDEX RANGE SCAN           | I_WRI$_OPTSTAT_HH_ST          |    990K |  5827 |     50264 |   +101 |  1423 |       4G |   41 | 328KB |    16.94 | buffer busy waits (3)                 |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | Cpu (8332)                            |
|      |                                  |                               |         |       |           |        |       |          |      |       |          | resmgr:cpu quantum (180)              |
=======================================================================================================================================================================================================
   3 - filter(ROWNUM<=NVL(:2,ROWNUM))
   5 - access("WRI$_OPTSTAT_HISTHEAD_HISTORY"."SYS_NC00024$"<SYS_EXTRACT_UTC(:1))

So, first thought was that:

1. I thought that MMON was responsible for purging old stats… clearly not in this case as there were multiple concurrent application connections purging old data as part of their ETL process.

2. The DELETE is deleting any old history older than a parameterised date, the first 10000 rows thereof. There is no connection to the object on whose statistics the application ETL jobs were working on.

3. I would expect a COUNT STOPKEY operation but then the NVL predicate avoids this optimisation.

4. UPDATE: The real time sql monitoring output is also reporting the metrics for 1423 executions of this statement. The clue is in the 14M rows reported in the COUNT + FILTER operations. 1423 * 10000 rows = 14M. But I requested the output for what I thought was a single execution id – 16777249 – strange… bulk/batched delete ?

More questions than answers…

Call vs Exec

Just a reference to a really simple difference between CALL and EXEC.
I thought I had mentioned this before but couldn’t find it so…

EXEC/EXECUTE is a SQL*Plus command which wraps the proc call in an anonymous BEGIN … END; block.

CALL is a SQL command hence it is limited to SQL data types and there are other restrictions which the documentation sums up pretty well.

Because CALL is SQL, there is on key behavioural difference which caused a bug on a project a few years ago when Java code was calling a stored proc not with BEGIN … END; but with CALL and ended up swallowing certain exceptions:

SQL> l
  1  create or replace procedure p1
  2  as
  3  begin
  4    raise no_data_found;
  5* end;
SQL> /

Procedure created.

SQL> exec p1;
BEGIN p1; END;

*
ERROR at line 1:
ORA-01403: no data found
ORA-06512: at "PGPS_UAT1.P1", line 4
ORA-06512: at line 1


SQL> call p1();

Call completed.

SQL>

SQL expects and handles certain exceptions.

So always use BEGIN and END; blocks in application code rather than CALL.

Follow

Get every new post delivered to your Inbox.

Join 78 other followers