Archivelog Aufkommen mit Logminer analysieren
Wenn eine Oracle Datenbank mehr Archivelogs als gewöhnlich erzeugt, fällt das meist entweder durch eine sich füllende Fast Recovery Area oder durch längere Backupzeiten auf. Dem möchte man natürlich auf den Grund gehen um die Ursache zu finden und zukünftig anders agieren zu können. Der Logminer kann hier eine gute Hilfe sein, denn wie der Name schon sagt, analysiert dieser die Inhalte von Archivelogs, und um die geht es ja gerade. Hinzu kommt, das der Logminer sowohl in der Standard Edition 2 als auch in der Enterprise Edition ohne Zusatzkosten zur Verfügung steht.
Bevor eine Analyse mit dem Logminer gestartet wird, muss der fragliche Zeitbereich ermittelt werden. Das wird am besten über die View V$ARCHIVED_LOG erledigt. Diese enthält alle nötigen Informationen zur Größe und Zeitstempeln der erzeugten Archivelogs.
SQL> li
1 select
2 trunc(first_time, 'dd') day,
3 trunc(first_time, 'hh') hour,
4 round(sum(blocks*block_size)/1024/1024) MB
5 from v$archived_log
6 where first_time > sysdate-2
7 group by rollup(
8 trunc(first_time, 'dd'),
9 trunc(first_time, 'hh')
10 )
11* order by 1, 2
SQL> /
DAY HOUR MB
------------------- ------------------- ----------
2020-01-27 00:00:00 2020-01-27 08:00:00 21
2020-01-27 00:00:00 2020-01-27 09:00:00 1784
2020-01-27 00:00:00 2020-01-27 22:00:00 103103
2020-01-27 00:00:00 2020-01-27 23:00:00 54668
2020-01-27 00:00:00 159575
2020-01-28 00:00:00 2020-01-28 00:00:00 1031
2020-01-28 00:00:00 2020-01-28 11:00:00 7
2020-01-28 00:00:00 1039
160614
9 rows selected.
Im Beispiel gab es eine Spitze im Archivelog Aufkommen zwischen 22:00 und 00:00 in der fast 160GB Archivelogs generiert wurden. Davor und danach war die angefallene Menge an Archivelogs dagegen verschwindend gering. Anhand dessen können nun die Namen einiger Archivelogs im betroffenen Zeitraum ermittelt werden.
SQL> li
1 select name from v$archived_log where first_time between
2 to_date('27.01.2020 22:10', 'dd.mm.yyyy hh24:mi')
3 and to_date('27.01.2020 22:11', 'dd.mm.yyyy hh24:mi')
4* and dest_id=1
SQL> /
NAME
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_904_h2ynfo38_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_905_h2ynfx1g_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_906_h2yng501_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_907_h2yngdy3_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_908_h2yngnh4_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_909_h2yngvyy_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_910_h2ynh2ps_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_911_h2ynhb2m_.arc
8 rows selected.
Man sieht, selbst in dieser einen Minute sind bereits 8 Archivelogs generiert worden. Mit den Namen dieser Archivelogs kann nun der Logminer gefüttert werden. Dazu dient die Prozedur ADD_LOGFILE des Packages DBMS_LOGMNR. Das erste Archivelog wird mit dem Parameter DBMS_LOGMNR.NEW übergeben um eine neue Session zu starten. Alle weiteren Archivelogs werden dieser Session hinzugefügt indem der Parameter DBMS_LOGMNR.ADDFILE verwendet wird.
SQL> exec dbms_logmnr.add_logfile('/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_904_h2ynfo38_.arc', dbms_logmnr.new);
PL/SQL procedure successfully completed.
SQL> exec dbms_logmnr.add_logfile('/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_905_h2ynfx1g_.arc', dbms_logmnr.addfile);
PL/SQL procedure successfully completed.
SQL> exec dbms_logmnr.add_logfile('/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_906_h2yng501_.arc', dbms_logmnr.addfile);
PL/SQL procedure successfully completed.
Nachdem hier drei der Archivelogs exemplarisch hinzugefügt wurden, muss der Logminer noch gestartet werden. Gehören die Archivelogs zur aktuellen Datenbank, kann das Dictionary zur Auflösung der Object IDs verwendet werden.
SQL> exec dbms_logmnr.start_logmnr(options => dbms_logmnr.DICT_FROM_ONLINE_CATALOG);
PL/SQL procedure successfully completed.
Nachdem der Logminer nun läuft, enthält die View V$LOGMNR_CONTENTS die Inhalte der zuvor übergebenen Archivelogs. Mit ein paar gezielten Abfragen kann nun versucht werden, den Grund für das erhöhte Archivelog Aufkommen zu ermitteln indem nach den häufigsten Operationen, Nutzern oder Segmenten gesucht wird.
SQL> select count(*), USERNAME from v$logmnr_contents where operation ='INTERNAL' group by USERNAME;
COUNT(*) USERNAME
---------- --------------------------
1445 UNKNOWN
1 rows selected.
SQL> select count(*), seg_name from v$logmnr_contents where operation ='INTERNAL' group by seg_name;
COUNT(*) SEG_NAME
---------- -------------------------
1445
1 rows selected.
SQL> select sql_redo from v$logmnr_contents where operation ='INTERNAL' and rownum<11;
SQL_REDO
---------------------------------------------------------------
10 rows selected.
Allerdings ist die Ausbeute im Beispiel hier eher dürftig. Offenbar ist etwas Oracle-internes die Ursache für das massive Archivelog Aufkommen. Der Logminer hilft also an dieser Stelle nicht weiter und kann wieder beendet werden.
SQL> exec dbms_logmnr.end_logmnr;
PL/SQL procedure successfully completed.
Um die Archivelogs nicht einzeln hinzufügen zu müssen, kann man auch PL/SQL bemühen. Im folgenden Beispiel werden Archivelogs zu einer anderen Zeitspanne des fraglichen Zeitraums hinzugefügt. Welche Archivelogs hinzugefügt wurden, ist dann aus der View V$LOGMNR_LOGS ersichtlich.
SQL> declare
2 flag number := 0;
3 begin
4 for rec in (
5 select name from v$archived_log where first_time between
6 to_date('27.01.2020 23:00', 'dd.mm.yyyy hh24:mi')
7 and to_date('27.01.2020 23:11', 'dd.mm.yyyy hh24:mi')
8 and dest_id=1
9 ) loop
10 if flag = 0 then
11 dbms_logmnr.add_logfile(rec.name, dbms_logmnr.new);
12 flag := 1;
13 else
14 dbms_logmnr.add_logfile(rec.name, dbms_logmnr.addfile);
15 end if;
16 end loop;
17* end;
SQL> /
PL/SQL procedure successfully completed.
SQL> select filename from v$logmnr_logs;
FILENAME
------------------------------------------------------------------------------------------------
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_932_h2yqpnw5_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_933_h2yqq9wj_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_934_h2yqqyx3_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_935_h2yqrmx1_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_936_h2yqs8y3_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_937_h2yqsxxv_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_938_h2yqtlxy_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_939_h2yqv7y2_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_940_h2yqvwyh_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_941_h2yr6skq_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_942_h2yr6tct_.arc
/u03/app/oracle/fast_recovery_area/D1LECARET/archivelog/2020_01_27/o1_mf_1_943_h2yr6tf0_.arc
12 rows selected.
SQL> exec dbms_logmnr.start_logmnr(options => dbms_logmnr.DICT_FROM_ONLINE_CATALOG);
PL/SQL procedure successfully completed.
Nachdem der Logminer nun wieder läuft, wird erneut geprüft, welche Operationen in diesem Zeitbereich am häufigsten auftraten.
SQL> select count(*), operation from v$logmnr_contents group by operation;
COUNT(*) OPERATION
---------- ------------------------------------------------------------------------------------------------
2495 START
127 UNSUPPORTED
260 INSERT
166 UPDATE
15 DELETE
263710 INTERNAL
12 ROLLBACK
2483 COMMIT
1 DDL
9 rows selected.
SQL> exec dbms_logmnr.end_logmnr;
PL/SQL procedure successfully completed.
Offenbar ist "INTERNAL" nach wie vor für den Großteil des Aufkommens verantwortlich. Da der Effekt 22:00 beginnt, liegt in diesem Fall die Vermutung nahe, dass ein automatischer Job dafür verantwortlich ist. Über die Job History lässt sich das gut ermitteln.
SQL> select CLIENT_NAME, JOB_NAME, JOB_STATUS, JOB_START_TIME, JOB_DURATION
2 from DBA_AUTOTASK_JOB_HISTORY
3* where JOB_START_TIME > systimestamp -1 order by JOB_START_TIME desc
SQL> /
CLIENT_NAME
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
JOB_NAME
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
JOB_STATUS JOB_START_TIME
------------------------------------------------------------------------------------------ ---------------------------------------------------------------------------
JOB_DURATION
---------------------------------------------------------------------------
[...]
auto space advisor
ORA$AT_SA_SPC_SY_13136
SUCCEEDED 27.01.20 22:00:02,085431 EUROPE/VIENNA
+000 02:11:55
auto optimizer stats collection
ORA$AT_OS_OPT_SY_13135
SUCCEEDED 27.01.20 22:00:02,066319 EUROPE/VIENNA
+000 00:01:18
SQL> select cpu_used from ALL_SCHEDULER_JOB_RUN_DETAILS where job_name='ORA$AT_SA_SPC_SY_13136';
CPU_USED
---------------------
+000 00:07:13.19
In diesem Fall wurde der Einfachheit halber der Auto Space Advisor deaktiviert, da dieser ohnehin nicht benötigt wird. Danach trat der Effekt nicht wieder auf. Der Logminer hat auf die richtige Spur geführt.
Kommentare
Keine Kommentare