log file switch (checkpoint incomplete)

早上开发的过来找我，说连接内网测试库的时候特别慢，偶尔还会超时
我ping了一下网络，没有问题
登录到机器上，直接sqlplus连接，同样的连接很慢
查看了一下CPU和负载信息，没有问题
检查了监听，监听日志，DNS/hosts解析，也没有问题
用strace跟踪sqlplus连接，也没有发现异常
iostat查看了一下磁盘IO，发现sdb1 的IO很高，那连接慢，估计就是因为IO高导致的
因为最开始只看了CPU和load的信息，检查没问题后就没有关注 IO的情况，导致我在处理问题的思路上偏离了，以后一定要注意全面的性能状态检查

[root@dg_135 test11g]# iostat -xm 1
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           3.00    0.00    1.33    8.58    0.00   87.08
Device:         rrqm/s   wrqm/s   r/s   w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdb               0.00   468.00  0.00 65.00     0.00     2.09    65.72     2.70   41.78  15.40 100.10
sdb1              0.00   468.00  0.00 65.00     0.00     2.09    65.72     2.70   41.78  15.40 100.10

[root@dg_135 test11g]# echo 1 > /proc/sys/vm/block_dump 
[root@dg_135 test11g]# dmesg -c
[root@dg_135 test11g]# dmesg 
oracle(12526): WRITE block 29391128 on sdb1
oracle(12528): WRITE block 13166438704 on sdb1
oracle(12528): WRITE block 13166438712 on sdb1
oracle(12528): WRITE block 13166438896 on sdb1
oracle(12528): WRITE block 13166438904 on sdb1
oracle(12526): WRITE block 29391376 on sdb1
oracle(12526): WRITE block 29391384 on sdb1
oracle(12528): WRITE block 13166439088 on sdb1
oracle(12528): WRITE block 13166439096 on sdb1
oracle(12526): WRITE block 29391440 on sdb1
oracle(12526): WRITE block 29391448 on sdb1
oracle(12528): WRITE block 13166439280 on sdb1
oracle(12528): WRITE block 13166439288 on sdb1
oracle(12526): WRITE block 29391536 on sdb1
oracle(12526): WRITE block 29391544 on sdb1
oracle(12526): WRITE block 29391824 on sdb1
oracle(12526): WRITE block 29391832 on sdb1
oracle(12528): WRITE block 13166439472 on sdb1
oracle(12528): WRITE block 13166439480 on sdb1
oracle(12526): WRITE block 29393648 on sdb1
oracle(12526): WRITE block 29393656 on sdb1
oracle(12528): WRITE block 13166439664 on sdb1
oracle(12528): WRITE block 13166439672 on sdb1
oracle(12532): WRITE block 12997365808 on sdb1
oracle(12532): WRITE block 12997365816 on sdb1
oracle(12532): WRITE block 12997627920 on sdb1
oracle(12532): WRITE block 12997627928 on sdb1
oracle(12532): WRITE block 13107553176 on sdb1
oracle(12532): WRITE block 13107553184 on sdb1
oracle(12532): WRITE block 13107553192 on sdb1
oracle(12532): WRITE block 13107553200 on sdb1
oracle(12532): WRITE block 13108829472 on sdb1
oracle(12532): WRITE block 13108829480 on sdb1
oracle(12532): WRITE block 13108829488 on sdb1
oracle(12532): WRITE block 13108829496 on sdb1
oracle(12528): WRITE block 13166439856 on sdb1
oracle(12528): WRITE block 13166439864 on sdb1
oracle(12526): WRITE block 29393904 on sdb1
oracle(12526): WRITE block 29393912 on sdb1
oracle(12528): WRITE block 13166440048 on sdb1
oracle(12528): WRITE block 13166440056 on sdb1
oracle(12528): WRITE block 13166440240 on sdb1
oracle(12528): WRITE block 13166440248 on sdb1
oracle(12526): WRITE block 29394032 on sdb1
oracle(12526): WRITE block 29394040 on sdb1
oracle(12528): WRITE block 13166440432 on sdb1
oracle(12528): WRITE block 13166440440 on sdb1
oracle(12528): WRITE block 13166440624 on sdb1
oracle(12528): WRITE block 13166440632 on sdb1
bash(15036): dirtied inode 5013587 (dmesg) on sda2
。。。。。
。。。。。
。。。。。
+++发现有三个进程对sdb1的写操作很频繁
这个系统上跑了两个实例
查一下这三个进程是属于哪个instance的

