Eventstore: Projections stalling

[fchaillou]

Hi,

We are still seeing the projections stalling with the 4.0.1 version of eventstore.
In the error log, we see some VERY SLOW QUEUE MSG

To fix the issue, we usually stop eventstore, reproject the index and restart it (which is starting to be long since we have more that 21 millions events in our system). We did it once without reprojecting the index and the projection restarted but missed some events so we do that to make sure.

[PID:00064:049 2017.06.05 05:10:39.955 ERROR QueuedHandlerThreadP] ---!!! VERY SLOW QUEUE MSG [StorageReaderQueue #3]: ReadStreamEventsForward - 7391ms. Q: 0/4.
[PID:00064:007 2017.06.05 05:10:47.793 ERROR QueuedHandlerThreadP] ---!!! VERY SLOW QUEUE MSG [StorageReaderQueue #4]: ReadStreamEventsBackward - 7857ms. Q: 1/13.
[PID:00064:054 2017.06.05 05:12:56.044 ERROR QueuedHandlerThreadP] ---!!! VERY SLOW QUEUE MSG [StorageReaderQueue #3]: ReadStreamEventsBackward - 7146ms. Q: 0/2.
[PID:00064:012 2017.06.05 05:32:44.582 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 22733ms. Q: 1/39.
[PID:00064:012 2017.06.05 05:33:01.439 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7163ms. Q: 1/7.
[PID:00064:012 2017.06.05 05:39:23.572 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 18270ms. Q: 1/21.
[PID:00064:012 2017.06.05 05:40:03.406 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 18052ms. Q: 1/62.
[PID:00064:012 2017.06.05 05:42:22.540 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 8473ms. Q: 0/13.
[PID:00064:012 2017.06.05 07:37:17.278 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 10664ms. Q: 0/0.
[PID:00064:012 2017.06.05 13:50:01.048 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 8526ms. Q: 0/19.
[PID:00064:012 2017.06.05 13:51:36.359 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 35260ms. Q: 0/4.
[PID:00064:012 2017.06.05 13:51:48.961 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7761ms. Q: 0/31.
[PID:00064:012 2017.06.05 13:51:58.448 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9486ms. Q: 0/50.
[PID:00064:012 2017.06.05 13:52:30.726 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 32276ms. Q: 0/143.
[PID:00064:012 2017.06.05 14:07:13.073 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 14960ms. Q: 1/87.
[PID:00064:012 2017.06.05 14:10:57.091 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 8968ms. Q: 0/0.
[PID:00064:012 2017.06.05 14:11:48.913 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 24266ms. Q: 0/20.
[PID:00064:012 2017.06.05 14:23:15.604 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 16753ms. Q: 0/44.
[PID:00064:012 2017.06.05 14:24:30.658 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7757ms. Q: 0/31.
[PID:00064:012 2017.06.05 14:26:02.731 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9218ms. Q: 0/0.
[PID:00064:012 2017.06.05 14:30:40.622 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 15095ms. Q: 0/8.
[PID:00064:012 2017.06.05 18:22:50.677 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 11573ms. Q: 0/0.
[PID:00064:012 2017.06.05 18:43:30.525 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9825ms. Q: 0/14.
[PID:00064:012 2017.06.05 18:44:15.961 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 13805ms. Q: 0/9.
[PID:00064:012 2017.06.05 19:43:43.269 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7910ms. Q: 1/21.
[PID:00064:012 2017.06.05 19:43:52.173 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 8904ms. Q: 0/32.
[PID:00064:012 2017.06.05 19:44:20.067 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 13576ms. Q: 0/50.
[PID:00064:012 2017.06.05 19:54:17.795 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9086ms. Q: 0/0.
[PID:00064:012 2017.06.05 20:04:41.431 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7281ms. Q: 0/10.
[PID:00064:012 2017.06.05 20:05:14.188 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 32736ms. Q: 0/27.
[PID:00064:041 2017.06.05 20:05:14.193 ERROR InMemoryBus         ] ---!!! VERY SLOW BUS MSG [manager input bus]: GetStatistics - 27774ms. Handler: ProjectionManager.
[PID:00064:041 2017.06.05 20:05:14.194 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [Projections Master]: GetStatistics - 27794ms. Q: 0/5.
[PID:00064:012 2017.06.05 21:57:46.268 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9949ms. Q: 1/9.
[PID:00064:012 2017.06.05 21:58:30.536 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 15705ms. Q: 1/8.
[PID:00064:063 2017.06.05 21:58:30.561 ERROR InMemoryBus         ] ---!!! VERY SLOW BUS MSG [Worker #3 Bus]: AuthenticatedHttpRequestMessage - 8397ms. Handler: AuthenticatedHttpRequestProcessor.
[PID:00064:063 2017.06.05 21:58:30.563 ERROR QueuedHandlerThreadP] ---!!! VERY SLOW QUEUE MSG [Worker #3]: AuthenticatedHttpRequestMessage - 8423ms. Q: 0/9.
[PID:00064:012 2017.06.05 22:05:13.824 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 7184ms. Q: 0/6.
[PID:00064:012 2017.06.05 23:43:18.927 ERROR QueuedHandlerAutoRes] ---!!! VERY SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 9496ms. Q: 1/17.

What else can i give you to help you ?
Thanks for your help
Fabien

[pgermishuys]

I have a couple of questions regarding your environment...

1. How many projections do you have running?
2. What are those projections doing if you have any custom ones?
3. What does your environment look like that you are running on (CPU, Disk, RAM, OS, etc)...

Thanks!

[fchaillou]

Hi,
FYI we already reported an issue on the subject last year (#1097 by a former colleague)
Here is the information on the environment :
1) We have 10 projections plus the 4 standard ones (we used to only have 7 and we had the issue with only seven)
2) the projections are pretty simple. Mostly grouping all events from a category into a unique stream

fromCategory("omrecord_events")
  .foreachStream()
  .when({
      $any : function(s,e){
         linkTo("omrecord_events_all", e);
      }
  })

and one grouping streams resulting from previous projections :

fromStreams(["omrecord_events_all","omplus_packets_persisted_all","omplus_gps_persisted_all"])
   .when({
     $any : function(s,e){
       linkTo("omrecord_discovery_events", e);
     }
  })

1. We have eventstore running in AWS on its own machine which is a r4.large (15.25 GB of memory, 2 vCPUs, Network up to 10Gigabit). It is running in a docker 1.6 container. The os is ubuntu Ubuntu 14.04.2 LTS with a linux kernel 3.13.0

Hopes that helps
Fabien

[nissbran]

What kind of disks are you using on AWS?

EventStore is very disk IO intensive, and can have performance problems if the disks are too slow. We used Azure with EventStore and we managed to hit the disk IOPS throttling quite easily during load tests.

[fchaillou]

We are using standard disk, we used to use ssd but in any case we really don't have a big load at all. looking at the cloudwatch monitoring, we almost never exceed 300 kb/s in write bandwitdh and our read bandwith is most of the time below 1kb/s (the exception is our daily backup/scavenge scheduled at night)

[nissbran]

Ok, then it might be something else. But the log output is very similar to the one we got when we load tested our solution (Disk IO Throttling).

[regis-leray]

@pgermishuys Hi for us it has been a real problem, what kind of informations or action can we do or provide to help to discover the root cause.

This problem was already there is 3.x and now in 4.x
I was reading the documentation, but i didn't see any hardware / software configuration minimun requirements ? Are we the only ones having this issue ?

We also since a long time (even after we have upgrade to better hardware) slow message queue
https://github.com/EventStore/EventStore/issues/1258. Do you have any informations about that ?

I will send to your email the full logs

Thanks

PS: I m a colleague of @fchaillou.

[pgermishuys]

@regis-leray and @fchaillou we are more than happy to work with you regarding this issue. I appreciate how frustrating this might be for you. There have been numerous fixes and improvements made to projections since 3.5.0 and we will continue to do so moving forward.

Can you provide us with the following

1. Set of logs
2. How do you determine that your projection is actually stalled?
3. Are all the projections stalled?
4. When you determine that your projection has stalled, what are the projection details? Capturing the projection state at that point would be helpful to diagnose the issue. This can be done via issuing a web request to the /projections/any endpoint
   e.g.

curl -i http://localhost:2113/projections/any

[regis-leray]

@pgermishuys

1. i sent you the logs for the full month of june to your email : petier at geteventstore com
   The stalling happen the 4 june , we only fix the problem the 6 june (by deleting the index and restart eventstore). Deleting the index is to be 100% sure the system will detect new events (it happens in the past), after this manual operation the system was up and running, no more issue.

2. The projection omrecord_events_alldidnt receive any new events. In the getevenstore UI, it was obvious to see in the stream omrecord_events_all didn't have any new events, and the last one was the 4 june. We could see in other streams omrecord_events-XXX they had new events.

fromCategory("omrecord_events")
  .foreachStream()
  .when({
      $any : function(s,e){
         linkTo("omrecord_events_all", e);
      }
  })

1. We didnt check, but when it happens the last time with version 3.x every projections were stalled
2. i didnt grab the projection status at this time, but i still have a backup at this period when the projections were stalled

[pgermishuys]

@regis-leray the email is pieter at geteventstore dot com...
I am not sure what you are referring to when you say you are rebuilding the index. What index?

[regis-leray]

we deleted the folder /var/lib/eventstore/index and restarted the server. And by default it rebuilds all the indexes.

[hayley-jean]

@regis-leray How did you correlate rebuilding the index to the skipped events in projections?
How did you determine that the events were skipped?

[hayley-jean]

And as a follow-up question, how big on average are your events?

[fchaillou]

@hayley-jean for the correlation, i once restarted eventstore while the projection got stuck without rebuilding the index and in that case, the projection started again but it skipped events whereas when we rebuild the index on restart, we don't have any skipped events issue.

for the size of our events, we mostly have pretty small events a few hundred bytes. We also have some bigger events (we are using some streams as snapshots) and for those we could go up to a few kilobytes.

[hayley-jean]

After looking through your logs, it looks like the reason your projection stalled was because the $by_category projection silently failed due to running out of retries for a write to one of the category streams:

[PID:00064:044 2017.06.05 13:51:43.360 INFO  CoreProjectionCheckp] Failed to write events to stream $ce-omrun_events. Error: CommitTimeout
[PID:00064:044 2017.06.05 13:51:43.360 DEBUG ResponseWriter      ] PROJECTIONS: Scheduling the writing of $faulted to $projections-$master. Current status of Writer: Busy: True

The reason for the silent failure is because of a read timeout on one of the main projection streams a few days prior. One of the responsibilities of the part that failed is to update the projection statuses (such as putting them into a failed state.) This means that the UI was not updated, and neither was the projection status, making it look like the projections had just stalled. I am currently investigating a fix for this issue so that it will not fail silently again.

If you run into this again, a restart should get everything up and running. An index rebuild would not be required. If you see skipped events in your projection again, please can you open another issue and provide logs and examples there.

[gregoryyoung]

As an aside to Hayley's answer why are you writing these projections?

fromCategory("omrecord_events")
.foreachStream()
.when({
$any : function(s,e){
linkTo("omrecord_events_all", e);
}
})

As example.

You can just use $ce-cmrecord_events which will have the exact same
data as your cmrecord_events_all stream.

On Wed, Jun 7, 2017 at 3:47 PM, Fabien Chaillou [e-mail]
wrote:

Hi,
FYI we already reported an issue on the subject last year (#1097
https://github.com/EventStore/EventStore/issues/1097 by a former
colleague)
Here is the information on the environment :

1. We have 10 projections plus the 4 standard ones (we used to only
   have 7 and we had the issue with only seven)
2. the projections are pretty simple. Mostly grouping all events from
   a category into a unique stream

fromCategory("omrecord_events")
.foreachStream()
.when({
$any : function(s,e){
linkTo("omrecord_events_all", e);
}
})

and one grouping streams resulting from previous projections :

fromStreams(["omrecord_events_all","omplus_packets_persisted_all","omplus_gps_persisted_all"])
.when({
$any : function(s,e){
linkTo("omrecord_discovery_events", e);
}
})

1. We have eventstore running in AWS on its own machine which is a
   r4.large (15.25 GB of memory, 2 vCPUs, Network up to 10Gigabit). It is
   running in a docker 1.6 container. The os is ubuntu Ubuntu 14.04.2 LTS with
   a linux kernel 3.13.0

Hopes that helps
Fabien

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/EventStore/EventStore/issues/1330#issuecomment-306818195,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAXRWt8n51Ag3vQu5V4hlA6GP8D_jbVkks5sBrgJgaJpZM4Nxk5T
.

--
Studying for the Turing test

[regis-leray]

@gregoryyoung we could totally use $ce-cmrecord_events we didn't know we have this stream available. thanks we will remove this useless projection. We dont need it !

@hayley-jean thanks for the investigation, we are waiting for the fix. Doesn't the failing will make the global projection failed $by_category and also $ce-omrecord_events ?

If the global projection $by_category failed, all the projections will failed also ?

[fchaillou]

@hayley-jean thanks for the investigation, this is great news ! Just a quick question though, do you have any idea why the projection would timeout ? Has it something to do with our the underlying hardware being not enough or an high load or something else maybe ? Do you have any suggestion to avoid those maybe ?

@gregoryyoung thanks for the advice, we will totally do that, this simplifies our code and probably avoids loading the system with useless processing.

[TheAngryByrd]

@hayley-jean any progress on investigating the system projections stopping?

[hayley-jean]

The issue is currently being worked on