[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};
}