[root@dg_135 ~]# ps aux | grep 12532
oracle   12532  0.0  0.7 15943360 515448 ?     Ss   May05   1:35 ora_ckpt_test11g
root     15038  0.0  0.0  61168   768 pts/1    S+   11:39   0:00 grep 12532
[root@dg_135 ~]# ps aux | grep 12528
oracle   12528  0.0 11.6 15971760 7706536 ?    Ds   May05   2:41 ora_dbw1_test11g
root     15046  0.0  0.0  61168   768 pts/1    S+   11:39   0:00 grep 12528
[root@dg_135 ~]# ps aux | grep 12526
oracle   12526  0.0 10.0 15971760 6623084 ?    Ds   May05   1:48 ora_dbw0_test11g
root     15058  0.0  0.0  61168   768 pts/1    S+   11:40   0:00 grep 12526
[root@dg_135 ~]# 

发现都是instance为test11g的库，ckpt和dbwr进程
检查等待事件和active的sql
SQL> select a.sql_text,b.MACHINE,b.event 
from v$sqlarea a,v$session b 
where a.sql_id = b.sql_id and status='ACTIVE' and username <>'SYS' and username is not null;
SQL_TEXT
--------------------------------------------------------------------------------
MACHINE
----------------------------------------------------------------
EVENT
----------------------------------------------------------------
update users set passwd=:1, email=:2, email_verified=:3, mobile=:4, mobile_verified=:5
hadoop-tasktracker-datanode-83
log file switch (checkpoint incomplete)
update users set passwd=:1, email=:2, email_verified=:3, mobile=:4, mobile_verif
ied=:5 where id=:6
hadoop-tasktracker-datanode-83
enq: TX - row lock contention

发现有大量的session在update 这个users表，而且是没有where条件的update，当然还有很多其他的DML操作，但是属于正常的操作
log file switch (checkpoint incomplete)这个等待事件，可能是因为事务繁忙，redo产生过快，日志文件过小，或者dbwr写太慢导致的
我觉得我这里应该是由于内网机器的磁盘IO本身就不好，又因为update大表导致产生大量redo
并且这套数据库系统是DG环境，为了测试读写分离而搭建的，有2个物理备库，最高可用模式，采用lgwr模式传输日志
SQL> col dest_name for a30
SQL> col error for a20
SQL> select dest_name,status,error,target,process from v$archive_dest where substr(dest_name,-1) in (1,2,3);

DEST_NAME                      STATUS    ERROR                TARGET  PROCESS
------------------------------ --------- -------------------- ------- ----------
LOG_ARCHIVE_DEST_1             VALID                          PRIMARY ARCH
LOG_ARCHIVE_DEST_2             VALID                          STANDBY LGWR
LOG_ARCHIVE_DEST_3             VALID                          STANDBY LGWR

暂时关掉2和3的归档
SQL> alter system set LOG_ARCHIVE_DEST_state_2=defer;

System altered.

SQL> alter system set LOG_ARCHIVE_DEST_state_3=defer;

System altered.

SQL> select dest_name,status,error,target,process from v$archive_dest where substr(dest_name,-1) in (1,2,3);

DEST_NAME                      STATUS    ERROR                TARGET  PROCESS
------------------------------ --------- -------------------- ------- ----------
LOG_ARCHIVE_DEST_1             VALID                          PRIMARY ARCH
LOG_ARCHIVE_DEST_2             DEFERRED                       STANDBY LGWR
LOG_ARCHIVE_DEST_3             DEFERRED                       STANDBY LGWR

检查redolog，发现所有的组，除了current，其他的全部处于active状态
SQL> select status from v$log;

STATUS
----------------
ACTIVE
CURRENT
ACTIVE
ACTIVE

status一直处于这个状态，update的等待事件一直是log file switch (checkpoint incomplete)

手工加了几个日志组：
SQL> alter database add logfile '/tol/oradata/test11g/redo07.log' size 1000m;

Database altered.

SQL> alter database add logfile '/tol/oradata/test11g/redo08.log' size 1000m;

Database altered.

SQL> alter database add logfile '/tol/oradata/test11g/redo09.log' size 1000m;

Database altered.

SQL> alter database add logfile '/tol/oradata/test11g/redo10.log' size 1000m;

Database altered.

SQL> select status from v$log;

