Clarification about statements and commit phase under save changes and "WAIT FOR EMON PROCESS NFTNS" error

[guilhermecampello]

Hello!

I'm facing some issues with a .NET 7 application, using Oracle.EntityFrameworkCore version 7.21.13 regarding the commit phase.

The scenario I have is that the command statements are running fast apparently(45ms) but the commit phase sometimes hangs for a long time (212 seconds!).

[21:19:44.441][INF][Microsoft.EntityFrameworkCore.Database.Command] Executed DbCommand (45ms)

For me it's clearly a locking problem but the DBA says that at the Database the commit was completed intantaneously and that this session had no more active transactions at this time.

Is there any "commit confirmation" that the client may be missing(lost over the network or blocked by the firewall, etc) that may cause this behaviour on the client? Or this is not an option and problably it's just waiting for the database to complete the commit?

After some time the DBA found a session with this error message "WAIT FOR EMON PROCESS NTFNS". I've read this article about the EMON and it raised my suspicious about some "commit completed acknowledgement" being lost over the network. Does this client depends on EMON somehow and these errors may be related?

Any advice for additional troubleshooting would be really appreciated!

Also is there any way to setup a "commit timeout"? I've tried to set the CommandTimeout like this:

        var timeOut = TimeSpan.FromSeconds(1);
        databaseContext.Database.SetCommandTimeout(timeOut);

but I think that it only applies to the command execution and not to the commiting phase.

Environment

• Windows Server 2022
• .NET 7.0
• Oracle.EntityFrameworkCore 7.21.13
• Database: Oracle 19c Enterprise

[alexkeh]

You can turn on ODP.NET tracing to see what ODP.NET is doing or waiting on in that 212 seconds. Here's how you would enable ODP.NET tracing in EF Core.

Let me note that .NET 7 and EFC 7 are no longer supported as of May, 2024. If this is a bug in .NET or ODP.NET, it would need to be resolved in a release for .NET 8 or higher.

With the trace, we can see if ODP.NET has some operation that takes a long time or it is waiting on the DB server for a response.

[guilhermecampello]

Hi Alex, thanks for the suggestion!

I was able to implement it and extract the trace at the moment the error happened. I'm adding them as attachments.

At the smaller file I extracted the commit delay moment from the full trace file.
From my perspective the commit was sent for the database at this moment

2025-04-04 12:14:36.818589 TID:11  (PUB) (ENT) OracleTransaction.Commit()
2025-04-04 12:14:36.818603 TID:11  (PRI) (SVC) (ENT) OracleTransactionImpl.Commit()
2025-04-04 12:14:36.818619 TID:11  (PRI) (SVC) (ENT) OracleConnectionImpl.AddAllPiggyBackRequests()
2025-04-04 12:14:36.818631 TID:11  (PRI) (TTC) (ENT) TTCClose.Write()
2025-04-04 12:14:36.818642 TID:11  (PRI) (TTC) (ENT) TTCFunction.WriteFunctionHeader()
2025-04-04 12:14:36.818654 TID:11  (PRI) (TTC) (ENT) TTCMessage.WriteTTCCode()
2025-04-04 12:14:36.818663 TID:11  (PRI) (TTC) (EXT) TTCMessage.WriteTTCCode()
2025-04-04 12:14:36.818672 TID:11  (PRI) (TTC) (EXT) TTCFunction.WriteFunctionHeader()
2025-04-04 12:14:36.818686 TID:11  (PRI) (TTC) (EXT) TTCClose.Write()
2025-04-04 12:14:36.818696 TID:11  (PRI) (SVC) (EXT) OracleConnectionImpl.AddAllPiggyBackRequests()
2025-04-04 12:14:36.818707 TID:11  (PRI) (TTC) (ENT) TTCSimpleOperations.WriteMessage()
2025-04-04 12:14:36.818716 TID:11  (PRI) (TTC) (ENT) TTCFunction.WriteFunctionHeader()
2025-04-04 12:14:36.818726 TID:11  (PRI) (TTC) (ENT) TTCMessage.WriteTTCCode()
2025-04-04 12:14:36.818735 TID:11  (PRI) (TTC) (EXT) TTCMessage.WriteTTCCode()
2025-04-04 12:14:36.818743 TID:11  (PRI) (TTC) (EXT) TTCFunction.WriteFunctionHeader()
2025-04-04 12:14:36.818752 TID:11  (PRI) (TTC) (EXT) TTCSimpleOperations.WriteMessage()
2025-04-04 12:14:36.818760 TID:11  (PRI) (TTC) (ENT) TTCSimpleOperations.ReadResponse()
2025-04-04 12:14:36.818798 TID:11  (NET) (SND) 00 00 00 17 06 00 00 00   |........|
2025-04-04 12:14:36.818801 TID:11  (NET) (SND) 00 00                     |..      |
2025-04-04 12:14:36.818812 TID:11  (NET) (SND) 11 69 00 01 01 02 01 08   |.i......|
2025-04-04 12:14:36.818814 TID:11  (NET) (SND) 01 08 03 0E 00            |.....   |
2025-04-04 12:14:36.818944 TID:11  (PRI) (BUF) (COBP.GET) (poolid:10) (key:8192) (bufid:278) (count:7) (OraBufReader.GetDataFromNetwork)
2025-04-04 12:14:49.030722 TID:18  (PRI) (ONS) (ENT) ReceiverThread.readNotificationMessage()

