starred/netbox
1
0
Fork 0
mirror of https://github.com/netbox-community/netbox.git synced 2026-01-13 05:50:33 +01:00
Code Issues 273 Packages Projects Releases 10 Wiki Activity

Improve performance of custom field models and serializers #3984

New Issue
Closed
opened 2025-12-29 18:32:26 +01:00 by adam · 4 comments
adam commented 2025-12-29 18:32:26 +01:00
Owner
Copy Link

Originally created by @roganartu on GitHub (Aug 13, 2020).

Environment

  • Python version: 3.6.5
  • NetBox version: 2.8.8

Proposed Functionality

Improve the performance of custom field models and serializers by reducing the number of SQL queries issued per request. GET /api/dcim/devices?limit=1000 takes ~20-30s on our best bare metal hardware (~10-15s with exclude=config_context), and results in thousands of duplicate SQL queries relating to custom fields.

The profiling I did seems to suggest some of this performance may be improved by #4878 too, though this issue seemed distinct enough to warrant a separate ticket. If you disagree, please feel free to close this.

Profiling

I did some Python profiling and Postgres query logging and found that the majority of queries come from a small number of sources. I will try to document the process I used thoroughly to make reproducing this easier.

I used the following command to generate the request each time:

$ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l

With the following postgres query logging config:

# Log queries temporarily
log_statement = 'all'
log_duration = on
log_filename = 'postgresql-%Y-%m-%d_%H%M%S'
log_destination = 'csvlog'
logging_collector = on
log_min_error_statement = error

Each query then created two lines in the query log like this:

2020-08-11 15:07:00.035 EDT,"netbox","netbox",7756,"127.0.0.1:57040",5f32ec50.1e4c,109,"idle",2020-08-11 15:06:56 EDT,6/68,0,LOG,00000,"statement: SELECT ""dcim_device"".""id"", ""dcim_device"".""local_context_data"", ""dcim_device"".""created"", ""dcim_device"".""last_updated"", ""dcim_device"".""device_type_id"", ""dcim_device"".""device_role_id"", ""dcim_device"".""tenant_id"", ""dcim_device"".""platform_id"", ""dcim_device"".""name"", ""dcim_device"".""_name"", ""dcim_device"".""serial"", ""dcim_device"".""asset_tag"", ""dcim_device"".""site_id"", ""dcim_device"".""rack_id"", ""dcim_device"".""position"", ""dcim_device"".""face"", ""dcim_device"".""status"", ""dcim_device"".""primary_ip4_id"", ""dcim_device"".""primary_ip6_id"", ""dcim_device"".""cluster_id"", ""dcim_device"".""virtual_chassis_id"", ""dcim_device"".""vc_position"", ""dcim_device"".""vc_priority"", ""dcim_device"".""comments"" FROM ""dcim_device"" WHERE ""dcim_device"".""id"" = 594219 LIMIT 21",,,,,,,,,""
2020-08-11 15:07:00.035 EDT,"netbox","netbox",7756,"127.0.0.1:57040",5f32ec50.1e4c,110,"SELECT",2020-08-11 15:06:56 EDT,6/0,0,LOG,00000,"duration: 0.224 ms",,,,,,,,,""

I then used the following (on a freshly rotated log file for each request) to aggregate query counts:

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" <path_to_log_file> | sort | uniq -c | sort -nr
      4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21
    ...

I also wrote an adhoc middleware plugin that let me pass enable_profiler=1 to get a cProfile.Profile() of the request dumped to /tmp that I then extracted the call graph from using gprof2dot and visualised using xdot. This allowed me to narrow down some of the sources of the SQL a little easier, since I'm not very familiar with Django.

The test database I did this profiling on contains:

  • ~15k devices
  • 24 custom fields
  • 13 custom field choices across two custom fields
  • ~200k custom field values for the dcim_device obj_type_id

Vanilla v2.8.8

The request typically takes ~10-15s depending on server load and executes ~3k SQL queries. This example is relatively fast because it was run with a local test DB that was idle:

$ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l
1000
curl -k -L -s   0.02s user 0.01s system 0% cpu 9.100 total
jq -r '.results[] | .name'  0.11s user 0.02s system 1% cpu 9.127 total
sort  0.00s user 0.00s system 0% cpu 9.113 total
uniq  0.00s user 0.00s system 0% cpu 9.111 total
wc -l  0.00s user 0.00s system 0% cpu 9.109 total

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" vanilla.csv | wc -l
3049

Almost all of these are identical, repeatedly fetching custom field names and choices:

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" vanilla.csv | sort | uniq -c | sort -nr | head
   1003 statement: SELECT "extras_customfield"."id", "extras_customfield"."type", "extras_customfield"."name", "extras_customfield"."label", "extras_customfield"."description", "extras_customfield"."required", "extras_customfield"."filter_logic", "extras_customfield"."default", "extras_customfield"."weight" FROM "extras_customfield" INNER JOIN "extras_customfield_obj_type" ON ("extras_customfield"."id" = "extras_customfield_obj_type"."customfield_id") WHERE "extras_customfield_obj_type"."contenttype_id" = 32 ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC
   1000 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 65 AND "extras_customfieldchoice"."id" = 23) LIMIT 21
    850 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 26) LIMIT 21
    146 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 28) LIMIT 21
      4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21
      3 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 32) LIMIT 21
      3 statement: SELECT d.datname as "Name", pg_catalog.pg_get_userbyid(d.datdba) as "Owner", pg_catalog.pg_encoding_to_char(d.encoding) as "Encoding", d.datcollate as "Collate", d.datctype as "Ctype", pg_catalog.array_to_string(d.datacl, E'\n') AS "Access privileges" FROM pg_catalog.pg_database d ORDER BY 1;
      3 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584969 LIMIT 21
      2 statement: SELECT "ipam_ipaddress"."id", "ipam_ipaddress"."created", "ipam_ipaddress"."last_updated", "ipam_ipaddress"."address", "ipam_ipaddress"."vrf_id", "ipam_ipaddress"."tenant_id", "ipam_ipaddress"."status", "ipam_ipaddress"."role", "ipam_ipaddress"."interface_id", "ipam_ipaddress"."nat_inside_id", "ipam_ipaddress"."dns_name", "ipam_ipaddress"."description" FROM "ipam_ipaddress" WHERE "ipam_ipaddress"."id" IN (NULL) ORDER BY "ipam_ipaddress"."address" ASC, "ipam_ipaddress"."id" ASC
      2 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" INNER JOIN "extras_customfield" ON ("extras_customfieldchoice"."field_id" = "extras_customfield"."id") WHERE "extras_customfieldchoice"."field_id" IN (63, 65, 115, 67, 68, 69, 71, 74, 75, 76, 78, 79, 83) ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC, "extras_customfieldchoice"."weight" ASC, "extras_customfieldchoice"."value" ASC

CustomFieldModelSerializer

Found here: ee51dae73f/netbox/extras/api/customfields.py (L132)

These two lines result in one SQL query per device object:

ee51dae73f/netbox/extras/api/customfields.py (L146-L148)

The specific query this executes ~1000 times is:

SELECT "extras_customfield"."id", "extras_customfield"."type", "extras_customfield"."name", "extras_customfield"."label", "extras_customfield"."description", "extras_customfield"."required", "extras_customfield"."filter_logic", "extras_customfield"."default", "extras_customfield"."weight" FROM "extras_customfield" INNER JOIN "extras_customfield_obj_type" ON ("extras_customfield"."id" = "extras_customfield_obj_type"."customfield_id") WHERE "extras_customfield_obj_type"."contenttype_id" = 32 ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC

However, afaict these lines can be removed and fields can be replaced with the existing self.context["custom_fields"] without any problems. It requires a minor change to how CustomFieldModel caches too since that seems to be where the DRF lazy execution actually ends up triggering the query. Someone who understands Django better should comment on the viability, but this use of self.context reduced the query count to ~2k and response time by ~17%:

$ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l
1000
curl -k -L -s   0.01s user 0.02s system 0% cpu 7.604 total
jq -r '.results[] | .name'  0.12s user 0.03s system 1% cpu 7.632 total
sort  0.00s user 0.00s system 0% cpu 7.612 total
uniq  0.00s user 0.00s system 0% cpu 7.611 total
wc -l  0.00s user 0.00s system 0% cpu 7.609 total

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | wc -l
2052

