ITPub博客
首页 博客 专栏 学院 社区 IT新媒体评选
发博

首页 > 数据库 > Oracle > [20260629]跟踪ora_cjq0_进程.txt

[20260629]跟踪ora_cjq0_进程.txt

原创 Oracle 作者：lfree 时间：2026-06-30 21:46:57 0 删除 编辑

[20260629]跟踪ora_cjq0_<sid>进程.txt

--//上午使用bpftrace脚本跟踪library cache lock /library cache pin.在测试环境跟踪全部进程时出现如下情况:
$ cat lkpn21c.bt
#!/usr/bin/env bpftrace
uprobe:/u01/app/oracle/product/21.0.0/dbhome_1/bin/oracle:kgllkal
/ $1 == 0 || pid == $1 /
{
    @lk++;
    printf("kgllkal count %02d -- handle address: %016lx, mode: %d ", @lk, arg2, arg3);
//  printf("spid %d ",pid);
    printf("kglnaobj address: %s\n", str(arg2 + 0x1c8, 256));
}

uprobe:/u01/app/oracle/product/21.0.0/dbhome_1/bin/oracle:kglpnal
/ $1 == 0 || pid == $1 /
{
    @pn++;
    printf("kglpnal count %02d -- handle address: %016lx, mode: %d ", @pn, arg2, arg3);
//  printf("spid %d ",pid);
    printf("kglnaobj address: %s\n", str(arg2 + 0x1c8, 256));
}

# bpftrace /home/oracle/study/202606/lkpn21c.bt  2951| ts.awk
Attached 2 probes
[2026-06-29 15:56:21] kgllkal count 01 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:21] kglpnal count 01 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:21] kgllkal count 02 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:21] kglpnal count 02 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:21] kgllkal count 03 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:21] kglpnal count 03 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:21] kgllkal count 04 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:21] kglpnal count 04 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:22] kgllkal count 05 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:22] kglpnal count 05 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:22] kgllkal count 06 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:22] kglpnal count 06 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:22] kgllkal count 07 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:22] kglpnal count 07 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 15:56:22] kgllkal count 08 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 15:56:22] kglpnal count 08 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
--//输出非常密集。
--//对应进程ora_cjq0_<sid>,跟踪spid=2951进程看看。

1.环境：
SYS@book> @ ver2
==============================
PORT_STRING                   : x86_64/Linux 2.4.xx
VERSION                       : 21.0.0.0.0
BANNER                        : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL                   : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY                 : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID                        : 0
PL/SQL procedure successfully completed.

2.测试：
SYS@book> @ uspid 2951
SYS@book> @ pr
==============================
U_USERNAME                    :
U_SID                         :  '221,19658'
U_AUDSID                      : 0
U_OSUSER                      : oracle
U_MACHINE                     : centos9
U_PROGRAM                     : oracle@centos9 (CJQ0)
SPID                          : 2951
SQL_HASH_VALUE                : 0
LASTCALL                      : 2774
STATUS                        : ACTIVE
PL/SQL procedure successfully completed.

SYS@book> exec dbms_monitor.session_trace_enable(session_id => 221,serial_num => 19658 , waits => true , binds => true);
PL/SQL procedure successfully completed.

SYS@book> @ usid 221
SYS@book> @ pr
==============================
U_USERNAME                    :
U_SID                         :  '221,19658'
U_AUDSID                      : 0
U_OSUSER                      : oracle
U_MACHINE                     : centos9
U_PROGRAM                     : (CJQ0)
U_SPID                        : 2951
U_PID                         : 86
CPID                          : 2951
SQL_ID                        :
USID_SQL_HASH_VALUE           : 0
LASTCALL                      : 2822
STATUS                        : ACTIVE
SADDR                         : 000000007E92A140
PADDR                         : 000000007E5CAD78
TADDR                         :
LOGON_TIME                    : 2026-06-29 15:11:42
TRACEFILE                     : /u01/app/oracle/diag/rdbms/book/book/trace/book_cjq0_2951.trc
PL/SQL procedure successfully completed.

