add a few additional optimizations to the callback receiver #8193

ryanpetrello · 2020-09-21T19:45:18Z

cc: @gamuniz

Many events, few tasks:

Many events, many tasks:

softwarefactory-project-zuul · 2020-09-21T19:53:28Z

Build succeeded.

awx-api-lint : SUCCESS in 1m 59s
awx-api : SUCCESS in 7m 06s
awx-ui : SUCCESS in 3m 29s
awx-ui-next : SUCCESS in 7m 33s
awx-swagger : SUCCESS in 7m 42s
awx-detect-schema-change : SUCCESS in 7m 50s (non-voting)
awx-ansible-modules : SUCCESS in 2m 15s

ryanpetrello · 2020-09-21T20:59:49Z

awx/main/models/events.py

@@ -58,6 +59,11 @@ def create_host_status_counts(event_data):


 def emit_event_detail(event):
+    if (
+        settings.UI_LIVE_UPDATES_ENABLED is False and
+        event.event not in ('playbook_on_stats', 'EOF')


I'd like to maybe make this be not startswith("runner_"), but I'm having some trouble getting the UI to behave in a reasonable way cc @jakemcdermott is taking a look, I think.

wenottingham · 2020-09-21T21:47:16Z

How hard is a placeholder in the text window in this case?

softwarefactory-project-zuul · 2020-09-21T23:06:15Z

Build succeeded.

awx-api-lint : SUCCESS in 2m 25s
awx-api : SUCCESS in 6m 26s
awx-ui : SUCCESS in 3m 13s
awx-ui-next : SUCCESS in 8m 05s
awx-swagger : SUCCESS in 7m 33s
awx-detect-schema-change : SUCCESS in 8m 08s (non-voting)
awx-ansible-modules : SUCCESS in 2m 37s

softwarefactory-project-zuul · 2020-09-21T23:20:17Z

Build succeeded.

awx-api-lint : SUCCESS in 2m 10s
awx-api : SUCCESS in 6m 21s
awx-ui : SUCCESS in 3m 34s
awx-ui-next : SUCCESS in 9m 38s
awx-swagger : SUCCESS in 7m 51s
awx-detect-schema-change : SUCCESS in 10m 07s (non-voting)
awx-ansible-modules : SUCCESS in 2m 43s

ryanpetrello · 2020-09-21T23:22:04Z

@wenottingham see updated behavior in GIFs above.

softwarefactory-project-zuul · 2020-09-22T00:52:38Z

Build succeeded.

awx-api-lint : SUCCESS in 2m 22s
awx-api : SUCCESS in 6m 51s
awx-ui : SUCCESS in 4m 06s
awx-ui-next : SUCCESS in 8m 35s
awx-swagger : SUCCESS in 6m 59s
awx-detect-schema-change : SUCCESS in 7m 47s (non-voting)
awx-ansible-modules : SUCCESS in 2m 21s

softwarefactory-project-zuul · 2020-09-22T13:08:12Z

Build succeeded.

awx-api-lint : SUCCESS in 11m 07s
awx-api : SUCCESS in 14m 33s
awx-ui : SUCCESS in 11m 47s
awx-ui-next : SUCCESS in 15m 55s
awx-swagger : SUCCESS in 16m 18s
awx-detect-schema-change : SUCCESS in 16m 17s (non-voting)
awx-ansible-modules : SUCCESS in 10m 43s

ryanpetrello · 2020-09-22T13:59:33Z

Here are some before/after numbers of this PR processing a large backlog of events on a single node m5.4xlarge install. Both are using the default settings.JOB_EVENT_WORKERS = 4, and the external logger is disabled.

before (devel)

[root@ip-10-0-4-131 ec2-user]# awx-manage callback_stats
main_jobevent
↳  last minute 123999

main_inventoryupdateevent
↳  last minute 0

main_projectupdateevent
↳  last minute 0

main_adhoccommandevent
↳  last minute 0

after (`UI_LIVE_UPDATES_ENABLED` = `False`)

[root@ip-10-0-5-5 ec2-user]# awx-manage callback_stats
main_jobevent
↳  last minute 532999

main_inventoryupdateevent
↳  last minute 0

main_projectupdateevent
↳  last minute 0

main_adhoccommandevent
↳  last minute 0

ryanpetrello · 2020-09-22T14:06:41Z

Here is the same comparison again, but with logging configured and pointed at a local UDP port via rsyslogd:

before (devel)

[root@ip-10-0-4-131 ec2-user]# awx-manage callback_stats
main_jobevent
↳  last minute 91999

main_inventoryupdateevent
↳  last minute 0

main_projectupdateevent
↳  last minute 0

main_adhoccommandevent
↳  last minute 0

after (UI_LIVE_UPDATES_ENABLED = False)

[root@ip-10-0-5-5 ec2-user]# awx-manage callback_stats
main_jobevent
↳  last minute 334999

main_inventoryupdateevent
↳  last minute 0

main_projectupdateevent
↳  last minute 0

main_adhoccommandevent
↳  last minute 0

ryanpetrello · 2020-09-22T14:16:17Z

With UI_LIVE_UPDATES_ENABLED = False and JOB_EVENT_WORKERS=16 on an m5.4xlarge (logging disabled), I'm able to break 1M inserts per minute:

[root@ip-10-0-5-5 ec2-user]# awx-manage callback_stats
main_jobevent
↳  last minute 1096363

main_inventoryupdateevent
↳  last minute 0

main_projectupdateevent
↳  last minute 0

main_adhoccommandevent
↳  last minute 0

awx/main/models/events.py

ryanpetrello · 2020-09-22T15:04:40Z

@moonrail @psuriset either of you have any time to give this patch a whirl in comparison with stable builds? Specifically, I'm curious to see how event processing time improves.

ryanpetrello · 2020-09-22T15:26:16Z

awx/main/models/events.py

-            'Event data saved.',
-            extra=dict(python_objects=dict(job_event=self))
-        )
+        if settings.LOG_AGGREGATOR_ENABLED:


Our custom filter technically checks this flag, too, but it does so after making the logging record and looping through all the handlers (which is actually pretty expensive). If logging is disabled, it's cheaper to just not call this .info() function at all.

ryanpetrello · 2020-09-22T19:41:34Z

awx/conf/settings.py

@@ -406,6 +410,7 @@ def _get_default(self, name):
    def SETTINGS_MODULE(self):
        return self._get_default('SETTINGS_MODULE')

+    @cachetools.cached(cache=cachetools.TTLCache(maxsize=2048, ttl=SETTING_MEMORY_TTL))


In my profiling for high workloads, the cache hits for redis actually add up and end up being quite expensive in bulk; even though it's just a round trip to a domain socket, it's still 10+ round trips per emitted event (because we access a handful of distinct settings to determine how to log) and that has a real cost when you multiply it by millions of events

For the purposes of the callback receiver, it's probably not imperative that we have real-time correctness for these setting values (caching for a few seconds locally in memory makes a notable performance improvement).

mabashian

UI changes lgtm

jbradberry · 2020-09-23T14:13:30Z

awx/main/models/events.py

@@ -57,7 +58,18 @@ def create_host_status_counts(event_data):
    return dict(host_status_counts)


+MINIMAL_EVENTS = set([


I would think that with a set this small that the hash calculation would overwhelm the big-O lookup advantage you gain by using a set instead of a tuple.

softwarefactory-project-zuul · 2020-09-23T14:58:40Z

Build succeeded (gate pipeline).

awx-api-lint : SUCCESS in 2m 06s
awx-api : SUCCESS in 8m 20s
awx-ui : SUCCESS in 3m 35s
awx-ui-next : SUCCESS in 8m 13s
awx-swagger : SUCCESS in 8m 11s
awx-detect-schema-change : SUCCESS in 9m 54s (non-voting)
awx-ansible-modules : SUCCESS in 2m 36s
awx-push-new-schema : SUCCESS in 8m 00s (non-voting)

mcharanrm · 2020-09-24T13:25:44Z

Hello @ryanpetrello, @kdelee CC: @psuriset, We deployed patch on 3 node cluster and all the 3 nodes are virtual machines (created using libvirt) with RHEL 7.8 installed. Each vm's configured with 4vcpus, 23G RAM, and 75G of shared disk space. We can see 33.8% increase in events processing rate after changing UI_LIVE_UPDATES_ENABLED: false and having higher event processing rate can explains less event lag between job run time and jobs events processing time.
Please take a look at our CPT graphs.

Please let me know if there is anything else that i need to test it.

ryanpetrello · 2020-09-24T13:30:16Z

This looks great - thank you @mcharanrm!

ryanpetrello assigned chrismeyersfsu, ghjm, wenottingham and jakemcdermott Sep 21, 2020

ryanpetrello unassigned chrismeyersfsu, ghjm, wenottingham and jakemcdermott Sep 21, 2020

ryanpetrello requested review from chrismeyersfsu, ghjm, jakemcdermott and wenottingham September 21, 2020 20:59

ryanpetrello commented Sep 21, 2020

View reviewed changes

jakemcdermott force-pushed the ws-broadcast-limited branch 2 times, most recently from 56e3470 to 9d23f64 Compare September 21, 2020 22:57

ansible deleted a comment from softwarefactory-project-zuul bot Sep 21, 2020

ryanpetrello force-pushed the ws-broadcast-limited branch from 9d23f64 to b22de28 Compare September 21, 2020 23:09

ryanpetrello requested a review from matburt September 21, 2020 23:13

jakemcdermott requested a review from mabashian September 21, 2020 23:18

ryanpetrello and others added 2 commits September 21, 2020 20:42

don't broadcast ws:// events when UI_LIVE_UPDATES_ENABLED is False

bed2dea

Reload on stats when live updates are disabled

b6afc08

ryanpetrello force-pushed the ws-broadcast-limited branch from b22de28 to b6afc08 Compare September 22, 2020 00:43

add a few additional optimizations to the callback receiver

b370e83

ryanpetrello changed the title ~~don't broadcast ws:// events when UI_LIVE_UPDATES_ENABLED is False~~ add a few additional optimizations to the callback receiver Sep 22, 2020

jakemcdermott reviewed Sep 22, 2020

View reviewed changes

awx/main/models/events.py Show resolved Hide resolved

ryanpetrello requested a review from AlanCoding September 22, 2020 15:25

ryanpetrello commented Sep 22, 2020

View reviewed changes

jakemcdermott added component:ui component:api state:needs_review labels Sep 22, 2020

jakemcdermott requested a review from jlmitch5 September 22, 2020 21:20

mabashian approved these changes Sep 22, 2020

View reviewed changes

jakemcdermott mentioned this pull request Sep 22, 2020

Remove any remaining window.liveUpdates behavior from lists #8211

Closed

rebeccahhh approved these changes Sep 23, 2020

View reviewed changes

jbradberry reviewed Sep 23, 2020

View reviewed changes

ryanpetrello requested a review from shanemcd September 23, 2020 14:26

ryanpetrello added the mergeit label Sep 23, 2020

shanemcd approved these changes Sep 23, 2020

View reviewed changes

softwarefactory-project-zuul bot merged commit d7ca49c into ansible:devel Sep 23, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add a few additional optimizations to the callback receiver #8193

add a few additional optimizations to the callback receiver #8193

ryanpetrello commented Sep 21, 2020 •

edited by jakemcdermott

Loading

softwarefactory-project-zuul bot commented Sep 21, 2020

ryanpetrello Sep 21, 2020

wenottingham commented Sep 21, 2020

softwarefactory-project-zuul bot commented Sep 21, 2020

softwarefactory-project-zuul bot commented Sep 21, 2020

ryanpetrello commented Sep 21, 2020 •

edited

Loading

softwarefactory-project-zuul bot commented Sep 22, 2020

softwarefactory-project-zuul bot commented Sep 22, 2020

ryanpetrello commented Sep 22, 2020

ryanpetrello commented Sep 22, 2020

ryanpetrello commented Sep 22, 2020 •

edited

Loading

ryanpetrello commented Sep 22, 2020

ryanpetrello Sep 22, 2020 •

edited

Loading

ryanpetrello Sep 22, 2020 •

edited

Loading

mabashian left a comment

jbradberry Sep 23, 2020

softwarefactory-project-zuul bot commented Sep 23, 2020

mcharanrm commented Sep 24, 2020 •

edited

Loading

ryanpetrello commented Sep 24, 2020

		@@ -57,7 +58,18 @@ def create_host_status_counts(event_data):
		return dict(host_status_counts)


		MINIMAL_EVENTS = set([

add a few additional optimizations to the callback receiver #8193

add a few additional optimizations to the callback receiver #8193

Conversation

ryanpetrello commented Sep 21, 2020 • edited by jakemcdermott Loading

softwarefactory-project-zuul bot commented Sep 21, 2020

ryanpetrello Sep 21, 2020

Choose a reason for hiding this comment

wenottingham commented Sep 21, 2020

softwarefactory-project-zuul bot commented Sep 21, 2020

softwarefactory-project-zuul bot commented Sep 21, 2020

ryanpetrello commented Sep 21, 2020 • edited Loading

softwarefactory-project-zuul bot commented Sep 22, 2020

softwarefactory-project-zuul bot commented Sep 22, 2020

ryanpetrello commented Sep 22, 2020

before (devel)

after (UI_LIVE_UPDATES_ENABLED = False)

ryanpetrello commented Sep 22, 2020

before (devel)

after (UI_LIVE_UPDATES_ENABLED = False)

ryanpetrello commented Sep 22, 2020 • edited Loading

ryanpetrello commented Sep 22, 2020

ryanpetrello Sep 22, 2020 • edited Loading

Choose a reason for hiding this comment

ryanpetrello Sep 22, 2020 • edited Loading

Choose a reason for hiding this comment

mabashian left a comment

Choose a reason for hiding this comment

jbradberry Sep 23, 2020

Choose a reason for hiding this comment

softwarefactory-project-zuul bot commented Sep 23, 2020

mcharanrm commented Sep 24, 2020 • edited Loading

ryanpetrello commented Sep 24, 2020

ryanpetrello commented Sep 21, 2020 •

edited by jakemcdermott

Loading

ryanpetrello commented Sep 21, 2020 •

edited

Loading

after (`UI_LIVE_UPDATES_ENABLED` = `False`)

ryanpetrello commented Sep 22, 2020 •

edited

Loading

ryanpetrello Sep 22, 2020 •

edited

Loading

ryanpetrello Sep 22, 2020 •

edited

Loading

mcharanrm commented Sep 24, 2020 •

edited

Loading