Logging options for Oracle Connector to identify "long running transactions"

[Matt Block]

I am looking for advice on what logging to enable/increase (without getting overloaded with logs) to understand the SCNs which are considered an open transaction which is causing substantial (7hrs) latency in the connector mining and getting caught up.

We have tables with LOB type columns which require us to use lob.enabled=true for mining.  Of course with this enabled, mining sessions (at least on 1.8.1 and 1.9.x on Oracle 19c with no continuous mining) have to continue to go back to the starting SCN of an open transaction when mining over multiple logs and SCNs.  We have noticed "challenges" for the connector on very large data sets when a nightly DB maintenance event is collecting stats, etc., has the SYS user, and has UNKNOWN schema name.  The query that gets executed does not select these transactions (to the best of our knowledge).  During this 40 minute process it generates 400,000+ SCNs, and around 400 log sequences.  According to the  NumberOfActiveTransactions metric, there is 1 to 3 active transactions during the process and in monitoring the oracle session waits, we can observe the connector mining through a series of sequences and then when the logging query completes, and the subsequent query is executed, it mines though the same series of sequences and the starting SCN is not progressing forward until it gets through most of the 40 minutes of activity.  What is confusing us, is that when we retroactively mine the logs, we only have been able to find transactions which remained open for short periods of time.  We must be missing something, or maybe we are seeing a gap in the connector logic.  Either way I have to solve this issue or we won't be able to use this CDC connector.

We added the two specific schemas we are capturing from in the schema.include.list and add SYS to the log.mining.username.exclude.list, but same behavior continues to happen.

Any and all help welcome

Matt

[Chris Cranford]

Hi Matt -

If you enable DEBUG for io.debezium.connector.oracle.logminer.processor.AbstractLogMinerEventProcessor, this will give you the following log entries on each LogMiner processed batch:

    Fetching results for SCN [xxxxx, yyyyy]
    <counter statistics>
    Processde in xxxx ms. Lag: xxx. Offset SCN: xxx, Offset Commit SCN: xxx, Active Transactions: xxxx

You might be able to use this SCN window combined with the "Active Transactions" indicator to see what SCN boundary opened new transactions and when these eventually close, but keep in mind that user activity and where the SCN boundary starts/ends can also influence whether there are other transactions that could be influencing the active transaction count. 

Another option might be to consider just checking out the specific tag of the version of the connector you are using and build it locally, adding a logging entry for what you want.  I would suggest inside AbstractLogMinerEventProcessor#process, just after the LOGGER.debug calls that write the counters and processed entries, add the following, which will print the HEX-based transaction ids. 

    LOGGER.info("Active transactions are: {}", String.join(",", getTransactionsCache().keySet()));

If you want to have it print the SCNs associated with each transaction, it would be:

    LOGGER.info("Active transactions are: {}", getTransactionCache().values().stream().map(T::getStartScn).map(Scn::toString).collect(Collectors.joining(",")));

If you think it's useful to log these values when TRACE or DEBUG logging is enabled, we could look at adding this if you think that's useful.  Let me know if you have any questions or need any more help.

Hope that helps.
Chris

--
You received this message because you are subscribed to the Google Groups "debezium" group.
To unsubscribe from this group and stop receiving emails from it, send an email to debezium+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/7f506ce9-6727-4a3d-b840-0b4dc2598f15n%40googlegroups.com.