Re: 12c Parallelism in windows potentially behind library cache lock/ PX Deq: Parse Reply/ PX Deq: Execution Msg
Date: Sat, 8 Jun 2019 15:17:36 +0000
Message-ID: <LO2P265MB04156692F43CEBDCFC0A8507A5110_at_LO2P265MB0415.GBRP265.PROD.OUTLOOK.COM>
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_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of k.hadd <kouss.hd_at_gmail.com> Sent: 08 June 2019 00:36
To: Oracle-L_at_freelists.org
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 596Explain 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.
- 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
Thank you very much for reading
Kouss
-- http://www.freelists.org/webpage/oracle-lReceived on Sat Jun 08 2019 - 17:17:36 CEST
- image/png attachment: image.png
