[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 |
||
| 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 ./flow_add_delete_test.py --host 127.0.0.1 --auth --threads 3 --flows 1000 --bulk-delete --timeout 1000 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:
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. |