ANBOB™

朋友一套12.2的RAC一节点CRASH, 发我一份alert log让帮着看看，crash的原因以后有时间再写，但是alert log中出现了大量的”WARNING: too many parse errors”，是以前的版本中从未见过，这也是12.2的新特性，自动生成解析失败的信息写入db alert log, 即使没有在数据库启用event 10035, 以前版本可以通过启用10035 event分析解决失败信息写入alert log.

db alert log

2017-11-21T04:22:55.526449+08:00
XXHCPDB(12):WARNING: too many parse errors, count=2996 SQL hash=0x117d3781
XXHCPDB(12):PARSE ERROR: ospid=56905, error=1446 for statement: 
2017-11-21T04:22:55.526595+08:00
XXHCPDB(12):select rowid as "__Oracle_JDBC_internal_ROWID__", inv_objs from (select count(*) as inv_objs from dba_objects where status='INVALID')
XXHCPDB(12):Additional information: hd=0x43f493be0 phd=0x4368401a0 flg=0x20 cisid=0 sid=0 ciuid=0 uid=0 
XXHCPDB(12):WARNING: too many parse errors, count=2996 SQL hash=0x92a117b7
XXHCPDB(12):PARSE ERROR: ospid=56905, error=918 for statement: 
2017-11-21T04:22:55.563449+08:00
XXHCPDB(12):select rowid as "__Oracle_JDBC_internal_ROWID__", ses,ac_ses,waits,ofn_files,fai_jobs,inv_objs,lck_objs from (select count(*) as ses from v$session),(select count(*) as ac_ses from v$session where status='ACTIVE'),(select count(*) as waits from v$session_wait),(select count(*) as ofn_files from v$datafile where status = 'OFFLINE'),(select count(*) as fai_jobs from dba_jobs where failures > 0),(select count(*) as lck_objs from v$locked_object),(select count(*) as inv_objs from dba_objects where status='INVALID')
XXHCPDB(12):Additional information: hd=0x479b14608 phd=0xfc3e4728 flg=0x20 cisid=0 sid=0 ciuid=0 uid=0 

Note:
从以上信息中可以看到的信息：
1， WARNING: too many parse errors
2， SQL HASH
3,    SQL TEXT
4,    SQL ERROR CODE
5,    __Oracle_JDBC_internal_ROWID__

[oracle@anbob ~]$ oerr ora 1446
 01446, 00000, "cannot select ROWID from, or sample, a view with DISTINCT, GROUP BY, etc."
 // *Cause:
 // *Action:
 [oracle@anbob ~]$ oerr ora 918
 00918, 00000, "column ambiguously defined"
 // *Cause:

SQL解析失败是一种常见现象，但是同一SQL频繁的解析失败会给数据库带来性能问题， 从AWR中的时间模型中同样可以发现parse, failed parse 占用较高的DB TIME,  以上DB Alert log中的输出是一种诊断信息的增强，可以默认把经常解决失败的信息写入db alert, 多数都是应用程序问题，解决方法自然是调整应用或SQL.

WARNING: too many parse errors 并不是每次解析都提示，默认是在同一SQL在60分钟内每出现100次就会提示一次worning到DB ALERT LOG. 对于这个阀值应该是有隐藏参数”_kks_parse_error_warning” 控制的。

SQL> @pd parse_error
Show all parameters and session values from x$ksppi/x$ksppcv...

       NUM N_HEX NAME                         VALUE         DESCRIPTION
---------- ----- ---------------------------- ------------- -------------------------
      3080   C08 _kks_cached_parse_errors     0             KKS cached parse errors
      3082   C0A _kks_parse_error_warning     100           Parse error warning

对于SQL文本是可以手动执行还原问题，ERROR 就是解析的错误ORACE的提示编号，这里的1446 是提示rowid 不能用于count这类汇总操作中。

对于SQL文本中的ROWID 和“__Oracle_JDBC_internal_ROWID__”应该不是程序员人为加入，ALERT中提示中出现了大量__Oracle_JDBC_internal_ROWID__字样，判断应该是ORACLE JDBC驱动自动附加的。

当JDBC 中scroll sensitive resultset 启用时，JDBC驱动就会在用户SQL中自动增加ROWID ，但是并不是所有的查询都适合附加rowid, 该功能是JDBC中对于结果集是否在数据改变后自动刷新，有TYPE_SCROLL_SENSITIVE和TYPE_SCROLL_INSENSITIVE两种，区别可以看这里。
–JAVA CODE Demo

