We’ve recently started having an issue with subscriptions to
Event Store.
When our application comes up, it subscribes to a stream on
the instance of EventStore with catch-up, reprocesses all the events during
catch-up, then switches to processing events live as they come in. We are
using periodic snapshots to minimize the number of events we need to replay, so
we’re requesting catch-up from a specific event number.
This has always worked fine, but recently we’ve started
seeing a problem. Specifically what seems to happen is that during
catch-up we process just the first event, then it stops without any error
message. If you leave it for a short while (it can be anything from 30s
to five minutes) it will then start replaying events again. This then
continues for a few events (sometimes 10s, sometimes 100s) before it stops
again. This carries on until the replaying has finished and the live
subscription starts. So far it seems that once this happens all is fine.
We’re running version 3.9.2, though this version ran fine
for some time so I don’t think it’s related to this.
We’re also using Event Store in this way with several other
applications, and also with the same application in a couple of other places,
and none of these are having an issue – this only appears to happen on one
machine.
Whenever this happens, we get lots of entries similar to
this in the log:
[PID:00800:054
2017.03.07 20:50:35.443 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 203ms. Q: 0/1.
[PID:00800:063
2017.03.07 20:50:37.804 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 234ms. Q: 0/1.
[PID:00800:059
2017.03.07 20:50:38.462 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 218ms. Q: 0/1.
[PID:00800:063
2017.03.07 20:50:43.246 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 203ms. Q: 0/1.
[PID:00800:063
2017.03.07 20:50:44.200 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 202ms. Q: 0/1.
[PID:00800:063
2017.03.07 20:50:44.575 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 218ms. Q: 0/1.
[PID:00800:055
2017.03.07 20:50:45.575 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 234ms. Q: 0/1.
[PID:00800:054
2017.03.07 20:50:46.654 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 203ms. Q: 0/1.
[PID:00800:054
2017.03.07 20:50:50.636 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue
#4]: ReadStreamEventsBackward - 203ms. Q: 0/0.
[PID:00800:039
2017.03.07 20:51:01.404 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #4]: ReadStreamEventsBackward - 218ms. Q: 0/0.
[PID:00800:022
2017.03.07 20:51:01.529 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 343ms. Q: 0/0.
[PID:00800:033
2017.03.07 20:51:02.421 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 234ms. Q: 0/0.
[PID:00800:059
2017.03.07 20:51:03.500 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 203ms. Q: 0/0.
[PID:00800:022
2017.03.07 20:51:09.385 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #4]: ReadStreamEventsBackward - 265ms. Q: 0/0.
[PID:00800:052
2017.03.07 20:51:21.170 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 265ms. Q: 0/0.
[PID:00800:039
2017.03.07 20:52:01.689 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #1]: ReadStreamEventsBackward - 281ms. Q: 0/0.
[PID:00800:063
2017.03.07 20:52:02.706 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 203ms. Q: 0/0.
[PID:00800:055
2017.03.07 20:52:06.785 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 218ms. Q: 0/0.
[PID:00800:063
2017.03.07 20:52:23.823 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 284ms. Q: 0/0.
[PID:00800:050
2017.03.07 20:52:23.851 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #4]: ReadStreamEventsBackward - 249ms. Q: 0/0.
[PID:00800:022
2017.03.07 20:52:26.899 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 203ms. Q: 0/0.
[PID:00800:055
2017.03.07 20:53:15.513 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 205ms. Q: 0/0.
[PID:00800:022
2017.03.07 20:53:23.210 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #4]: ReadStreamEventsBackward - 218ms. Q: 0/0.
[PID:00800:069
2017.03.07 20:53:23.226 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [StorageReaderQueue
#3]: ReadStreamEventsBackward - 328ms. Q: 0/0.
[PID:00800:052
2017.03.07 20:53:25.118 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 250ms. Q: 0/0.
[PID:00800:055
2017.03.07 20:53:25.149 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 265ms. Q: 0/0.
[PID:00800:055
2017.03.07 20:53:26.119 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #4]: ReadStreamEventsBackward - 234ms. Q: 0/0.
[PID:00800:052
2017.03.07 20:53:27.199 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 249ms. Q: 0/0.
[PID:00800:054
2017.03.07 20:53:27.215 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 265ms. Q: 0/0.
[PID:00800:054
2017.03.07 20:53:44.201 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #3]: ReadStreamEventsBackward - 203ms. Q: 0/0.
[PID:00800:063
2017.03.07 20:55:55.302 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 281ms. Q: 0/0.
[PID:00800:059
2017.03.07 20:56:47.487 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG
[StorageReaderQueue #2]: ReadStreamEventsBackward - 202ms. Q: 0/0.
Does anyone have any idea what might be causing this?
Regards,
Carmen C.