add_entity has periodic long wait that raise an Exception when exceeds 15 minutes #45
Comments
|
The mentioned work-around may be worst. When we start having many threads working at the same time I get a lot of these exceptions: Under investigation... |
|
Work-around (this one works): I created a new thread-pool object with a data pool to accumulate transactions to be sent. Other objects (also threads) fills the pool. |
Using: azure-cosmosdb-table==1.0.6
Problem description: Keeping an instance of TableService for a long time (hours) to perform regular “add_entity” result in rare but recurring long transaction time: up to 15+ minutes. When the 15 minute mark is exceeded on a transaction an exception occurs of type “EntityAlreadyExists”. Querying the database then shows the data was saved at the time of the request (15 minutes earlier).
Expected behavior:
Problem details:
Context: every 30 seconds I gather data and send them to an Azure CosmosDb using TableService via add_entity. Here is some pseudo code of such an operation:
Please find later, via attachment, code sample and a stack-trace when the problem occurs.
Problem observation:
The call to add_entity usually returns in less than 0.2 second.
Every once in a while the call takes anywhere from several seconds to 15 minutes to return, but recovers without any reported error, no raised exception. This sometime occurs in a 2 to 30 seconds range but most of the time between 100 to 960 seconds.
And then at some point, after running for 2 to 16 hours, the call exceed 15 minutes and an “EntityAlreadyExists” exception is raised. In fact for the first several days of tracking this issue, the exception always occurred at exactly 962 seconds. This cannot be a coincidence. (Since then I witnessed longer time, but in a test environment with less trace enabled).
Weird: When the exception occurs, checking the database shows the last data-entry with a time-stamp at the exact second the function was called, (about 15 minutes before the exception was thrown). Was the transaction successful but failed to be reported and retried by the client side for the last 15 minutes? The EntityAlreadyExist exception was a valid reported error. But it is very weird this only occurs at 962 second mark but never when a slow operation occurs under that time.
Work-around: Create a new instance of the TableService each time we write to the database. This works but should not be necessary.
Additional comments:
Code used to reproduce the problem:
Please find in attachment the test I used to reproduce the issue, run under PyTest: test_stress_azure_tiny.txt
Test results: (latest)
The test was started at 8h17, last entry in DB was 17h02 and the exception stopped the test at 17h36 (34 minutes in limbo). So this time we waited 8+hours for the problem to occur.
The last entry from that test:
{
"PartitionKey": "azure_stress_test",
"RowKey": "998417850225.1086",
"Timestamp": "2020-02-19T22:03:56.835937+00:00",
"etag": "W/"datetime'2020-02-19T22%3A03%3A56.8359377Z'"",
"iteration": 1027,
"last_test_run_time": 0.01710820198059082,
"test_time_local": "2020-02-19 17:02:53.891263"
},
Pytest failure terminal output:
Stack trace obtained while a transaction is stuck
The test code and console output provided gives the stack when the exception occurs. But more interesting is: where is the stack when the TableService transaction appear to be stuck? It's doing “something” for 15+ minutes, but what? To obtain the stack of a stuck transaction, I use TableService in a separate thread, and dump the stack when it was taking too long to complete. I dumped the stack at regular intervals while researching this and always obtained the same stack.
STACK TRACE: of add_entity transaction pending for several minutes:
(using faulthandler.dump_traceback)
The text was updated successfully, but these errors were encountered: