ORA-942错误的跟踪(一)

日期: 2009-03-19 作者:杨廷琨 来源:TechTarget中国 英文

今天碰到一个很有意思的错误,通过JAVA程序连接数据库,运行程序时报错,错误信息就是ORA-00942: table or view does not exist。

下面我简单描述错误现象和问题初步诊断。

根据程序员的描述,SQL运行时报错ORA-942,如果将SQL语句中的表名改为大写,就不会报错了。

听到这个现象描述,第一个反应就是表名大小写的问题。

不过现在现象有点奇怪,表名小写的时候并没有加上双引号。那么Oracle自动会将这个语句转化为大写,所以应该和表名大写的SQL没有区别才对。

观察了一下程序的执行,当程序执行到select * from usr_action语句的时候,出现了这个ORA-942错误。而如果将SQL改为select * from USR_ACTION,则不会有问题,这个SQL可以顺利的执行。

更奇怪的是,这个问题似乎只对JAVA程序才会出现,在sqlplus和sqldeveloper中,不会出现同样的问题。

看来问题不是简单的表名大小写的问题,问题显然要复杂得多。

下面简单描述一下当前的环境,由于这个环境恰好是一个同事在我指导下完成的,所以我对这个环境还比较了解。

程序连接的用户是TJSQ_TRADE,程序访问的表包括两部分,一部分就是TJSQ_TRADE这个SCHEMA中的表,另一部分是TJSQ_NDMAIN用户中的表,这部分表在TJSQ_TRADE中建立同义词,并有TJSQ_NDMAIN用户将这些表的访问权限赋给了TJSQ_TRADE用户。

下面在说说这两个用户是怎样建立的,在这两个用户建立之前,系统中建立过结构完全相同的用户:BJSQ_TRADE和BJSQ_NDMAIN。这次要新建结构完全相同的两个用户,于是采用了数据泵的方式导出BJSQ_TRADE和BJSQ_NDMAIN两个用户的源数据,并采用REMAP_TABLESPACE和REMAP_SCHEMA方式导入到TJSQ_TRADE和TJSQ_NDMAIN用户中。

无论是程序还是数据结构都是相同的,那么同样的问题没有发生在BJSQ_TRADE用户中,而发生在TJSQ_TRADE中,说明问题很可能和这个用户的生成方式有关系。不过数据泵REMAP_SCHEMA方式以前也做过很多次,从来没有碰到过类似的问题,虽然这次并不是我自己动手操作的,但是大部分关键步骤都是在我指导下进行的,应该不会有什么大问题。如果问题确实与用户的生成方式有关,那么不是当前的环境的特殊性导致的问题,就是数据泵导出导入过程中和以往有一些小的差异,从而导致了问题的产生。

通过DBMS_METADATA获取源数据的方法,对比了BJSQ_TRADE和TJSQ_TRADE的同义词,以及BJSQ_NDMAIN和TJSQ_NDMAIN方案下的表,没有发现任何的区别。看来至少当前环境中,新建用户TJSQ_NDMAIN和TJSQ_TRADE与老用户BJSQ_NDMAIN和BJSQ_TRADE没有区别。对比环境的不同找不到什么线索,那么看看能否从错误信息着手。

对于这种错误,最简单的办法是通过TRACE的方式来看看Oracle在运行这个SQL的时候到底发生了什么。不过由于在SQLPLUS中没有重现错误,导致诊断问题变得很麻烦,必须配合JAVA程序一起联合进行诊断。由于JAVA程序使用了连接池,导致一旦程序启动,就会有多个会话同时连接到数据库中,因此很难判断到底哪个会话会执行出错的SQL语句。当然可以修改程序,在运行出错的SQL前面运行ALTER SESSION SET SQL_TRACE = TRUE。但是还是由于连接池的特性,无法保证ALTER SESSION语句与随后的select语句在同一个会话上执行。随意修改程序的方法是行不通的。还有一个办法,就是修改中间件连接池,使得程序只有一个会话连接到Oracle数据库中。不过现在还没有定位问题的真正原因,且目前来看问题似乎和JAVA程序有关,现在还无法排除中间件的问题,直接贸然修改其他的配置和可能会导致测试结果改变。

如果在数据库级设置SQL_TRACE,不但会产生大量的无用trace,也会给进一步分析问题带来麻烦。配合JAVA程序的断点单步调试,利用DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION过程最为合适:


