Jobs results can be very slow / unable to display due to thousands of ensure_git_repository calls
#1515
Comments
|
I just saw nautobot/nautobot/docs/release-notes/version-1.3.md Lines 24 to 41 in 6616f55 |
|
I was able to access the page using this temporary workaround (caching for 5 secs the docker-compose exec --user root nautobot sed -ie '/@cached(timeout=5) # TMP/d;s/def get_jobs/@cached(timeout=5) # TMP\ndef get_jobs/' /usr/local/lib/python3.10/site-packages/nautobot/extras/jobs.py
docker-compose restart nautobot(For some reason, my user page count was set to 1000, that's why there were so many things to refresh; still that shouldn't happen) |
|
Adding caching here would definitely be an appropriate improvement to make. The introduction of the concrete Job model may help somewhat but I think this is likely to still be an issue in some views, which caching could improve immensely. |
glennmatthews
added
type: bug
Note that this workaround seems to cause issues when a job form is refreshed rapidly (and maybe at other places), some custom job fields, like selection, can appear unpopulated, while the job code populate it correctly .. |
|
@jathanism thank you, I was able to test but result was the same as in #1515 (comment), still some errors. First I though it was a concurrency issue with To workaround this, I tried to use a custom per-thread caching key: # https://github.com/Suor/django-cacheops/blob/5.1/cacheops/simple.py#L53
# https://github.com/Suor/django-cacheops/blob/5.1/cacheops/utils.py#L89
# https://docs.python.org/3/library/threading.html
# https://github.com/python/cpython/blob/3.10/Lib/threading.py
def _cacheops_func_cache_key_per_thread(func, args, kwargs, extra=None):
"""
Calculate cache key based on func, arguments and current thread
"""
import threading
from cacheops.utils import json, md5hex, obj_key
current_thread = threading.current_thread()
thread_factors = [current_thread.name, current_thread.ident]
if hasattr(current_thread, 'native_id'):
thread_factors.append(current_thread.native_id)
factors = [func, args, kwargs, extra, thread_factors]
key = md5hex(json.dumps(factors, sort_keys=True, default=obj_key))
# Debug
#import logging
#logging.getLogger("nautobot.jobs").warning('>>>>>>>>>>>>>>>>>>>>>>>>> {} {} {}'.format(threading.current_thread(), thread_factors, key))
return key
@cached(timeout=60, key_func=_cacheops_func_cache_key_per_thread)
def get_jobs():
[...]This forces each thread to run Note that with uWSGI, I'm not sure this is enough to cover all uWSGI configurations however. And about
The empty selection error was because I used a generator to populate a ChoiceVar field, this wasn't correct as only the first read would return choices, adding caching made this appear. Also, Nautobot seems to import jobs as top-level modules (https://github.com/nautobot/nautobot/blob/v1.2.10/nautobot/extras/jobs.py#L826), couldn't this be an issue with a job file named Some notes to play with import cacheops, pickle, pickletools
pickle.loads(cacheops.redis.redis_client.get('c:963f6d84537803f7b1b7ac6d318eb132'))
pickletools.dis(cacheops.redis.redis_client.get('c:963f6d84537803f7b1b7ac6d318eb132')) |
|
@u1735067 Great feedback, thanks! I very much appreciate your in-depth analysis here. |
Would you mind filing this as a new issue? You're spot on here and it would be good to get this addressed by changing the way job modules are imported. |
Glad to help :)
Sure, done in #1598 (FE)
This may be better written like this, because of uwsgi specificities: def _cacheops_func_cache_key_per_thread(func, args, kwargs, extra=None):
"""
Calculate cache key based on func, arguments and current thread
"""
import threading
from cacheops.utils import json, md5hex, obj_key
current_thread = threading.current_thread()
thread_factors = [
current_thread.name,
current_thread.ident,
current_thread.native_id if hasattr(current_thread, 'native_id') else 0
]
# https://uwsgi-docs.readthedocs.io/en/latest/PythonModule.html
# https://github.com/unbit/uwsgi/blob/2.0.20/plugins/python/uwsgi_pymodule.c#L2157
# https://github.com/unbit/uwsgi/blob/2.0.20/core/master_utils.c#L702
try:
import uwsgi
uwsgi_workers = uwsgi.workers()
uwsgi_worker_id = uwsgi.worker_id()
uwsgi_worker_index = uwsgi_worker_id - 1
thread_factors += (
uwsgi_worker_id,
# Because workers might respawn, worker_id is not enough
uwsgi_workers[uwsgi_worker_index]['pid'],
uwsgi_workers[uwsgi_worker_index]['last_spawn']
)
except ImportError:
pass
factors = [func, args, kwargs, extra, thread_factors]
key = md5hex(json.dumps(factors, sort_keys=True, default=obj_key))
# Debug
#import logging
#logging.getLogger("nautobot.jobs").warning('>>>>>>>>>>>>>>>>>>>>>>>>> {} {} {}'.format(threading.current_thread(), thread_factors, key))
return key |
Thanks for this deep analysis. I for one very much appreciate you taking the time and effort to help us arrive at a solution. After reviewing it, your solution is specific to uWSGI workers and so may be incomplete for installations not using uWSGI. So after doing some debugging we tried to arrive at an alternate solution that uses file-based caching, so that thread safety is obviated and all processes on the same system can access the cache directly from the file system. If you wouldn't mind trying the latest HEAD from the PR, that would be fabbbuulouuuuus. Thanks! |
Yes thank you, I'll test in the next days, I'm not sure it'll work however, as the issue when using cache (redis or file backed) is that the |
We moved the cached call down to
|
Oh right, I looked quickly and missed that, sorry! I just tested and there's no errors yes 🙂
And the case when repo is removed but
This is still a large part of the time sadly, I tested the TTBF (time to first byte) of 1063 git jobresults
|
|
Thinking about this from a different angle - as you pointed out, the main critical path here is I wonder therefore if we should revisit how this table column is calculated/rendered so that it only calls def job_creator_link(value, record):
"""
Get a link to the related object, if any, associated with the given JobResult record.
"""
# record.related_object is potentially slow if the related object is a Job class,
# as it needs to actually (re)load the Job class into memory. That's unnecessary
# computation as we don't actually need the class itself, just its class_path which is already
# available as record.name on the JobResult itself. So save some trouble:
if record.obj_type == ContentType.objects.get(app_label="extras", model="job"):
return reverse("extras:job", kwargs={"class_path": record.name})
# If it's not a Job class, maybe it's something like a GitRepository, which we can look up cheaply:
related_object = record.related_object
if related_object:
return related_object.get_absolute_url()
return None |
Giving this a try and will report back. |
|
That won't be exactly right, on reflection, as you will want to change the Column definition so that it doesn't automatically try to load |
|
@u1735067 We revised this again to hybridize the approach here to assert that the caching is in place for Git-based jobs, and that the One thing however, is that we updated the base for this fix from |
|
While we believe this issues will be closed with #1585, we will leave this open for a bit of time to confirm resolution with reporter. |
|
On 1.2.10 it's not enough as accessing the name (by The same happens on 1.3.0: In 1.2.10, patching @property
def related_name(self):
if self.obj_type == ContentType.objects.get(app_label="extras", model="job"):
return self.name
related_object = self.related_object
if not related_object:
return self.name
if hasattr(related_object, "name"):
return related_object.name
return str(related_object)Not caching |
It's messy - Git repository syncs are not presently considered to be Jobs, but they do create a JobResult where the GitRepository is the Thanks for the update! |
|
In the short term I think we could collapse the |
Environment
Steps to Reproduce
Expected Behavior
Job results are displayed in less than a few seconds max
Observed Behavior
Navigation fails, reverse proxy displays 502 Bad Gateway after 60s or more time, or if there's too much trafic, the container itself is considered unhealthy and a reverse proxy like Traefik can remove it as backend, resulting in 404.
Additional informations
(maybe this title could be added by default to the bug template ?)
In the container logs (of the
nautobotcontainer, not thecelery_workerone), I've noticed thousands of thoses lines:I've noticed this in the past (#744) but it seemed harmless at the time; today, with way more JobResults, it's impossible for the page to display.
The
ensure_git_repositorycall seems to be made for each JobResult related to a Git job, maybe limited to the MAX_PAGE_SIZE count or the user page count, but I'm not sure since there's really a lot of logs.This can be critical, because when called multiple times, it can cause the healthcheck to fail / timeout, and it may be possible to DoS the instance this way.
In the Docker (itself) logs, it's also possible to notice:
I tried to find where this call originate from and noted:
The path I think is problematic is
JobResult.related_object() > Jobs.get_job > Jobs.get_jobs > Jobs._get_job_source_paths -> ensure_git_repository.Maybe
Jobs.get_jobscould be cached (per request?) (to deduplicateensure_git_repositorycalls)? Or maybeensure_git_repositoryshould not be called at all (updating list on git creation/sync only? And a beat/watcher could monitor changes for local jobs). And shouldn'tensure_git_repositoryrun only on the celery worker?The text was updated successfully, but these errors were encountered: