Implicit Timestamp Conversions… yet again

After blogging about implicit date/timestamp conversions not once but twice you would like to think that I’m fully aware of the problems and would never stumble over them myself. Wrong!

Okay, in my defence, it was only an ad-hoc query in a test environment that I was running but it raises yet another scenario that’s worthy of a short post. The table I was querying was range partitioned on a timestamp column with each partition just one day. I wanted to query just the last 4 days so my query resembled:

SELECT *
FROM   daily_partitioned_table
WHERE  tstamp >= SYSTIMESTAMP - INTERVAL '4' DAY

What could be simpler, right? Well, after waiting for a couple of minutes for a result I realised something was wrong. If we look at the execution plan for such a query we will find the problem:

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------
Plan hash value: 620599123

--------------------------------------------------------------------------------------
| Id  | Operation           | Name                    | Rows  | Bytes |Pstart| Pstop |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |                         |    25 |   375 |      |       |
|   1 |  PARTITION RANGE ALL|                         |    25 |   375 |    1 |1048575|
|*  2 |   TABLE ACCESS FULL | DAILY_PARTITIONED_TABLE |    25 |   375 |    1 |1048575|
--------------------------------------------------------------------------------------

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

   2 - filter(SYS_EXTRACT_UTC(INTERNAL_FUNCTION("TSTAMP"))>=SYS_EXTRACT_UTC(SYSTIMESTAMP(6)-INTERVAL'+0
              4 00:00:00' DAY(2) TO SECOND(0)))

From here it’s quite simple to see what’s happening; Oracle did not do any partition elimination as shown by the Pstart and Pstop columns. The reason for this is explained by the predicate details. Oracle is applying the functions SYS_EXTRACT_UTC(INTERNAL_FUNCTION(“TSTAMP”)) to the TSTAMP column, which thereby prevents partition elimination from occurring. A quick look up of documentation for SYSTIMESTAMP reveals the return data type to be TIMESTAMP WITH TIME ZONE. So, Oracle’s approach to resolving the query is to implicitly convert the TSTAMP column to TIMESTAMP WITH TIME ZONE, rather than converting the SYSTIMESTAMP expression to a TIMESTAMP data type.

Of course the solution was trivial:

SELECT *
FROM   daily_partitioned_table
WHERE  tstamp >= CAST(SYSTIMESTAMP - INTERVAL '4' DAY AS TIMESTAMP)

We can now see that partition elimination has taken place, as shown by the Pstart column containing the value of KEY:

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------
Plan hash value: 4082052782

-------------------------------------------------------------------------------------------
| Id  | Operation                | Name                    | Rows  | Bytes |Pstart| Pstop |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                         |    69 |  1035 |   |          |
|   1 |  PARTITION RANGE ITERATOR|                         |    69 |  1035 |  KEY |1048575|
|*  2 |   TABLE ACCESS FULL      | DAILY_PARTITIONED_TABLE |    69 |  1035 |  KEY |1048575|
-------------------------------------------------------------------------------------------

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

   2 - filter("TSTAMP">=CAST(SYSTIMESTAMP(6)-INTERVAL'+04 00:00:00' DAY(2) TO SECOND(0) AS TIMESTAMP))

SQL blocking with IOT FK parent

I was asked to make a trivial data change to a reference table; update some non-indexed, non-key columns in two rows. While the table is referenced heavily by a core application the table is not subject to change. I scripted up the necessary updates, ran the them, verified the changes and committed them. Given what I know about how Oracle handles locking and blocking I was rather surprised to see a system alert shortly thereafter that a critical process had suffered a delay in its processing.

Diagnosing the cause of the delay was trivial. A quick query against Active Session History showed the critical processes had been waiting on acquiring a row lock and the blocking session was the one that I ran the update within. This puzzled me as the critical process did not modify the table that I had updated. Furthermore, the statement that had been blocked was a MERGE statement on a different table.

As it turned out, the table I had been updating was a indexed organised table (IOT) and the table the critical process was performing the MERGE on had a foreign key to the table. Given that my update had obtained exclusive locks on referenced rows the critical process was unable to obtain the necessary shared locks on those rows and therefore waited for my update to be committed.

We can easily demonstrate this behaviour with a simple test:

CREATE TABLE parent
   (parent_id    NUMBER(10)   NOT NULL
   ,parent_name  VARCHAR2(50) NOT NULL
   ,CONSTRAINT parent_pk PRIMARY KEY (parent_id))
ORGANIZATION INDEX
/

CREATE TABLE child
   (child_id    NUMBER(10)   NOT NULL
   ,parent_id   NUMBER(10)   NOT NULL
   ,child_name  VARCHAR2(50) NOT NULL)
/

ALTER TABLE child
   ADD CONSTRAINT child_pk
   PRIMARY KEY (child_id)
/

ALTER TABLE child
   ADD CONSTRAINT child_fk1
   FOREIGN KEY (parent_id)
   REFERENCES parent (parent_id)
/

CREATE INDEX child_i1
   ON child (parent_id)
/

INSERT INTO parent
SELECT ROWNUM
,      'Parent ' || TO_CHAR(ROWNUM)
FROM   dual
CONNECT BY level <= 10
/

INSERT INTO child
SELECT ROWNUM
,      CASE WHEN MOD(ROWNUM,10)=0 THEN 10 ELSE MOD(ROWNUM,10) END
,      'Child ' || TO_CHAR(ROWNUM)
FROM   dual
CONNECT BY level <= 100
/

COMMIT
/

EXEC dbms_stats.gather_table_stats ('','parent')
EXEC dbms_stats.gather_table_stats ('','child')

We have a PARENT and a CHILD table with a foreign key relationship between them. PARENT has 10 rows and CHILD has 100 rows. In one session we perform an update on a PARENT row:

UPDATE parent
SET    parent_name = 'PARENT ' || 5
WHERE  parent_id = 5
/

and in a separate session we run a series of DML statements:

-- STATEMENT 1
-- insert using unlocked parent row
INSERT INTO child
VALUES (101,1,'CHILD 101')
/

-- STATEMENT 2
-- insert using locked parent row
INSERT INTO child
VALUES (102,5,'CHILD 101')
/

-- STATEMENT 3
-- delete using locked parent
DELETE
FROM   child
WHERE  child_id = 55
/

-- STATEMENT 4
-- update using locked parent
UPDATE child
SET    child_name = 'NEW CHILD 65'
WHERE  child_id = 65
/

-- STATEMENT 5
-- merge using unlocked parent
MERGE INTO child dest
USING  (SELECT 103         AS child_id
        ,      7           AS parent_id
        ,      'CHILD 103' AS child_name
        FROM   dual) src
ON (src.child_id = dest.child_id)
WHEN MATCHED THEN UPDATE
SET dest.child_name = src.child_name
WHEN NOT MATCHED THEN INSERT
   (child_id
   ,parent_id
   ,child_name)
VALUES
   (src.child_id
   ,src.parent_id
   ,src.child_name)
/   

-- STATEMENT 6
-- merge using locked parent
MERGE INTO child dest
USING  (SELECT 104         AS child_id
        ,      5           AS parent_id
        ,      'CHILD 104' AS child_name
        FROM   dual) src
ON (src.child_id = dest.child_id)
WHEN MATCHED THEN UPDATE
SET dest.child_name = src.child_name
WHEN NOT MATCHED THEN INSERT
   (child_id
   ,parent_id
   ,child_name)
VALUES
   (src.child_id
   ,src.parent_id
   ,src.child_name)
/   

Both STATEMENT 2, insert into CHILD referencing the locked PARENT entry, and STATEMENT 6, merge into CHILD using the locked PARENT entry, are blocked by the transaction against the PARENT table. If we were to replace the PARENT IOT with a normal heap table then we would find that no operation against the CHILD table is blocked.

So why does an IOT parent table make such a difference? I would guess that performing INSERT and MERGE Oracle needs to take out a shared lock on the parent to ensure referential integrity. We certainly would not want to perform an insert into a child table only to have the referenced parent table entry deleted by another session whilst our insert transaction is still in progress. With an IOT there is no table structure and all data is stored in the primary key index so when we updates the PARENT “table” we are actually updating the primary key index entry. Our PARENT update would have to take an exclusive lock on that and therefore denies the CHILD operations the ability to obtain a shared lock.

Obtaining an Execution Plan – part 2

As short follow-up to obtaining an SQL execution plan, a point regarding DBMS_XPLAN.DISPLAY_CURSOR that I failed to note previously was that with no arguments it returns the plan for the last statement run within the session. I seem to recall that this routine appeared in Oracle 10g.

This is really cool feature as it means your process can capture execution plans themselves for analysis later on. Sure, you can extract the execution plan for a query direct from the SGA or from AWR but if you have concerns about the plan for an SQL statement you can simply log it immediately after its execution with no hassles (or in the case of AWR, no extra licensing fees). This approach might not be suitable for OLTP systems but for those hairy data extract / reporting queries that all too regularly seem to go wrong in the middle of the night this might provide a convenient means of checking execution details. It also provides a convenient way for developers to obtain the execution plan for their queries while doing their development, without having to poke around in the SGA looking up SQL_IDs and PLAN_HASH_VALUEs.

Let’s take a quick look at how you might do this. I’m going to reuse the READINGS table that I created in a previous post along with the query to obtain the latest reading timestamp for a given meter. This routine utilises PKG_LOG to log the execution plan, after having converted to a CLOB.

DECLARE
   
   TYPE t_xplan_table   IS TABLE OF VARCHAR2(300);

   l_meter_id           readings.meter_id%TYPE := 1234;
   l_max_reading_tstamp readings.reading_tstamp%TYPE;
   l_xplan_table        t_xplan_table;

   -- a simple routine that converts t_xplan_table
   -- to a CLOB
   FUNCTION to_clob (p_xplan_table IN t_xplan_table)
   RETURN CLOB
   AS
      c_new_line     CONSTANT VARCHAR2(2) := CHR(10) || CHR(13);
      l_return_value CLOB;
   BEGIN
      dbms_lob.createtemporary (l_return_value, FALSE);
      FOR i IN 1..p_xplan_table.COUNT
      LOOP
         dbms_lob.writeappend (l_return_value
                              ,LENGTH(p_xplan_table(i)||c_new_line) 
                              ,p_xplan_table(i)||c_new_line);
      END LOOP;
      RETURN l_return_value;
   END to_clob;
   
BEGIN

   pkg_app_info.set_module ('Capture SQL plan');
   pkg_log.enable_logging;

   -- run the query whose plan we want to capture   
   SELECT MAX(reading_tstamp)
   INTO   l_max_reading_tstamp
   FROM   readings
   WHERE  meter_id = l_meter_id
   AND    reading_type = 'A';
   
   -- grab the plan of the previously executed query
   SElECT t.plan_table_output
   BULK COLLECT INTO l_xplan_table
   FROM   TABLE(dbms_xplan.display_cursor()) t;
   
   -- write the plan to our LOGS table
   pkg_log.info (p_msg => 'SQL plan capture'
                ,p_msg_detail => to_clob(l_xplan_table));
                
END;
/                   

Once logged we can examine the plan directly from the LOGS table by running something like:

SELECT msg_detail
FROM   logs
WHERE  module = 'Capture SQL plan'
AND    log_timestamp >= SYSTIMESTAMP - INTERVAL '5' MINUTE

One important point to note though, akin to implicit cursor attributes, no other SQL statement can occur between the statements whose plan you want to capture and the call to DBMS_XPLAN. As such, I strongly recommend that the call to DBMS_XPLAN occur immediately after the SQL statement itself. Feel free to create a simple procedure to do this though, perhaps using the PKG_LOG.DEBUG routine so that it’s only enabled when logging is running in “debug mode”:

CREATE OR REPLACE PROCEDURE capture_sql_plan
AS
   
   TYPE t_xplan_table   IS TABLE OF VARCHAR2(300);

   l_xplan_table        t_xplan_table;

   -- a simple routine that converts t_xplan_table
   -- to a CLOB
   FUNCTION to_clob (p_xplan_table IN t_xplan_table)
   RETURN CLOB
   AS
      c_new_line     CONSTANT VARCHAR2(2) := CHR(10) || CHR(13);
      l_return_value CLOB;
   BEGIN
      dbms_lob.createtemporary (l_return_value, FALSE);
      FOR i IN 1..p_xplan_table.COUNT
      LOOP
         dbms_lob.writeappend (l_return_value
                              ,LENGTH(p_xplan_table(i)||c_new_line) 
                              ,p_xplan_table(i)||c_new_line);
      END LOOP;
      RETURN l_return_value;
   END to_clob;
   
BEGIN

   -- grab the plan of the previously executed query
   SElECT t.plan_table_output
   BULK COLLECT INTO l_xplan_table
   FROM   TABLE(dbms_xplan.display_cursor()) t;
   
   -- write the plan to our LOGS table
   pkg_log.debug (p_msg => 'SQL plan capture'
                 ,p_msg_detail => to_clob(l_xplan_table));
                
END capture_sql_plan;