SQL Statements Run Slower Waiting on "PGA memory operation" and "Acknowledge over PGA limit" After Migrate from 12.1 to 12.2
(Doc ID 2337875.1)
Last updated on NOVEMBER 28, 2022
Applies to:
Oracle Database Cloud Schema Service - Version N/A and laterOracle Database Exadata Express Cloud Service - Version N/A and later
Oracle Database Exadata Cloud Machine - Version N/A and later
Oracle Cloud Infrastructure - Database Service - Version N/A and later
Oracle Database Backup Service - Version N/A and later
Information in this document applies to any platform.
Symptoms
- Performance of customer's application SQL statements degraded after migrated from 12.1.0.2 environment to 12.2.0.1 environment. From following 10046 events trace files, in 12.2.0.1, there are far more waiting events of "PGA memory operation" and "acknowledge over PGA limit". There is especially more time spent on "acknowledge over PGA limit". Furthermore both 12.1.0.2 and 12.2.0.1 environments had a lot of waiting events "direct path read" and "direct path read temp".
In 12.1.0.2:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.76 0.68 0 40 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 6.56 7.16 84598 85108 5 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 7.32 7.85 84598 85148 5 3
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
Disk file operations I/O 8 0.00 0.00
direct path read 381 0.03 0.49
direct path write temp 2 0.00 0.00
direct path read temp 377 0.00 0.06
SQL*Net message from client 2 11.19 11.19
In 12.2.0.1:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 1.95 3.97 0 15 0 0
Execute 1 0.00 0.08 0 0 0 0
Fetch 2 6.18 14.13 60055 79304 28 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 8.14 18.20 60055 79319 28 3
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1926 0.00 0.07
acknowledge over PGA limit 536 0.02 6.11
SQL*Net message to client 2 0.00 0.00
Disk file operations I/O 8 0.00 0.01
direct path read 93 0.00 0.25
direct path write temp 128 0.04 1.02
direct path read temp 135 0.01 0.48
SQL*Net message from client 2 10.10 10.11 - No significant long elapsed time of all Row Source Operation steps:
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
3 3 3 TABLE ACCESS BY INDEX ROWID <TABLE NAME> (cr=11 pr=0 pw=0 time=3 us cost=3 size=18 card=1)
3 3 3 INDEX UNIQUE SCAN <INDEX NAME> (cr=8 pr=0 pw=0 time=3 us cost=2 size=0 card=1)(object id 302050)
2 2 2 TABLE ACCESS BY INDEX ROWID <TABLE NAME>(cr=34 pr=0 pw=0 time=3 us cost=1 size=7 card=1)
2 2 2 INDEX UNIQUE SCAN <INDEX NAME> (cr=32 pr=0 pw=0 time=3 us cost=0 size=0 card=1)(object id 301973)
3 3 3 SORT AGGREGATE (cr=30 pr=0 pw=0 time=3 us)
2 2 2 NESTED LOOPS (cr=30 pr=0 pw=0 time=3 us cost=14 size=34 card=1)
2 2 2 NESTED LOOPS (cr=28 pr=0 pw=0 time=3 us cost=14 size=34 card=1)
... ...
47 47 47 VIEW <VIEW_NAME> (cr=60280 pr=60055 pw=7090 time=1 us cost=29080 size=15826944 card=989184)
47 47 47 HASH GROUP BY (cr=60280 pr=60055 pw=7090 time=1 us cost=29080 size=39567360 card=989184)
47 47 47 JOIN FILTER USE :BF0005 (cr=60280 pr=60055 pw=7090 time=1 us cost=29080 size=39763600 card=994090)
994091 994091 994091 MERGE JOIN (cr=60280 pr=60055 pw=7090 time=1 us cost=29080 size=39763600 card=994090)
994091 994091 994091 SORT JOIN (cr=7311 pr=0 pw=0 time=1 us cost=7901 size=18887729 card=994091)
994091 994091 994091 TABLE ACCESS FULL <TABLE NAME> (cr=7311 pr=0 pw=0 time=1 us cost=2017 size=18887729 card=994091)
994091 994091 994091 SORT JOIN (cr=52969 pr=60055 pw=7090 time=994091 us cost=21179 size=21506835 card=1024135)
1024227 1024227 1024227 TABLE ACCESS FULL <TABLE NAME> (cr=52969 pr=52965 pw=0 time=1 us cost=14538 size=21506835 card=1024135)
- SQL performance has not been improved, after alter parameter pga_aggregate_limit to 0, which made waiting events "acknowledge over PGA limit" disappear. From the following 10046 events trace file, almost all time is spent on CPU during Fetch phase. Wait events "PGA memory operation" still happens frequently although it seems not to take time. And, there is still no significant long elapsed time of all Row Source Operation steps.
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
3 3 3 TABLE ACCESS BY INDEX ROWID <TABLE NAME> (cr=11 pr=0 pw=0 time=3 us cost=3 size=18 card=1)
3 3 3 INDEX UNIQUE SCAN <INDEX NAME> (cr=8 pr=0 pw=0 time=3 us cost=2 size=0 card=1)(object id 302050)
2 2 2 TABLE ACCESS BY INDEX ROWID <TABLE NAME>(cr=34 pr=0 pw=0 time=3 us cost=1 size=7 card=1)
2 2 2 INDEX UNIQUE SCAN <INDEX NAME>(cr=32 pr=0 pw=0 time=3 us cost=0 size=0 card=1)(object id 301973)
3 3 3 SORT AGGREGATE (cr=30 pr=0 pw=0 time=3 us)
2 2 2 NESTED LOOPS (cr=30 pr=0 pw=0 time=3 us cost=14 size=34 card=1)
2 2 2 NESTED LOOPS (cr=28 pr=0 pw=0 time=3 us cost=14 size=34 card=1)
2 2 2 TABLE ACCESS BY INDEX ROWID BATCHED <TABLE NAME>(cr=22 pr=0 pw=0 time=3 us cost=12 size=24 card=1)
... ...
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1551 0.02 0.03
SQL*Net message to client 2 0.00 0.00
SQL*Net more data to client 1 0.00 0.00
asynch descriptor resize 1 0.00 0.00
Disk file operations I/O 8 0.00 0.01
direct path read 136 0.04 0.37
direct path write temp 116 0.02 0.75
direct path read temp 137 0.01 0.38
SQL*Net message from client 2 25.48 25.49
- The SQL plan of 12.2.0.1 environment has been changed slightly, but SQL performance has not improved after hinting of full outline data of SQL plan of 12.1.0.2, which force this SQL to use the sql plan of 12.1.0.2.
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 1.71 1.75 0 398 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 7.71 8.99 60054 78906 28 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 9.43 10.75 60054 79304 28 3
- From the timestamp information of "*** 2017-12-07T09:40:xx.xxxx" of raw 10046 trace file, a lot of time elapsed while waiting for "PGA memory operation", "direct path read" and "direct path read temp", but the total elapsed time of these waiting events is much less than total DB elapsed time.
*** 2017-12-07T09:40:40.889004+09:00
WAIT #2177686296376: nam='PGA memory operation' ela= 32 p1=65536 p2=1 p3=0 obj#=-1 tim=3536775238798
WAIT #2177686296376: nam='PGA memory operation' ela= 12 p1=65536 p2=1 p3=0 obj#=-1 tim=3536775246162
WAIT #2177686296376: nam='PGA memory operation' ela= 23 p1=65536 p2=1 p3=0 obj#=-1 tim=3536775393379
... ...
*** 2017-12-07T09:40:41.873379+09:00
WAIT #2177686296376: nam='PGA memory operation' ela= 11 p1=65536 p2=1 p3=0 obj#=241772 tim=3536776216177
WAIT #2177686296376: nam='PGA memory operation' ela= 10 p1=65536 p2=1 p3=0 obj#=241772 tim=3536776217992
WAIT #2177686296376: nam='direct path read' ela= 2123 file number=13 first dba=218368 block cnt=128 obj#=241772 tim=3536776221793
... ...
*** 2017-12-07T09:40:42.873379+09:00
WAIT #2177686296376: nam='direct path read' ela= 1682 file number=12 first dba=172800 block cnt=128 obj#=241772 tim=3536777221367
WAIT #2177686296376: nam='direct path read' ela= 7706 file number=12 first dba=173184 block cnt=128 obj#=241772 tim=3536777236938
WAIT #2177686296376: nam='direct path read' ela= 733 file number=12 first dba=173440 block cnt=128 obj#=241772 tim=3536777242865
... ...
*** 2017-12-07T09:40:43.889011+09:00
WAIT #2177686296376: nam='direct path write temp' ela= 11584 file number=201 first dba=227037 block cnt=31 obj#=241772 tim=3536778239804
WAIT #2177686296376: nam='direct path write temp' ela= 10085 file number=201 first dba=227068 block cnt=4 obj#=241772 tim=3536778251945
WAIT #2177686296376: nam='direct path read temp' ela= 535 file number=201 first dba=227324 block cnt=4 obj#=241772 tim=3536778255605
... ...
*** 2017-12-07T09:40:44.967129+09:00
WAIT #2177686296376: nam='direct path read temp' ela= 3422 file number=201 first dba=225280 block cnt=31 obj#=241772 tim=3536779313130
WAIT #2177686296376: nam='direct path read temp' ela= 512 file number=201 first dba=225376 block cnt=31 obj#=241772 tim=3536779415223
WAIT #2177686296376: nam='direct path read temp' ela= 8112 file number=201 first dba=227584 block cnt=31 obj#=241772 tim=3536779457514
... ...
*** 2017-12-07T09:40:45.920251+09:00
WAIT #2177686296376: nam='direct path read temp' ela= 2457 file number=201 first dba=227552 block cnt=31 obj#=241772 tim=3536780269333
WAIT #2177686296376: nam='direct path read temp' ela= 577 file number=201 first dba=226944 block cnt=31 obj#=241772 tim=3536780301955
WAIT #2177686296376: nam='direct path read temp' ela= 623 file number=201 first dba=227070 block cnt=2 obj#=241772 tim=3536780359766
... ...
*** 2017-12-07T09:40:47.014007+09:00
WAIT #2177686296376: nam='direct path read temp' ela= 550 file number=201 first dba=227968 block cnt=31 obj#=241772 tim=3536781369960
WAIT #2177686296376: nam='direct path read temp' ela= 280 file number=201 first dba=227999 block cnt=1 obj#=241772 tim=3536781398909
WAIT #2177686296376: nam='direct path read temp' ela= 528 file number=201 first dba=228000 block cnt=31 obj#=241772 tim=3536781400494
- From the raw trace file, the Available Physical Memory size of 12.2.0.1 is much less than 12.1.0.2.
In 12.1.0.2:
Memory (Avail/Total): Ph:2358M/8191M, Ph+PgF:2995M/9471MIn 12.2.0.1:
Memory (Avail/Total): Ph:788M/8191M, Ph+PgF:1643M
* This information only output on Windows platform.
- This SQL statements had a lot of data blocks to read to PGA and sort/merge in workarea.
994091 994091 994091 MERGE JOIN (cr=60280 pr=60054 pw=7089 time=1 us cost=29080 size=39763600 card=994090)
994091 994091 994091 SORT JOIN (cr=7311 pr=0 pw=0 time=1 us cost=7901 size=18887729 card=994091)
994091 994091 994091 TABLE ACCESS FULL <TABLE NAME> (cr=7311 pr=0 pw=0 time=1 us cost=2017 size=18887729 card=994091)
994091 994091 994091 SORT JOIN (cr=52969 pr=60054 pw=7089 time=994091 us cost=21179 size=21506835 card=1024135)
1024227 1024227 1024227 TABLE ACCESS FULL <TABLE NAME> (cr=52969 pr=52965 pw=0 time=1 us cost=14538 size=21506835 card=1024135)
Cause
To view full details, sign in with your My Oracle Support account. |
|
Don't have a My Oracle Support account? Click to get started! |
In this Document
| Symptoms |
| Cause |
| Solution |
| References |