一次ORA-942错误的跟踪（一）

今天碰到一个很有意思的错误，通过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 ct=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 bj=120997 p='TABLE ACCESS FULL USR_ACTION (cr=65 pr=0 pw=0 time=670 us)'
=====================

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

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

 

 

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

转载于:http://blog.itpub.net/4227/viewspace-571488/