首页 » ORACLE, ORACLE [C]系列 » 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.

alter system set “_column_tracking_level”=17 scope=both; (– 12c default 21; 19c default 53;)

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
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]

打赏

目前这篇文章还没有评论(Rss)

我要评论