Event Daemon Slowness?

I am not sure if we just have to many events registered or something else, but it is taking 40+min from when an event happens to when our event daemon finally triggers it.

I was curious if anyone had any issues with this or had best daemon practices for performance.

TIA

6 Likes

Hi Chris,

How many events are registered? What about the performance if you use API to access shotgun server?

Thanks

Loney

1 Like

Just to add my thoughts as well. It sounds as though your event daemon is running behind, and has a backlog of events to catch up on.

If you have many event plugins or your events are likely to get triggered frequently and respond to large volumes of events, you need to make sure they are written and efficiently as possible.

You should limit the number of calls you make to Shotgun, try to use batch calls where possible.

When not debugging, try to ensure they produce as little logging output as possible.

You can also enable a timer logging on your plugins to see which ones are taking the most time:

If you have any plugins that need to do heavy lifting, consider threading them out or sending them as jobs to a farm to process.

Shotgun API calls can be configured as to whether they generate events, by setting it on the Script entity you’re using to authenticate within Shotgun. If your plugins are making changes to the Shotgun site and they are further triggering plugins needlessly then consider perhaps using a script that doesn’t generate events.

This may not apply in your situation, but when I was a using Shotgun in production we had a tool that ingested a load of data into Shotgun, creating up wards of about 300 assets in one go. We had an event daemon plugin that we wanted to respond to some of the changes, but when ever we ingested a large amount of data this would create a backlog. So instead we made it so the tool didn’t generate events automatically, and at the end of ingestion, it manually created a custom event in Shotgun and provided a dictionary of the entities it created via the metadata field. Then our plugin would respond to the single custom event and read the assets out of the meta data and respond accordingly.
You could argue that why didn’t the ingest tool handle the logic rather than deferring it to the event daemon, but the reason was that we had other tools where similar operations could occur and so we opted to have these tools create custom events representing multiple changes and have it processed in one place.

Anyway enough of my rambling :smiley: !

7 Likes

Thanks Phillip and Loney,

Just to provide the info here:

We have about 23 callbacks registered. The shotgun API performance seems pretty quick.

Looking into Philip’s point, the evidence does seem to point to a lagging behind behavior.
Thank you very much for the helpful tips! Will try to implement and post back if we find any interesting notes.

3 Likes

Hi Philip,

I do not seem to have such a timing_log option in my current configuration, is it something that can be added manually or do I need to update my configuration?

Thanks a lot,
Francois

1 Like

You might want to update from master.

1 Like

Yep, I will have to :smiley:

I would like to have some input about two parameters I noticed in shotgunEventDaemon.conf:
fetch_interval = 5 and
max_event_batch_size = 500

If I get it right, the _mainloop of shotgunEventDaemon :

  1. fetches events with _get_NewEvents, which takes the last processed event as starting point and fetches all events with IDs above this reference,
  2. processes these events with the plugins
  3. checks the amount of processed events and sleeps for fetch_interval seconds if this amount is under max_event_batch_size

So now I’m wondering how changing max_event_batch_size to 300 (for ex) would impact the event handler. It would sleep less, so from my point of view there would be less risk of lag; but I guess there are some reasons not visible from the shotgunEventHandler code to choose these two values of 500 events and 5s. Would it remain stable? would the batch operations be still optimum?

Edit: looking into the logs of shotgunEventDaemon I noticed it seems to get locked on some of the events sometimes, and processing them again and again and again, until it jumps over for whatever reason:

2019-10-25 00:24:43,931 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:24:49,147 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:24:54,362 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:24:59,578 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:04,793 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:10,035 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:15,246 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:20,455 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:25,683 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:30,887 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:36,101 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:41,327 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:46,555 - engine - DEBUG - Checking events from 22120170
2019-10-25 00:25:53,764 - engine - DEBUG - Checking events from 22120185
2019-10-25 00:25:59,297 - engine - DEBUG - Checking events from 22120188
2019-10-25 00:26:04,518 - engine - DEBUG - Checking events from 22120188
2019-10-25 00:26:09,744 - engine - DEBUG - Checking events from 22120188
2019-10-25 00:26:14,964 - engine - DEBUG - Checking events from 22120188
2019-10-25 00:26:20,384 - engine - DEBUG - Checking events from 22120194
2019-10-25 00:26:25,592 - engine - DEBUG - Checking events from 22120194
2019-10-25 00:26:30,799 - engine - DEBUG - Checking events from 22120194
2019-10-25 00:26:36,106 - engine - DEBUG - Checking events from 22120197
2019-10-25 00:26:41,325 - engine - DEBUG - Checking events from 22120197
2019-10-25 00:26:47,006 - engine - DEBUG - Checking events from 22120214

(Sorry, I know this makes a lot of questions :-/ )

2 Likes

Hi François,

The max_event_batch_size is a default value for the number of events to fetch which is a compromise between the time it takes for the app to produce results and the time for them to be sent over the wire. You don’t want to fetch too many events that your request blocks one of the app’s threads too long but you don’t want to fetch too few that you’re spending your time waiting for tiny batches of data over your network link’s latency.

This being said, the key parameter will be the fetch_interval. If the last time the daemon loaded data, if it got fewer than max_event_batch_size events, it’ll wait the amount of time prescribed by fetch_interval so increasing this value will process things slightly faster and will increase the probability your next fetch gets fewer than max_event_batch_size.

There’s a third value you can tweak but isn’t exposed in the config as it is much more delicate.

There is a phenomenon by which there can be a gap in the event sequence and sometimes that gap can be filled in later. Gaps aren’t super frequent but are regular, gaps that get filled in are rarer. Even if this later phenomenon is rare, we need to ensure that events are processed linearly otherwise we can introduce bad data. To do this, each missing event is given a time window in which it can reappear. We’ll process all events up to a gap, wait there, if and when the gap fills up we continue until the next gap. This build up what we call a backlog. The amount of time we wait is defined by a constant you can find the source code called BACKLOG_TIMEOUT. If you decrease this, gaps won’t slow down your daemon as much but the probability you miss a gap that fills up will increase. Ultimately, tweaking this value depends on your level of risk aversion.

Sure hope this helps you tweak your daemon!

3 Likes

Hi Patrick, thanks for your help.

I will do my best not to reach the BACKLOG_TIMEOUT point :wink:

Just to be sure: you mean 'decreasing", right?

Francois

1 Like