Parallel Query Activity just stops

Recently I found at one customer site a strange bug on version 12.2. A parallel query just sits there and never finishes. When you further investigate the issue it becomes obvious that a sort of deadlock arises beween the query coordinator and one of the query slaves.

Both wait on table queue communication. The query coordinator will wait for PX Deq: Execute Reply and the blocking slave process is waiting for PX Deq: Table Q Normal. The rest of the slaves are waiting on PX Deq: Execution Msg.

For this to happen the query must include an analytic function.

The whole issue has a lot to do with the way Oracle parallelized the calculation of analytic functions. In particular it is about how the window sort is parallelized.

For a in depth explaination I refer to this blog post of Phythian’s Christo Kutrovsky: Oracle parallel query hints reference – part 5: PQ_DISTRIBUTE_WINDOW

For our purpose it is good enough to undstand that there are 3 methods of distributing the work to parallel slaves when calculating analytic functions in parallel. Method 3 is the traditionel method, method 1 and 2 are new in version 12. The bug can occur, if method 2 gets used.

Thankfully  Andreas Schlögl analyzed the issue and found a workaround by applying the new PQ_DISTRIBUTE_WINDOW hint. You find below his testcase, which should be self explaining.

rem ##################################
rem # Objects                        #
rem ##################################

alter session set optimizer_adaptive_plans = false;
alter system flush shared_pool;

drop table asc_dmy1;
drop table asc_dmy3;

create table asc_dmy1
parallel 8
as 
select 'AAA' f001
  from xmltable('1 to 300');
  
--note: this table has no parallel degree
create table asc_dmy3
as
select 'AAA' f001, 1 acc206
  from dual;

rem #############################################
rem # SORT then distribute by HASH (Bug)        #
rem #############################################  
/*
   leads to a HASH JOIN in Line 7, which imo must be a HASH JOIN BUFFERED (due to 2 active PX SENDs at 9 and 13) 
   This SQL hangs and never finishes 
   
   https://oracle-randolf.blogspot.com/2012/12/hash-join-buffered.html
   "At most one data distribution can be active at the same time"
   
   "Since it doesn't seem to be supported to have two PX SEND operations active at the same time, 
    some artificial blocking operation needs to be introduced, in this case the HASH JOIN BUFFERED, 
	that first consumes the second row source completely before starting the actual probe phase"
*/
select /*+ pq_distribute_window(@"SEL$1" 2) */
       max(v.acc206) over (partition by v.f001) max_bew
  from asc_dmy3 v,
       asc_dmy1 e
 where e.f001 = v.f001
   and v.f001 = e.f001;  

/*   
-----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name     | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |    TQ  |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |          |      1 |   419 |     6  (17)| 00:00:01 |        |      |            |
|   1 |  PX COORDINATOR              |          |        |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)        | :TQ10003 |      1 |   419 |     6  (17)| 00:00:01 |  Q1,03 | P->S | QC (RAND)  |
|   3 |    WINDOW CONSOLIDATOR BUFFER|          |      1 |   419 |     6  (17)| 00:00:01 |  Q1,03 | PCWP |            |
|   4 |     PX RECEIVE               |          |      1 |   419 |     6  (17)| 00:00:01 |  Q1,03 | PCWP |            |
|   5 |      PX SEND HASH            | :TQ10002 |      1 |   419 |     6  (17)| 00:00:01 |  Q1,02 | P->P | HASH       |
|   6 |       WINDOW SORT            |          |      1 |   419 |     6  (17)| 00:00:01 |  Q1,02 | PCWP |            |
|*  7 |        HASH JOIN             |          |      1 |   419 |     5   (0)| 00:00:01 |  Q1,02 | PCWP |            |
|   8 |         PX RECEIVE           |          |      1 |   415 |     3   (0)| 00:00:01 |  Q1,02 | PCWP |            |
|   9 |          PX SEND HASH        | :TQ10000 |      1 |   415 |     3   (0)| 00:00:01 |  Q1,00 | S->P | HASH       |
|  10 |           PX SELECTOR        |          |        |       |            |          |  Q1,00 | SCWC |            |
|  11 |            TABLE ACCESS FULL | ASC_DMY3 |      1 |   415 |     3   (0)| 00:00:01 |  Q1,00 | SCWP |            |
|  12 |         PX RECEIVE           |          |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,02 | PCWP |            |
|  13 |          PX SEND HASH        | :TQ10001 |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | P->P | HASH       |
|  14 |           PX BLOCK ITERATOR  |          |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | PCWC |            |
|  15 |            TABLE ACCESS FULL | ASC_DMY1 |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | PCWP |            |
-----------------------------------------------------------------------------------------------------------------------   
*/