try {
        Class.forName(driverName).newInstance();
        connection = DriverManager.getConnection(url+dbName, userName, password);
           Statement stmt = connection.createStatement(
              ResultSet.TYPE_SCROLL_SENSITIVE,
              ResultSet.CONCUR_READ_ONLY);
...
if (res.getType() == ResultSet.TYPE_SCROLL_SENSITIVE) {
          System.out.println("ResultSet TYPE_SCROLL_SENSITIVE.");
        }
'''
}

解决该类问题需要程序员了解TYPE_SCROLL_SENSITIVE的限制，修改SQL解析失败处代码ResultSet型的类

AWK 提取 db alert中的 parse error信息

定期的提取一下parse error 如语法错误的或权限错误的SQL, 有必要提供给前端修正。从多到少的修复。

-- DB ALERT LOG
WARNING: too many parse errors, count=650096763 SQL hash=0xa101d379
PARSE ERROR: ospid=2526, error=911 for statement:
2021-01-19T13:10:00.717433+08:00
 SELECT 1 FROM TAB_ANBOB_COM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
Additional information: hd=c0000001cd576b28 phd=c0000001cd576f50 flg=0x28 cisid=52 sid=52 ciuid=52 uid=52
2021-01-19T13:10:01.827376+08:00
WARNING: too many parse errors, count=650096863 SQL hash=0xa101d379
PARSE ERROR: ospid=2496, error=911 for statement:
2021-01-19T13:10:01.828177+08:00
 SELECT 1 FROM TAB_ANBOB_COM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
Additional information: hd=c0000001cd576b28 phd=c0000001cd576f50 flg=0x28 cisid=52 sid=52 ciuid=52 uid=52
2021-01-19T13:10:03.047922+08:00
WARNING: too many parse errors, count=650096963 SQL hash=0xa101d379
PARSE ERROR: ospid=2514, error=911 for statement:
2021-01-19T13:10:03.049293+08:00
 SELEC
 WARNING: too many parse errors, count=650096763 SQL hash=0xa101d379
PARSE ERROR: ospid=2526, error=911 for statement:
2021-01-19T13:10:00.717433+08:00
 SELECT 1 FROM TAB_ANBOB_COM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
Additional information: hd=c0000001cd576b28 phd=c0000001cd576f50 flg=0x28 cisid=52 sid=52 ciuid=52 uid=52
2021-01-19T13:10:01.827376+08:00
WARNING: too many parse errors, count=650096863 SQL hash=0xa101d379
PARSE ERROR: ospid=2496, error=911 for statement:
2021-01-19T13:10:01.828177+08:00
 SELECT 1 FROM TAB_ANBOB_COM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
Additional information: hd=c0000001cd576b28 phd=c0000001cd576f50 flg=0x28 cisid=52 sid=52 ciuid=52 uid=52
2021-01-19T13:10:03.047922+08:00
WARNING: too many parse errors, count=650096963 SQL hash=0xa101d379
PARSE ERROR: ospid=2514, error=911 for statement:
2021-01-19T13:10:03.049293+08:00
 SELEC

-- 记算不同sql hash出次的次数
#  cat alert\ parse\ error.sql |awk '/parse error/ { H=$8 ;next;}; /PARSE ERROR/ { E= $4 ;print H " " E}' |sort |uniq -c|sort -n
      1 hash=0xa101d300 error=904
      1 hash=0xa101d379 error=905
      1 hash=0xa101d379 error=912
      3 hash=0xa101d379 error=911

-- 报错明细时间
# cat alert\ parse\ error.sql|awk '/parse error/ { H=$8 ; next;};/PARSE ERROR/{R=NR;E= $4 }NR==R+1{ D=$0; print "****" H " " E  " " D};'
****hash=0xa101d379 error=911 2021-01-19T13:10:00.717433+08:00
****hash=0xa101d379 error=911 2021-01-19T13:10:01.828177+08:00
****hash=0xa101d300 error=904 2021-01-19T13:10:03.049293+08:00
****hash=0xa101d379 error=911 2021-01-19T13:10:00.717433+08:00
****hash=0xa101d379 error=905 2021-01-19T13:10:01.828177+08:00
****hash=0xa101d379 error=912 2021-01-19T13:10:03.049293+08:00

-- 报错明细SQL
# cat alert\ parse\ error.sql|awk '/parse error/ { H=$8 ; next;};/PARSE ERROR/{R=NR;E= $4 }NR==R+2{ D=$0; print "****" H " " E  " " D};'
****hash=0xa101d379 error=911  SELECT 1 FROM GROUP_MEMBER_CONFRIM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
****hash=0xa101d379 error=911  SELECT 1 FROM GROUP_MEMBER_CONFRIM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
****hash=0xa101d300 error=904  SELECt 1
****hash=0xa101d379 error=911  SELECT 1 FROM GROUP_MEMBER_CONFRIM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
****hash=0xa101d379 error=905  SELECT 1 FROM GROUP_MEMBER_CONFRIM WHERE REGION= 313 AND　STATUS= :STATUS   AND  CREATEDATE <= SYSDATE - :DATACYCLE/24  AND  ROWNUM < 2
****hash=0xa101d379 error=912  SELECt 1

Known Issue

— update 2024/9/25 —
在oracle 19.19 RU中存在一个bug 导致db alert log中的parse error 并不输出SQL TEXT文本

alert_v1919.log

2023-10-17T21:28:26.828730+00:00
OS Pid: 4070331 executed alter system set events ‘10035 trace name context forever, level 1’ <<######### 即使配置 event 10035 configured..
2023-10-17T21:28:35.250854+00:00
PARSE ERROR: ospid=4070331, error=942 for statement:
Additional information: hd=0x66afde50 phd=0x66aff5a8 flg=0x20 cisid=0 sid=0 ciuid=0 uid=0 sqlid=g9b7tgg6dm018 <<######### no SQL TEXT is seen ..
…Current username=SYS
…Application: sqlplus@perf-adat-instance (TNS V1-V3) Action:

原因
BUG 35888571 – NEED TO RECORD SQL THAT HITS PARSE ERRORS (Status=80)

修复
fixed in 23.4 或安装one-off patch。

— enjoy —

打赏

微信扫一扫，打赏作者吧～