STATUS
----------------
ACTIVE
ACTIVE
ACTIVE
ACTIVE
CURRENT
UNUSED
UNUSED
UNUSED

8 rows selected.

联系开发的，说可能是在程序中，sql写错了，本来update是要加条件了
打算kill掉这些session
SQL> alter system kill session '896,4075';

System altered.

SQL> alter system kill session '1151,282';

System altered.

SQL> alter system kill session '1023,2608';

System altered.

SQL> alter system kill session '1165,394';

System altered.
。。。。。
。。。。。

kill完，事务需要回滚，还是会占用很大的IO
等了差不多半个小时，IO还是持续很高
奇怪的是，redolog的status一直处于active
SQL> select status from v$log;

STATUS
----------------
ACTIVE
ACTIVE
ACTIVE
ACTIVE
CURRENT
ACTIVE
ACTIVE
ACTIVE

8 rows selected.

是因为IO太慢，还是dbwr进程有问题
决定冒险重启一下数据库看看（因为这里是内网测试库，如果是生产环境，不能这么草率重启）

SQL> shut abort
ORACLE instance shut down.

SQL> startup
ORA-32004: obsolete or deprecated parameter(s) specified for RDBMS instance
ORACLE instance started.

Total System Global Area 1.6034E+10 bytes
Fixed Size                  2219552 bytes
Variable Size            4630512096 bytes
Database Buffers         1.1341E+10 bytes
Redo Buffers               60084224 bytes
Database mounted.
ORA-03113: end-of-file on communication channel
Process ID: 31701
Session ID: 764 Serial number: 3

alter日志信息：
Thu May 08 12:19:09 2014
ALTER DATABASE   MOUNT
Successful mount of redo thread 1, with mount id 998909821
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Thu May 08 12:19:17 2014
ALTER DATABASE OPEN
Beginning crash recovery of 1 threads
 parallel recovery started with 11 processes
All no-data-loss archivelog destinations have been invalidated
All no-data-loss archivelog destinations have been removed
Started redo scan
Thu May 08 12:19:33 2014
Completed redo scan
 read 1207302 KB redo, 53816 data blocks need recovery
Thu May 08 12:19:47 2014
Started redo application at
 Thread 1: logseq 9518, block 23
Recovery of Online Redo Log: Thread 1 Group 8 Seq 9518 Reading mem 0
  Mem# 0: /tol/oradata/test11g/redo10.log
Recovery of Online Redo Log: Thread 1 Group 5 Seq 9519 Reading mem 0
  Mem# 0: /tol/oradata/test11g/redo05.log
Recovery of Online Redo Log: Thread 1 Group 6 Seq 9520 Reading mem 0
  Mem# 0: /tol/oradata/test11g/redo06.log
Thu May 08 12:20:00 2014
Recovery of Online Redo Log: Thread 1 Group 9 Seq 9521 Reading mem 0
  Mem# 0: /tol/oradata/test11g/redo11.log
Completed redo application of 730.51MB

Thu May 08 12:28:43 2014
Completed crash recovery at
 Thread 1: logseq 9521, block 373734, scn 9992550063
 53816 data blocks read, 46589 data blocks written, 1207302 redo k-bytes read
Thu May 08 12:28:49 2014
LGWR: STARTING ARCH PROCESSES
Thu May 08 12:28:49 2014
ARC0 started with pid=30, OS id=1515 
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Thu May 08 12:28:50 2014
ARC1 started with pid=31, OS id=1517 
Thu May 08 12:28:50 2014
ARC2 started with pid=32, OS id=1519 
ARC1: Archival started
Thu May 08 12:28:50 2014
ARC3 started with pid=33, OS id=1521 
ARC2: Archival started
ARC2: Becoming the 'no FAL' ARCH
ARC2: Becoming the 'no SRL' ARCH
ARC1: Becoming the heartbeat ARCH
LGWR: Primary database is in MAXIMUM AVAILABILITY mode
LGWR: Destination LOG_ARCHIVE_DEST_1 is not serviced by LGWR
LGWR: Minimum of 1 LGWR standby database required
Errors in file /opt/app/oracle/test11g/diag/rdbms/test11g_135/test11g/trace/test11g_lgwr_31684.trc:
ORA-16072: a minimum of one standby database destination is required
Errors in file /opt/app/oracle/test11g/diag/rdbms/test11g_135/test11g/trace/test11g_lgwr_31684.trc:
ORA-16072: a minimum of one standby database destination is required
LGWR (ospid: 31684): terminating the instance due to error 16072
Instance terminated by LGWR, pid = 31684

