本文讲述了作者排查逻辑从库日志应用延迟的问题，通过监控和日志分析，发现是由大量无索引的DELETE操作引起。通过在逻辑从库端skip相关表并优化代码，解决了延迟问题，强调了主库操作对逻辑从库的影响，并提出了预防措施。
这台逻辑从库自从建立之后,就没怎么管,因为应用也没有迁移的紧迫性,也不急着迁移过来.这段时间主要还是看看在日志应用的过程中是不是会遭遇bug而导致日志应用不下去的问题.所以只是跳过了比如mlog$这样一些肯定要跳过去的对象,没有仔细的针对应用看看还需要跳过哪些对象.监控上也主要是看看是不是会遭遇bug而导致应用不下去的情况,所以只是每2个小时检查一下
SELECT * FROM V$LOGSTDBY_PROGRESS p where nvl(p.LATEST_TIME-p.APPLIED_TIME,10)>1/12;
看看是不是会返回数据行.每天凌晨2:15的时候,都会收到告警的邮件,说日志应用延迟超过了2个小时,之后包括4:15就不再收到邮件了,说明只是那段时间日志应用缓慢,之后就跟上来了,而不是遭遇bug导致lsp进程终止了,而且其它监控包括告警日志文件的监控也没有收到错误信息,所以也就没有太关注这个逻辑从库.
这段时间,闲了下来,就决定看看到底是什么导致那个时间段日志应用缓慢了.就简单的写了个shell脚本,包括下面的内容:
insert into zsj_logstdby_progress
select sysdate gather_time,p.applied_scn,p.APPLIED_TIME,p.LATEST_SCN,p.LATEST_TIME,p.MINING_SCN,p.MINING_TIME from v$logstdby_progress p;
每5分钟从os端调用执行一次.
其实我原来认为那段时间日志应用缓慢很可能是因为晚上12点开始执行的一系列统计更新的job造成的呢,因为这台数据库主库的一个特点就是一般晚上要比白天负载高,因为晚上从12点开始要有一系列的统计更新的job执行,而且很多的静态发布是在晚上执行的.但查看zsj_logstdby_progress这个表数据的时候,发现不是这样的,应该不是因为晚上12点开始执行的一系列job造成的(其实细想也是这样的,那一系列job要统计信息也要更新表,是从12点开始执行的,有12点开始执行的,也有1点,2点,3点,4点,5点执行的,而前面检测日志应用缓慢的脚本是每2个小时执行一次的,它2:15的时候发现有日志应用延迟超过2小时的,那么这个缓慢是12点之前就开始的可能性是很大的),从主库时间23:43:16开始applied_time很长时间都不进行下去了,而这个时间是我的一个package差不多要执行完的时间.我查看了一下我的package执行的日志记录,从时间序列上来看,确定很可能是这样的代码引起的:
dbms_application_info.set_module(module_name => null,action_name => null);
EXECUTE IMMEDIATE 'truncate table queryproductresult';
INSERT INTO queryproductresult(CATALOGID,BRANDID,SERIESID,PRICEID,SCATALOGITEMS,PRODUCTCOUNT,COUNTTIME,ID,PAGEURL,NEWPAGEURL)
SELECT CATALOGID,BRANDID,SERIESID,PRICEID,SCATALOGITEMS,PRODUCTCOUNT,COUNTTIME,ID,PAGEURL,NEWPAGEURL
FROM queryproductresult_app2;
COMMIT; --把数据填充进正式表里去
mark_del_newpageurl();
error_alert(v_publish_start_date);
INSERT INTO publish_log(id,message) VALUES(seq_publish_log_id.NEXTVAL,'pack_publish.main end');
COMMIT;
很可能是因为这里的insert into queryproductresult引起的,虽然说我也有些怀疑,因为它这里只是插入数据呀,而且queryproductresult这个表主键id,业务上的唯一索引都有的呀,按说不应该是因为它呀,但我当时也没有细想,还是决定对它做些什么:
这个表只是我这里truncate之后一次性的插入数据,然后,静态发布的一些应用读取这个表数据,也就是说只是我这里对它进行dml操作的,所以我决定从逻辑从库端skip过它:
ALTER DATABASE STOP LOGICAL STANDBY APPLY;
execute dbms_logstdby.skip (stmt => 'DML',schema_name => 'PRODUCTUSER', object_name => 'QUERYPRODUCTRESULT');
execute dbms_logstdby.skip (stmt => 'SCHEMA_DDL',schema_name => 'PRODUCTUSER', object_name => 'QUERYPRODUCTRESULT');
ALTER DATABASE START LOGICAL STANDBY APPLY IMMEDIATE;
然后每天定时执行:
ALTER DATABASE STOP LOGICAL STANDBY APPLY;
execute dbms_logstdby.instantiate_table('PRODUCTUSER','QUERYPRODUCTRESULT','DB_231_MSPDB_PRODUCTUSER');
ALTER DATABASE START LOGICAL STANDBY APPLY IMMEDIATE;
重新初始化数据的,可这样存在一些问题,我这里每次都要stop/start LSP进程,这样操作失败的风险在增大,而且它这里instantiate_table 实际上是在drop掉原来的对象后重新创建一个同名的对象,使用impdp导入的,所以每次这个对象都变成unskip的了,我这里为了确保不出现问题,在instantiate_table之后还得再执行一个skip操作.所以决定不采取这个操作了,而是一次性的skip掉数据之后,手工的通过db link插入数据了:
sqlplus -s /nolog<<DBAEOF
connect username/password
truncate table queryproductresult;
insert into queryproductresult select * from queryproductresult@db_231_mspdb_productuser;
commit;
exit;
DBAEOF
至于这个代码执行的时间点,必须在主库端执行完上面的代码之后才能执行的,因为我这个package是11点开始执行的,12点之前肯定可以执行完的,所以现在就按12点执行吧,如果真的是因为这个操作引起的,具体什么时间点执行到时候再想吧,肯定是要在那段代码执行完之后,而不能按经验说12点就肯定可以执行了,不过这是后话了,我得先确定日志应用缓慢是不是因为这个操作引起的再想了,所以这次就按12点执行了.同时每5分钟执行一次的监控日志应用进度的代码仍然执行着.
第二天,发现那个时间点日志应用还是缓慢,这也解除了我心中的困惑,怎么可能是因为insert操作导致的问题呢,按说日志应用缓慢很可能是因为delete,update这样的一些操作引起的,看来只能继续查看代码了.
error_alert(v_publish_start_date);这段代码是计算的过程中出现问题的话,发告警邮件的,和它应该是没有关系的,而mark_del_newpageurl()很可能是存在问题的,这个sub过程定义如下:
procedure mark_del_newpageurl
is
begin
insert into qpresult_pageurl_this(NEWPAGEURL) select NEWPAGEURL from queryproductresult;
delete from qpresult_pageurl_del;
insert into qpresult_pageurl_del(NEWPAGEURL)
select a.NEWPAGEURL
from qpresult_pageurl_last a,qpresult_pageurl_this b
where a.newpageurl=b.newpageurl(+) and b.newpageurl is null;
delete from qpresult_pageurl_last;
insert into qpresult_pageurl_last(NEWPAGEURL) select NEWPAGEURL from qpresult_pageurl_this;
delete from qpresult_pageurl_this;
commit;
end;
这三个表上都没有索引,都是只有一个url字段.数据量来说:
qpresult_pageurl_del 基本上就是4,5百的数据量
qpresult_pageurl_this,qpresult_pageurl_last 55W左右的数据.
这样delete from qpresult_pageurl_last;在逻辑从库端sql应用的时候,会变成delete from qpresult_pageurl_last where newpageurl=:1的语句执行55W次,而因为newpageurl上没有索引,就变成了这个表的全表扫描要执行55W次,虽说这个表不是很大吧,但55W次的全表扫描肯定会带来性能上的问题的,delete from qpresult_pageurl_this;这个也是同样的问题.
而且从日志应用延迟时间来看,实际上是有两个主库端的时间点上应用缓慢的,23:43:29和23:43:37,这两个时间点和这两个delete操作正好是对应的.不过最好还是使用日志挖掘确认一下这个问题吧:
从日志应用延迟的时间点上确认了两个日志文件(实际上那个时间点主库redo操作量并不大)
sys@MSPDB> alter session set nls_language=american;
Session altered.
sys@MSPDB> begin
2 sys.dbms_logmnr.add_logfile('/home1/archivelog/mspdb/702819540_42589_1.log',sys.dbms_logmnr.NEW);
3 sys.dbms_logmnr.add_logfile('/home1/archivelog/mspdb/702819540_42590_1.log',sys.dbms_logmnr.ADDFILE);
4 sys.dbms_logmnr.start_logmnr(options => sys.dbms_logmnr.dict_from_online_catalog);
5 end;
6 /
PL/SQL procedure successfully completed.
sys@MSPDB> create table productuser.zhaosj_logmnr
as select L.SCN,L.TIMESTAMP,L.SEG_OWNER,L.SEG_NAME,L.SEG_TYPE_NAME,L.TABLE_NAME,ROLLBACK,OPERATION,SQL_REDO
from v$logmnr_contents L;
Table created.
--这里zhaosj_%是逻辑从库端skip掉的
sys@MSPDB> sys@MSPDB> exec sys.dbms_logmnr.end_logmnr();
PL/SQL procedure successfully completed.
select * from zhaosj_logmnr
where timestamp between to_date('2010-12-02 23:43:28','yyyy-mm-dd hh24:mi:ss') and to_date('2010-12-02 23:43:30','yyyy-mm-dd hh24:mi:ss');
SQL_REDO
delete from "PRODUCTUSER"."QPRESULT_PAGEURL_LAST" where "NEWPAGEURL" = '/controlsystem/5000/hedong/' and ROWID = 'AAATUVAATAAAYGHAAI';
发现都是这样的sql语句.
另一个时间点都是这样的语句:
delete from "PRODUCTUSER"."QPRESULT_PAGEURL_THIS" where "NEWPAGEURL" = '/notebookpc/6000/500gb/14yingcun/penryn/asus/' and ROWID = 'AAATUWAATAAAYVfABU';
select seg_name,seg_type_name,operation,count(1)
from zhaosj_logmnr
where timestamp between to_date('2010-12-02 23:43:20','yyyy-mm-dd hh24:mi:ss') and to_date('2010-12-02 23:43:45','yyyy-mm-dd hh24:mi:ss')
group by seg_name,seg_type_name,operation
order by 4 desc;
SEG_NAME SEG_TYPE_NAME OPERATION COUNT(1)
-------------------------------------------------------------------------------- -------------------------------- -------------------------------- ----------
QPRESULT_PAGEURL_LAST TABLE INSERT 556103
QPRESULT_PAGEURL_THIS TABLE DELETE 556103
QPRESULT_PAGEURL_LAST TABLE DELETE 555807
INTERNAL 4510
START 1751
COMMIT 1680
BQ TABLE DELETE 1645
QPRESULT_PAGEURL_DEL TABLE INSERT 106
ROLLBACK 73
DPI SAVEPOINT 23
PRODUCT_VS_PRODUCT TABLE UPDATE 4
PRODUCT_VS_PRODUCT TABLE INSERT 2
JOB$ TABLE UPDATE 1
PUBLISH_LOG TABLE INSERT 1
14 rows selected
基本上可以确认是这两个delete语句引发的问题了.
所以这次就在逻辑从库端把qpresult_pageurl_last,qpresult_pageurl_this这两个表给skip掉了,不通过sql应用维护了,因为其实这两个表只是我这里使用的两个临时表,应用上根本就不会用到的,应用上使用的只有qpresult_pageurl_del这个表,同时把queryproductresult unskip了,不再通过前面的代码维护,而仍然使用sql应用来维护了,这样根本就不需要考虑什么时候同步数据的问题了.
第二天,检查zsj_logstdby_progress表,发现基本上不存在日志应用延迟的问题了,看来确实是这两个没有索引的表的delete操作引发的日志应用延迟.
同时主库端进行了如下的操作:
create index ind1_qpresult_pageurl_del on qpresult_pageurl_del(newpageurl);
需要sql应用维护的表加上索引,这样如果数据量多了,性能上也不会太差的
同时修改了包的代码,将一些delete改成truncate:
procedure mark_del_newpageurl
is
begin
insert into qpresult_pageurl_this(NEWPAGEURL) select NEWPAGEURL from queryproductresult;
delete from qpresult_pageurl_del;
insert into qpresult_pageurl_del(NEWPAGEURL)
select a.NEWPAGEURL
from qpresult_pageurl_last a,qpresult_pageurl_this b
where a.newpageurl=b.newpageurl(+) and b.newpageurl is null;
execute immediate 'truncate table qpresult_pageurl_last';
insert into qpresult_pageurl_last(NEWPAGEURL) select NEWPAGEURL from qpresult_pageurl_this;
execute immediate 'truncate table qpresult_pageurl_this';
end;
qpresult_pageurl_last,qpresult_pageurl_this 都只是我这里使用的中间表,应用根本就不访问的,所以直接truncate了.
qpresult_pageurl_del 应用还是访问的,并且就是几百的数据行,也加上了索引,所以就不变了.
其实说到这个包,这是我不多的几个觉得写得还有些技术含量的东西,这里自己手工拆分任务,通过job来并行完成计算过程,把多个CPU都充分利用起来;虽然是拼装组合的sql(这个是由早期的产品设计决定的,也是没有办法),但仍然通过dbms_sql包使用了绑定变量,大大减少了分析相关的执行时间及可能带来的问题;根据应用的特点使用了递归算法(工作这几年,印象中实际工作中使用到递归算法的好像只有两次,除了这次,就是很早的时候,因为行列转换,而且行列转换的次数是不确定的,那次也使用了递归算法,其它好像就没用过了),使得原来java程序2,3个小时都计算不完的工作半个小时就计算完了,而且这里最重要的一点是产品人员多加一个筛选条件,我这里就可能多出几十w,几百w甚至几千W的计算量,也就是多出这么多次的sql执行量(这个和产品设计有关),但即使是那样,这个包运行也一年了,执行时间最多也就是现在,45分钟而已.
可真没有想到却会因为这段前不久加上去的代码给逻辑从库带来这么大的影响,确实因为逻辑从库sql应用维护的特点,在主库端执行没有任何问题的sql语句,都可能给逻辑从库带来很大的影响的,所以有了逻辑从库之后,主库端的操作确实需要注意了.
在这个逻辑从库真的上了应用之前,和开发人员商量又跳过了一些逻辑从库应用不需要的表.而且规定新建的表都必须有主键(虽说对于关系型数据库来说,这个要求再合理不过了,但实际应用中可能不是这样去实施的),所有临时使用的表都必须以temp_data_开头(逻辑从库端跳过temp_data_%的对象的sql应用维护).
但在测试静态发布的应用的时候还是出了点儿问题,报错:
ORA-16224: Database Guard is enabled
ORA-06512: at "PRODUCTUSER.BATCHPUBLISHPRODUCT_BYCIDS", line 56
ORA-06512: at line 1
发现是这样的代码:
INSERT INTO pq(id,productid,ptt,priority,inputdate)
VALUES (pqid.NEXTVAL,cp.id,v_type,0,SYSDATE);
pq这样的发布队列表,逻辑从库端确实skip过了,但pqid这样的主键序列却没有skip,将这样的序列skip之后,静态发布的应用就没有问题了.
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