Here is the commit that achieved this, let me know if this makes sense and I can submit a PR: 13238ea6c7

I did some adhoc testing of the returned objects, and the custom_fields in them appeared to be correct. I admit I do not understand how DRF serialization contexts work (further than a cursory read while doing this investigation), so if this is obviously the incorrect way to fix this I'd love to learn more.

CustomFieldManager

This one is basically the same as above, but the calls are generated from each instantiated model instead of each serializer. This seems to make it harder to deal with on a per-request basis, since the CustomFieldManager doesn't appear to have any kind of request context, unlike the serializer which has the per-request self.context["custom_fields"].

I don't know how to approach this correctly, but as a proof-of-concept to demonstrate this is where these queries are coming from, I made the CustomFieldManager a singleton with a per-model._meta.concrete_model lru_cache around the CustomFieldManager.get_for_model method from here:

d5b9722533/netbox/extras/models/customfields.py (L61)

Before (including the CustomFieldModelSerializer fix):

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | wc -l
2052

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | sort | uniq -c | sort -nr | head -n 3
   1000 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 65 AND "extras_customfieldchoice"."id" = 23) LIMIT 21
    850 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 26) LIMIT 21
    146 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 28) LIMIT 21

After (including the CustomFieldModelSerializer fix):

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | wc -l
57

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | sort | uniq -c | sort -nr | head -n 1
      4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21

This is the part of this issue that I think is most related to #4878. I wonder if thread locals could be used (with a middleware to create/del a context dict) to give a per-request cache for this stuff to the model objects?

Missing Index

I didn't do enough digging to see what exactly is generating this query, but it's missing an index which makes it rather slow on large extras_customfieldvalue tables.

Before:

SELECT "extras_customfieldvalue"."id", "extras_customfieldvalue"."field_id", "extras_customfieldvalue"."obj_type_id", "extras_customfieldvalue"."obj_id", "extras_customfieldvalue"."serialized_value" FROM "extras_customfieldvalue" WHERE ("extras_customfieldvalue"."obj_id" IN (<many IDs>) AND "extras_customfieldvalue"."obj_type_id" = 32) ORDER BY "extras_customfieldvalue"."obj_type_id" ASC, "extras_customfieldvalue"."obj_id" ASC, "extras_customfieldvalue"."id" ASC

 Gather Merge  (cost=153573.71..154312.58 rows=6425 width=19) (actual time=699.040..701.888 rows=11768 loops=1)
   Workers Planned: 1
   Workers Launched: 1
   ->  Sort  (cost=152573.70..152589.76 rows=6425 width=19) (actual time=697.309..697.566 rows=5884 loops=2)
         Sort Key: obj_id, id
         Sort Method: quicksort  Memory: 651kB
         Worker 0:  Sort Method: quicksort  Memory: 654kB
         ->  Parallel Seq Scan on extras_customfieldvalue  (cost=0.00..152167.33 rows=6425 width=19) (actual time=0.307..695.073 rows=5884 loops=2)
               Filter: ((obj_type_id = 32) AND (obj_id = ANY ('{<many IDs>}'::integer[])))
               Rows Removed by Filter: 95668
 Planning Time: 13.572 ms
 Execution Time: 702.269 ms

Proposed index:

netbox=# CREATE INDEX ON extras_customfieldvalue (obj_id, obj_type_id);
CREATE INDEX

After:

 Sort  (cost=8810.83..8838.14 rows=10922 width=19) (actual time=7.269..7.647 rows=11768 loops=1)
   Sort Key: obj_id, id
   Sort Method: quicksort  Memory: 1304kB
   ->  Index Scan using extras_customfieldvalue_obj_id_obj_type_id_idx on extras_customfieldvalue  (cost=0.42..8078.24 rows=10922 width=19) (actual time=0.210..4.884 rows=11768 loops=1)
         Index Cond: ((obj_id = ANY ('{<many IDs>}'::integer[])) AND (obj_type_id = 32))
 Planning Time: 13.444 ms
 Execution Time: 7.953 ms

