Sluggish performance, database corruption? #14726

Unanswered

llamafilm asked this question in Help Wanted!

llamafilm
Jan 8, 2024

I noticed that some API queries are feeling sluggish. For example this one takes 23 seconds. I have 1158 devices.

/api/plugins/prometheus-sd/devices/?status=active&cf_prometheus_blackbox_module__n=null

I have some experience debugging other systems as a sys admin, but I'm very new to Netbox. So here's my attempt at diagnosing the issue.

That example HTTP download takes less than 10ms; most of the time is spent talking to the database. Postgres is running in RDS Aurora and its metrics look fine, fairly low utilization. Netbox is running on EC2 m5.large with 2 CPU cores, so I tried upgrading to m5.2xlarge (8 cores) and that didn't help at all. The Prometheus plugin is the main problem, but other pages are fairly slow too. Here /dcim/devices takes 845ms shown in Chrome dev tools, and again most of the time is spent waiting on the server.

I turned on debug logging for netbox and django, and the log file is massive, growing in 250MB in just a few minutes. Below is an example of one of the errors. It looks like something is corrupt in the database, and I don't know how to fix it. I tried removing all plugins. I'm not sure if this is a red herring... is is it normal for the debug log to be filled with exceptions like this? With debug turned off, I don't see any errors, but performance is still sluggish.

Specs

Netbox v3.7.0
PostgreSQL 15.3
Python 3.10.12

expand for debug log snippet

(0.002) SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1; args=(); alias=default No previous configuration found in database; proceeding with default values Initialized configuration Cleared configuration Exception while resolving variable 'raw' in template 'debug_toolbar/panels/request.html'. Traceback (most recent call last): File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup current = current[bit] TypeError: 'RequestPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [raw] in {'list': []}
Exception while resolving variable 'raw' in template 'debug_toolbar/panels/request.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'RequestPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [raw] in {'list': []}
Exception while resolving variable 'raw' in template 'debug_toolbar/panels/request.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'RequestPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [raw] in {'list': []}
Exception while resolving variable 'raw' in template 'debug_toolbar/panels/request.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'RequestPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [raw] in {'list': []}
Exception while resolving variable 'similar_count' in template 'debug_toolbar/panels/sql.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'SQLPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'similar_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'similar_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'similar_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [similar_count] in {'vendor': 'postgresql', 'alias': 'default', 'sql': 'SELECT "core_configrevision"."id",
       "core_configrevision"."created",
       "core_configrevision"."comment",
       "core_configrevision"."data"
  FROM "core_configrevision"
