OraFAQ Forum: Performance Tuning » excessive parsing ?

Home » RDBMS Server » Performance Tuning » excessive parsing ? (DB SE2 19.3.0.0.0)

Show: Today's Messages :: Polls :: Message Navigator
E-mail to friend

excessive parsing ? [message #685978]

Fri, 13 May 2022 05:17

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

I have a performance issue that I think may be excessive parsing. It is a procedure that runs for close to three hours, and we need it to be under 10 minutes. In a statspack report for the run I see this,

Time Model System Stats  DB/Inst: redacted  Snaps: 292-296
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % DB time
----------------------------------- -------------------- ---------
sql execute elapsed time                        10,263.1     100.0
DB CPU                                           8,851.7      86.2
parse time elapsed                               6,982.6      68.0
hard parse elapsed time                          6,963.3      67.8
failed parse elapsed time                        3,471.2      33.8
hard parse (sharing criteria) elaps              3,410.1      33.2
PL/SQL execution elapsed time                      101.8       1.0
hard parse (bind mismatch) elapsed                   2.6        .0
PL/SQL compilation elapsed time                      1.8        .0
repeated bind elapsed time                           1.8        .0
RMAN cpu time (backup/restore)                       0.6        .0
connection management call elapsed                   0.0        .0
DB time                                         10,263.8
background elapsed time                            794.7
background cpu time                                 38.6

which I interpret as a massive hard parsing workload. I had enabled tracing in the session before running the rocedure with

exec dbms_monitor.session_trace_enable(waits=>true,binds=>true)

and in the tkprof output I see this for statement with the longest exeela,

SQL ID: brzrz3zut1yxp Plan Hash: 1635839828

SELECT redacted


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    73799     87.46      89.74          0          0          0           0
Execute  73799   6049.57    6307.49          0   17715420          2           0
Fetch    73799    211.26     222.71          0    2361568          0       73799
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   221397   6348.30    6619.95          0   20076988          2       73799

Misses in library cache during parse: 73799
Misses in library cache during execute: 73799
Optimizer mode: ALL_ROWS
Parsing user id: 120     (recursive depth: 1)
Number of plan statistics captured: 73799

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
redacted


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            8        0.00          0.00
  latch: shared pool                              1        0.00          0.00
********************************************************************************

Is this telling me that the statement was executed 73799 times and that each time required a hard parse? If so, why?? Furthermore, the trace tells me that the parse took only 89.74 seconds, but statspack is telling me that 67.8% of the total DB Time was parsing; how can I reconcile these figures?

Thank you for any insight.

--update: a bit more information. In the Instance Activity Stats section of statspack, I see this

parse count (failures)                       147,602           14.3          2.0
parse count (hard)                           296,376           28.6          4.0
parse count (total)                        1,941,296          187.4         26.2
parse time cpu                                34,402            3.3          0.5
parse time elapsed                            31,822            3.1          0.4

which doesn't look too good. But again, I can't reconcile those figure with anything else.

[Updated on: Fri, 13 May 2022 05:32]

Report message to a moderator

Re: excessive parsing ? [message #685979 is a reply to message #685978]

Fri, 13 May 2022 06:16

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

And more: I see this at the end of my tkprof,

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3    401.60     415.47          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5    401.60     415.47          0          0          0           3

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2      182.67        182.67
  PGA memory operation                            2        0.00          0.00
  log file sync                                   1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   1918847    338.00     304.00          0          0          2           0
Execute 4588680   7692.04    9075.18          0   18971458    1287557      222016
Fetch   4441053    970.24     860.95          0  103596595          0     4497753
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   10948580   9000.29   10240.15          0  122568053    1287559     4719769

Misses in library cache during parse: 221450
Misses in library cache during execute: 73850

I also see this in the statspack,

Library Cache Activity  DB/Inst: ITRKDEV/itrkdev  Snaps: 292-296
->"Pct Misses"  should be very low

                         Get  Pct        Pin        Pct               Invali-
Namespace           Requests  Miss     Requests     Miss     Reloads  dations
--------------- ------------ ------ -------------- ------ ---------- --------
AUDIT POLICY               8    0.0              8    0.0          0        0
BODY                   3,615    0.0         10,101    0.3         26        0
CLUSTER                   26    0.0             26    0.0          0        0
DBLINK                     9    0.0              0                 0        0
EDITION                  199    0.0            245    0.0          0        0
HINTSET OBJECT       811,800    0.0        811,800    9.1     73,800        0
INDEX                      1    0.0              1    0.0          0        0
OBJECT ID                  2  100.0              0                 0        0
SCHEMA                   633    0.0              0                 0        0
SQL AREA             153,080    0.5      6,412,585    9.2    295,398  295,211
SQL AREA BUILD       295,934    0.1              0                 0        0
SQL AREA STATS       295,843    0.2        295,843    0.2          0        0
TABLE/PROCEDURE      594,952    0.0      4,747,609    0.0         80        0
TRIGGER                  176    0.0            212    0.0          0        0
USER PRIVILEGE             2    0.0              2  100.0          2        0
          -------------------------------------------------------------

all those invalidations can't be right.
What might be going on?

Report message to a moderator

Re: excessive parsing ? [message #685980 is a reply to message #685979]

Sun, 15 May 2022 05:33

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

I think I have the answer: dynamic sampling. This was set to 4, putting it back to the default of 2 (ie, it won't do any because all the objects do have stat's) has removed all that parsing completely. I find this worrying because previously I have always strongly recommended dynamic sampling at level 4. I have known this deliver dramatic benefits, and never (previously....) seen it cause a problem.
The process is now running in 25 minutes instead of 170, should be able to tune that down below 10 now Smile

Report message to a moderator

Previous Topic:	Re-Partitioning
Next Topic:	query tunning

Goto Forum:

-=] Back to Top [=-

[ Syndicate this forum (XML) ] [

]

Current Time: Sat Nov 23 03:28:17 CST 2024