I can submit a PR with a migration to add this index if you agree it should be fixed.

Remaining queries

This should probably be a separate issue, but about half the remaining queries seem to be parent device lookups. It'd be nice if these were just one query (eg as WHERE dcim_device.id IN (...)) but I'm not sure how easy Django makes that. This is obviously a much less significant improvement than the other 3,000 queries though!

$ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | sort | uniq -c | sort -nr | rg ' WHERE "dcim_device"."id"'
      4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21
      3 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584969 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594197 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594114 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594110 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593992 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593954 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593864 LIMIT 21
      2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 585350 LIMIT 21
      1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594219 LIMIT 21
      1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593979 LIMIT 21
      1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593883 LIMIT 21
      1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 585165 LIMIT 21
      1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584795 LIMIT 21

Use Case

We do a lot of things that involve fetching data for a large number of devices. Additionally, we have a large number of custom fields, though that doesn't seem to really matter that much here. It seems that the number of queries currently executed is 3*N where N is number of CustomFieldModel objects instantiated. Reducing this to a constant number of queries should significantly improve general Netbox performance.

Database Changes

See Proposed index section above.

External Dependencies

None.

Originally created by @roganartu on GitHub (Aug 13, 2020). ## Environment * Python version: 3.6.5 * NetBox version: 2.8.8 ### Proposed Functionality Improve the performance of custom field models and serializers by reducing the number of SQL queries issued per request. `GET /api/dcim/devices?limit=1000` takes ~20-30s on our best bare metal hardware (~10-15s with `exclude=config_context`), and results in thousands of duplicate SQL queries relating to custom fields. The profiling I did seems to suggest some of this performance may be improved by #4878 too, though this issue seemed distinct enough to warrant a separate ticket. If you disagree, please feel free to close this. ### Profiling I did some Python profiling and Postgres query logging and found that the majority of queries come from a small number of sources. I will try to document the process I used thoroughly to make reproducing this easier. I used the following command to generate the request each time: ``` $ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l ``` With the following postgres query logging config: ``` # Log queries temporarily log_statement = 'all' log_duration = on log_filename = 'postgresql-%Y-%m-%d_%H%M%S' log_destination = 'csvlog' logging_collector = on log_min_error_statement = error ``` Each query then created two lines in the query log like this: ``` 2020-08-11 15:07:00.035 EDT,"netbox","netbox",7756,"127.0.0.1:57040",5f32ec50.1e4c,109,"idle",2020-08-11 15:06:56 EDT,6/68,0,LOG,00000,"statement: SELECT ""dcim_device"".""id"", ""dcim_device"".""local_context_data"", ""dcim_device"".""created"", ""dcim_device"".""last_updated"", ""dcim_device"".""device_type_id"", ""dcim_device"".""device_role_id"", ""dcim_device"".""tenant_id"", ""dcim_device"".""platform_id"", ""dcim_device"".""name"", ""dcim_device"".""_name"", ""dcim_device"".""serial"", ""dcim_device"".""asset_tag"", ""dcim_device"".""site_id"", ""dcim_device"".""rack_id"", ""dcim_device"".""position"", ""dcim_device"".""face"", ""dcim_device"".""status"", ""dcim_device"".""primary_ip4_id"", ""dcim_device"".""primary_ip6_id"", ""dcim_device"".""cluster_id"", ""dcim_device"".""virtual_chassis_id"", ""dcim_device"".""vc_position"", ""dcim_device"".""vc_priority"", ""dcim_device"".""comments"" FROM ""dcim_device"" WHERE ""dcim_device"".""id"" = 594219 LIMIT 21",,,,,,,,,"" 2020-08-11 15:07:00.035 EDT,"netbox","netbox",7756,"127.0.0.1:57040",5f32ec50.1e4c,110,"SELECT",2020-08-11 15:06:56 EDT,6/0,0,LOG,00000,"duration: 0.224 ms",,,,,,,,,"" ``` I then used the following (on a freshly rotated log file for each request) to aggregate query counts: ``` $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" <path_to_log_file> | sort | uniq -c | sort -nr 4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21 ... ``` I also wrote an adhoc middleware plugin that let me pass `enable_profiler=1` to get a `cProfile.Profile()` of the request dumped to `/tmp` that I then extracted the call graph from using `gprof2dot` and visualised using `xdot`. This allowed me to narrow down some of the sources of the SQL a little easier, since I'm not very familiar with Django. The test database I did this profiling on contains: - ~15k devices - 24 custom fields - 13 custom field choices across two custom fields - ~200k custom field values for the `dcim_device` `obj_type_id` #### Vanilla v2.8.8 The request typically takes ~10-15s depending on server load and executes ~3k SQL queries. This example is relatively fast because it was run with a local test DB that was idle: ``` $ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l 1000 curl -k -L -s 0.02s user 0.01s system 0% cpu 9.100 total jq -r '.results[] | .name' 0.11s user 0.02s system 1% cpu 9.127 total sort 0.00s user 0.00s system 0% cpu 9.113 total uniq 0.00s user 0.00s system 0% cpu 9.111 total wc -l 0.00s user 0.00s system 0% cpu 9.109 total $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" vanilla.csv | wc -l 3049 ``` Almost all of these are identical, repeatedly fetching custom field names and choices: ``` $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" vanilla.csv | sort | uniq -c | sort -nr | head 1003 statement: SELECT "extras_customfield"."id", "extras_customfield"."type", "extras_customfield"."name", "extras_customfield"."label", "extras_customfield"."description", "extras_customfield"."required", "extras_customfield"."filter_logic", "extras_customfield"."default", "extras_customfield"."weight" FROM "extras_customfield" INNER JOIN "extras_customfield_obj_type" ON ("extras_customfield"."id" = "extras_customfield_obj_type"."customfield_id") WHERE "extras_customfield_obj_type"."contenttype_id" = 32 ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC 1000 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 65 AND "extras_customfieldchoice"."id" = 23) LIMIT 21 850 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 26) LIMIT 21 146 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 28) LIMIT 21 4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21 3 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 32) LIMIT 21 3 statement: SELECT d.datname as "Name", pg_catalog.pg_get_userbyid(d.datdba) as "Owner", pg_catalog.pg_encoding_to_char(d.encoding) as "Encoding", d.datcollate as "Collate", d.datctype as "Ctype", pg_catalog.array_to_string(d.datacl, E'\n') AS "Access privileges" FROM pg_catalog.pg_database d ORDER BY 1; 3 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584969 LIMIT 21 2 statement: SELECT "ipam_ipaddress"."id", "ipam_ipaddress"."created", "ipam_ipaddress"."last_updated", "ipam_ipaddress"."address", "ipam_ipaddress"."vrf_id", "ipam_ipaddress"."tenant_id", "ipam_ipaddress"."status", "ipam_ipaddress"."role", "ipam_ipaddress"."interface_id", "ipam_ipaddress"."nat_inside_id", "ipam_ipaddress"."dns_name", "ipam_ipaddress"."description" FROM "ipam_ipaddress" WHERE "ipam_ipaddress"."id" IN (NULL) ORDER BY "ipam_ipaddress"."address" ASC, "ipam_ipaddress"."id" ASC 2 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" INNER JOIN "extras_customfield" ON ("extras_customfieldchoice"."field_id" = "extras_customfield"."id") WHERE "extras_customfieldchoice"."field_id" IN (63, 65, 115, 67, 68, 69, 71, 74, 75, 76, 78, 79, 83) ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC, "extras_customfieldchoice"."weight" ASC, "extras_customfieldchoice"."value" ASC ``` #### `CustomFieldModelSerializer` Found here: https://github.com/netbox-community/netbox/blob/ee51dae73f1fc0ad306c16f95efcfa9a5474fd81/netbox/extras/api/customfields.py#L132 These two lines result in one SQL query per device object: https://github.com/netbox-community/netbox/blob/ee51dae73f1fc0ad306c16f95efcfa9a5474fd81/netbox/extras/api/customfields.py#L146-L148 The specific query this executes ~1000 times is: ``` SELECT "extras_customfield"."id", "extras_customfield"."type", "extras_customfield"."name", "extras_customfield"."label", "extras_customfield"."description", "extras_customfield"."required", "extras_customfield"."filter_logic", "extras_customfield"."default", "extras_customfield"."weight" FROM "extras_customfield" INNER JOIN "extras_customfield_obj_type" ON ("extras_customfield"."id" = "extras_customfield_obj_type"."customfield_id") WHERE "extras_customfield_obj_type"."contenttype_id" = 32 ORDER BY "extras_customfield"."weight" ASC, "extras_customfield"."name" ASC ``` However, afaict these lines can be removed and `fields` can be replaced with the existing `self.context["custom_fields"]` without any problems. It requires a minor change to how `CustomFieldModel` caches too since that seems to be where the DRF lazy execution actually ends up triggering the query. Someone who understands Django better should comment on the viability, but this use of `self.context` reduced the query count to ~2k and response time by ~17%: ``` $ time curl -k -L -s "http://localhost/api/dcim/devices/?limit=1000&exclude=config_context" | jq -r '.results[] | .name' | sort | uniq | wc -l 1000 curl -k -L -s 0.01s user 0.02s system 0% cpu 7.604 total jq -r '.results[] | .name' 0.12s user 0.03s system 1% cpu 7.632 total sort 0.00s user 0.00s system 0% cpu 7.612 total uniq 0.00s user 0.00s system 0% cpu 7.611 total wc -l 0.00s user 0.00s system 0% cpu 7.609 total $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | wc -l 2052 ``` Here is the commit that achieved this, let me know if this makes sense and I can submit a PR: https://github.com/roganartu/netbox/commit/13238ea6c76f6c039fb83dc3e188939a8ca13e1e I did some adhoc testing of the returned objects, and the custom_fields in them appeared to be correct. I admit I do not understand how DRF serialization contexts work (further than a cursory read while doing this investigation), so if this is obviously the incorrect way to fix this I'd love to learn more. #### `CustomFieldManager` This one is basically the same as above, but the calls are generated from each instantiated model instead of each serializer. This seems to make it harder to deal with on a per-request basis, since the `CustomFieldManager` doesn't appear to have any kind of request context, unlike the serializer which has the per-request `self.context["custom_fields"]`. I don't know how to approach this correctly, but as a proof-of-concept to demonstrate this is where these queries are coming from, I made the `CustomFieldManager` a singleton with a per-`model._meta.concrete_model` `lru_cache` around the `CustomFieldManager.get_for_model` method from here: https://github.com/netbox-community/netbox/blob/d5b972253346532d6549f574b8730ee49e726c9c/netbox/extras/models/customfields.py#L61 Before (including the `CustomFieldModelSerializer` fix): ``` $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | wc -l 2052 $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldModelSerializer.csv | sort | uniq -c | sort -nr | head -n 3 1000 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 65 AND "extras_customfieldchoice"."id" = 23) LIMIT 21 850 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 26) LIMIT 21 146 statement: SELECT "extras_customfieldchoice"."id", "extras_customfieldchoice"."field_id", "extras_customfieldchoice"."value", "extras_customfieldchoice"."weight" FROM "extras_customfieldchoice" WHERE ("extras_customfieldchoice"."field_id" = 76 AND "extras_customfieldchoice"."id" = 28) LIMIT 21 ``` After (including the `CustomFieldModelSerializer` fix): ``` $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | wc -l 57 $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | sort | uniq -c | sort -nr | head -n 1 4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21 ``` This is the part of this issue that I think is most related to #4878. I wonder if thread locals could be used (with a middleware to create/del a context dict) to give a per-request cache for this stuff to the model objects? #### Missing Index I didn't do enough digging to see what exactly is generating this query, but it's missing an index which makes it rather slow on large `extras_customfieldvalue` tables. Before: ``` SELECT "extras_customfieldvalue"."id", "extras_customfieldvalue"."field_id", "extras_customfieldvalue"."obj_type_id", "extras_customfieldvalue"."obj_id", "extras_customfieldvalue"."serialized_value" FROM "extras_customfieldvalue" WHERE ("extras_customfieldvalue"."obj_id" IN (<many IDs>) AND "extras_customfieldvalue"."obj_type_id" = 32) ORDER BY "extras_customfieldvalue"."obj_type_id" ASC, "extras_customfieldvalue"."obj_id" ASC, "extras_customfieldvalue"."id" ASC Gather Merge (cost=153573.71..154312.58 rows=6425 width=19) (actual time=699.040..701.888 rows=11768 loops=1) Workers Planned: 1 Workers Launched: 1 -> Sort (cost=152573.70..152589.76 rows=6425 width=19) (actual time=697.309..697.566 rows=5884 loops=2) Sort Key: obj_id, id Sort Method: quicksort Memory: 651kB Worker 0: Sort Method: quicksort Memory: 654kB -> Parallel Seq Scan on extras_customfieldvalue (cost=0.00..152167.33 rows=6425 width=19) (actual time=0.307..695.073 rows=5884 loops=2) Filter: ((obj_type_id = 32) AND (obj_id = ANY ('{<many IDs>}'::integer[]))) Rows Removed by Filter: 95668 Planning Time: 13.572 ms Execution Time: 702.269 ms ``` Proposed index: ``` netbox=# CREATE INDEX ON extras_customfieldvalue (obj_id, obj_type_id); CREATE INDEX ``` After: ``` Sort (cost=8810.83..8838.14 rows=10922 width=19) (actual time=7.269..7.647 rows=11768 loops=1) Sort Key: obj_id, id Sort Method: quicksort Memory: 1304kB -> Index Scan using extras_customfieldvalue_obj_id_obj_type_id_idx on extras_customfieldvalue (cost=0.42..8078.24 rows=10922 width=19) (actual time=0.210..4.884 rows=11768 loops=1) Index Cond: ((obj_id = ANY ('{<many IDs>}'::integer[])) AND (obj_type_id = 32)) Planning Time: 13.444 ms Execution Time: 7.953 ms ``` I can submit a PR with a migration to add this index if you agree it should be fixed. #### Remaining queries This should probably be a separate issue, but about half the remaining queries seem to be parent device lookups. It'd be nice if these were just one query (eg as `WHERE dcim_device.id IN (...)`) but I'm not sure how easy Django makes that. This is obviously a much less significant improvement than the other 3,000 queries though! ``` $ python -c "import csv; import sys; reader = csv.reader(open(sys.argv[1], 'r')); print('\n'.join([' '.join(r[13].split()) for r in reader if r[13].startswith('statement: ')]))" CustomFieldManager.csv | sort | uniq -c | sort -nr | rg ' WHERE "dcim_device"."id"' 4 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584989 LIMIT 21 3 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584969 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594197 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594114 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594110 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593992 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593954 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593864 LIMIT 21 2 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 585350 LIMIT 21 1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 594219 LIMIT 21 1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593979 LIMIT 21 1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 593883 LIMIT 21 1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 585165 LIMIT 21 1 statement: SELECT "dcim_device"."id", "dcim_device"."local_context_data", "dcim_device"."created", "dcim_device"."last_updated", "dcim_device"."device_type_id", "dcim_device"."device_role_id", "dcim_device"."tenant_id", "dcim_device"."platform_id", "dcim_device"."name", "dcim_device"."_name", "dcim_device"."serial", "dcim_device"."asset_tag", "dcim_device"."site_id", "dcim_device"."rack_id", "dcim_device"."position", "dcim_device"."face", "dcim_device"."status", "dcim_device"."primary_ip4_id", "dcim_device"."primary_ip6_id", "dcim_device"."cluster_id", "dcim_device"."virtual_chassis_id", "dcim_device"."vc_position", "dcim_device"."vc_priority", "dcim_device"."comments" FROM "dcim_device" WHERE "dcim_device"."id" = 584795 LIMIT 21 ``` ### Use Case We do a lot of things that involve fetching data for a large number of devices. Additionally, we have a large number of custom fields, though that doesn't seem to really matter that much here. It seems that the number of queries currently executed is `3*N` where N is number of `CustomFieldModel` objects instantiated. Reducing this to a constant number of queries should significantly improve general Netbox performance. ### Database Changes See `Proposed index` section above. ### External Dependencies None.
adam added the type: housekeeping label 2025-12-29 18:32:26 +01:00
adam closed this issue 2025-12-29 18:32:26 +01:00
adam commented 2025-12-29 18:32:28 +01:00
Author
Owner
Copy Link