rem #############################################
rem # distribute by HASH then SORT  (Success)   #
rem #############################################  
/*
   leads to a HASH JOIN *BUFFERED* in Line 6, which is inevitably necessary imo
   This SQL finishes immediately
*/ 
select /*+ pq_distribute_window(@"SEL$1" 1) */
       max(v.acc206) over (partition by v.f001) max_bew
  from asc_dmy3 v,
       asc_dmy1 e
 where e.f001 = v.f001
   and v.f001 = e.f001;    

/*
------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name     | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |    TQ  |IN-OUT| PQ Distrib |  OMem |  1Mem |  O/1/M   |
------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |          |        |       |     6 (100)|          |        |      |            |       |       |          |
|   1 |  PX COORDINATOR            |          |        |       |            |          |        |      |            | 73728 | 73728 |          |
|   2 |   PX SEND QC (RANDOM)      | :TQ10003 |      1 |   419 |     6  (17)| 00:00:01 |  Q1,03 | P->S | QC (RAND)  |       |       |          |
|   3 |    WINDOW SORT             |          |      1 |   419 |     6  (17)| 00:00:01 |  Q1,03 | PCWP |            | 20480 | 20480 |     8/0/0|
|   4 |     PX RECEIVE             |          |      1 |   419 |     5   (0)| 00:00:01 |  Q1,03 | PCWP |            |       |       |          |
|   5 |      PX SEND HASH          | :TQ10002 |      1 |   419 |     5   (0)| 00:00:01 |  Q1,02 | P->P | HASH       |       |       |          |
|*  6 |       HASH JOIN BUFFERED   |          |      1 |   419 |     5   (0)| 00:00:01 |  Q1,02 | PCWP |            |  3400K|  3091K|     8/0/0| 
|   7 |        PX RECEIVE          |          |      1 |   415 |     3   (0)| 00:00:01 |  Q1,02 | PCWP |            |       |       |          |
|   8 |         PX SEND HASH       | :TQ10000 |      1 |   415 |     3   (0)| 00:00:01 |  Q1,00 | S->P | HASH       |       |       |          |
|   9 |          PX SELECTOR       |          |        |       |            |          |  Q1,00 | SCWC |            |       |       |          |
|  10 |           TABLE ACCESS FULL| ASC_DMY3 |      1 |   415 |     3   (0)| 00:00:01 |  Q1,00 | SCWP |            |       |       |          |
|  11 |        PX RECEIVE          |          |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,02 | PCWP |            |       |       |          |
|  12 |         PX SEND HASH       | :TQ10001 |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | P->P | HASH       |       |       |          |
|  13 |          PX BLOCK ITERATOR |          |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | PCWC |            |       |       |          |
|* 14 |           TABLE ACCESS FULL| ASC_DMY1 |    300 |  1200 |     2   (0)| 00:00:01 |  Q1,01 | PCWP |            |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------------------
*/

Unpivot using CROSS_APPLY

Sometimes our processing logic requires us to do an unpivot. For example, if a generic interface is to be filled. Typically, such an interface table includes key fields, a column name and a column value.