And the commit ack came only at this moment:

2025-04-04 12:15:20.463079 TID:7   (NET) (REC) New receive packet. Header: 
2025-04-04 12:15:20.463138 TID:7   (NET) (REC) 00 00 00 10 06 00 00 00   |........|
2025-04-04 12:15:20.463142 TID:7   (NET) (REC) 00 00                     |..      |
2025-04-04 12:15:20.463153 TID:7   (NET) (REC) 09 01 05 02 87 5A         |.....Z  |
2025-04-04 12:15:20.463163 TID:7   (PRI) (TTC) Data Length Read From Network: 6
2025-04-04 12:15:20.463174 TID:7   (PRI) (TTC) (EXT) TTCSimpleOperations.ReadResponse()
2025-04-04 12:15:20.463190 TID:7   (PRI) (SVC) (EXT) OracleTransactionImpl.Commit()
2025-04-04 12:15:20.463201 TID:7   (PRI) (ENT) OracleConnection.CheckForWarnings()
2025-04-04 12:15:20.463213 TID:7   (PRI) (EXT) OracleConnection.CheckForWarnings()
2025-04-04 12:15:20.463222 TID:7   (PRI) (SVC) (ENT) OracleConnectionImpl.SetAutoCommit()
2025-04-04 12:15:20.463231 TID:7   (PRI) (SVC) (EXT) OracleConnectionImpl.SetAutoCommit()
2025-04-04 12:15:20.463240 TID:7   (PUB) (ENT) OracleTransaction.Dispose()
2025-04-04 12:15:20.463254 TID:7   (PUB) (EXT) OracleTransaction.Dispose()
2025-04-04 12:15:20.463263 TID:7   (PUB) (EXT) OracleTransaction.Commit()
2025-04-04 12:15:20.463335 TID:7   (NET) (ENT) OracleCommunication.TransportAlive()
2025-04-04 12:15:20.463383 TID:7   (NET) (SND) 00 00 00 0A 06 00 00 00   |........|
2025-04-04 12:15:20.463385 TID:7   (NET) (SND) 00 00                     |..      |
2025-04-04 12:15:20.463404 TID:7   (NET) (EXT) OracleCommunication.TransportAlive()  (full-socket-check) 
2025-04-04 12:15:20.463526 TID:7   (PUB) (ENT) OracleConnection.Close() (conid=56093799) (state=Open) (sessid=3088) (implid=63382935) (pooling=T) (aff=n/a) (inst=consinco1) (affmatch=n/a) (pr.service=consinco) (pr.pdb=) (pr.edition=) (sessid=3088:34924) (T;F;F;consinco1;N) (pmid=56764196) 
2025-04-04 12:15:20.463594 TID:7   (PRI) (ENT) (CP) PoolManager.Close() TransportAlive()
2025-04-04 12:15:20.463684 TID:7   (NET) (ENT) OracleCommunication.TransportAlive()
2025-04-04 12:15:20.463701 TID:7   (NET) (EXT) OracleCommunication.TransportAlive()  (no-op) 
2025-04-04 12:15:20.463710 TID:7   (PRI) (EXT) (CP) PoolManager.Close() TransportAlive()
2025-04-04 12:15:20.463721 TID:7   (PRI) (SVC) (ENT) OracleConnectionImpl.FireConnectionCloseEvent()
2025-04-04 12:15:20.463733 TID:7   (PRI) (SVC) (EXT) OracleConnectionImpl.FireConnectionCloseEvent()
2025-04-04 12:15:20.463742 TID:7   (PRI) (SVC) (ENT) OracleConnectionImpl.FlushPendingPiggybackMessages()
2025-04-04 12:15:20.463751 TID:7   (PRI) (SVC) (EXT) OracleConnectionImpl.FlushPendingPiggybackMessages()
2025-04-04 12:15:20.463761 TID:7   (PRI) (CP) OracleConnection.Close() (PUT) (ENDSID=3088:34924)

This is the same behaviour our application is experiencing.

Do you see any strange behaviour?

oracle-client-trace-long-running-commit.txt

fulltrace.zip

[alexkeh]

Reviewing the trace, we see ODP.NET send the commit here:

2025-04-04 12:14:36.818798 TID:11 (NET) (SND) 00 00 00 17 06 00 00 00 |........|

Then, ODP.NET receives acknowledgment here:

2025-04-04 12:15:20.480349 TID:11 (NET) (REC) New receive packet. Header:

ODP.NET waits almost 44 seconds for the DB to send back a response.

We don't see any other ODP.NET operations being performed on this thread (TID:11). Other ODP.NET threads are working on internal housekeeping operations unrelated to this transaction.

The next thing I would look into is what is the DB doing in these 44 seconds.