SYS@book> exec dbms_monitor.session_trace_disable(session_id => 221,serial_num => 19658 );
PL/SQL procedure successfully completed.

3.查看跟踪文件：

$ tkprof /u01/app/oracle/diag/rdbms/book/book/trace/book_cjq0_2951.trc

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  rdbms ipc message                             477        0.22         96.91
  control file sequential read                    6        0.00          0.00
  PGA memory operation                           43        0.00          0.00
  PX Deq: Join ACK                               12        0.00          0.00
  PX Deq: Parse Reply                            12        0.05          0.11
  PX Deq: Execute Reply                          52        0.02          0.10
  PX qref latch                                   1        0.00          0.00
  PX Deq: Signal ACK EXT                         12        0.00          0.00
  PX Deq: Slave Session Stats                    12        0.00          0.00
  enq: PS - contention                            3        0.00          0.00

--//还存在小量的sql语句执行。

--//查看跟踪文件主要如下：
*** 2026-06-29T15:53:22.799201+08:00 (CDB$ROOT(1))
WAIT #139942057084752: nam='rdbms ipc message' ela= 208955 timeout=20 p2=0 p3=0 obj#=8851 tim=2623547094
XCTEND rlbk=0, rd_only=1, tim=2623547548
WAIT #139942057084752: nam='rdbms ipc message' ela= 189888 timeout=18 p2=0 p3=0 obj#=8851 tim=2623737498
XCTEND rlbk=0, rd_only=1, tim=2623738179
WAIT #139942057084752: nam='rdbms ipc message' ela= 200884 timeout=20 p2=0 p3=0 obj#=8851 tim=2623939148
XCTEND rlbk=0, rd_only=1, tim=2623939543
WAIT #139942057084752: nam='rdbms ipc message' ela= 202625 timeout=20 p2=0 p3=0 obj#=8851 tim=2624142232
XCTEND rlbk=0, rd_only=1, tim=2624142547
WAIT #139942057084752: nam='rdbms ipc message' ela= 206682 timeout=20 p2=0 p3=0 obj#=8851 tim=2624349274
XCTEND rlbk=0, rd_only=1, tim=2624349733

SYS@book> @ ev_namezpr 'rdbms ipc message$'
==============================
EVENT#                        : 7
EVENT_ID                      : 866018717
NAME                          : rdbms ipc message
PARAMETER1                    : timeout
PARAMETER2                    :
PARAMETER3                    :
WAIT_CLASS_ID                 : 2723168908
WAIT_CLASS#                   : 6
WAIT_CLASS                    : Idle
DISPLAY_NAME                  : rdbms ipc message
CON_ID                        : 0
PL/SQL procedure successfully completed.

SYS@book> @ oid 8851
SYS@book> @ pr
==============================
O_OWNER                       : SYS
O_OBJECT_NAME                 : SCHEDULER$_CLASS
O_OBJECT_TYPE                 : TABLE
SUBOBJECT_NAME                :
CREATED                       : 2021-07-27 19:15:53
LAST_DDL_TIME                 : 2021-07-27 19:15:53
O_STATUS                      : VALID
DATA_OBJECT_ID                : 8851
OBJECT_ID                     : 8851
PL/SQL procedure successfully completed.

SYS@book> @ col_def sys.SCHEDULER$_CLASS

column RES_GRP_NAME format a30
column AFFINITY format a64
column COMMENTS format a100

SYS@book> select * from SCHEDULER$_CLASS;
      OBJ# RES_GRP_NAME  DEFAULT_PRIORITY AFFINITY    LOG_HISTORY      FLAGS COMMENTS