I’m not a fan of such interface tables, but you do not always have the choice. 😉 When developing a time-critical code, the standard unpivot was too slow for me and I was looking for alternatives.

In the process, I came across the relatively new cross_apply clause and found it even more interesting to learn more about it. Actually the unpivot proofed to be a rather cool example.

I do not want to deny you this task.

So if that below is my Unpivot query, how can you get the same result with cross_apply?

SELECT empno, column_name, value
FROM emp t
UNPIVOT ( VALUE FOR COLUMN_NAME IN ( Mgr, deptno, sal))
/


How to create multiple SQL Monitor Reports from History

Sometimes I sat in front of the screen until late into the night and watched a batch job go by. At regular intervals, I kept storing SQL Monitor reports for later analysis.
With Oracle 12 the historical SQL Monitor became available.
I have written a small script that can generate sql monitor reports from history.
IMHO it’s the most useful script I’ve ever written.
It has no parameters, I prefer to edit my scripts.
The script has of course still room for improvement.
Maybe someone would like to publish a better version?

And, by the way, it’s written for Sql * Plus …

set newpage 0
set space 0
SET LONG 10000000 LONGCHUNKSIZE 10000000 pages 0 lines 500
set echo off
set feedback off
set verify off
set heading off
set trimspool on
set sqlp ''
spool temp.sql
WITH reps as (
	SELECT REPORT_ID,
	  KEY1 SQL_ID,
	  KEY2 SQL_EXEC_ID,
	  KEY3 SQL_EXEC_START,
	  T.PERIOD_START_TIME,
	  T.PERIOD_END_TIME,
	  TRUNC(86400*(T.PERIOD_END_TIME-T.PERIOD_START_TIME)) DURATION,
	  DECODE(TO_NUMBER(EXTRACTVALUE(XMLTYPE(REPORT_SUMMARY), '/report_repository_summary/sql/plsql_entry_object_id')), 
				NULL, EXTRACTVALUE(XMLTYPE(REPORT_SUMMARY), '/report_repository_summary/sql/module'),
			   (SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID = TO_NUMBER(EXTRACTVALUE(XMLTYPE(REPORT_SUMMARY), '/report_repository_summary/sql/plsql_entry_object_id')))) CALLED_FROM ,
	  EXTRACTVALUE(XMLTYPE(REPORT_SUMMARY), '/report_repository_summary/sql/module') module
	FROM DBA_HIST_REPORTS t,
	  dba_hist_sqltext st
	WHERE T.PERIOD_START_TIME BETWEEN TO_DATE('01.07.2017 01:00:00','DD.MM.YYYY HH24:MI:SS') AND TO_DATE('03.07.2017 23:59:00','DD.MM.YYYY HH24:MI:SS')
	  AND 86400*(T.PERIOD_END_TIME-T.PERIOD_START_TIME) >= 1000 -- abitrary treshold, longrunning statement
	  AND ST.SQL_ID                                      = T.KEY1
	  AND COMMAND_TYPE                                  <> 47 -- no PL/SQL 
	  and EXTRACTVALUE(XMLTYPE(REPORT_SUMMARY), '/report_repository_summary/sql/module')!='DBMS_SCHEDULER'), -- No gather stats
commands as (
	SELECT REPORT_ID, 1 line, 'spool sqlmon_'||SQL_ID||'_'||CALLED_FROM||'_'||REPORT_ID||'.html'  command FROM REPS
	UNION ALL
	SELECT REPORT_ID,2, 'SELECT DBMS_AUTO_REPORT.REPORT_REPOSITORY_DETAIL(RID => '|| REPORT_ID||', TYPE => ''EM'')       FROM dual;' FROM REPS
	UNION ALL
	SELECT REPORT_ID,3, 'SPOOL OFF' FROM REPS
)
SELECT COMMAND
  from commands
order by REPORT_ID,  line;
spool off
@@temp
set echo on
set feedback on
set verify on