ORDER BY "core_configrevision"."created" ASC
LIMIT 1SELECT ••• FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'duration': 2.0716879807878286, 'raw_sql': 'SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'params': '[]', 'raw_params': (), 'stacktrace': '/usr/lib/python3.10/concurrent/futures/thread.py in _worker(83)\n work_item.run()\n\n/usr/lib/python3.10/concurrent/futures/thread.py in run(58)\n result = self.fn(*self.args, **self.kwargs)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle(282)\n keepalive = self.handle_request(req, conn)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle_request(334)\n respiter = self.wsgi(environ, resp.start_response)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/graphiql_debug_toolbar/middleware.py in call(70)\n response = super().call(request)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/corsheaders/middleware.py in call(56)\n result = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(47)\n response = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(186)\n if get_config().MAINTENANCE_MODE:\n\n/opt/netbox/netbox/netbox/config/init.py in get_config(27)\n _thread_locals.config = Config()\n\n/opt/netbox/netbox/netbox/config/init.py in init(49)\n self._populate_from_db()\n\n/opt/netbox/netbox/netbox/config/init.py in _populate_from_db(80)\n revision = ConfigRevision.objects.last()\n\n', 'template_info': None, 'trans_id': None, 'trans_status': 'Idle', 'iso_level': None, 'form': , 'is_slow': False, 'is_select': True, 'rgb_color': [256, 0, 0], 'width_ratio': 100.0, 'start_offset': 0, 'end_offset': 100.0, 'trace_color': '#800000'}
Exception while resolving variable 'duplicate_count' in template 'debug_toolbar/panels/sql.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'SQLPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'duplicate_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'duplicate_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'duplicate_count'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [duplicate_count] in {'vendor': 'postgresql', 'alias': 'default', 'sql': 'SELECT "core_configrevision"."id",
       "core_configrevision"."created",
       "core_configrevision"."comment",
       "core_configrevision"."data"
  FROM "core_configrevision"
ORDER BY "core_configrevision"."created" ASC
LIMIT 1SELECT ••• FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'duration': 2.0716879807878286, 'raw_sql': 'SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'params': '[]', 'raw_params': (), 'stacktrace': '/usr/lib/python3.10/concurrent/futures/thread.py in _worker(83)\n work_item.run()\n\n/usr/lib/python3.10/concurrent/futures/thread.py in run(58)\n result = self.fn(*self.args, **self.kwargs)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle(282)\n keepalive = self.handle_request(req, conn)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle_request(334)\n respiter = self.wsgi(environ, resp.start_response)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/graphiql_debug_toolbar/middleware.py in call(70)\n response = super().call(request)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/corsheaders/middleware.py in call(56)\n result = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(47)\n response = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(186)\n if get_config().MAINTENANCE_MODE:\n\n/opt/netbox/netbox/netbox/config/init.py in get_config(27)\n _thread_locals.config = Config()\n\n/opt/netbox/netbox/netbox/config/init.py in init(49)\n self._populate_from_db()\n\n/opt/netbox/netbox/netbox/config/init.py in _populate_from_db(80)\n revision = ConfigRevision.objects.last()\n\n', 'template_info': None, 'trans_id': None, 'trans_status': 'Idle', 'iso_level': None, 'form': , 'is_slow': False, 'is_select': True, 'rgb_color': [256, 0, 0], 'width_ratio': 100.0, 'start_offset': 0, 'end_offset': 100.0, 'trace_color': '#800000'}
Exception while resolving variable 'in_trans' in template 'debug_toolbar/panels/sql.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'SQLPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'in_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'in_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'in_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [in_trans] in {'vendor': 'postgresql', 'alias': 'default', 'sql': 'SELECT "core_configrevision"."id",
       "core_configrevision"."created",
       "core_configrevision"."comment",
       "core_configrevision"."data"
  FROM "core_configrevision"
ORDER BY "core_configrevision"."created" ASC
LIMIT 1SELECT ••• FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'duration': 2.0716879807878286, 'raw_sql': 'SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'params': '[]', 'raw_params': (), 'stacktrace': '/usr/lib/python3.10/concurrent/futures/thread.py in _worker(83)\n work_item.run()\n\n/usr/lib/python3.10/concurrent/futures/thread.py in run(58)\n result = self.fn(*self.args, **self.kwargs)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle(282)\n keepalive = self.handle_request(req, conn)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle_request(334)\n respiter = self.wsgi(environ, resp.start_response)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/graphiql_debug_toolbar/middleware.py in call(70)\n response = super().call(request)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/corsheaders/middleware.py in call(56)\n result = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(47)\n response = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(186)\n if get_config().MAINTENANCE_MODE:\n\n/opt/netbox/netbox/netbox/config/init.py in get_config(27)\n _thread_locals.config = Config()\n\n/opt/netbox/netbox/netbox/config/init.py in init(49)\n self._populate_from_db()\n\n/opt/netbox/netbox/netbox/config/init.py in _populate_from_db(80)\n revision = ConfigRevision.objects.last()\n\n', 'template_info': None, 'trans_id': None, 'trans_status': 'Idle', 'iso_level': None, 'form': , 'is_slow': False, 'is_select': True, 'rgb_color': [256, 0, 0], 'width_ratio': 100.0, 'start_offset': 0, 'end_offset': 100.0, 'trace_color': '#800000'}
Exception while resolving variable 'starts_trans' in template 'debug_toolbar/panels/sql.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'SQLPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'starts_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'starts_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'starts_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [starts_trans] in {'vendor': 'postgresql', 'alias': 'default', 'sql': 'SELECT "core_configrevision"."id",
       "core_configrevision"."created",
       "core_configrevision"."comment",
       "core_configrevision"."data"
  FROM "core_configrevision"
ORDER BY "core_configrevision"."created" ASC
LIMIT 1SELECT ••• FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'duration': 2.0716879807878286, 'raw_sql': 'SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'params': '[]', 'raw_params': (), 'stacktrace': '/usr/lib/python3.10/concurrent/futures/thread.py in _worker(83)\n work_item.run()\n\n/usr/lib/python3.10/concurrent/futures/thread.py in run(58)\n result = self.fn(*self.args, **self.kwargs)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle(282)\n keepalive = self.handle_request(req, conn)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle_request(334)\n respiter = self.wsgi(environ, resp.start_response)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/graphiql_debug_toolbar/middleware.py in call(70)\n response = super().call(request)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/corsheaders/middleware.py in call(56)\n result = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(47)\n response = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(186)\n if get_config().MAINTENANCE_MODE:\n\n/opt/netbox/netbox/netbox/config/init.py in get_config(27)\n _thread_locals.config = Config()\n\n/opt/netbox/netbox/netbox/config/init.py in init(49)\n self._populate_from_db()\n\n/opt/netbox/netbox/netbox/config/init.py in _populate_from_db(80)\n revision = ConfigRevision.objects.last()\n\n', 'template_info': None, 'trans_id': None, 'trans_status': 'Idle', 'iso_level': None, 'form': , 'is_slow': False, 'is_select': True, 'rgb_color': [256, 0, 0], 'width_ratio': 100.0, 'start_offset': 0, 'end_offset': 100.0, 'trace_color': '#800000'}
Exception while resolving variable 'ends_trans' in template 'debug_toolbar/panels/sql.html'.
Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
TypeError: 'SQLPanel' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 880, in _resolve_lookup
current = current[bit]
KeyError: 'ends_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 890, in _resolve_lookup
current = getattr(current, bit)
AttributeError: 'dict' object has no attribute 'ends_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 896, in _resolve_lookup
current = current[int(bit)]
ValueError: invalid literal for int() with base 10: 'ends_trans'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/django/template/base.py", line 903, in _resolve_lookup
raise VariableDoesNotExist(
django.template.base.VariableDoesNotExist: Failed lookup for key [ends_trans] in {'vendor': 'postgresql', 'alias': 'default', 'sql': 'SELECT "core_configrevision"."id",
       "core_configrevision"."created",
       "core_configrevision"."comment",
       "core_configrevision"."data"
  FROM "core_configrevision"
ORDER BY "core_configrevision"."created" ASC
LIMIT 1SELECT ••• FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'duration': 2.0716879807878286, 'raw_sql': 'SELECT "core_configrevision"."id", "core_configrevision"."created", "core_configrevision"."comment", "core_configrevision"."data" FROM "core_configrevision" ORDER BY "core_configrevision"."created" ASC LIMIT 1', 'params': '[]', 'raw_params': (), 'stacktrace': '/usr/lib/python3.10/concurrent/futures/thread.py in _worker(83)\n work_item.run()\n\n/usr/lib/python3.10/concurrent/futures/thread.py in run(58)\n result = self.fn(*self.args, **self.kwargs)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle(282)\n keepalive = self.handle_request(req, conn)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/gunicorn/workers/gthread.py in handle_request(334)\n respiter = self.wsgi(environ, resp.start_response)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/graphiql_debug_toolbar/middleware.py in call(70)\n response = super().call(request)\n\n/opt/netbox-3.7.0/venv/lib/python3.10/site-packages/corsheaders/middleware.py in call(56)\n result = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(47)\n response = self.get_response(request)\n\n/opt/netbox/netbox/netbox/middleware.py in call(186)\n if get_config().MAINTENANCE_MODE:\n\n/opt/netbox/netbox/netbox/config/init.py in get_config(27)\n _thread_locals.config = Config()\n\n/opt/netbox/netbox/netbox/config/init.py in init(49)\n self._populate_from_db()\n\n/opt/netbox/netbox/netbox/config/init.py in _populate_from_db(80)\n revision = ConfigRevision.objects.last()\n\n', 'template_info': None, 'trans_id': None, 'trans_status': 'Idle', 'iso_level': None, 'form': , 'is_slow': False, 'is_select': True, 'rgb_color': [256, 0, 0], 'width_ratio': 100.0, 'start_offset': 0, 'end_offset': 100.0, 'trace_color': '#800000'}

Replies: 2 comments 4 replies

llamafilm
Jan 8, 2024
Author

It looks like the majority of my problem may be inefficient code in this Prometheus plugin. I turned on log_statement=all in Postgres and found this single API call causes 6157 SELECT statements, which accounts for 99% of the Netbox processing time.

3 replies

candlerb Jan 8, 2024

And could you show what those SELECT statements are doing?

It seems to me like the first query is missing some select_related clause, so every object it iterates over is triggering one or more additional SELECTs per object.

This is a common problem with ORMs in general (and is one reason why I don't like ORMs - especially those derived from the "active record" design philosophy)

llamafilm Jan 8, 2024
Author

Sure, here you can see all the queries I pulled from Postgres log. It might be worth noting that approximately 2/3 of these queries return 0 rows.
https://drive.google.com/file/d/1U6sxJAy8zfvUsmqZqdcJse9bZgEulIbi/view?usp=sharing

candlerb Jan 8, 2024

Sorry, my fault: I didn't notice before that this query is for a plugin, so you need to raise this with the plugin author. The queries made by a plugin are completely outside of the control of Netbox core.

llamafilm
Jan 8, 2024
Author

Just as another data point — I bulk deleted 1000 devices using the webpage and the operation took 290 seconds (measured by analyzing Postgres log). I'm not sure if these kind of speeds are considered normal for Netbox?

1 reply

candlerb Jan 8, 2024

Normal for Django-based applications, yes. A bulk delete is going to iterate over all the objects, performing model checks, webhook triggers, per-object change logging, etc.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment