[20230228]产生大量日志分析(生产系统日志分析).txt
[20230228]产生大量日志分析(生产系统日志分析).txt
--//生产系统优化已经基本完成,我发现这套系统日志产生非常大对比我以前管理优化类似的项目.
--//一直没时间，今天有空简单探究看看.
1.环境:
SYS@192.168.100.235:1521/orcl> @ pr
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 19.0.0.0.0
BANNER : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
BANNER_FULL : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
BANNER_LEGACY : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.问题提出:
SYS@192.168.100.235:1521/orcl> @ ashtop event 1=1 &day
Total Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps
--------- ------- ------- ---------------------------- ------------------- ------------------- ---------- --------
16362 .2 51% | 2023-02-26 10:48:20 2023-02-27 10:47:57 8620 14724
3584 .0 11% | log file sync 2023-02-26 10:48:12 2023-02-27 10:48:07 1 2799
3214 .0 10% | log file parallel write 2023-02-26 10:48:12 2023-02-27 10:48:07 1 2738
2874 .0 9% | RMAN backup & recovery I/O 2023-02-26 23:53:59 2023-02-27 02:31:08 1 2862
2718 .0 8% | db file sequential read 2023-02-26 10:48:41 2023-02-27 10:47:54 1769 2614
893 .0 3% | db file parallel read 2023-02-26 10:49:56 2023-02-27 10:48:08 514 877
--//log file sync 排在第一,log file parallel write第2,说明写入redo很多.
--//RMAN 备份主要原因是增量备份没有打开块跟踪,以及archive log重复备份的问题.
SYS@192.168.100.235:1521/orcl> @ d_arc
DATE WEEK SIZE_MB NUMBER_OF_SWITCHES_PER_DAY
------------- ------------- ---------- --------------------------
2023-02-27 09 MONDAY 2984 6 --//当天
2023-02-26 09 SUNDAY 4381 8
2023-02-25 08 SATURDAY 5488 10
2023-02-24 08 FRIDAY 6773 11
2023-02-23 08 THURSDAY 7236 12
2023-02-22 08 WEDNESDAY 7832 12
2023-02-21 08 TUESDAY 7978 12
2023-02-20 08 MONDAY 6940 11
2023-02-19 08 SUNDAY 4293 8
2023-02-18 07 SATURDAY 5216 9
...
--//可以看出每天正常业务基本在6G上下.实际上以前类似系统仅仅1.XG上下(顺便说一下当时系统日志实际上还是偏大的).对比几乎增加
--//4-5倍.实际上我提出来团队的人根本不当一回事.
--//我仔细看了redo dump,日志的产生主要集中在表LIS.LIS_RESULT.仔细查看我才发现开发编程上的问题.开发太不了解oracle数据库了.
--//一些细节慢慢展开....
3.分析:
SYS@192.168.100.235:1521/orcl> @ cs lis
alter session set current_schema=lis
Session altered.
$ cat aa1.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
--select current_scn-1e4 scn1 from v$database;
select id,max(item_id) item_id from LIS_RESULT where id = (select max(id) from LIS_RESULT ) group by id;
host sleep &&1
--select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result.id
,lis_result.item_id
--FROM LIS_RESULT VERSIONS BETWEEN scn &v_scn1 and &v_scn2
FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id and item_id = &&v_item_id
-- order by VERSIONS_STARTSCN
;
--//注:选择sleep N一定时间,可能是IMU导致的情况,如果输入0可能出现看不到update的执行.
--//正常情况选择3秒比较稳妥.
--//另外说明字段id,item_id组成主键.
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:07:46. 0C001E00889B1E00 U 44616129592 26961471 7075
2023-03-01 09:07:46. 2023-03-01 09:07:46. 08001F0043E61600 I 44616129291 44616129592 26961471 7075
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:07:52. 0C000A00909B1E00 U 44616131159 26961475 3791
2023-03-01 09:07:49. 2023-03-01 09:07:52. 0C000F00EF9A1E00 I 44616130857 44616131159 26961475 3791
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:08:49. 02000100EDE51300 U 44616150499 26961554 7436
2023-03-01 09:08:46. 2023-03-01 09:08:49. 05000B0042F01500 I 44616150170 44616150499 26961554 7436
--//相差3秒.
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:09:52. 0C001900379C1E00 U 44616170991 26961673 3431
2023-03-01 09:09:52. 2023-03-01 09:09:52. 0100110024371600 I 44616170950 44616170991 26961673 3431
--//看versions_operation列,先insert然后update,看VERSIONS_STARTTIME列几乎在同一个时间点完成或者相差3秒马上修改.
--//不知道3秒是否是IMU的影响.我执行许多次要么相差3秒,要么基本相差0.
--//修改如下,注解item_id = &&v_item_id.
$ cat aa1.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
select current_scn-1e4 scn1 from v$database;
select id,max(item_id) item_id from LIS_RESULT where id = (select max(id) from LIS_RESULT ) group by id;
host sleep &&1
select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result.id
,lis_result.item_id
FROM LIS_RESULT VERSIONS BETWEEN scn &v_scn1 and &v_scn2
-- FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id
--and item_id = &&v_item_id
order by versions_startscn
;
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226539 26961902 3429
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226536 26961902 3428
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226527 26961902 3423
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226530 26961902 3425
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226542 26961902 3430
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226533 26961902 3427
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226548 26961902 3431
2023-03-01 09:12:59. 060014008F631600 U 44616226527 26961902 3423
2023-03-01 09:12:59. 08000E0059E61600 U 44616226530 26961902 3425
2023-03-01 09:12:59. 0C0008005E9C1E00 U 44616226533 26961902 3427
2023-03-01 09:12:59. 0A001B005CD61800 U 44616226536 26961902 3428
2023-03-01 09:12:59. 0C001400349D1E00 U 44616226539 26961902 3429
2023-03-01 09:12:59. 0C000000009D1E00 U 44616226542 26961902 3430
2023-03-01 09:12:59. 0C000900479D1E00 U 44616226548 26961902 3431
14 rows selected.
--//基本类似!!可以看出开发犯了一个错误,应该不要分2步完成业务的逻辑操作(先insert后update),这样几乎产生3倍的日志量.
--//insert的前image很少,仅仅包括rowdi,因为回滚是delete操作,仅仅需要知道rowid就ok了.
--//而update的前image,就是修改前的内容,后iamge是修改后的内容,这样产生的redo量很大.
--//如果先组织好数据,1次性插入完成操作,可以大大的减少redo的产生.
--//可以看出一个特点inert是批量插入,而update是一条一条update的,不知道我的这个判断是否正确?
--//查询共享池,发现update执行如下语句.
SYS@192.168.100.235:1521/orcl> @ sql_id dpmmf1c22cfx8
--SQL_ID = dpmmf1c22cfx8
UPDATE lis_result
SET item_sort = :item_sort
,item_name = :item_name
,item_name_cn = :item_name_cn
,item_code = :item_code
,neg_text = :neg_text
,item_ref_min = :item_ref_min
,item_ref_max = :item_ref_max
,item_flag = :item_flag
,item_flag_str = :item_flag_str
,crt_flag = :crt_flag
,RESULT_TIME = :RESULT_TIME
,his_flag = :his_flag
,his_result = :his_result
,his_result_time = :his_result_time
,tip_ratio = :tip_ratio
,item_method = :item_method
,test_inst_id = :test_inst_id
,Inst_Alam = :Inst_Alam
,print_grp = :print_grp
,item_result = :item_result
,result_symbol = :result_symbol
,item_result_text = :item_result_text
,item_remark = :item_remark
,item_od = :item_od
,item_sco = :item_sco
,cutt_of = :cutt_of
,ITEM_UNIT = :ITEM_UNIT
,ITEM_REF = :ITEM_REF
,item_result2 = :item_result2
,item_result3 = :item_result3
,item_result4 = :item_result4
,HIS_RESULT2 = :HIS_RESULT2
,HIS_RESULT_TIME2 = :HIS_RESULT_TIME2
,HIS_RESULT1 = :HIS_RESULT1
,HIS_RESULT_TIME1 = :HIS_RESULT_TIME1
,order_id = :order_id
,order_item_id = :order_item_id
,order_item_name = :order_item_name
,REPORT_NOT_PRINT = :REPORT_NOT_PRINT
,ITEM_FEE = :ITEM_FEE
,TEST_INST_NAME = :TEST_INST_NAME
,INPUT_TYPE = :INPUT_TYPE
,CHECK_FLAG = :CHECK_FLAG
,MSG_RESULT_MIN_MAX = :MSG_RESULT_MIN_MAX
,MSG_RESULT_FLAG = :MSG_RESULT_FLAG
,ORI_ITEM_RESULT = :ORI_ITEM_RESULT
,ORDER_NO = :ORDER_NO
,CRIT_REF = :CRIT_REF
WHERE id = :id AND item_id = :item_id;
--//注做了格式化处理!!
SYS@192.168.100.235:1521/orcl> @ d_bufferx dpmmf1c22cfx8 60 1
SQL_ID INST_ID MODULE EXECUTIONS CPU_TIME ELAPSED_TIME BUFFER_GETS ROWS_PROCESSED CPU_PER_EXEC ELAPSED_TIME_EXEC BUFFER_GETS_EXEC ROWS_PROCESSED_EXEC
------------- --------------- ------------ ---------- --------------- --------------- --------------- --------------- --------------- ----------------- ---------------- -------------------
dpmmf1c22cfx8 1 w3wp.exe 1200 109992 215504 7324 1200 91.66 179.59 6.10 1.00
--//1分钟里面执行1200次.
--//我不知道这样改进能减少多少redo的产生,不过效果应该不错.
3.看看日志转储的情况:
SYS@192.168.100.235:1521/orcl> @ o2 lis.lis_result
owner object_name object_type status OID D_OID CREATED LAST_DDL_TIME
----- ----------- ----------- --------- ----- ------ ------------------- -------------------
LIS LIS_RESULT TABLE VALID 73760 73760 2020-11-27 16:43:13 2023-02-20 20:48:04
$ cat dumpredo.sql
column member new_value v_member
column member noprint
set numw 12
--//pause alter system switch logfile ;
--//pause alter system archive log current;
--//12c不允许在pluggable database执行以上命令,可以在别的回话执行然后继续。
--//SELECT member FROM v$log a, v$logfile b WHERE a.group#(+) = b.group# and a.STATUS='CURRENT' and rownum=1;
column scn1 new_value v_scn1
column scn2 new_value v_scn2
select current_scn scn1 from v$database;
--//以下DML操作内容:
--//update t1 set small_vc = upper(small_vc);
--//commit ;
host sleep &&1
select current_scn scn2 from v$database;
--//prompt alter system dump logfile '&&v_member' scn min &&v_curr1 scn max &&v_curr2;
--//alter system dump logfile '&&v_member' scn min &&v_curr1 scn max &&v_curr2;
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 Objno 73760;
SYS@192.168.100.235:1521/orcl> @ dumpredo 20
SCN1
------------
44616387435
SCN2
------------
44616392839
System altered.
$ egrep "LEN.*VLD|OBJ:" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc > /tmp/aa1.txt
REDO RECORD - Thread:1 RBA: 0x00335f.0016ec2c.0010 LEN: 0x0330 VLD: 0x05 CON_UID: 0
CHANGE #1 CON_ID:0 TYP:0 CLS:25 AFN:4 DBA:0x010000c0 OBJ:4294967295 SCN:0x0000000a63580e9d SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
CHANGE #2 CON_ID:0 TYP:0 CLS:26 AFN:4 DBA:0x010668b2 OBJ:4294967295 SCN:0x0000000a63580e9c SEQ:3 OP:5.1 ENC:0 RBL:0 FLG:0x0000
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fafed OBJ:73760 SCN:0x0000000a63580f6f SEQ:1 OP:11.2 ENC:0 RBL:0 FLG:0x0000
REDO RECORD - Thread:1 RBA: 0x00335f.0016ec2f.0010 LEN: 0x055c VLD: 0x05 CON_UID: 0
CHANGE #1 CON_ID:0 TYP:0 CLS:39 AFN:4 DBA:0x01000118 OBJ:4294967295 SCN:0x0000000a63580f6c SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
CHANGE #2 CON_ID:0 TYP:0 CLS:40 AFN:4 DBA:0x010635d4 OBJ:4294967295 SCN:0x0000000a63580f6b SEQ:3 OP:5.1 ENC:0 RBL:0 FLG:0x0000
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fc26b OBJ:73760 SCN:0x0000000a6356dc28 SEQ:1 OP:11.5 ENC:0 RBL:0 FLG:0x0000
--//OP: 11.2 insert , 11.5 update.
--//insert产生日志长度在0x0330.
--//update产生日志长度在0x055c.
--//有点复杂,放弃!!
$ egrep "^CHANGE" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc | sed "s/^.*OP://" | awk '{print $1}'| sort | uniq -c | sort -nr
827 5.1
684 11.5
594 5.2
582 5.20
118 11.2
29 13.22
17 11.4
15 4.1
8 11.6
2 13.24
5.1修改undo header中的事务信息
5.2事务开始
5.4 commit
11.2插入一条数据
11.3删除一条数据
11.4锁定数据(select for update)
11.5更新记录
11.6行链接
$ perl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc
OBJECT_ID REDO_SIZE
73760 985712
NON-OBJECT REDO 4504
--//20秒,odbject_id=73760,产生了985712,接近1M.
--//修改:
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 Objno 73760;
--//为
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 ;
SYS@192.168.100.235:1521/orcl> @ dumpredo 20
SCN1
------------
44616972825
SCN2
------------
44616979192
System altered.
$ perl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_7455.trc | head
OBJECT_ID REDO_SIZE
73760 1766264
NON-OBJECT REDO 626700
194159 524444
73757 416740
195403 396376
73621 306072
214792 227400
74655 198564
215210 166736
.......
--//可以大部分对象是object_id=73760.
--//如果仅仅1个insert.至少减少一半的日志大小。.
--//如果你看update的相关日志:
REDO RECORD - Thread:1 RBA: 0x00335f.0016e66b.0010 LEN: 0x05c4 VLD: 0x05 CON_UID: 0
SCN: 0x0000000a63580c1c SUBSCN: 1 03/01/2023 09:22:18
CHANGE #1 CON_ID:0 TYP:0 CLS:21 AFN:4 DBA:0x010000a0 OBJ:4294967295 SCN:0x0000000a63580c05 SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
ktudh redo: slt: 0x0005 sqn: 0x0014dffb flg: 0x0012 siz: 660 fbi: 0
uba: 0x010080ac.034d.23 pxid: 0x0000.000.00000000
CHANGE #2 CON_ID:0 TYP:0 CLS:22 AFN:4 DBA:0x010080ac OBJ:4294967295 SCN:0x0000000a63580c04 SEQ:4 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 660 spc: 2410 flg: 0x0012 seq: 0x034d rec: 0x23
xid: 0x0003.005.0014dffb
ktubl redo: slt: 5 wrp: 1 flg: 0x0c08 prev dba: 0x00000000 rci: 0 opc: 11.1 [objn: 73760 objd: 73760 tsn: 8]
[Undo type ] Regular undo [User undo done ] No [Last buffer split] No
[Temp object] No [Tablespace Undo ] No [User only ] No
Begin trans
prev ctl uba: 0x010080ac.034d.1f prev ctl max cmt scn: 0x0000000a63580200
prev tx cmt scn: 0x0000000a63580233
txn start scn: 0xffffffffffffffff logon user: 106
prev brb: 0x010080aa prev bcl: 0x00000000
BuExt idx: 0 flg2: 0
KDO undo record:
KTB Redo
op: 0x04 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: L itl: xid: 0x000c.010.001e9637 uba: 0x01072687.17be.04
flg: C--- lkc: 0 scn: 0x0000000a634f990a
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x020fbcf1 hdba: 0x00801262
itli: 5 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15) flag: 0x2c lock: 0 ckix: 254
ncol: 56 nnew: 47 size: 13
col 3: [ 2] c1 46
...
col 55: [24]
00 31 00 5e 00 31 00 5e 00 32 00 35 00 31 00 39 00 37 00 34 00 35 00 31
--//后image
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fbcf1 OBJ:73760 SCN:0x0000000a63580c1a SEQ:1 OP:11.5 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x01 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0003.005.0014dffb uba: 0x010080ac.034d.23
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x020fbcf1 hdba: 0x00801262
itli: 5 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15) flag: 0x2c lock: 5 ckix: 254
ncol: 55 nnew: 46 size: -13
col 3: [ 2] c1 46
..
col 54: [ 8] 00 30 00 2e 00 31 00 30
--//前image
--//注意IMU是反过来的保存的!!
CHANGE #4 MEDIA RECOVERY MARKER CON_ID:0 SCN:0x0000000000000000 SEQ:0 OP:5.20 ENC:0 FLG:0x0000
session number = 31
serial number = 22815
transaction name =
version 318767104
audit sessionid 6720706
Client Id =
login username = LIS
(LWN RBA: 0x00335f.0016e66f.0010 LEN: 0x00000004 NST: 0x0001 SCN: 0x0000000a63580c1f)
--//看看object_id=194159.
SYS@192.168.100.235:1521/orcl> @ oid 194159
owner object_name object_type SUBOBJECT_NAME CREATED LAST_DDL_TIME status DATA_OBJECT_ID
----- --------------- ----------- -------------- ------------------- ------------------- --------- --------------
LIS LIS_RESULT_TEMP TABLE 2022-07-01 12:06:16 2022-10-20 11:16:17 VALID 194159
--//根据情况修改aa1.txt => aa2.txt,id是LIS_RESULT_TEMP的主键.
$ cat aa2.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
select current_scn-1e4 scn1 from v$database;
select max(id) id from LIS_RESULT_temp;
host sleep &&1
select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result_temp.id
FROM LIS_RESULT_TEMP VERSIONS BETWEEN scn &v_scn1 and &v_scn2
-- FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id
--and item_id = &&v_item_id
order by versions_startscn
;
SYS@192.168.100.235:1521/orcl> @ aa2.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:26:48. 2023-03-01 10:26:48. 0C00150016B41E00 I 44617508176 44617508212 219375442
2023-03-01 10:26:48. 04001A00E48F1400 U 44617508212 219375442
SYS@192.168.100.235:1521/orcl> @ aa2.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:26:54. 2023-03-01 10:26:54. 03000900C8E11400 I 44617509759 44617509775 219375476
2023-03-01 10:26:54. 0C0020000FB41E00 U 44617509775 219375476
--//^_^,一样的情况!!大致明白为什么会产生这样大的日志量,开发把数据库当作垃圾桶!!
--//再看另外一个对象73757.
SYS@192.168.100.235:1521/orcl> @oid 73757
owner object_name object_type SUBOBJECT_NAME CREATED LAST_DDL_TIME status DATA_OBJECT_ID
----- ---------------- ----------- -------------- ------------------- ------------------- --------- --------------
LIS LIS_ORDER_DETAIL TABLE 2020-11-27 16:43:13 2023-02-20 20:47:34 VALID 76018
SYS@192.168.100.235:1521/orcl> @ aa3.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:30:54. 2023-03-01 10:30:54. 0C000500E2B51E00 I 44617592015 44617592021 134648696
2023-03-01 10:30:54. 2023-03-01 10:30:54. 07000800C6F51400 U 44617592021 44617592059 134648696
2023-03-01 10:30:54. 0C0011005EB51E00 U 44617592059 134648696
SYS@192.168.100.235:1521/orcl> @ aa3.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:32:33. 2023-03-01 10:32:33. 0C000700A8B61E00 I 44617636753 44617636768 134650263
2023-03-01 10:32:33. 2023-03-01 10:32:33. 03000D0013E21400 U 44617636768 44617636886 134650263
2023-03-01 10:32:33. 0C00020093B61E00 U 44617636886 134650263
--//2次update!!到此,终于明白为什么这套系统日志比原来旧系统多很多的原因.
--//应该一次insert就完成的业务，开发写成insert+update来完成。
--//简单估算(0x0330+0x055c)/0x400 = 2.13671875，这样写日志至少增加1倍日志量。
4.附录:
--//脚本的来源当时没记录,也不知道是否可靠与正确.
$ cat /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl
# TDH 2008-09-26
# Analyses a formatted redo dump and
# summarises redo bytes by object.
#
my $current_object;
my $current_bytes;
my %object_bytes = ();
sub DescendingNum {
$object_bytes{$b} <=> $object_bytes{$a};
}
while (<>) {
if (/LEN: 0x([a-f0-9A-F]+) VLD/) {
if (defined($current_object)) {
$object_bytes{$current_object} += $current_bytes;
}
elsif (defined($current_bytes)) {
$object_bytes{"NON-OBJECT REDO"} += $current_bytes;
}
$current_bytes = hex($1);
$current_object = undef;
}
elsif (/objn: (\d+) objd/) {
$current_object = $1;
}
}
printf "%20s %40s\n","OBJECT_ID","REDO_SIZE";
foreach my $key (sort DescendingNum(keys(%object_bytes))) {
printf "%20s %40s\n",$key,$object_bytes{$key};
}
--//生产系统优化已经基本完成,我发现这套系统日志产生非常大对比我以前管理优化类似的项目.
--//一直没时间，今天有空简单探究看看.
1.环境:
SYS@192.168.100.235:1521/orcl> @ pr
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 19.0.0.0.0
BANNER : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
BANNER_FULL : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
BANNER_LEGACY : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.问题提出:
SYS@192.168.100.235:1521/orcl> @ ashtop event 1=1 &day
Total Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps
--------- ------- ------- ---------------------------- ------------------- ------------------- ---------- --------
16362 .2 51% | 2023-02-26 10:48:20 2023-02-27 10:47:57 8620 14724
3584 .0 11% | log file sync 2023-02-26 10:48:12 2023-02-27 10:48:07 1 2799
3214 .0 10% | log file parallel write 2023-02-26 10:48:12 2023-02-27 10:48:07 1 2738
2874 .0 9% | RMAN backup & recovery I/O 2023-02-26 23:53:59 2023-02-27 02:31:08 1 2862
2718 .0 8% | db file sequential read 2023-02-26 10:48:41 2023-02-27 10:47:54 1769 2614
893 .0 3% | db file parallel read 2023-02-26 10:49:56 2023-02-27 10:48:08 514 877
--//log file sync 排在第一,log file parallel write第2,说明写入redo很多.
--//RMAN 备份主要原因是增量备份没有打开块跟踪,以及archive log重复备份的问题.
SYS@192.168.100.235:1521/orcl> @ d_arc
DATE WEEK SIZE_MB NUMBER_OF_SWITCHES_PER_DAY
------------- ------------- ---------- --------------------------
2023-02-27 09 MONDAY 2984 6 --//当天
2023-02-26 09 SUNDAY 4381 8
2023-02-25 08 SATURDAY 5488 10
2023-02-24 08 FRIDAY 6773 11
2023-02-23 08 THURSDAY 7236 12
2023-02-22 08 WEDNESDAY 7832 12
2023-02-21 08 TUESDAY 7978 12
2023-02-20 08 MONDAY 6940 11
2023-02-19 08 SUNDAY 4293 8
2023-02-18 07 SATURDAY 5216 9
...
--//可以看出每天正常业务基本在6G上下.实际上以前类似系统仅仅1.XG上下(顺便说一下当时系统日志实际上还是偏大的).对比几乎增加
--//4-5倍.实际上我提出来团队的人根本不当一回事.
--//我仔细看了redo dump,日志的产生主要集中在表LIS.LIS_RESULT.仔细查看我才发现开发编程上的问题.开发太不了解oracle数据库了.
--//一些细节慢慢展开....
3.分析:
SYS@192.168.100.235:1521/orcl> @ cs lis
alter session set current_schema=lis
Session altered.
$ cat aa1.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
--select current_scn-1e4 scn1 from v$database;
select id,max(item_id) item_id from LIS_RESULT where id = (select max(id) from LIS_RESULT ) group by id;
host sleep &&1
--select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result.id
,lis_result.item_id
--FROM LIS_RESULT VERSIONS BETWEEN scn &v_scn1 and &v_scn2
FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id and item_id = &&v_item_id
-- order by VERSIONS_STARTSCN
;
--//注:选择sleep N一定时间,可能是IMU导致的情况,如果输入0可能出现看不到update的执行.
--//正常情况选择3秒比较稳妥.
--//另外说明字段id,item_id组成主键.
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:07:46. 0C001E00889B1E00 U 44616129592 26961471 7075
2023-03-01 09:07:46. 2023-03-01 09:07:46. 08001F0043E61600 I 44616129291 44616129592 26961471 7075
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:07:52. 0C000A00909B1E00 U 44616131159 26961475 3791
2023-03-01 09:07:49. 2023-03-01 09:07:52. 0C000F00EF9A1E00 I 44616130857 44616131159 26961475 3791
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:08:49. 02000100EDE51300 U 44616150499 26961554 7436
2023-03-01 09:08:46. 2023-03-01 09:08:49. 05000B0042F01500 I 44616150170 44616150499 26961554 7436
--//相差3秒.
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:09:52. 0C001900379C1E00 U 44616170991 26961673 3431
2023-03-01 09:09:52. 2023-03-01 09:09:52. 0100110024371600 I 44616170950 44616170991 26961673 3431
--//看versions_operation列,先insert然后update,看VERSIONS_STARTTIME列几乎在同一个时间点完成或者相差3秒马上修改.
--//不知道3秒是否是IMU的影响.我执行许多次要么相差3秒,要么基本相差0.
--//修改如下,注解item_id = &&v_item_id.
$ cat aa1.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
select current_scn-1e4 scn1 from v$database;
select id,max(item_id) item_id from LIS_RESULT where id = (select max(id) from LIS_RESULT ) group by id;
host sleep &&1
select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result.id
,lis_result.item_id
FROM LIS_RESULT VERSIONS BETWEEN scn &v_scn1 and &v_scn2
-- FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id
--and item_id = &&v_item_id
order by versions_startscn
;
SYS@192.168.100.235:1521/orcl> @ aa1.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID ITEM_ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------ ------------
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226539 26961902 3429
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226536 26961902 3428
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226527 26961902 3423
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226530 26961902 3425
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226542 26961902 3430
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226533 26961902 3427
2023-03-01 09:12:59. 2023-03-01 09:12:59. 0A001E00B1D61800 I 44616226517 44616226548 26961902 3431
2023-03-01 09:12:59. 060014008F631600 U 44616226527 26961902 3423
2023-03-01 09:12:59. 08000E0059E61600 U 44616226530 26961902 3425
2023-03-01 09:12:59. 0C0008005E9C1E00 U 44616226533 26961902 3427
2023-03-01 09:12:59. 0A001B005CD61800 U 44616226536 26961902 3428
2023-03-01 09:12:59. 0C001400349D1E00 U 44616226539 26961902 3429
2023-03-01 09:12:59. 0C000000009D1E00 U 44616226542 26961902 3430
2023-03-01 09:12:59. 0C000900479D1E00 U 44616226548 26961902 3431
14 rows selected.
--//基本类似!!可以看出开发犯了一个错误,应该不要分2步完成业务的逻辑操作(先insert后update),这样几乎产生3倍的日志量.
--//insert的前image很少,仅仅包括rowdi,因为回滚是delete操作,仅仅需要知道rowid就ok了.
--//而update的前image,就是修改前的内容,后iamge是修改后的内容,这样产生的redo量很大.
--//如果先组织好数据,1次性插入完成操作,可以大大的减少redo的产生.
--//可以看出一个特点inert是批量插入,而update是一条一条update的,不知道我的这个判断是否正确?
--//查询共享池,发现update执行如下语句.
SYS@192.168.100.235:1521/orcl> @ sql_id dpmmf1c22cfx8
--SQL_ID = dpmmf1c22cfx8
UPDATE lis_result
SET item_sort = :item_sort
,item_name = :item_name
,item_name_cn = :item_name_cn
,item_code = :item_code
,neg_text = :neg_text
,item_ref_min = :item_ref_min
,item_ref_max = :item_ref_max
,item_flag = :item_flag
,item_flag_str = :item_flag_str
,crt_flag = :crt_flag
,RESULT_TIME = :RESULT_TIME
,his_flag = :his_flag
,his_result = :his_result
,his_result_time = :his_result_time
,tip_ratio = :tip_ratio
,item_method = :item_method
,test_inst_id = :test_inst_id
,Inst_Alam = :Inst_Alam
,print_grp = :print_grp
,item_result = :item_result
,result_symbol = :result_symbol
,item_result_text = :item_result_text
,item_remark = :item_remark
,item_od = :item_od
,item_sco = :item_sco
,cutt_of = :cutt_of
,ITEM_UNIT = :ITEM_UNIT
,ITEM_REF = :ITEM_REF
,item_result2 = :item_result2
,item_result3 = :item_result3
,item_result4 = :item_result4
,HIS_RESULT2 = :HIS_RESULT2
,HIS_RESULT_TIME2 = :HIS_RESULT_TIME2
,HIS_RESULT1 = :HIS_RESULT1
,HIS_RESULT_TIME1 = :HIS_RESULT_TIME1
,order_id = :order_id
,order_item_id = :order_item_id
,order_item_name = :order_item_name
,REPORT_NOT_PRINT = :REPORT_NOT_PRINT
,ITEM_FEE = :ITEM_FEE
,TEST_INST_NAME = :TEST_INST_NAME
,INPUT_TYPE = :INPUT_TYPE
,CHECK_FLAG = :CHECK_FLAG
,MSG_RESULT_MIN_MAX = :MSG_RESULT_MIN_MAX
,MSG_RESULT_FLAG = :MSG_RESULT_FLAG
,ORI_ITEM_RESULT = :ORI_ITEM_RESULT
,ORDER_NO = :ORDER_NO
,CRIT_REF = :CRIT_REF
WHERE id = :id AND item_id = :item_id;
--//注做了格式化处理!!
SYS@192.168.100.235:1521/orcl> @ d_bufferx dpmmf1c22cfx8 60 1
SQL_ID INST_ID MODULE EXECUTIONS CPU_TIME ELAPSED_TIME BUFFER_GETS ROWS_PROCESSED CPU_PER_EXEC ELAPSED_TIME_EXEC BUFFER_GETS_EXEC ROWS_PROCESSED_EXEC
------------- --------------- ------------ ---------- --------------- --------------- --------------- --------------- --------------- ----------------- ---------------- -------------------
dpmmf1c22cfx8 1 w3wp.exe 1200 109992 215504 7324 1200 91.66 179.59 6.10 1.00
--//1分钟里面执行1200次.
--//我不知道这样改进能减少多少redo的产生,不过效果应该不错.
3.看看日志转储的情况:
SYS@192.168.100.235:1521/orcl> @ o2 lis.lis_result
owner object_name object_type status OID D_OID CREATED LAST_DDL_TIME
----- ----------- ----------- --------- ----- ------ ------------------- -------------------
LIS LIS_RESULT TABLE VALID 73760 73760 2020-11-27 16:43:13 2023-02-20 20:48:04
$ cat dumpredo.sql
column member new_value v_member
column member noprint
set numw 12
--//pause alter system switch logfile ;
--//pause alter system archive log current;
--//12c不允许在pluggable database执行以上命令,可以在别的回话执行然后继续。
--//SELECT member FROM v$log a, v$logfile b WHERE a.group#(+) = b.group# and a.STATUS='CURRENT' and rownum=1;
column scn1 new_value v_scn1
column scn2 new_value v_scn2
select current_scn scn1 from v$database;
--//以下DML操作内容:
--//update t1 set small_vc = upper(small_vc);
--//commit ;
host sleep &&1
select current_scn scn2 from v$database;
--//prompt alter system dump logfile '&&v_member' scn min &&v_curr1 scn max &&v_curr2;
--//alter system dump logfile '&&v_member' scn min &&v_curr1 scn max &&v_curr2;
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 Objno 73760;
SYS@192.168.100.235:1521/orcl> @ dumpredo 20
SCN1
------------
44616387435
SCN2
------------
44616392839
System altered.
$ egrep "LEN.*VLD|OBJ:" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc > /tmp/aa1.txt
REDO RECORD - Thread:1 RBA: 0x00335f.0016ec2c.0010 LEN: 0x0330 VLD: 0x05 CON_UID: 0
CHANGE #1 CON_ID:0 TYP:0 CLS:25 AFN:4 DBA:0x010000c0 OBJ:4294967295 SCN:0x0000000a63580e9d SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
CHANGE #2 CON_ID:0 TYP:0 CLS:26 AFN:4 DBA:0x010668b2 OBJ:4294967295 SCN:0x0000000a63580e9c SEQ:3 OP:5.1 ENC:0 RBL:0 FLG:0x0000
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fafed OBJ:73760 SCN:0x0000000a63580f6f SEQ:1 OP:11.2 ENC:0 RBL:0 FLG:0x0000
REDO RECORD - Thread:1 RBA: 0x00335f.0016ec2f.0010 LEN: 0x055c VLD: 0x05 CON_UID: 0
CHANGE #1 CON_ID:0 TYP:0 CLS:39 AFN:4 DBA:0x01000118 OBJ:4294967295 SCN:0x0000000a63580f6c SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
CHANGE #2 CON_ID:0 TYP:0 CLS:40 AFN:4 DBA:0x010635d4 OBJ:4294967295 SCN:0x0000000a63580f6b SEQ:3 OP:5.1 ENC:0 RBL:0 FLG:0x0000
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fc26b OBJ:73760 SCN:0x0000000a6356dc28 SEQ:1 OP:11.5 ENC:0 RBL:0 FLG:0x0000
--//OP: 11.2 insert , 11.5 update.
--//insert产生日志长度在0x0330.
--//update产生日志长度在0x055c.
--//有点复杂,放弃!!
$ egrep "^CHANGE" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc | sed "s/^.*OP://" | awk '{print $1}'| sort | uniq -c | sort -nr
827 5.1
684 11.5
594 5.2
582 5.20
118 11.2
29 13.22
17 11.4
15 4.1
8 11.6
2 13.24
5.1修改undo header中的事务信息
5.2事务开始
5.4 commit
11.2插入一条数据
11.3删除一条数据
11.4锁定数据(select for update)
11.5更新记录
11.6行链接
$ perl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_254310.trc
OBJECT_ID REDO_SIZE
73760 985712
NON-OBJECT REDO 4504
--//20秒,odbject_id=73760,产生了985712,接近1M.
--//修改:
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 Objno 73760;
--//为
alter system dump redo scn min &&v_scn1 scn max &&v_scn2 ;
SYS@192.168.100.235:1521/orcl> @ dumpredo 20
SCN1
------------
44616972825
SCN2
------------
44616979192
System altered.
$ perl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_7455.trc | head
OBJECT_ID REDO_SIZE
73760 1766264
NON-OBJECT REDO 626700
194159 524444
73757 416740
195403 396376
73621 306072
214792 227400
74655 198564
215210 166736
.......
--//可以大部分对象是object_id=73760.
--//如果仅仅1个insert.至少减少一半的日志大小。.
--//如果你看update的相关日志:
REDO RECORD - Thread:1 RBA: 0x00335f.0016e66b.0010 LEN: 0x05c4 VLD: 0x05 CON_UID: 0
SCN: 0x0000000a63580c1c SUBSCN: 1 03/01/2023 09:22:18
CHANGE #1 CON_ID:0 TYP:0 CLS:21 AFN:4 DBA:0x010000a0 OBJ:4294967295 SCN:0x0000000a63580c05 SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
ktudh redo: slt: 0x0005 sqn: 0x0014dffb flg: 0x0012 siz: 660 fbi: 0
uba: 0x010080ac.034d.23 pxid: 0x0000.000.00000000
CHANGE #2 CON_ID:0 TYP:0 CLS:22 AFN:4 DBA:0x010080ac OBJ:4294967295 SCN:0x0000000a63580c04 SEQ:4 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 660 spc: 2410 flg: 0x0012 seq: 0x034d rec: 0x23
xid: 0x0003.005.0014dffb
ktubl redo: slt: 5 wrp: 1 flg: 0x0c08 prev dba: 0x00000000 rci: 0 opc: 11.1 [objn: 73760 objd: 73760 tsn: 8]
[Undo type ] Regular undo [User undo done ] No [Last buffer split] No
[Temp object] No [Tablespace Undo ] No [User only ] No
Begin trans
prev ctl uba: 0x010080ac.034d.1f prev ctl max cmt scn: 0x0000000a63580200
prev tx cmt scn: 0x0000000a63580233
txn start scn: 0xffffffffffffffff logon user: 106
prev brb: 0x010080aa prev bcl: 0x00000000
BuExt idx: 0 flg2: 0
KDO undo record:
KTB Redo
op: 0x04 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: L itl: xid: 0x000c.010.001e9637 uba: 0x01072687.17be.04
flg: C--- lkc: 0 scn: 0x0000000a634f990a
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x020fbcf1 hdba: 0x00801262
itli: 5 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15) flag: 0x2c lock: 0 ckix: 254
ncol: 56 nnew: 47 size: 13
col 3: [ 2] c1 46
...
col 55: [24]
00 31 00 5e 00 31 00 5e 00 32 00 35 00 31 00 39 00 37 00 34 00 35 00 31
--//后image
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x020fbcf1 OBJ:73760 SCN:0x0000000a63580c1a SEQ:1 OP:11.5 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x01 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0003.005.0014dffb uba: 0x010080ac.034d.23
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x020fbcf1 hdba: 0x00801262
itli: 5 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15) flag: 0x2c lock: 5 ckix: 254
ncol: 55 nnew: 46 size: -13
col 3: [ 2] c1 46
..
col 54: [ 8] 00 30 00 2e 00 31 00 30
--//前image
--//注意IMU是反过来的保存的!!
CHANGE #4 MEDIA RECOVERY MARKER CON_ID:0 SCN:0x0000000000000000 SEQ:0 OP:5.20 ENC:0 FLG:0x0000
session number = 31
serial number = 22815
transaction name =
version 318767104
audit sessionid 6720706
Client Id =
login username = LIS
(LWN RBA: 0x00335f.0016e66f.0010 LEN: 0x00000004 NST: 0x0001 SCN: 0x0000000a63580c1f)
--//看看object_id=194159.
SYS@192.168.100.235:1521/orcl> @ oid 194159
owner object_name object_type SUBOBJECT_NAME CREATED LAST_DDL_TIME status DATA_OBJECT_ID
----- --------------- ----------- -------------- ------------------- ------------------- --------- --------------
LIS LIS_RESULT_TEMP TABLE 2022-07-01 12:06:16 2022-10-20 11:16:17 VALID 194159
--//根据情况修改aa1.txt => aa2.txt,id是LIS_RESULT_TEMP的主键.
$ cat aa2.txt
set numw 12
column id new_value v_id
column item_id new_value v_item_id
column scn1 new_value v_scn1
column scn2 new_value v_scn2
set term off
select current_scn-1e4 scn1 from v$database;
select max(id) id from LIS_RESULT_temp;
host sleep &&1
select current_scn scn2 from v$database;
set term on
SELECT versions_starttime
,versions_endtime
,versions_xid
,versions_operation
,versions_startscn
,versions_endscn
,lis_result_temp.id
FROM LIS_RESULT_TEMP VERSIONS BETWEEN scn &v_scn1 and &v_scn2
-- FROM LIS_RESULT VERSIONS BETWEEN TIMESTAMP sysdate-1/1440 and sysdate
WHERE id = &&v_id
--and item_id = &&v_item_id
order by versions_startscn
;
SYS@192.168.100.235:1521/orcl> @ aa2.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:26:48. 2023-03-01 10:26:48. 0C00150016B41E00 I 44617508176 44617508212 219375442
2023-03-01 10:26:48. 04001A00E48F1400 U 44617508212 219375442
SYS@192.168.100.235:1521/orcl> @ aa2.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:26:54. 2023-03-01 10:26:54. 03000900C8E11400 I 44617509759 44617509775 219375476
2023-03-01 10:26:54. 0C0020000FB41E00 U 44617509775 219375476
--//^_^,一样的情况!!大致明白为什么会产生这样大的日志量,开发把数据库当作垃圾桶!!
--//再看另外一个对象73757.
SYS@192.168.100.235:1521/orcl> @oid 73757
owner object_name object_type SUBOBJECT_NAME CREATED LAST_DDL_TIME status DATA_OBJECT_ID
----- ---------------- ----------- -------------- ------------------- ------------------- --------- --------------
LIS LIS_ORDER_DETAIL TABLE 2020-11-27 16:43:13 2023-02-20 20:47:34 VALID 76018
SYS@192.168.100.235:1521/orcl> @ aa3.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:30:54. 2023-03-01 10:30:54. 0C000500E2B51E00 I 44617592015 44617592021 134648696
2023-03-01 10:30:54. 2023-03-01 10:30:54. 07000800C6F51400 U 44617592021 44617592059 134648696
2023-03-01 10:30:54. 0C0011005EB51E00 U 44617592059 134648696
SYS@192.168.100.235:1521/orcl> @ aa3.txt 3
VERSIONS_STARTTIME VERSIONS_ENDTIME VERSIONS_XID V VERSIONS_STARTSCN VERSIONS_ENDSCN ID
-------------------- -------------------- ---------------- - ----------------- --------------- ------------
2023-03-01 10:32:33. 2023-03-01 10:32:33. 0C000700A8B61E00 I 44617636753 44617636768 134650263
2023-03-01 10:32:33. 2023-03-01 10:32:33. 03000D0013E21400 U 44617636768 44617636886 134650263
2023-03-01 10:32:33. 0C00020093B61E00 U 44617636886 134650263
--//2次update!!到此,终于明白为什么这套系统日志比原来旧系统多很多的原因.
--//应该一次insert就完成的业务，开发写成insert+update来完成。
--//简单估算(0x0330+0x055c)/0x400 = 2.13671875，这样写日志至少增加1倍日志量。
4.附录:
--//脚本的来源当时没记录,也不知道是否可靠与正确.
$ cat /u01/app/oracle/diag/rdbms/orcl/orcl/trace/redo_summary.pl
# TDH 2008-09-26
# Analyses a formatted redo dump and
# summarises redo bytes by object.
#
my $current_object;
my $current_bytes;
my %object_bytes = ();
sub DescendingNum {
$object_bytes{$b} <=> $object_bytes{$a};
}
while (<>) {
if (/LEN: 0x([a-f0-9A-F]+) VLD/) {
if (defined($current_object)) {
$object_bytes{$current_object} += $current_bytes;
}
elsif (defined($current_bytes)) {
$object_bytes{"NON-OBJECT REDO"} += $current_bytes;
}
$current_bytes = hex($1);
$current_object = undef;
}
elsif (/objn: (\d+) objd/) {
$current_object = $1;
}
}
printf "%20s %40s\n","OBJECT_ID","REDO_SIZE";
foreach my $key (sort DescendingNum(keys(%object_bytes))) {
printf "%20s %40s\n",$key,$object_bytes{$key};
}
