我就让他去找锁。苗同学果然发现数据库中有锁,但还是有问题,他的描述是:
a ,这个栏目信息修改时不会加锁,则是在该栏目的上级栏目使用“应用到子栏目”功能时每次都会加锁,并且一直不释放。
b ,只有这个栏目有问题。
c ,锁不能直接kill杀掉,只能重启oracle进程。
这是一个很奇怪的现象。这个问题最后就转到我手上来了。我测试发现:
a,在这个栏目的上级栏目使用“应用到子栏目”功能时确实每次都会加锁。
b,但换了一个栏目也会加锁,不是只有这个栏目有问题。
c,关掉java进程则锁会自然释放。
然后我就去调试代码,找到“应用到子栏目”对应的UI方法,代码如下:
代码一:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
|
@Priv
(CatalogExtendAdminPriv.ID +
".${ID}"
)
public
void
applyToChildren() {
String id = $V(
"ID"
);
if
(ObjectUtil.empty(id)) {
return
;
}
Transaction trans =
new
Transaction();
ZCCatalog catalog = CatalogUtil.getDAO(Long.parseLong(id));
DAOSet<ZCCatalog> set =
new
ZCCatalog().query(
new
Q().where(
"ContentType"
, catalog.getContentType()).and()
.likeRight(
"InnerCode"
, catalog.getInnerCode()));
for
(ZCCatalog child : set) {
child.setConfigProps(catalog.getConfigProps());
ExtendManager.invoke(BeforeCatalogPropSave.ExtendPointID,
new
Object[] { trans, child });
// Extend Point
}
trans.add(set, Transaction.UPDATE);
if
(trans.commit()) {
for
(ZCCatalog child : set) {
CacheManager.set(ContentCoreCache.ProviderID,
"Catalog"
, child.getID(), child);
// 更新缓存
}
success(Lang.get(
"Common.SaveSuccess"
));
}
}
|
这段代码非常简单,实际上就是一个DAOSet的update动作。调试进去,发现线程会停留在DAOSet.update()方法中调用PreparedStatement.executeBatch()这个方法中。
我于把这段代码移出来,新建一个有main()方法的类,在这个类中调用UI方法,代码如下:
代码二:
1
2
3
4
5
6
7
|
public
static
void
main(String[] args) {
Config.isPluginContext =
true
;
ExtendManager.getInstance().start();
Current.prepare(
null
);
Current.getRequest().put(
"ID"
,
"9195"
);
new
CatalogUI().applyToChildren();
}
|
执行这个方法,结果和在tomcat中一样会导致线程挂起。
但如果改成更简单的方法就没有问题,如下所示:
代码三:
1
2
3
4
|
public
static
void
main(String[] args) {
Q q =
new
Q(
"where ContentType='Article' and InnerCode like '000023%'"
);
new
ZCCatalog().query(q).update();
}
|
这两个main方法的区别有两个:
a,前一个使用了事务,后一个没有。
b,前一个在插件环境下运行,后一个没有。
然后进一步排除插件环境的影响,发现只有使用了事务和没有使用事务这一个区别。
我再将改造出一个main方法,使用DataAccess手工控制事务,代码如下:
代码四:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
public
static
void
main(String[] args) {
DataAccess da =
new
DataAccess();
try
{
da.setAutoCommit(
false
);
Q q =
new
Q(
"where ContentType='Article' and InnerCode like '000023%'"
);
DAOSet<ZCCatalog> set =
new
ZCCatalog().query(q);
set.setDataAccess(da);
set.update();
da.commit();
da.setAutoCommit(
true
);
}
catch
(Exception e) {
e.printStackTrace();
}
finally
{
da.close();
}
}
|
这段代码和代码二实际上等价,结果也一致,都会导致线程挂起。
然后进一步改造,代码如下:
代码五:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
|
public
static
void
main(String[] args) {
DataAccess da =
new
DataAccess();
try
{
da.setAutoCommit(
false
);
Q q =
new
Q(
"where ContentType='Article' and InnerCode like '000023%'"
);
DAOSet<ZCCatalog> set =
new
ZCCatalog().query(q);
for
(ZCCatalog c : set) {
c.setDataAccess(da);
c.update();
}
da.commit();
da.setAutoCommit(
true
);
}
catch
(Exception e) {
e.printStackTrace();
}
finally
{
da.close();
}
}
|
这段代码将使用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端才能重现,没法使用。折腾了好久,找到了一个有效的办法,如下所示:
1
2
|
da.executeNoQuery(
new
Q(
"alter session set sql_trace=true"
));
da.executeNoQuery(
new
Q(
"alter session set events '10046 trace name context forever,level 8'"
));
|
即在执行其他SQL之前先执行这两个,这样就会在oracle的udump目录下生成会话对应的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字段,代码如下:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
|
public
static
void
main() {
DataAccess da =
new
DataAccess();
try
{
da.executeNoQuery(
new
Q(
"alter session set sql_trace=true"
));
da.executeNoQuery(
new
Q(
"alter session set events '10046 trace name context forever,level 8'"
));
Q q =
new
Q(
"where ContentType='Article' and InnerCode like '000023%'"
);
ZCCatalog catalog =
new
ZCCatalog();
catalog.setDataAccess(da);
DAOSet<ZCCatalog> set = catalog.query(q);
set.setOperateColumns(
"ConfigProps"
);
set.setDataAccess(da);
set.update();
}
catch
(Exception e) {
e.printStackTrace();
}
finally
{
da.close();
}
}
|
问题依旧。
不死心,换成了同一个实例下的另一个栏目:
1
|
Q q =
new
Q(
"where ContentType='Article' and InnerCode like '000021%'"
);
|
结果发现竟然没有问题!苗同学的描述是有正确的地方的,这个问题是和数据有关的!
然后分析两个栏目的数据,依然发现正常的栏目的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,解决问题的过程就是排除各种可能的过程,运气不好的话可能要到只剩下唯一的可能才会找到根源。