SQL> SELECT SID, SERIAL#
2 FROM V$SESSION
3 WHERE USERNAME = ‘TJSQ_TRADE’
4 AND MACHINE = ‘kylin-TinkPad’;
SID SERIAL#
———- ———-
129 2494
130 224
147 14635
SQL> SELECT SPID FROM V$PROCESS
2 WHERE ADDR IN (SELECT PADDR FROM V$SESSION WHERE SID IN (129, 130, 147));
SPID
————
595
744
746
SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(129, 2494, TRUE)
PL/SQL procedure successfully completed.
SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(130, 224, TRUE)
PL/SQL procedure successfully completed.
SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(147, 14635, TRUE)
PL/SQL procedure successfully completed.

通过查询V$SESSION,并指定应用服务器的连接的主机名和连接用户名称,定位JAVA程序连接到Oracle的会话,为了方便查找生成的trace文件,这里还查询对应操作系统的进程ID。

随后分别为3个会话设置SQL_TRACE,然后运行JAVA程序继续运行,执行报错的SQL语句:select * from usr_action。神奇的事情发生了,这次JAVA程序中没有报错。而检查后台对应trace文件,也可以看到这个语句成功执行了:


$ more newdemo_ora_744.trc 
/data/oracle/admin/newdemo/udump/newdemo_ora_744.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 – 64bit Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /data/oracle/product/10.2
System name: Linux
Node name: yans2
Release: 2.6.9-42.0.0.0.1.ELsmp
Version: #1 SMP Sun Oct 15 15:13:57 PDT 2006
Machine: x86_64
Instance name: newdemo
Redo thread mounted by this instance: 1
Oracle process number: 37
Unix process pid: 744, image: oraclenewdemo@yans2
*** 2009-03-18 09:47:08.552
*** SERVICE NAME:(SYS$USERS) 2009-03-18 09:47:08.552
*** SESSION ID:(147.14635) 2009-03-18 09:47:08.552
=====================
PARSING IN CURSOR #2 len=25 dep=0 uid=104 oct=3 lid=104 tim=1208340652883521 hv=1367961303 ad=’6ee009b0′
select * from usr_action 
END OF STMT
PARSE #2:c=0,e=188,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1208340652883516
EXEC #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1208340652883819
FETCH #2:c=0,e=127,p=0,cr=3,cu=0,mis=0,r=10,dep=0,og=1,tim=1208340652897864
*** 2009-03-18 09:55:14.856
FETCH #2:c=0,e=77,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341127789416
FETCH #2:c=0,e=44,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341127805165
FETCH #2:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341127819547
FETCH #2:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341127831599
FETCH #2:c=0,e=31,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341127843581
.
.
.
FETCH #2:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341128460244
FETCH #2:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=10,dep=0,og=1,tim=1208341128473093
FETCH #2:c=0,e=47,p=0,cr=2,cu=0,mis=0,r=4,dep=0,og=1,tim=1208341128485355
STAT #2 id=1 cnt=594 pid=0 pos=1 obj=120997 op=’TABLE ACCESS FULL USR_ACTION (cr=65 pr=0 pw=0 time=670 us)’
=====================

没有想到的是,由于TRACE的出现,居然改变了SQL语句行为,使得原本报错的SQL,现在可以顺利执行了。为了验证是否确实是TRACE影响了测试的结果,关闭会话的SQL_TRACE,再次运行JAVA程序,错误再次出现。根据上面的方法再次设置SQL_TRACE,错误又再次消失了。

这个问题太神奇了,如果你想通过数据库的一些手段来观察、监测它,它就不出现了。而你去掉监测的方法,它又冒出来了。

我们一直都在努力坚持原创.......请不要一声不吭,就悄悄拿走。

我原创,你原创,我们的内容世界才会更加精彩!

【所有原创内容版权均属TechTarget,欢迎大家转发分享。但未经授权,严禁任何媒体(平面媒体、网络媒体、自媒体等)以及微信公众号复制、转载、摘编或以其他方式进行使用。】

微信公众号

TechTarget微信公众号二维码

TechTarget

官方微博

TechTarget中国官方微博二维码

TechTarget中国

电子邮件地址不会被公开。 必填项已用*标注

敬请读者发表评论,本站保留删除与本文无关和不雅评论的权力。

相关推荐