Re: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg
- From: Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
- To: "Oracle-L@xxxxxxxxxxxxx" <Oracle-L@xxxxxxxxxxxxx>
- Date: Sat, 8 Jun 2019 15:17:36 +0000
I would be very cautious about trusting any timing information for a query
running with DOP 32 (and 64 PX processes) on a virtual machine with 16 virtual
CPUs. What fraction of a real CPU is a virtual CPU, and are your "real CPUs"
based on a core count or thread count ? You may have far less CPU available
than you think - and in a virtual environment you could be subject to all
sorts of odd time-losses that Oracle doesn't know about when a process is
pre-empted, or queued.
I can't work out exactly how long your query is taking from the stats you
supplied, but some of them seem to indicate reasonable behaviour - when you
optimize the query (and you don't say how many branches you have to the UNION
ALL) one process could demand a lot of CPU for optimising leaving 64 processes
waiting for the optimisation to complete.
Are you licensed for the performance and diagnostic packs ?
Have you checked who the waiters are waiting for, and how much CPU that blocker
takes to optimise the query, and how much "lost time" that single session
records. (This may mean taking one trace file and comparing the e= and c=
values and tim= timestamps at points where the session is apparently not
waiting.
Regards
Jonathan Lewis
________________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on behalf
of k.hadd <kouss.hd@xxxxxxxxx>
Sent: 08 June 2019 00:36
To: Oracle-L@xxxxxxxxxxxxx
Subject: Fwd: 12c Parallelism in windows potentially behind library cache lock/
PX Deq: Parse Reply/ PX Deq: Execution Msg
Hi Oracle mates,
I have been tracing sessions this week where a query with multiple unions
caused user sessions to freeze subsequently .There seemed to be a contention
in the library cache (locks) but -Oddly- when I checked the trace file report
using sqlt a huge time For these queries was unaccounted for or Idle Time (PX
Deq: Parse Reply )
Environment : OS : (VM) Windows server 2012 16 VCPU [ CPU and RAM aren't
reserved ]
DB : 12c Enterprise Edition Release 12.1.0.1.0 - 64bit
Also worth mentioning is that sometimes the optimizer has a knack for wrongly
choosing parallel over serial execution when the later is 50% faster.
Any clue or insight on best practices to tackle parallelism issues on VM server
(other than completely disabling parallelism )?
Note: OPTIMIZER_ADAPTIVE_FEATURES to FALSE didn't help But disabling
parallelism kept the execution in sequence . I don' know why the Optimizer
keeps choosing a PX plan .
Back when the application ran on 10g we used to have Px deq : credit wait
events a lot but it's other parallel events since the upgrade to 12c.
Really appreciate any input .
Thank you
• Context and findings :
Below are the informations collected so far between ORACLE-S-ASH views and the
sqlt (TRCANLZR) report on the trace File ( 30 minutes).
1- S-ASH Top events report for the related period (times are in Secs)
BEGIN_TIME END_TIME WAIT_CLASS EVENT
SQL_ID COUNT TIME_WAITED AVG_TIME_WAITED
-------------------- -------------------- ------------
---------------------------------------- ------------- ---------- -----------
---------------
31-may-2019 10:00:00 31-may-2019 10:14:59 Concurrency library cache lock
11wythn1bf8c5 190968 556700 2,91
31-may-2019 10:00:03 31-may-2019 10:14:29 Concurrency library cache: mutex X
11wythn1bf8c5 1690 15 0
31-may-2019 10:01:04 31-may-2019 10:01:07 Concurrency cursor: pin S wait on X
11wythn1bf8c5 4 10 2,5
2- The TraceFile for one of the users
Relevant Executions
Performance stats for for one of the executions . Both Idle (PX deq :
Parse Reply which isn't really idle time) and non accounted for times make for
almost 100% of the response time.
I suspect the freeze comes from a parallel CPU en-queue during library
cache access but don't know how I could avoid this .
Rank Trace
ET
Pct1 Self
Elapsed
Time2 CPU Time Non-Idle
Wait Time Recursive
Elapsed
Time3 Exec
Count User Depth SQL Text Hash Value SQL ID Plan
Hash
Value
1: 79.1% 841.060 22.094 0.814 0.850 3 115 0 SELECT
1*1 TypeEnregistrement ,1* EMPLH.ID_R ID_
45556101<https://mail.google.com/mail/u/0/#sql298> 11wythn1bf8c5
3867173512
Call Response Time
Accounted-for Elapsed
Time CPU Time Non-Idle
Wait Time Elapsed Time
Unaccounted-for Idle
Wait Time
Parse: 0.042 0.032 0.016 0.001 0.016 0.010
Execute: 7.153 7.153 6.906 0.123 0.124 0.000
Fetch: 826.337 413.562 0.703 0.308 412.551 412.775
Total: 833.532 420.747 7.625 0.432 412.690 412.785
Fetch
Call Response Time
Accounted-for Elapsed
Time CPU Time Non-Idle
Wait Time Elapsed Time
Unaccounted-for Idle
Wait Time Call Timestamp
First: 826.080 413.810 0.984 0.306 412.529 412.541 MAY-31 10:44:33.191
[image.png]
Rank 1 : 11wythn1bf8c5 3867173512
Event Name Wait Class Non-Idle
Wait Time Times
Waited
Non-Idle Idle
Wait Time Times
Waited
Idle Average
Wait Time Max
Wait Time Blocks Average
Blocks
PX Deq: Parse Reply: Idle 412.533 64 6.445834
85.928264
enq: PS - contention: Other 0.301 64 0.004699
0.008888
SQL*Net message from client: Idle 0.246 56
0.004394 0.011639
db file sequential read: User I/O 0.128 127
0.001011 0.014514 127 1
PX Deq: Join ACK: Idle 0.004 127 0.000029
0.000645
PX Deq Credit: send blkd: Idle 0.002 6
0.000392 0.000937
SQL*Net more data to client: Network 0.002 65
0.000027 0.000272
log file sync: Commit 0.001 1 0.000595 0.000595
SQL*Net message to client: Network 0.000 57
0.000001 0.000003
latch: row cache objects: Concurrency 0.000 4
0.000010 0.000020
SQL*Net more data from client: Network 0.000 1
0.000013 0.000013
latch: shared pool: Concurrency 0.000 1
0.000005 0.000005
Total: 0.432 320 412.785 253
Fetch
Call Recursive
Call
Count OS
Buffer Gets
(disk) BG Consistent
Read Mode
(query) BG Current
Mode
(current) Rows
Processed
or Returned Library
Cache
Misses Times
Waited
Non-Idle Times
Waited
Idle Call Timestamp
First: 3000 10 198855 0 100 0 78 198 MAY-31
10:44:33.191
Second: 0 0 0 0 100 0 2 1 MAY-31
10:44:33.197
Third: 0 0 0 0 100 0 2 1 MAY-31
10:44:33.201
Last: 0 0 0 0 66 0 2 1 MAY-31
10:44:33.457
overview of the data exchange between the producers/consumer during the
execution
Username QC/Slave SlaveSet SID Slave INS STATE WAIT_EVENT
QC SID QC INS Req. DOP Actual DOP
------------ -------- -------- ------ --------- --------
------------------------------ ------ ------ -------- ----------
APP1 QC 596 1 WAIT PX Deq: Parse Reply
596
- p00k (Slave) 1 16 1 WAIT PX Deq: Execution Msg
596 1 32 32
- p006 (Slave) 1 62 1 WAIT PX Deq: Execution Msg
596 1 32 32
- p00l (Slave) 1 211 1 WAIT PX Deq: Execution Msg
596 1 32 32
- p00a (Slave) 1 224 1 WAIT PX Deq: Execution Msg
596 1 32 32
- p00m (Slave) 1 384 1 WAIT PX Deq: Execution Msg
596 1 32 32
- p00p (Slave) 1 405 1 WAIT library cache lock
596 1 32 32
- p008 (Slave) 1 421 1 WAIT cursor: pin S wait on
X 596 1 32 32
Explain Plan : did not match the the plan used for execution which was had
parallel processes (adaptive_plan).
Again , I always wanted to ask the client to reserve esx cpu and the ram for
the vm but lacked concrete evidence of it's impact on Oracle parallelism to
back it up.
Thank you very much for reading
Kouss
- References:
Other related posts:
- » RE: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg- Mark W. Farnham
- » Re: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg - Jonathan Lewis
- » Re: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg- k.hadd
- » Re: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg- k.hadd
