Transaction recovery: lock conflict caught and ignored

Je viens de rencontrer un problème chez l'un de nos clients.

Il s'agit d'une base de données RAC 11.2.0.1 à trois (3) noeuds en environnement Oracle Solaris SPARC 64-bit.

Sur l'un des noeuds, le fichier $DIAG_HOME/diag/rdbms/<db_name>/<instance_name>/trace/alert_INSTANCE.log (ancien format du fichier alert de l'instance 2) contient la ligne suivante à répétition:

...
Transaction recovery: lock conflict caught and ignored
Transaction recovery: lock conflict caught and ignored
Transaction recovery: lock conflict caught and ignored
...

Il faut souligner que les 2 autres instances n'ont pas ce message dans leur fichier alert.

En conséquence, la base de données génère un nombre excessif d'archives.

Je me suis rendu compte qu'il y avait plusieurs enregistrements dans la vue GV$FAST_START_TRANSACTIONS (GV$ car en rac, enlever le G pour avoir juste l'info pour l'instance sur laquelle l'on est connecté), ce qui voudrait dire qu'il existe des transactions qui sont en train d'être recouvrées.

select * from GV$FAST_START_TRANSACTIONS;

INST_ID USN SLT SEQ STATE UNDOBLOCKSDONE UNDOBLOCKSTOTAL PID CPUTIME PARENTUSN PARENTSLT PARENTSEQ XID PXID RCVSERVERS
---------- ---------- ---------- ---------- ---------------- -------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------------- ---------------- ----------
3 23 15 242931 RECOVERING 0 110 248184 0017000F0003B4F3 0
3 2 30 217700 RECOVERING 0 109 248184 0002001E00035264 0
3 25 8 228906 RECOVERING 0 110 248184 0019000800037E2A 0
2 23 15 242931 RECOVERING 0 110 248183 0017000F0003B4F3 0
2 2 30 217700 RECOVERING 0 109 248183 0002001E00035264 0
2 25 8 228906 RECOVERING 0 110 248183 0019000800037E2A 0
2 27 15 434163 RECOVERING 0 110 248183 001B000F00069FF3 0

7 ligne(s) sÚlectionnÚe(s).

La requête précédente montre que 4 segments d'undo sont concernés par ce problème: Il s'agit des segments 2, 23, 25 et 27:

_SYSSMU2_4041828287$ (2)
_SYSSMU23_314669895$ (23)
_SYSSMU25_528020860$ (25)
_SYSSMU27_3428318680$ (27)

Une interrogation de la table x$ktuxe donne le résultat suivant:

SYS@E1002> select sum(distinct(ktuxesiz)) from x$ktuxe where ktuxecfl = 'DEAD';

SUM(DISTINCT(KTUXESIZ))
-----------------------
18

SYS@E1002>

Pour une recherche plus approfondie, les informations suivantes ont été transférées à Oracle Support:

Juste un extrait des échanges...

a) show the following output in order to confirm the undo segments as involved (2,23,25,27):
SQL>
connect / as sysdba
set pagesize 9999
set nls_date_format='dd-mon-yyyy hh24:mi:ss';

spool /tmp/dba_rollback_segs.html
set markup html on
select * from dba_rollback_segs order by segment_id;
spool off

==> upload /tmp/dba_rollback_segs.html

b) provide a segment header dump for the undo segments 2 + 23 + 25 + 27:
(Note.249814.1 How to Obtain a Segment Header Dump)
SQL>
connect / as sysdba
alter session set tracefile_identifier='undo_segment_header_dump';
alter system dump undo header '&name_of_undo_segment';
...

==> upload /diag/rdbms/<db_name>/<instance_name>/trace/*undo_segment_header_dump*.trc

c) show the following output in order to exclude distributed TX's being the cause:
connect / as sysdba
set pagesize 9999
alter session set nls_date_format='dd-mon-yyyy hh24:mi:ss';

spool /tmp/dba_2pc_pending.html
set markup html on
select * from dba_2pc_pending;
spool off

==> upload /tmp/dba_2pc_pending.html

d) show the following output from v$transaction:

connect / as sysdba
set pagesize 9999
alter session set nls_date_format='dd-mon-yyyy hh24:mi:ss';

spool /tmp/transaction.html
set markup html on
select * from v$transaction order by xidusn,xidslot;
spool off

==> upload /tmp/transaction.html

Par la suite, un dump des transactions (XID) a été transféré à Oracle Support:

1) show that these transactions do consist of:

SQL>
connect / as sysdba
alter session set max_dump_file_size=unlimited;
alter session set tracefile_identifier='dump_xids';

alter system dump undo block '_SYSSMU2_4041828287$' xid 2 30 217700;
alter system dump undo block '_SYSSMU23_314669895$' xid 23 15 242931;
alter system dump undo block '_SYSSMU25_528020860$' xid 25 8 228906;
alter system dump undo block '_SYSSMU27_3428318680$' xid 27 15 434163;

==> upload /diag/rdbms/<db_name>/<instance_name>/trace/*dump_xids*trc

Puis...

1) in order to know what the transactions consist off and if there are common objects involved we need to dump the transactions as following:

SQL>
connect / as sysdba
alter session set max_dump_file_size=unlimited;
alter session set tracefile_identifier='dump_xid';

alter system dump undo block '_SYSSMU2_4041828287$' xid 2 30 217700;
alter system dump undo block '_SYSSMU23_314669895$' xid 23 15 242931;
alter system dump undo block '_SYSSMU25_528020860$' xid 25 8 228906;
alter system dump undo block '_SYSSMU27_3428318680$' xid 27 15 434163;

==> upload /diag/rdbms/<db_name>/<instance_name>/trace/*dump_xid*trc

Le dump précédent a révélé les OBJECT_ID des tables pour lesquelles il y avait un problème de recouvrement.
Ces tables ont été recrées pour que leurs OBJECT_ID changent de sorte à ce que les transactions à problème soient ignorées. On peut les recréer d'une des manières suivantes:
(exp/drop/imp ou CTAS/truncate/insert).

Après avoir recréé les tables à problème, la fréquence de génération des archives a diminué pour redevenir presque normale mais les transactions sont toujours restées dans la vue GV$FAST_START_TRANSACTIONS.

Oracle Support a finalement proposé d'appliquer le patch qui corrige le bug 9489626. Il s'agit du même patch que celui qui corrige le bug 9857702.
C'est le Patch 9857702 (dans mon cas, il s'agit d'un environnement Sun Solaris SPARC 64-bit).

Voir ORA-600 [4464] in a RAC Environment with Supplemental Logging Enabled [ID 1228295.1]

Je n'ai pas encore eu le temps de l'appliquer pour voir si ça corrige effectivement le problème, mais j'aurai l'occasion de revenir mettre à jour l'information.