@DanSheps commented on GitHub (Aug 17, 2020):

I think we would be best to hold off on this until we get #4878 completed

@DanSheps commented on GitHub (Aug 17, 2020): I think we would be best to hold off on this until we get #4878 completed
adam commented 2025-12-29 18:32:28 +01:00
Author
Owner
Copy Link

@jeremystretch commented on GitHub (Aug 18, 2020):

While I appreciate the thoughtful analysis, as Dan points out, #4878 was opened specifically to address the shortcomings of the current implementation. I'd hate to see people spend too much time working to improve the current implementation only for it to be ripped out in v2.10. That said, I'll leave this open for anyone who wants to volunteer to make improvements, with the understanding that any changes to the data model itself are untenable given the pending work.

@jeremystretch commented on GitHub (Aug 18, 2020): While I appreciate the thoughtful analysis, as Dan points out, #4878 was opened specifically to address the shortcomings of the current implementation. I'd hate to see people spend too much time working to improve the current implementation only for it to be ripped out in v2.10. That said, I'll leave this open for anyone who wants to volunteer to make improvements, with the understanding that any changes to the data model itself are untenable given the pending work.
adam commented 2025-12-29 18:32:28 +01:00
Author
Owner
Copy Link

@roganartu commented on GitHub (Aug 18, 2020):

