首页 » Cloud, ORACLE 9i-23ai » Troubleshooting Library cache lock (OPTIMIZER EXPRESSION HEADER ) on oracle 19c
Troubleshooting Library cache lock (OPTIMIZER EXPRESSION HEADER ) on oracle 19c
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
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.
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;)
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
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
[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>
other issue case:
Troubleshooting ORA-00600 [qosdExpStatRead: expcnt mismatch]
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。