一、oratop发现异常会话
打开oratop观察一下数据库状态，无意中发现一条等到时间长达20天的会话。作为oltp数据库，存在长达20天的事务，明天这条事务不正常。同时其它会话的oratop的SQLID/BLOCKER偶尔会看到会话被（2:7938）2节点7398号会话阻塞。看来需要定位处置
Oracle 19c - Primary orcl 10:25:40 up: 70d, 2 ins, 3.9k sn, 17 us, 158G sga, 2% fra, 0 er, 4.9%db
ID CPU %CPU %DCP LOAD AAS ASC ASI ASW IDL ASP LAT MBPS IOPS R/S W/S LIO GCPS %FR PGA TEMP UTPS UCPS RT/X DCTR DWTR
2 136 4.5 2.8 5.1 8.3 3 0 9 857 0 44u 50.5 1.6k 240 1.4k 193k 178 5 2.7G 10M 1.2k 7.2k 6.9m 49 53
1 136 4.6 2.4 9.4 5.1 4 2 1 1.9k 2 12u 67.1 4.0k 3.2k 989 878k 146 8 3.6G 21M 813 14k 6.7m 63 36
EVENT (C) TOTAL WAITS TIME(s) AVG_MS PCT WAIT_CLASS
DB CPU 2.24E+07 47
log file sync 4.935E+09 1.70E+07 3.5 35 Commit
Redo Transport MISC 2.025E+09 3870925 1.9 8 Other
SYNC Remote Write 2.025E+09 2752831 1.4 6 Other
SQL*Net message from dblink 6.266E+08 1905778 3.5 4 Network
ID SID SPID USERNAME PROGRAM SRV SERVICE PGA SQLID/BLOCKER OPN E/T STA STE WAIT_CLASS EVENT/*LATCH W/T
2 7938 110458 xxxx plsqldev. DED orcl 4.4M 787z87d7jq8sn SEL 20d ACT WAI Network SQL*Net message from 20d
1 9365 130718 xxxx oracle@ho DED orcl 4.2M 2:7938 SEL 20d ACT WAI Other DFS lock handle 3.9s
二、查看会话
检查该会话对应的sql，发现不存在。可以看到是plsqldev连接数据库执行的会话。那么可以初步判断是个人用户连接执行脚本。同时检查会话状态发现该会话竟然是活动状态
SQL> select * from gv$sqlarea where sql_id='787z87d7jq8sn';
no rows selected
SQL> select * from gv$sql where sql_id='787z87d7jq8sn';
no rows selected
SQL> select paddr,username,machine,sql_id,event,p1,p2,program from v$session where sid='7938' and serial#='41571';
PADDR USERNAME MACHINE SQL_ID EVENT P1 P2 PROGRAM
---------------- --------------- -------------------- ------------------ ---------------------------------------- ---------- ---------- ------------------------------
0000000781AC87A0 xxxx xxxxxxxxxx 787z87d7jq8sn SQL*Net message from dblink 675562835 1 plsqldev.exe
此时使用swc脚本也可以看到偶尔出现7938号会话阻塞其它会话的情况
三、追踪
既然没办法看到会话执行的sql，此时使用oradebug dump出会话的信息检查一下。
*** 2023-09-04T10:26:37.349738+08:00
*** SESSION ID:(1069.5066) 2023-09-04T10:26:37.349749+08:00
*** CLIENT ID:() 2023-09-04T10:26:37.349755+08:00
*** SERVICE NAME:(SYS$BACKGROUND) 2023-09-04T10:26:37.349759+08:00
*** MODULE NAME:() 2023-09-04T10:26:37.349765+08:00
*** ACTION NAME:() 2023-09-04T10:26:37.349769+08:00
*** CLIENT DRIVER:() 2023-09-04T10:26:37.349773+08:00
Dumping process info of pid[361.110458] requested by pid[70.90291]
Dumping process 361.110458 info:
*** 2023-09-04T10:26:37.349848+08:00
Process diagnostic dump for oracle@host01, OS id=110458,
pid: 361, proc_ser: 210716, sid: 7938, sess_ser: 41571
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 10:26:37 ]
NOTE: scheduling delay has not been sampled for 0.039365 secs
0.000000 secs from [ 10:26:33 - 10:26:38 ], 5 sec avg
0.000000 secs from [ 10:25:38 - 10:26:38 ], 1 min avg
0.000000 secs from [ 10:21:38 - 10:26:38 ], 5 min avg
...
service name: orcl
client details:
O/S info: user: xxxx, term: xxxxxxxxxx, ospid: 94752:60872
machine: WORKGROUP\xxxxxxxxxx program: plsqldev.exe
application name: PL/SQL Developer, hash value=1190136663
action name: xxxx.sql, hash value=2441959089
Current Wait Stack:
0: waiting for 'SQL*Net message from dblink'
driver id=0x28444553, #bytes=0x1, =0x0
wait_id=84 seq_num=93 snap_id=1
wait times: snap=28900 min 8 sec, exc=28900 min 8 sec, total=28900 min 8 sec
wait times: max=infinite, heur=28900 min 8 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a0
There are 1 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 9365, ser: 12689
wait event: 'DFS lock handle'
p1: 'type|mode'=0x44580005
p2: 'id1'=0x7b752b13
p3: 'id2'=0x0
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 0 secs, waiter_cache_ver: 1249
Wait State:
fixed_waits=0 flags=0x22 boundary=(nil)/-1
...
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[121 samples, 10:24:39 - 10:26:39]
waited for 'SQL*Net message from dblink', seq_num: 93
p1: 'driver id'=0x28444553
p2: '#bytes'=0x1
p3: ''=0x0
time_waited: >= 120 sec (still in wait)
SOC: 0x2738142d8, type: LIBRARY OBJECT LOCK (118), map: 0x1debbaed0
state: LIVE (0x99fc), flags: INIT (0x1)
LibraryObjectLock: Address=0x2738142d8 Handle=0xbddc6708 Mode=N
CanBeBrokenCount=1 Incarnation=1 ExecutionCount=0
Context=0x7f73e4f73cb0
User=0x7e2adb460 Session=0x7e2adb460 ReferenceCount=1
Flags=CBK/[0020] SavepointNum=0
LibraryHandle: Address=0xbddc6708 Hash=0 LockMode=N PinMode=X LoadLockMode=0 Status=VALD
Name: Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=1 TotalLockCount=1 TotalPinCount=2
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=0 HandleInUse=0 HandleReferenceCount=0
Concurrency: DependencyMutex=0xbddc67b8(0, 0, 0, 0) Mutex=0x184e858b0(0, 32040, 0, 0)
Flags=RON/PIN/PN0/EXP/CHD/[10012111] Flags2=[0000]
WaitersLists:
Lock=0xbddc6798[0xbddc6798,0xbddc6798]
Pin=0xbddc6778[0xbddc6778,0xbddc6778]
LoadLock=0xbddc67f0[0xbddc67f0,0xbddc67f0]
LibraryObject: Address=0x2796f01c0 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] Flags3=[0000] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=KGLH0^4f1b2314 pins=0 Change=NONE
Heap=0x26e731768 Pointer=0x2796f02a0 Extent=0x2796f0100 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=2.585938 Size=3.937500 LoadTime=85059407863
Block: #='6' name=SQLA^4f1b2314 pins=0 Change=NONE
Heap=0x35704b438 Pointer=0x189ce8560 Extent=0x189ce7988 Flags=I/-/P/A/-/-/E
FreedLocation=0 Alloc=0.000000 Size=0.000000 LoadTime=0
NamespaceDump:
Child Cursor: Heap0=0x2796f02a0 Heap6=0x189ce8560 Heap0 Load Time=08-15-2023 08:45:31 Heap6 Load Time=08-15-2023 08:45:31
...
SO: 0x47c3ca6f8, type: OS proc request holder (28), map: 0x52986b3e8
state: LIVE (0x4532), flags: 0x0
owner: 0x7fff0bdd8, proc: 0x7fff0bdd8
link: 0x47c3ca718[0x7fff0be48, 0x47b3b50b8]
pg: 0
SOC: 0x52986b3e8, type: OS proc request holder (28), map: 0x47c3ca6f8
state: LIVE (0x99fc), flags: INIT (0x1)
(osp req holder)
Enqueue blocker waiting on 'SQL*Net message from dblink'
由dump结果可以看出会话该会话等待SQL*Net message from dblink长达exc=28900 min 8 sec，同时There are 1 sessions blocked by this session.被该会话阻塞。
四、处置
通过主机信息定位是否由业务人员操作，同时由业务人员判断可以kill后杀死该会话即可。
SQL> select sid,serial#,event,program,sql_id,status from v$session where sql_id='787z87d7jq8sn';
STATUS
SID SERIAL# EVENT PROGRAM SQL_ID STATE
---------- ---------- ---------------------------------------- ------------------------------ ------------------ ----------
7938 41571 SQL*Net message from dblink plsqldev.exe 787z87d7jq8sn ACTIVE
SQL> alter system kill session '7938,41571' immediate;
System altered.
SQL> select sid,serial#,event,program,sql_id,status from v$session where sql_id='787z87d7jq8sn';
no rows selected
五、总结
oratop是一个分厂不错的实时监控数据库状态的工具，在实际生产中多次帮我发现一些隐藏较深的隐患。
最后修改时间：2023-09-05 09:43:07
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。
