咽完午饭，已经是11点半了。食堂的午餐虽然难吃，但是有公司买单，所以虽然大家一致觉得很难吃，可是也没见到谁放弃了这个福利。
看来大家都不富裕啊,北京房价这么高，能省点就省点吧……
有意思的是，最近大家多了个爱好，每天吃完午饭，就到附近的一个台球馆打球，步行15分钟就到了。
以前打小案子来的，北方很流行的黑8，谁输谁下，人多的时候，一下能去五六个，所以打黑8的话大伙能多打几把。
可是时间长了，大家就有点腻了，决定换斯诺克打打，也感受一下什么叫远台进攻。
进了球馆，选好杆，电话又不争气的响了，我的心一下提到嗓子眼上。”乖乖，希望是我老婆的来电。”。可是往往是你不希望来什么，却偏偏来什么。
果然，出现告警了，有个系统的归档文件系统76％，告警阀值是70%-80%,据说还在继续增长。
这在以前是不正常的。以前的使用率，历史峰值也从来没超过40%。
我现在在外面，10分钟后回去’,挂了电话，跟同伴们摆了一个无奈的表情。走出了球馆……
一路上我开始琢磨起来了，这是一个HPUX 11.23上的9208的环境，单实例。对于应用方面的信息，我则知之甚少。
赶回来的路上，我给应用开发商的左工去了个电话，跟他说明了这个情况，并且希望一会他能给我应用方面的支持。
我简单咨询了一下关于这个应用的架构。
这个系统的设计很简单，接受外围系统ftp过来的数据，做了预处理后，用SQL*LOADER入库，经过运算再把运算结果导出返回给外围系统，类似一个数据加工厂。
外围各个系统给过来的数据是按天给的，文件按不同的系统放在不同的目录下。每天给一次数据。每个系统给过来的数据的时间不确定。
系统中存在一个守护进程在扫描各个目录，发现有文件过来后，会先做一些预处理，然后启动入库；如果发现没有文件，则睡眠一段时间后醒来继续扫描……如此往复。
可以说这是一个日终程序，跑的任务是固定的。不像其他系统，可能并发突然加大。
难道今天开发商上来做了什么其他大的操作么？按理来说不会啊，这边的流程控制很严格，这种现象几乎是不可能出现的。
我也询问了一下左工，他们今天是否有大的动作。他很肯定的回答没有。这也是预料之中的事情。
那么能解释这点的，似乎只有”今天的数据量比以往大得多”这个理由了。可是，今天只是很普通的一天，不是月初，也不是月末的。
不知不觉已经到了公司，登陆上去检查一下就可以揭开谜底了。
1、检查归档路径
SQL> archive log list
Database log mode Archive Mode
Automatic archival Enabled
Archive destination /home/db/archive_b
Oldest online log sequence 16570
Next log sequence to archive 16571
Current log sequence 16571
2、检查文件系统使用率
/home/db/oracle_b #bdf
Filesystem kbytes used avail %used Mounted on
/dev/VGXX/LVYY 31457280 23907532 7549748 76% /home/db/archive_b
确实，归档文件系统已经到了76%，并且使用率还在上升没有停止的势头。为了避免归档文件系统被占满而导致系统挂起，
我请应用运维人员联系备份组启动legato把归档先备走，并且密切关注该文件系统的使用率，一旦超过50%，需要再启动LEGATO把归档备走。
好为自己核查问题赢得更充裕的时间。
那么到底是哪个会话什么程序导致了这个问题呢。
3、检查哪个会话生成最多的归档最多
SQL> select STATISTIC# ,NAME from v$statname where name like ‘%redo size%’;
STATISTIC# NAME
———- —————————————————————-
115 redo size
create table tmp_0422 as select sid,value from v$sesstat where statistic#=115;
稍微等上几分钟，执行
SQL> select a.sid,b.value-a.value from tmp_0422 a,v$sesstat b where a.sid=b.sid(+) and b.statistic#=115 order by 2;
SID B.VALUE-A.VALUE
———- —————
1 0
3 0
4 0
6 0
7 0
10 0
12 0
20 0
36 0
22 0
11 0
SID B.VALUE-A.VALUE
———- —————
9 0
5 193120
8 301712
2 18705888
16 1701174280
16 rows selected.
3、
两个时间段一减，立刻发现会话16生成了1.7个G的redo log，在所有会话里生成量最大。这段时间生成1.7G的数据量算不算正常呢？没有历史数据做比对，这个问题不好回答。
接着检查该会话的详细信息，发现
SQL>select machine,program from v$session where sid=’16′
——————————————–
HOST_AP sqlldr (TNS V1-V3
恩，是SQL*LOADER，看来正在入库数据。
SQL> select sql_text from v$sqltext where address in(select sql_address from v$session where sid=16) order by piece;
SQL_TEXT
—————————————————————-
INSERT INTO BC_LOG_STOCKTRANSFER (CREDIT_ID,USERID,TXCODE,SERI
AL,ACC_DATE,BRANCH_CODE,TRAN_DATE,IP_ADD,BBRANCH_CODE,ACC_NO,ACC
_TYPE,BROKER_CODE,BOURSE_CODE,STOCKHOLDER_CODE,FEE,AMOUNT,CUR_TY
PE,STATUS,DAC,TRAN_TYPE) VALUES (:CREDIT_ID,:USERID,:TXCODE,:SER
IAL,:ACC_DATE,:BRANCH_CODE,:TRAN_DATE,:IP_ADD,:BBRANCH_CODE,:ACC
_NO,:ACC_TYPE,:BROKER_CODE,:BOURSE_CODE,:STOCKHOLDER_CODE,:FEE,:
AMOUNT,:CUR_TYPE,:STATUS,:DAC,:TRAN_TYPE)
7 rows selected.
……过了一会再检查……
SQL> select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’&sid’) order by piece;
Enter value for sid: 16
old 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’&sid’) order by piece
new 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’16′) order by piece
SQL_TEXT
—————————————————————-
INSERT INTO BC_LOG_PAYMENT (CREDIT_ID,USERID,TXCODE,SERIAL,ACC
_DATE,BRANCH_CODE,TRAN_DATE,IP_ADD,PAY_BBRANCH_CODE,PAY_ACC_NO,P
AY_ACC_TYPE,MER_ACC_NO,POS_CODE,MERCHANT_CODE,REMARK1,REMARK2,FE
E,ORDER_NUM,CUR_TYPE,AMOUNT,STATUS,DAC,PAY_ACC_NAME,AGREE_STATUS
,LOCATION,REFUNDEMENT_AMOUNT) VALUES (:CREDIT_ID,:USERID,:TXCODE
,:SERIAL,:ACC_DATE,:BRANCH_CODE,:TRAN_DATE,:IP_ADD,:PAY_BBRANCH_
CODE,:PAY_ACC_NO,:PAY_ACC_TYPE,:MER_ACC_NO,:POS_CODE,:MERCHANT_C
ODE,:REMARK1,:REMARK2,:FEE,:ORDER_NUM,:CUR_TYPE,:AMOUNT,:STATUS,
AC,:PAY_ACC_NAME,:AGREE_STATUS,:LOCATION,:REFUNDEMENT_AMOUNT)
……过了一会再检查……
发现的信息无非是会话在往另外一张表导入数据。相应的文件导入相应的表中
4、
回到最开始的分析，验证下今天入库文件的数据量是不是比以前多了。
根据电话里左工一步步的指导，我找到了当天过来的所有文件，和前7天的数据做了比对，和以前是一个数量级的。
排除了这个情况。那么还可能是什么原因呢，检查也没发现有其他会话在干活。跟之前对系统描述的是一样的。
时间一分一秒过去，也没有发现造成这个问题的根本原因。
接下来系统开始空跑了。也就是进程进入了睡眠时间。
归档日志之前被LEGATO备走后，才一会功夫，又涨到了20%。不过进程进入了睡眠，归档文件系统的使用率也暂时停止了增长。
左工告诉我，要休眠30分钟才会醒来扫描别的目录，发现别的系统传来了文件则继续处理。
趁着这中间的工夫，我出去抽了根烟，把思路好好缕缕，也好提提神。
5、
好不容易等半个小时过去了，SQL*LOADER的入库非常快，这次我一定在入库的过程中好好检查检查。
依然是查找生成归档日志最大的会话
SQL> select a.sid,b.value-a.value from tmp_0422 a,v$sesstat b where a.sid=b.sid(+) and b.statistic#=115 order by 2;
SID B.VALUE-A.VALUE
———- —————
18 -4520
1 0
3 0
4 0
6 0
7 0
10 0
20 0
22 0
12 0
11 0
SID B.VALUE-A.VALUE
———- —————
9 0
5 365936
8 735792
2 42392032
28 1988499944
16 rows selected.
重新起来后，可以看到进程以新的SID 28来导数了。
SQL> @sql_sid
Enter value for sid: 28
old 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’&sid’) order by piece
new 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’28′) order by piece
SQL_TEXT
—————————————————————-
INSERT INTO BC_LOG_PAYMENT (CREDIT_ID,USERID,TXCODE,SERIAL,ACC
_DATE,BRANCH_CODE,TRAN_DATE,IP_ADD,PAY_BBRANCH_CODE,PAY_ACC_NO,P
AY_ACC_TYPE,MER_ACC_NO,POS_CODE,MERCHANT_CODE,REMARK1,REMARK2,FE
E,ORDER_NUM,CUR_TYPE,AMOUNT,STATUS,DAC,PAY_ACC_NAME,AGREE_STATUS
,LOCATION,REFUNDEMENT_AMOUNT) VALUES (:CREDIT_ID,:USERID,:TXCODE
,:SERIAL,:ACC_DATE,:BRANCH_CODE,:TRAN_DATE,:IP_ADD,:PAY_BBRANCH_
CODE,:PAY_ACC_NO,:PAY_ACC_TYPE,:MER_ACC_NO,:POS_CODE,:MERCHANT_C
ODE,:REMARK1,:REMARK2,:FEE,:ORDER_NUM,:CUR_TYPE,:AMOUNT,:STATUS,
AC,:PAY_ACC_NAME,:AGREE_STATUS,:LOCATION,:REFUNDEMENT_AMOUNT)
9 rows selected.
还是老套路，我这样能查到问题吗？我开始怀疑自己了。
不过，再仔细看这个语句，终于发现了问题的线索了……
这个不就是上一次入库中SQL*LOADER中曾经导入的其中一张表吗？为什么会重复导2次呢？
难道是……难道是程序进入了死循环？！
这个想法一出，我整个人马上兴奋起来了。接下来，我要验证我的想法是不是真的疯了。我把第二次抓到的表名和第一次抓到的表名逐一做了比对，真的是完全的重复！
6、
我把我的想法告诉了左工，’不会吧’,左工不敢相信。
接下来就是要验证这个想法了，通过左工电话中的描述，我一步一步的进入到了导入程序的LOG。
发现了下面的这一段应用日志
71476 Import data into bc_log_fundtransfer Success ……–<2009-04-22 16:49:40>
71477
71478 bc_log_fundtransfer 导数成功
71479 清空基金确认信息表,个人客户新增、变动信息临时表
71480
71481 Table truncated.
71482
71483
71484 Table truncated.
71485
71486
71487 Table truncated.
71488
71489
71490 Table truncated.
71491
71492 开始装载[20090421]基金确认信息(来自ods)的数据
71493
71494 gzip: CAS_ODS_TCONFIRM_20090421.dat.gz: invalid compressed data–format violated
71495 CAS_ODS_TCONFIRM_20090421.dat file not found!
71496 装载[20090421]基金确认信息(来自ods)的数据失败
……
……
……
############
Commit point reached – logical record count 20537
69821 Commit point reached – logical record count 22305
69822 Import data into bc_log_fundtransfer Success ……–<2009-04-22 16:13:59>
69823
69824 bc_log_fundtransfer 导数成功
69825 清空基金确认信息表,个人客户新增、变动信息临时表
69826
69827 Table truncated.
69828
69829
69830 Table truncated.
69831
69832
69833 Table truncated.
69834
69835
69836 Table truncated.
69837
69838 开始装载[20090421]基金确认信息(来自ods)的数据
69839
69840 gzip: CAS_ODS_TCONFIRM_20090421.dat.gz: invalid compressed data–format violated
##########
这段LOG被重复着，而其他归档日志量正常的时候，这段LOG只出现了一次。
从这段LOG中也不难看出，由于在解压缩gzip: CAS_ODS_TCONFIRM_20090421.dat.gz的时候，报了无效的压缩数据而使程序退出。
之后睡眠了30分钟，又重复进行的导入。
严格来说，这个程序的逻辑是有问题的。即使出现了异常，也不应该从头把所有数据再导一次啊。毕竟前面的数据是导成功了的。没必要truncate掉重新导。
这个属于后期的调整建议了。马上修改不现实，毕竟需要代码测试、新版本上线等流程。
找到了根本原因，问题就好解决了，只需要让对方重传正确的数据，就可以跳出这个死循环了。
7、
终于外围的一个系统传来了正确的数据，观察导入程序的日志，终于出现了期待中的正常导入。
76453
76454 开始装载[20090421]基金确认信息(来自ods)的数据
76455 Import data from CAS_ODS_TCONFIRM_20090421.dat into t_fund_conf_info Begining ……–<2009-04-22 18:36:56>
76458 SQL*Loader: Release 9.2.0.8.0 – Production on Wed Apr 22 18:36:56 2009
76459
76460 Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
76461
76462 Commit point reached – logical record count 2442
76463 Commit point reached – logical record count 4884
76464 Commit point reached – logical record count 7326
76465 Commit point reached – logical record count 9768
看到这个日志，终于放下心来了。不然这个归档日志不断的增长，要折腾多少人不能下班和睡觉呢。
庆幸。
总结：
1、这个事情本来是要应用运维人员要第一时间去查应用日志的问题。可是报警的是数据库的归档日志，结果承受压力的是我一个人，查应用日志的人却是我，对应用不了解的人。
说明了有很多需要思考的地方。
2、了解应用的设计，处理好和应用开发商的关系对问题的处理很重要。本次开发商的左工给了我应用方面的很多支持，包括要导入的文件放在哪，导入程序的LOG在哪。
3、细心是不可缺少的。将多个现象联系起来给出大胆的猜想，然后去验证。
Recent Comments