Can a select statement create a transaction Lock?

Recently I had to research a “enq: TM contention” wait event. I queried active session history (ASH) an found blocking session’s id.

I queried ASH again and found what the blocking session was doing right at the time when the other session was waiting on the “enq: TM contention” lock. At this time there was a long running select statement active in the blocking session.

How is that possible? Can a select create a lock? What must have happened ? Would it actually help to tune the select?

For a further hint you might wat to read Arup Nanda’s blog on transaction locks.

enq: TX row lock contention and enq:TM contention

Index Rebuild: Magic or Voodoo?

I actually don’t like to write about todays topic. However, I hope you will agree this story is worth to be told.

Via Freelist somebody asked if an Index rebuild could be occaisionally usefull. There was a case at hand, where index rebuild seemed to be usefull after a big delete. I sometimes got annoyed by the popular myth, that regular index rebuild would be helpfull. This is one of the more popular database myths as branded by Mr. Index, Richard Foote.

Thus, I could not resist the opportunity to trash the myth I don’t like and answered that there is no such case. I ignored the warning wisper in my head telling me that things are never that easy.
Of course, the unavoidable happened Jonathan Lewis corrected me stating that there are corner cases were index rebuild can be useful ( e.g. after a big delete).

As if this would not be enough shortly thereafter I came accross this little statement below. (I presenting a test case that makes use of the SH schema.)

select time_id from sales where sparse is not null;

The Exection Plan with runtime statistics looks like that:

-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name       | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |            |      1 |        |      0 |00:00:00.04 |   41770 |
|   1 |  TABLE ACCESS BY GLOBAL INDEX ROWID BATCHED| SALES      |      1 |      1 |      0 |00:00:00.04 |   41770 |
|*  2 |   INDEX FULL SCAN                          | SPARSE_IDX |      1 |      1 |      0 |00:00:00.04 |   41770 |
-------------------------------------------------------------------------------------------------------------------

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

   2 - filter("SPARSE" IS NOT NULL)

Why did the optimizer choose a full index scan? Actually a full table scan would be much better. The estimate (E-Rows) is correct. The statistcs are current.

Can you guess what is missing from my test case? Hint: I researched the DML on this table and I found an update statement.

A Strange Condition in the Where Clause

It makes me proud to learn that Carlos Sierra is following my blog. I knew Carlos from my time at Oracle, even though we only recently met for the first time. I see Carlos as a man who acts rather than complains. One of the people that make a difference.
With my next example I will show that it is also an astute analyst.
I recently saw a condition in an execution plan that was not present in the sql statement. I wanted to know how the condition came from.
I give a simple example: Consider a table x that looking like this:


SQL> desc x
Name Null? Typ
----------------------------------------- -------- -----------------
Y NUMBER
Z NOT NULL NUMBER


Let us do a query on x:


select count(*) from x where z=1;


The execution plan looks like this:

Plan hash value: 989401810

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |   420 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    13 |            |          |
|*  2 |   TABLE ACCESS FULL| X    |  1144K|    14M|   420   (2)| 00:00:01 |
---------------------------------------------------------------------------

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

   2 - filter(NVL("Z",1)=1)

Why is does the execution plan show this strange condition? You will find the answer in Carlos Sierra’s blog.
One more hint: It has something to do with default values. Good luck.

Parallel Activity just drops

In one of my DWH POCs for Oracle’s Real World Performance Group we did see an unexpected drop of activity. The customer wanted to know why it happened.
This is how sql monitor’s activity tab looked:

I investigated carefully and found out that the reason was in both cases an outer join that looked liked that

FROM T_TAB1 T1
LEFT OUTER JOIN T_TAB2 T2
ON T2.X_ID    = T1.X_ID