---------- ------------- ---------------- ----------- ----------- ---------- -----------------------------------------------------------
     21057                                                                68 This is the default job class.
     21058                                                               132 This is the default job class if you want minimal logging.
     21059                                                               132 This is the default job class for in-memory jobs.
     21060                                                                36 This is the job class for jobs created through DBMS_JOB.
     21061 ORA$AUTOTASK                                                   68 This is the default job class for autotask jobs.
     21190 ORA$AUTOTASK                                   1000000        260 auto optimizer stats collection
     21191 ORA$AUTOTASK                                   1000000        260 auto optimizer stats collection
     21192 ORA$AUTOTASK                                   1000000        260 auto optimizer stats collection
     21194 ORA$AUTOTASK                                   1000000        260 auto space advisor
     21195 ORA$AUTOTASK                                   1000000        260 auto space advisor
     21196 ORA$AUTOTASK                                   1000000        260 auto space advisor
     21198 ORA$AUTOTASK                                   1000000        260 sql tuning advisor
     21199 ORA$AUTOTASK                                   1000000        260 sql tuning advisor
     21200 ORA$AUTOTASK                                   1000000        260 sql tuning advisor
     21736                                                                64 Default job class for AQ propagation jobs
     24098                                                               128
16 rows selected.

--//开启数据库一段时间后,基本稳定下来.
# bpftrace /home/oracle/study/202606/lkpn21c.bt  2951| ts.awk
Attached 2 probes
[2026-06-29 16:10:19] kgllkal count 01 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:19] kglpnal count 01 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:19] kgllkal count 02 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 16:10:19] kglpnal count 02 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 16:10:24] kgllkal count 03 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:24] kglpnal count 03 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:24] kgllkal count 04 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 16:10:24] kglpnal count 04 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 16:10:29] kgllkal count 05 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:29] kglpnal count 05 -- handle address: 0000000073c50640, mode: 2 spid 2951 kglnaobj address: SCHEDULER_DISABLEDSYSCDB$ROOT
[2026-06-29 16:10:29] kgllkal count 06 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
[2026-06-29 16:10:29] kglpnal count 06 -- handle address: 000000006bf0d820, mode: 2 spid 2951 kglnaobj address: LAST_OBSERVED_EVENTSYSCDB$ROOT
--//也出现5秒间隔输出的情况。

--//再次启动跟踪,跟踪文件内容如下:
*** 2026-06-29T16:13:34.567214+08:00 (CDB$ROOT(1))
WAIT #139942048334160: nam='rdbms ipc message' ela= 5001289 timeout=500 p2=0 p3=0 obj#=8851 tim=3835315099
XCTEND rlbk=0, rd_only=1, tim=3835315629

*** 2026-06-29T16:13:39.578100+08:00 (CDB$ROOT(1))
WAIT #139942048334160: nam='rdbms ipc message' ela= 5010163 timeout=500 p2=0 p3=0 obj#=8851 tim=3840325857
XCTEND rlbk=0, rd_only=1, tim=3840326658

*** 2026-06-29T16:13:43.732656+08:00 (CDB$ROOT(1))
WAIT #139942048334160: nam='rdbms ipc message' ela= 4153806 timeout=500 p2=0 p3=0 obj#=8851 tim=3844480551
--//timeout=500,仔细看前面timeout=20. 为什么出现这样情况不是很清楚.是否刚刚开启数据库检查后台schedule相关.

来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3174934/ ，如需转载，请注明出处，否则将追究法律责任。

0
0
上一篇： [20260629]使用bpftrace跟踪library cache lock/library cache pin的疑问.txt
下一篇： [20260703]跟踪library cache lock library cache pin的bpftrace脚本转换为bcc脚本
请登录后发表评论 登录
全部评论
lfree
专家姓名：张文胜
熟悉oracle相关技术，擅长sql优化，rman备份与恢复，熟悉linux shell编程。

注册时间：2008-01-03

  • 博文量
    4006
  • 访问量
    7969194

最新文章

支持我们 作者招募 用户协议 FAQ Contact Us

北京盛拓优讯信息技术有限公司. 版权所有  京ICP备16024965号-8 北京市公安局海淀分局网监中心备案编号：11010802021510 niuxiaotong@pcpop.com 17352615567 未成年人举报专区

广播电视节目制作经营许可证(京) 字第1234号 中国互联网协会会员

违法和不良信息举报电话:18101376593