Alert: Oracle SQL Parse Error绝不能放任不管, 产生未知bug
在早期接触 Oracle 12c 的生产环境时，我在数据库警告日志（db alert log）中发现了“WARNING: too many parse errors, count=NNNNN SQL hash=0x****”的警告信息。Oracle 通过这种方式提示我们，应用中有一些解析失败的无效 SQL 正在耗费系统资源。Oracle 建议根据这些 SQL 文本和错误信息来修正 SQL。然而，某些应用或 DBA 可能会对这些警告视而不见，尤其是从 12c 前版本升级上来的用户，更是觉得可以安全地忽略这些警告。 几年前，我记录过一个客户在 Oracle 12.2 中遇到的《Oracle 12.2 DB alert show “WARNING: too many parse errors” or “__Oracle_JDBC_internal_ROWID__” in sql》现象。最近，另一个客户也持续遇到解析失败的问题，,最终会话永久挂起，发现这绝对不能放任不管，因此做了简单记录。
parse error count
错误日志会记录当前 SQL Hash 的解析失败次数，这是实例启动以来的累计值。如果某个 SQL 在 60 分钟内尝试解析失败的次数超过参数 _kks_parse_error_warning（默认值为 100）次，系统会在数据库警告日志（db alert log）中提示一次警告。然而，这个解析失败次数是否有上限呢？如果达到上限又会怎样呢？
案例
在 Oracle 19c (19.9) RAC 环境中，某天在对数据库进行活动巡检时，发现几个会话已经持续了 17 万秒，处于一种自旋状态。通过 v$session.event 可以看到会话在 ON CPU 和 cursor: mutex s 之间交替显示。由于 SQL ID 无法显示对应的文本，v$session 视图中的 SQL_ID、SQL_EXEC_START 字段，以及 ASH 视图中的 TIME_WAITED、IN_PARSE、IN_HARD_PARSE 和 IN_SQL_EXECUTION 字段可以用于分析会话是否在解析阶段。cursor: xx 事件也能指示问题可能出在解析阶段。
SQL>select sql_hash_value,SQL_ID,SQL_EXEC_START,state,event,last_call_et,wait_time,seq# from v$session where sid=xxx SQL> oradebug short_stack ... <-kgxWait()+836<-kgxShared()+1203<-kkshGetNextChild()+250<-kkscsSearchChildList()+2567<-kksfbc()+8938<-kkspsc0()+3746<-kksParseCursor()+3682... SQL> oradebug short_stack ... <-kgxRelease()+1929<-kkshGetNextChild()+899<-kkscsSearchChildList()+2567<-kksfbc()+8938<-kkspsc0()+3746<-kksParseCursor()+3682 ...
对于确认 SQL，可以通过 Oracle 事件转储（event dump）来找出具体的 SQL 文本。如果是解析错误的 SQL，Oracle 12c 会在警告日志（alert log）中记录相应的警告，这样可以更方便地定位 SQL 文本。根据 hash value 或 SQL_ID 可以找到属于某个解析错误的 SQL，而日志中记录的 session 正是那些持续活动的会话。会话挂起的时间与数据库警告日志（db alert log）中最后一次记录该 SQL 解析失败警告的时间相吻合。
2024-04-18T07:38:10.297755+08:00 WARNING: too many parse errors, count=4294967283 SQL hash=0x540d5967 PARSE ERROR: ospid=13250, error=923 for statement: select anbob; Additional information: hd=0x7f2ca2c8 phd=0x7f2cba20 flg=0x28 cisid=0 sid=0 ciuid=0 uid=0 sqlid=7m9w94kkz2862 ...Current username=xxx ...Application: sqlplus@xxxxxxx (TNS V1-V3) Action: ----- PL/SQL Call Stack ----- object line object handle number name 0x7f2d04c0 5 anonymous block SQL> @printtab "select KGLHDPAR,KGLHDADR,KGLNAOBJ,KGLNAHSH,KGLNAHSV,KGLHDNSD,KGLOBT03,kglhdexc from x$kglob where KGLNAOBJ like ''select anbob%''" KGLHDPAR : 000000007F2D5AC8 KGLHDADR : 000000007F2D4370 KGLNAOBJ : select anbob KGLNAHSH : 1891140680 KGLNAHSV : d67bdb5500517dd491048d1570b88448 KGLHDNSD : SQL AREA KGLOBT03 : 9214d2psbj128 KGLHDEXC : 0 ----------------- KGLHDPAR : 000000007F2D5AC8 KGLHDADR : 000000007F2D5AC8 KGLNAOBJ : select anbob KGLNAHSH : 1891140680 KGLNAHSV : d67bdb5500517dd491048d1570b88448 KGLHDNSD : SQL AREA KGLOBT03 : 9214d2psbj128 KGLHDEXC : 0 -----------------
手动尝试执行报错的 SQL 文本时，可以复现该问题：当前会话挂起，且前台窗口未按预期提示 SQL 语法错误。同事对数字非常敏感，注意到错误计数值为 42 亿，这正好是 32 位无符号整数的最大值 [4294967295（2^32-1）]，怀疑是否达到了计数器的上限。然而，这个数字非常大，如果要以解析的速度还原问题，可能需要运行好几天。目前尚未找到查询计数器的视图。尽管解析错误的 SQL text 无法在 v$SQL[AREA] 中查到，但可以从 x$kglob 中找到相关信息。
模拟parse error count
# session 1 ---解析错误SQL select testparseerror ---调整解析错误日志输出阀值,避免日志输出过多 SQL> alter system set "_kks_parse_error_warning"=1000000; System altered. begin --for i in 1..100000000 loop begin execute immediate 'select testparseerror'; exception when others then null; end; end loop; end; /
持续跑了几天后，复现了该问题
WARNING: too many parse errors, count=4294179999 SQL hash=0xa5f120c2 <<<<
PARSE ERROR: ospid=47975, error=923 for statement:
2024-05-01T01:45:40.830736+08:00
select testparseerror <<<<
Additional information: hd=0x2bf7e27e0 phd=0xbeaebb08 flg=0x28 cisid=0 sid=0 ciuid=0 uid=0 sqlid=7m9w94kkz2862
同时手动执行SQL 同样被挂起，查看等待
SQL> select STATE,event,p1,p2,p3,last_call_et,SECONDS_IN_WAIT,FINAL_BLOCKING_INSTANCE,FINAL_BLOCKING_SESSION from v$session where sid=5691; STATE EVENT P1 P2 P3 LAST_CALL_ET SECONDS_IN_WAIT FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION ------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- ----------------------- ---------------------- WAITED SHORT TIME cursor: mutex S 0 14568529068033 4294967296 2022 2023 SQL> select STATE,event,p1,p2,p3,last_call_et,SECONDS_IN_WAIT,FINAL_BLOCKING_INSTANCE,FINAL_BLOCKING_SESSION from v$session where sid=5691; STATE EVENT P1 P2 P3 LAST_CALL_ET SECONDS_IN_WAIT FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION ------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- ----------------------- ---------------------- WAITED SHORT TIME cursor: mutex S 0 14568529068033 4294967296 2025 2026 SQL> select STATE,event,p1,p2,p3,last_call_et,SECONDS_IN_WAIT,FINAL_BLOCKING_INSTANCE,FINAL_BLOCKING_SESSION from v$session where sid=5691; STATE EVENT P1 P2 P3 LAST_CALL_ET SECONDS_IN_WAIT FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION ------------------- -------------------- -------------------- -------------------- -------------------- -------------------- -------------------- ----------------------- ---------------------- WAITED SHORT TIME cursor: mutex S 0 14568529068033 4294967296 2027 2027
查找ALERT LOG PARSE ERROR
从db alert log 日志中使用shell 过滤parse error 的记录，提前发现近最大上限的SQL.
$ grep "parse error" alert.log
WARNING: too many parse errors, count=81932900 SQL hash=0xa5f120c2
WARNING: too many parse errors, count=81933000 SQL hash=0xa5f120c2
WARNING: too many parse errors, count=81933100 SQL hash=0xa5f120c2
WARNING: too many parse errors, count=81933200 SQL hash=0xa5f120c2
WARNING: too many parse errors, count=81933300 SQL hash=0xa5f120c2
...
-- 造一些数据
$ vi b.txt
117904400 SQL hash 0xa5f120c2
117904500 SQL hash 0xa5f120c2
117904600 SQL hash 0xa5f120c2
117904700 SQL hash 0xa5f120c2
117904800 SQL hash 0xa5f120c2
117904900 SQL hash 0xa5f120c2
117905000 SQL hash 0xa5f120c2
117905100 SQL hash 0xa5f120c2
117905200 SQL hash 0xa5f120c2
117905300 SQL hash 0xa5f120c2
117905400 SQL hash 0xa5f120c2
117905500 SQL hash 0xa5f120c2
117905600 SQL hash 0xa5f120c2
117905700 SQL hash 0xa5f120c2
117905800 SQL hash 0xa5f120c2
117905900 SQL hash 0xa5f120c2
117906000 SQL hash 0xa5f120c2
117906100 SQL hash 0xa5f120c2
117906200 SQL hash 0xa5f120c2
117906300 SQL hash 0xa5f120c2
117906400 SQL hash 0xa5f120c2
117906500 SQL hash 0xa5f120c2
117906600 SQL hash 0xa5f120c2
117906700 SQL hash 0xa5f120c2
117906800 SQL hash 0xa5f120c2
117906900 SQL hash 0xa5f120c2
117907000 SQL hash 0xa5f120c2
117907100 SQL hash 0xa5f120c2
117907200 SQL hash 0xa5f120c
11790 SQL hash 0xa5f120c
1170 SQL hash 0xa5f12c
-- 每个SQL HASH记录数
$cat b.txt|awk -F= '{print $2 " " $3}'| awk '{count[$4]++} END { for(i in count) {print i" " count[i]}}'
0xa5f12c 1
0xa5f120c 2
0xa5f120c2 28
-- 每个SQL HASH 最在计数
$cat b.txt|awk -F= '{print $2 " " $3}'|awk '{if($1>x[$4]) {x[$4]=$1}} END {for(i in x) {print i, x[i]}}'
0xa5f12c 1170
0xa5f120c 117907200
0xa5f120c2 117907100
$grep "many parse errors" alert*.log|awk -F= '{print $2 " " $3}'|awk '{if($1>x[$4]) {x[$4]=$1}} END {for(i in x) {print i, x[i]}}'
0xa5f120c2 119299900
小结：
自 Oracle 12c 起，系统增加了针对 SQL 解析失败（Parse fail）的警告提示。该提示会在解析失败达到一定次数后触发。推测其失败次数的计数器是 32 位无符号整数。当解析失败次数达到约 42 亿次时，会导致该 SQL 的解析记录无法再增加，从而导致会话挂起，并等待 cursor: mutex s 事件。此时，唯一的解决方法是杀掉会话，重启实例以释放资源。
对于解析错误的 SQL，如果其执行频率不高，可能会从共享池（shared pool）中逐渐淘汰（age out）。此外，通过刷新共享池（flush shared pool）也可以重置计数器。
微信扫一扫，打赏作者吧～
目前这篇文章还没有评论(Rss)