The environment is Oracle 19.14 RAC 4-nodes, After the database was upgraded to 19c, there was a performance problem. From AWR, I saw a large number of library cache locks and library cache pins in the top event.namespace was OPTIMIZER EXPRESSION HEADER
TOP EVENT
| Event | % Event | P1, P2, P3 Values | % Activity | Parameter 1 | Parameter 2 | Parameter 3 |
|---|---|---|---|---|---|---|
| library cache lock | 27.55 | “13790213352”,”6288331144″,”8978434″ | 0.04 | handle address | lock address | 100*mode+namespace |
| library cache pin | 26.13 | “19222291528”,”18524475888″,”8978434″ | 0.06 | handle address | pin address | 100*mode+namespace |
DIAG
|
1 2 3 4 5 6 7 8 9 10 11 |
SQL> @dec 8978434 DEC HEX ----------------------------------- -------------------- 8978434.000000 890002 --namespace 1 row selected. SQL> select KGLSTDSC from x$kglst where INDX=to_number('89','xxxxxxxxxxxxxx') and KGLSTTYP='NAMESPACE'; KGLSTDSC ---------------------------------------------------------------- OPTIMIZER EXPRESSION HEADER 1 row selected. |
Optimizer expression statistics monitoring is introduced in 12.2 database version. Some related tables and views（These objects are defined in doptim.bsq） ：
SYS.EXP_HEAD$
SYS.EXP_OBJ$
SYS.EXP_STAT$
DBA_EXPRESSION_STATISTICS
Expression Tracking
Expression statistics monitoring is enabled by default in 12.2. Monitoring expression statistics is introduced for a new optimizer feature in 12.2 to collect expression usage statistics in SQL queries.Expression Tracking feature is enabled only when OPTIMIZER_FEATURES_ENABLE parameter is set to 12.2.0.1.
Note: Currently, it is not possible to turn off Expression Tracking feature using OFE (OPTIMIZER_FEATURES_ENABLE) parameter.However, setting OPTIMIZER_FEATURES_ENABLE=12.1.0.2 or 11.2.0.4 still collects expression tracking information into dba_expression_statistics. Bug 27256484
What is this feature used for? You can imagine that it is useful for optimization in general, but right now it has a single “client”: Oracle Database In-Memory, where it’s referred to as the Expression Statistics Store (ESS).
Monitoring feature is controlled by parameter “_column_tracking_level”.
Disable future monitoring:
if SQL text have huge number of union all or too many columns，sql parse time will be increase. CPU high and SQL parse slow. I’m not sure _column_tracking_level values means. but you can disable the feature. e.g.
|
1 2 3 4 5 6 7 8 |
SQL> @pd column_tracking Show all parameters and session values from x$ksppi/x$ksppcv... NUM N_HEX NAME VALUE DESCRIPTION ------------------------- ----- -------------------------------- ------------------------------ ---------------------------- 3855 F0F _column_tracking_level 53 column usage tracking alter system set "_column_tracking_level"=17 scope=both; (-- 12c default 21; 19c default 53;) |
|
1 2 |
other case in order to avoid unnecessary parsing expression tracking can be disabled . "_column_tracking_level"=49; |
Things to Consider to Avoid Database Performance Problems on 19c (Doc ID 2773012.1)
High CPU for SQL statements with too many columns. The short stack shows functions spinning on qosdGetOptDir, qosdInitDirCtx, qosdUpdExprExecStatsRws. There could be high latch waits including GES latches in RAC.
Solution: Set _column_tracking_level=1 at system level. Its a dynamic parameter. This is to avoid the extensive column usage tracking which could incur more CPU. The default value was 1 in 11.2 & 12.1 and changed to 21 in 12.2 .
DEBUG
Parameter Name:_kgl_debug Description:Library cache debugging Type:CHARO bsoleted:FALSECan ALTER SESSION:TRUECan ALTER SYSTEM:IMMEDIATE
KGL=Kernel General Library cache manager
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 |
SQL> @hex 89 DEC HEX ----------------------------------- -------------------- 137.000000 89 USERNAME INST_NAME HOST_NAME I# SID SERIAL# VERSION STARTED SPID OPID CPID SADDR PADDR -------------------- -------------------- ------------------------- --- ----- -------- ---------- -------- ---------- ----- --------------- ---------------- ---------------- SYS PDB1-anbob19c oel7db1 1 1 41449 19.0.0.0.0 20220705 27576 33 27492 0000000078481028 00000000790F7F48 SQL> create table anbob.t300 as select * from anbob.t1; Table created. SQL> alter session set "_kgl_debug"="namespace=137 debug=33552"; Session altered. SQL> alter session set events '10046 trace name context forever, level 12'; Session altered. SQL> select v1,v2,v3,v2||v3 from anbob.t300; no rows selected SQL> select v1,v2,v3,v3||v2 from anbob.t300; no rows selected SQL> select v1,v2,v3,v3||v2||v1 from anbob.t300; no rows selected SQL> @t TRACEFILE -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- /u01/app/oracle/diag/rdbms/anbob19c/anbob19c/trace/anbob19c_ora_27576.trc SQL> alter session set events '10046 trace name context off'; Session altered. SQL> alter session set "_kgl_debug"=''; Session altered. SQL> @t TRACEFILE --------------------------------------------------------------------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------- ----------------------------------- /u01/app/oracle/diag/rdbms/anbob19c/anbob19c/trace/anbob19c_ora_26700.trc SQL> @o anbob.t300 owner object_name subname object_type status OID D_OID CREATED LAST_DDL_TIME ------------------------- ------------------------------ ------------------------------ -------------------- --------- ----------------------------------- ----------------------------------- ------------------- ------------------- ANBOB T300 TABLE VALID 79658 79658 2022-07-05 17:04:04 2022-07-05 17:04:04 SQL> select * from exp_head$ where objn=79658; EXP_ID OBJN SUB_ID FIXED_COST TEXT COL_LIST FLAGS CTIME ----------------------------------- -------- ------ ----------------------------------- ------------------------------ -------------------- ----- ------------------- 8282378911508228890 79658 0 .0000000337759769235673 "V1" 1 8 2022-07-05 17:04:54 7456516794188148783 79658 0 .0000000337759769235673 "V2" 2 8 2022-07-05 17:04:54 11908693237719893826 79658 0 .0000000337759769235673 "V3" 3 8 2022-07-05 17:04:54 7722139356252261926 79658 0 .00000337759769235673 "V2"||"V3" 2,3 0 2022-07-05 17:04:54 590799069359706895 79658 0 .00000337759769235673 "V3"||"V2" 2,3 0 2022-07-05 17:05:17 287817618524253030 79658 0 .00000675519538471346 "V3"||"V2"||"V1" 1,2,3 0 2022-07-05 17:05:28 6 rows selected. |
Trace file
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 |
[oracle@oel7db1 ~]$ grep -B 12 -A 2 8282378911508228890 /u01/app/oracle/diag/rdbms/anbob19c/anbob19c/trace/anbob19c_ora_27576.trc <Function>kglLock</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>0</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>0</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>0</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglpin</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>2</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>S</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>0</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglobld</Function> <Reason>TRACELOD</Reason> <Param1>0x7ffd079b7368</Param1> <Param2>1</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>S</LockMode> <PinMode>S</PinMode> <LoadLockMode>X</LoadLockMode> <Status>0</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- </KGLTRACE> ===================== PARSING IN CURSOR #139994476561720 len=124 dep=1 uid=0 oct=3 lid=0 tim=27656425791 hv=4179850718 ad='698b48b8' sqlid='10gywwmwk6xfy' select /* QOSD */ /*+ index(eh)*/ objn, sub_id, fixed_cost, text, col_list, flags, ctime from exp_head$ eh where exp_id = :1 END OF STMT PARSE #139994476561720:c=347,e=347,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=27656425790 BINDS #139994476561720: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=7f530110c910 bln=22 avl=11 flg=05 value=8282378911508228890 EXEC #139994476561720:c=1588,e=1448,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=1426583507,tim=27656427308 FETCH #139994476561720:c=9,e=9,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=1426583507,tim=27656427335 -- <Function>kglHandleInitialize</Function> <Reason>TRACEBAS</Reason> <Param1>0x65b76ce8</Param1> <Param2>1</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>S</LockMode> <PinMode>S</PinMode> <LoadLockMode>X</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglLock</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>0</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>0</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglpin</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>3</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>X</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- CLOSE #139994470481640:c=1,e=1,dep=2,type=3,tim=27656463500 ===================== PARSING IN CURSOR #139994476905728 len=137 dep=1 uid=0 oct=2 lid=0 tim=27656463643 hv=309576400 ad='65b730b8' sqlid='dbvj6jc977hqh' insert /* QOSD */ into exp_head$ (exp_id, objn, sub_id, fixed_cost, text, col_list, flags, ctime) values (:1, :2, :3, :4, :5, :6, :7, :8) END OF STMT PARSE #139994476905728:c=4967,e=4561,p=0,cr=38,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=27656463643 BINDS #139994476905728: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=00 fl2=1000001 frm=00 csi=00 siz=96 off=0 kxsbbbfp=7f5306974328 bln=22 avl=11 flg=05 value=8282378911508228890 Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 -- <Function>kglLock</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>0</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>0</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglpin</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>2</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>S</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglLock</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>0</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>0</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> -- <Function>kglpin</Function> <Reason>TRACEBAS</Reason> <Param1>(nil)</Param1> <Param2>2</Param2> <LibraryHandle> <Address>0x65b77e30</Address> <Hash>aa314e8b</Hash> <LockMode>S</LockMode> <PinMode>0</PinMode> <LoadLockMode>0</LoadLockMode> <Status>VALD</Status> <ObjectName> <Name>PDB1.8282378911508228890 </Name> <FullHashValue>0758891be74bb5696b9af621aa314e8b</FullHashValue> <Namespace>OPTIMIZER EXPRESSION HEADER(137)</Namespace> |