[CONTROLLER-1103] Clustering : ReadData messages for ReadOnly Transactions sometimes end up in dead letters causing timeouts Created: 14/Jan/15  Updated: 25/Jul/23  Resolved: 07/Apr/15

Status: Resolved
Project: controller
Component/s: mdsal
Affects Version/s: None
Fix Version/s: None

Type: Bug
Reporter: Moiz Raja Assignee: Tom Pantelis
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All


External issue ID: 2588
Priority: Normal

 Description   

From debugging it seems like this is happening because the ShardTransaction actor is killed before the ReadData message makes it to the actor. This appears to be related to our usage of PhantomReferences to track ReadOnly transactions. The reference sometimes seem to get collected right after the transaction is created and before the read data message could be send to the transaction resulting in the actor being killed and the read data being lost.

We do need to shut down read-only transaction actors ASAP as they could hold on to a lot of memory but we may need to review our usage of phantom reference and see if we can come up with a better alternative.



 Comments   
Comment by Tom Pantelis [ 18/Jan/15 ]

The PhantomReferences are only used for read-only transactions and I'm not sure if these are actually used anywhere. In addition, the client would have to add a callback to returned ListenableFuture and return quickly so that the transaction instance goes out of scope quickly and has the possibility of being GC'ed.

Even so, I don't think the TransactionProxy could get GC'ed prior to sending the ReadData message. The only possibility for this would be if the read operation is queued on TransactionFutureCallback waiting for the shard transaction to be created. On completion of the create transaction Future, the TransactionFutureCallback adds the transaction actor to the remoteTransactionActors list. This list is accessed by the TransactionProxyCleanupPhantomReference when it runs. After that, the TransactionFutureCallback invokes the queued operations. The read operation executes an ask to send the ReadData message. Therefore, TransactionProxy instance would have to get GC'ed and the TransactionProxyCleanupPhantomReference run in the small window between adding to the remoteTransactionActors list and sending the ReadData message. If the instance is GC'ed after the ReadData message is sent then the CloseTransaction message sent by the TransactionProxyCleanupPhantomReference would arrive at the transaction after the ReadData message.

However, the TransactionProxy instance is still reachable via a GC root during the small time window via the akka dispatcher thread that is executing the TransactionFutureCallback#onComplete method so it can't get GC'ed (the TransactionProxy instance is reachable by the TransactionFutureCallback instance which is reachable by the akka thread). I also verified this in a unit test.

There is another mechanism which could cause a ReadData message (or any shard transaction operation) to get lost. We set a 10 minute receive time out on shard transaction actors. If there's been no message during that time, akka will send the ReceiveTimeout message to the actor and, on receipt, we send the PoisonPill to kill it.

There may be some client that keeps a reusable transaction open for a long period of time such that it times out.

Is this reproducible? Is there any info on which section of client code that experienced dropped ReadData messages?

Comment by Moiz Raja [ 03/Feb/15 ]

This is not easy to reproduce but the steps to reproduce are as follows in a single node setup,

1. Increase operation timeout to say 300 seconds
2. Connect mininet with say 15 switches
3. In the integration repo look for this file flow_add_delete_test.py
4. Execute the following on your controller

./flow_add_delete_test.py --host 127.0.0.1 --auth --threads 3 --flows 1000 --bulk-delete --timeout 1000
5. At some point you will find that the stats printout will pause for about 5 minutes. This pause is unexpected.

The pause happens when reading config data and I believe it's the Statistics Manager reading the statistics.

Comment by Tom Pantelis [ 02/Apr/15 ]

I was able to reproduce the issue. The issue emanates from FlowCapableInventoryProvider. What happens is that the FlowCapableInventoryProvider gets a list of data store operations to perform, creates a RW txn, performs/applies them to the txn and then immediately submits the txn. It’s agnostic to what operations that it’s given, can be a mix of reads and writes. The reads are done async, i.e. it doesn’t block on the future. So if the timing is right, a read request can be sent to or processed by the txn actor after the txn is readied. Once readied, we kill the txn actor. So a “late” ReadData message may get a ReadFailedException from the underlying DOM txn if the message got thru before the PoisonPill or the ReadData message is dropped to dead letters if the PoisonPill already killed the actor.

The simple scenario is:

  • create a RW txn
  • do a put operation
  • do an async read (don’t wait for future complete)
  • submit the txn

The simplest solution is to always just send the ReadData message. Currently if there were prior write/merge/delete mod operation messages in flight, we wait for those to complete before sending the ReadData message. However if the prior mod messages aren't complete before the txn is readied, this issue may occur. The reason we wait for the prior mod futures is to ensure they completed successfully so we can fail the read in case the read depended on them. But I don’t think this is really necessary.

Comment by Tom Pantelis [ 03/Apr/15 ]

Submitted https://git.opendaylight.org/gerrit/#/c/17682/

Verified the fix eliminates the issue for RW transactions.

I still saw some read failures/dead letter messages for some RO txns. This is due to an issue in the stats manager - tracked by https://bugs.opendaylight.org/show_bug.cgi?id=2945.

Generated at Wed Feb 07 19:54:42 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.