昨天苗同学发现了一个很奇怪的BUG : ZCMS 中有一个栏目修改信息后不能保存,也不报任何异常,就一直在那等着。我听了以后认为是有人用了类似 PLSQL Developer 之类的工具编辑了栏目表的数据,然后忘了提交了,导致相关记录被锁住,从而使别的用户 update 相关记录时一直处于等待的状态。这种忘了提交导致别人线程挂起的事情在基于 oracle 的项目中时有发生。

 

  我就让他去找锁。苗同学果然发现数据库中有锁,但还是有问题,他的描述是:

  a ,这个栏目信息修改时不会加锁,则是在该栏目的上级栏目使用“应用到子栏目”功能时每次都会加锁,并且一直不释放。

  b ,只有这个栏目有问题。

  c ,锁不能直接kill杀掉,只能重启oracle进程。

 

  这是一个很奇怪的现象。这个问题最后就转到我手上来了。我测试发现:

  a,在这个栏目的上级栏目使用“应用到子栏目”功能时确实每次都会加锁。

  b,但换了一个栏目也会加锁,不是只有这个栏目有问题。

  c,关掉java进程则锁会自然释放。

 

  然后我就去调试代码,找到“应用到子栏目”对应的UI方法,代码如下:

  代码一:

 

  这段代码非常简单,实际上就是一个DAOSetupdate动作。调试进去,发现线程会停留在DAOSet.update()方法中调用PreparedStatement.executeBatch()这个方法中。

  我于把这段代码移出来,新建一个有main()方法的类,在这个类中调用UI方法,代码如下:

  代码二:

  执行这个方法,结果和在tomcat中一样会导致线程挂起。

 

  但如果改成更简单的方法就没有问题,如下所示:

  代码三:

  这两个main方法的区别有两个:

  a,前一个使用了事务,后一个没有。

  b,前一个在插件环境下运行,后一个没有。

 

  然后进一步排除插件环境的影响,发现只有使用了事务和没有使用事务这一个区别。

  我再将改造出一个main方法,使用DataAccess手工控制事务,代码如下:

  代码四:

  这段代码和代码二实际上等价,结果也一致,都会导致线程挂起。

  然后进一步改造,代码如下:

  代码五:

  这段代码将使用DAOSet.update()调用改成了逐个调用DAO类的update(),结果没有问题,不会导致线程挂起。而DAOSet.update()中使用了PreparedStatement.addBatch()和executeBatch()来批量更新数据,它和DAO.update()就这一点区别。这就很神奇了:

  a, 在事务中使用批量模式就会导致线程挂起。

  b,  如果单个更新则没有问题。

  c, 不使用事务批量更新也没有问题。

  d, 只有这个表有问题,其他表用类似的代码试了,没有问题。

 

  要知道这几种情况都是使用的一模一样的数据,而且都没有任何异常,oracle也没有任何错误日志输出。

  如果在事务中使用了批量模式导致线程挂起后,在oracle下执行SQL:select * from v$sqlarea where address in (select sql_address from v$session where sid in (select session_id from v$locked_object))

  发现ZCCatalog确实被锁了。然后再执行:select * from v$session_wait where sid in (select session_id from v$locked_object)

  发现这个会话的当前事件是SQL*Net message from client,然后去搜了一堆文章,最后发现这是很正常的事件,所以的oracle会话在没有执行SQL时都可能会是这个事件。

 

  这个事件似乎是表明oracle在等待jdbc返回进一步的信息,我就怀疑是不是jdbc驱动有问题?然后从oracle官网上下载了好几个版本的驱动,一一尝试后发现都有问题。因此排除了jdbc驱动的原因。

 

  从java端彻底没什么办法可想了,只能从oracle端想办法。百度了一大堆文章,没有找到一篇对这个问题有帮助的。我对oracle也不是很熟,根据一篇文章的建议开启一下会话跟踪,尝试了好几个办法,都是在命令行开启的,但我的问题是在jdbc端才能重现,没法使用。折腾了好久,找到了一个有效的办法,如下所示:

  

  即在执行其他SQL之前先执行这两个,这样就会在oracleudump目录下生成会话对应的trc文件。

 

  看了生成的trc文件好久,包括使用了tkprof工具分析,试了又试,也没得到什么结果。最后发现有时候jvm退出后trc文件中会追加几句话,如下所示:

  STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  (cr=1 pr=0 pw=0 time=77 us)'

  STAT #2 id=2 cnt=1 pid=1 pos=1 obj=162560 op='INDEX UNIQUE SCAN OBJ#(162560) (cr=1 pr=0 pw=0 time=11 us)'

  WAIT #0: nam='log file sync' ela= 221 p1=855 p2=0 p3=0

 

  于是就去搜索这个'log file sync',又是看了一堆资料,还是没什么收获。突然想起这台机器的另一个端口上有另外的oracle实例,我就在那台机器上试了一下类似的代码(只是改了一个栏目ID),发现没有问题。

  我仔细检查了两个实例上的代码,发现只有数据上的差异,能在事务中使用批量模式正常update的实例中的数据只有一点和有问题的实例不同:ConfigProps字段时的数据要短一些。

  但ConfigProps可是varchar2(4000),存的数据最长也只有1200个字符,并且都是英文。

  我又人工把正常的实例中的数据的ConfigProps字段加长到和有问题的实例一样大,结果还是可以正常执行。

 

  很显然,问题就在于两个实例的配置有差异。但我分析不出是什么原因,就把两个实例的spfile都尽量改成一致。特别是根据那个'log file sync'的提示,将两者的log_buffer都改成一样了。

  结果有问题的还是有问题,正常的还是正常。我又发现两个实例的Redo日志的大小不一样,正常的那个是每个日志文件100M,不正常的是10M,怀疑是不是因为日志文件太小了,导致频繁切换日志,就把两者调成一样的。结果问题依旧。

  然后又回来折腾java代码,将更新所有字段改成只更新ConfigProps字段,代码如下:

  问题依旧。

 

  不死心,换成了同一个实例下的另一个栏目:

  结果发现竟然没有问题!苗同学的描述是有正确的地方的,这个问题是和数据有关的!

  然后分析两个栏目的数据,依然发现正常的栏目的ConfigProps字段时的数据要短一些。

  试了又试,最后发现如果ConfigProps字段中的字符数正好是1000个的时候能执行,但1001个就不行。又是一通百度,发现oracle这个坑爹的地方:如果使用的AL32UTF8字符集,1个英文要占4个字节!

  这个违反我心中的常识:存英文字符所有字符集都最多只有两个字节,UTF8甚至只需要1个。这就导致虽然ConfigProps的差异在解决问题的过程中一再被发现,但我一直都没重视。

  更坑爹的是:oracle只在有事务的批量模式的时候限制varchar2(4000)只能存1000个字符,其他情况没问题,你可以正常保存1001个!

  问题终于找到,这只是个测试库,明天重做数据库,把字符集改成符合预期的AMERICAN_AMERICA.UTF8就可以了。

 

  总结如下

 

  a,国外的IT公司也会有很多坑爹的BUG

 

  b ,其他同事因为各种原因会向你描述一些不太正确的现象,这也很正常的,你自己也会想偏。

 

  c ,软件给出的各种信息有时候也具有误导性。

 

  d,解决问题的过程就是排除各种可能的过程,运气不好的话可能要到只剩下唯一的可能才会找到根源。