That's entirely reasonable. The primary motivation for submitting this was that I'd done the profiling and I figured a ticket seemed as good a place as any to document my findings since I hadn't seen an deep analysis of the root causes anywhere yet.

Would a PR for 13238ea6c7 be compatible with your plans for #4878? It represents a nearly 20% improvement by cutting out one SQL query per result object, and only touches the model to add an optional kwarg for custom field memoisation, otherwise it just uses the existing serialiser cache.

@roganartu commented on GitHub (Aug 18, 2020): That's entirely reasonable. The primary motivation for submitting this was that I'd done the profiling and I figured a ticket seemed as good a place as any to document my findings since I hadn't seen an deep analysis of the root causes anywhere yet. Would a PR for https://github.com/roganartu/netbox/commit/13238ea6c76f6c039fb83dc3e188939a8ca13e1e be compatible with your plans for #4878? It represents a nearly 20% improvement by cutting out one SQL query per result object, and only touches the model to add an optional kwarg for custom field memoisation, otherwise it just uses the existing serialiser cache.
adam commented 2025-12-29 18:32:28 +01:00
Author
Owner
Copy Link

@jeremystretch commented on GitHub (Sep 17, 2020):

Given that #4878 has been merged into develop-2.10 at this point, I don't think it makes sense to commit any further development effort to the current implementation (except for any bugs that happen to pop up). However I invite you to experiment with the upcoming release and share any suggestions you have for improvements.

@jeremystretch commented on GitHub (Sep 17, 2020): Given that #4878 has been merged into `develop-2.10` at this point, I don't think it makes sense to commit any further development effort to the current implementation (except for any bugs that happen to pop up). However I invite you to experiment with the upcoming release and share any suggestions you have for improvements.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
beta
breaking change
complexity: high
complexity: low
complexity: medium
needs milestone
netbox
pending closure
plugin candidate
pull-request
Mirrored from GitHub Pull Request
 severity: high
severity: low
severity: medium
status: accepted
status: backlog
status: blocked
status: duplicate
status: needs owner
status: needs triage
status: revisions needed
status: under review
topic: GraphQL
topic: Internationalization
topic: OpenAPI
topic: UI/UX
topic: cabling
topic: event rules
topic: htmx navigation
topic: industrialization
topic: migrations
topic: plugins
topic: scripts
topic: templating
topic: testing
type: bug
type: deprecation
type: documentation
type: feature
type: housekeeping
type: translation
No Label type: housekeeping
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
adam
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: starred/netbox#3984
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?