由于是最高可用模式，这些我把2和3的归档路径都defer了，导致LGWR进程终止了实例

SQL> startup mount
ORA-24324: service handle not initialized
ORA-01041: internal error. hostdef extension doesn't exist
SQL> conn / as sysdba
Connected to an idle instance.
SQL> startup mount
ORA-32004: obsolete or deprecated parameter(s) specified for RDBMS instance
ORACLE instance started.

Total System Global Area 1.6034E+10 bytes
Fixed Size                  2219552 bytes
Variable Size            4630512096 bytes
Database Buffers         1.1341E+10 bytes
Redo Buffers               60084224 bytes
Database mounted.

先把库设置为最大性能模式
SQL> alter database set standby database to maximize performance;

Database altered.

SQL> alter database open;

Database altered.

alter日志信息：
ALTER DATABASE   MOUNT
Successful mount of redo thread 1, with mount id 998936590
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Thu May 08 12:30:22 2014
alter database set standby database to maximize performance
Completed: alter database set standby database to maximize performance
alter database open
Thu May 08 12:30:30 2014
LGWR: STARTING ARCH PROCESSES
Thu May 08 12:30:30 2014
ARC0 started with pid=19, OS id=2170 
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Thu May 08 12:30:31 2014
ARC1 started with pid=20, OS id=2172 
Thu May 08 12:30:31 2014
ARC2 started with pid=21, OS id=2174 
ARC1: Archival started
Thu May 08 12:30:31 2014
ARC3 started with pid=22, OS id=2176 
ARC2: Archival started
ARC2: Becoming the 'no FAL' ARCH
ARC2: Becoming the 'no SRL' ARCH
ARC1: Becoming the heartbeat ARCH
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
Thread 1 advanced to log sequence 9522 (thread open)
Thread 1 opened at log sequence 9522
  Current log# 10 seq# 9522 mem# 0: /tol/oradata/test11g/redo12.log
Successful open of redo thread 1
Thu May 08 12:30:36 2014
SMON: enabling cache recovery
Thu May 08 12:30:41 2014
Successfully onlined Undo Tablespace 2.
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is UTF8
Thu May 08 12:30:41 2014
Archived Log entry 8096 added for thread 1 sequence 9521 ID 0x331dda8e dest 1:
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Starting background process QMNC
Thu May 08 12:30:45 2014
QMNC started with pid=23, OS id=2180 
Completed: alter database open
Thu May 08 12:30:50 2014
db_recovery_file_dest_size of 200 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Thu May 08 12:30:51 2014
Starting background process CJQ0
Thu May 08 12:30:51 2014
CJQ0 started with pid=26, OS id=2194 

SQL> select status from v$log;

STATUS
----------------
INACTIVE
INACTIVE
INACTIVE
INACTIVE
INACTIVE
INACTIVE
INACTIVE
CURRENT

8 rows selected.

IO:
vg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.00    0.00    0.00    0.08    0.00   99.92

Device:         rrqm/s   wrqm/s   r/s   w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda5              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdb               0.00     8.00  0.00  4.00     0.00     0.05    24.00     0.01    3.25   2.25   0.90
sdb1              0.00     8.00  0.00  4.00     0.00     0.05    24.00     0.01    3.25   2.25   0.90

如果需要，删除多余的redolog，我这里保留了后来新加的redo
恢复2和3的归档路径状态，调整DG模式为MAXIMUM AVAILABILITY mode
SQL> alter system set log_archive_dest_state_2='enable';

System altered.

SQL> alter system set log_archive_dest_state_3='enable';

System altered.

SQL> shut immediate
Database closed.
Database dismounted.
ORACLE instance shut down.
SQL> startup mount
ORA-32004: obsolete or deprecated parameter(s) specified for RDBMS instance
ORACLE instance started.

Total System Global Area 1.6034E+10 bytes
Fixed Size                  2219552 bytes
Variable Size            4630512096 bytes
Database Buffers         1.1341E+10 bytes
Redo Buffers               60084224 bytes
Database mounted.
SQL> alter database set standby database to maximize availability;

Database altered.

SQL> alter database open;

Database altered

让开发的调整程序，update的sql加上where条件
后续观察系统性能

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

转载于:http://blog.itpub.net/23249684/viewspace-1156680/