I found that 90% of all values in T1.X_ID were Null values. The distribution for the join was hash. Thus, the parallel slave dealing with null values got most of the work and was for quite some time the only one running. Table T1 was the biggest table, to broadcast it was out of question.
(You may also compare Randolf’s article on skew parallel distribution: Parallel Execution Skew – Demonstrating Skew).

Can you now re-code the join condition such that the join is done by all parallel slaves? (This was version 11G. In version 12 the optimizer should take care of it.)  Further assumption: table T2 has a one column primary key call T2_id.

 

The Collection in The Collection

We had to rewrite a commonly used PL / SQL function. The code suffered heavily from the Context Switch. He literally was called millions of times. We set ourselves the goal of having a single Bulk Collect to read all data from the database . I give here a code skeleton that I have adapted to the scott / tiger schema.

DECLARE
   CURSOR c1
   IS
   SELECT deptno, dname
     FROM dept;
   CURSOR c2 (p_deptno NUMBER)
       IS
       SELECT empno,ename,sal, comm
         FROM emp
        WHERE deptno= p_deptno;
BEGIN
   FOR c1rec IN C1
   LOOP
      FOR c2rec IN c2(c1rec.deptno)
      LOOP
         NULL;
      END LOOP;
   END LOOP;
END;
/

 

In reality, of course, there was complex logic instead of null in the loop. I worked jointly with a developer of the Software vendors on the problem. We did not have enough time to understand this code. We decided to only formally convert the code and to keep the loops. As mentioned, we wanted to read all the data in a single step in a nested array.
There should be an outer department collection that contains an inner employee collection as a nested table. There are other solutions (as Bryn Llewellyn thankfully pointed out one in the comment), but the nested table solution merges smoothly with the legacy code. As in our example also in reality the amount of data per query was so small that it all would easily fit into one array .

How does the select look like?

 

Is the migration database slower?

My customer set up a database in a virtual environment to support a migration. Initial tests show that the migration database is many times slower than the production database. The tests focus on a particular query.

Here is an excerpt from an AWR of the migration database. You can see the relevant data from the sql command that you should investigate as part of the list “SQL ordered by elapsed time”.

apsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO
199.24	1	199.24	98.16	3.93	96.72

For comparison, the same data from the production database:

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO
11.02	1	11.02	65.95	99.98	0.0

What makes you curious? What working hypothesis would you choose to start your investigation and what would you check? Hint: This sql statement we investigate is a count which scans only one table. The execution plan is identical in both cases, it is in each case a full table scan.

Why is the new Hardware slow?

You buy new hardware to be faster. This is a normal expectation. But what if the new hardware is slower than the old one? The speculation about the cause went wildly. Since I had to wait for this assignment due to holiday time, the tension was high as the examination could finally begin.

A quick check showed that the new hardware was no slower than the old one. The decisive hint brought a raw trace. I show only the important part.

On the old hardware of trace looked like this:


FETCH #25:c=1154407,e=1152124,p=0,cr=102603,cu=0,mis=0,r=101,dep=0,og=1,tim=650755949521


Cursor # 25 is a large Select that runs slowly. On the new hardware trace looked as follows:


FETCH #601010888:c=31200,e=22483,p=0,cr=3706,cu=50,mis=0,r=1,dep=0,og=1,plh=3621104505,tim=39783214696
WAIT #601010888: nam='SQL*Net message from client' ela= 171 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=39783217398
LOBGETLEN: c=0,e=3,p=0,cr=0,cu=0,tim=39783217416
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=39783217423
WAIT #0: nam='SQL*Net message from client' ela= 117 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=39783217546
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=39783217560
LOBREAD: c=0,e=12,p=0,cr=1,cu=0,tim=39783217567


Cursor # 601010888: corresponds cursor # 25 on the old hardware. The database on the new hardware is version 11, the database on the old hardware version 10.
Obviously except for the version there is at least one other difference between the two databases. What is it? What is effect of this difference?
Both databases are accessed via the exact same program, which is implemented using MS Visual Studio.