NetBox 2.9.11 and 2.11.7 is a lot slower than 2.8.5

[markkuleinio]

Briefly: NetBox 2.8.5 runs fine, but upgrading to 2.9.11 or 2.11.7 makes operations slow. For example: the same app that takes ~1 second in 2.8.5 takes ~12 seconds in 2.11.7.

Platform info at start:

• Both VMs are Ubuntu 20.04 instances in AWS (t3.medium, 2 vCPU, 4GB RAM), configured identically
• Both are using same sized Amazon RDS Postgres 12.5 databases in the same region
• server1 = prod = NetBox 2.8.5 (installed about 8 months ago)
• server2 = dev = NetBox 2.8.5 (installed now, with "git checkout v2.8.5")
• gunicorn is configured wth the contrib settings (5 workers etc.)
• Database is pg_dumped from prod to dev, ./upgrade.sh is run (and redis package is manually upgraded to 3.5.3 to match the production setup and prevent errors)

Test procedure:

• Running with pynetbox for example timeit.timeit('netbox.circuits.providers.get(name="Elisa")', number=50, setup="from __main__ import netbox") gives identical results (like 2.2 seconds)
• Running with curl /api/circuits/providers/ takes under 0.1 seconds on both (3 providers listed)

Now upgrade dev (server2) to 2.9.11:

• Stop netbox and netbox-rq
• git checkout 3f5a2b9
• Check configuration.py (edit LDAP auth etc.)
• ./upgrade.sh, no errors
• Start netbox and netbox-rq

Redoing the test procedure above:

• timeit.timeit('netboxdev.circuits.providers.get(name="Elisa")', number=50, setup="from __main__ import netboxdev") takes ~15 seconds (prod is still 2.2 seconds)
• GET /api/circuits/providers/ takes 0.3 - 0.5 seconds (prod is still under 0.1 seconds)

Now upgrade dev to 2.11.7:

• Stop netbox and netbox-rq
• git checkout master
• ./upgrade.sh, no errors (takes a minute or so with extras.0051_migrate_customfields)
• Start netbox and netbox-rq

Redoing the test procedure above:

• No change from 2.9.11 = still a lot slower than 2.8.5
• (Note: I've also tried upgrading directly from 2.8.5 to 2.11.7, the results are the same, a lot slower than 2.8.5)

This same slowness is present in all apps, like VRFs, getting a tenant, or getting an unexisting prefix, etc.

What I noticed is when I keep GETting for example an unexisting prefix (/api/ipam/prefixes/1111/) with curl and I keep top running, I see gunicorn in the top, no surprise there. But in prod it takes like 1-2 percent of CPU but in dev it takes easily like 20-50 percent. So there probably is the reason for slowness.

Any ideas how to troubleshoot this further?

Update: With another identical server+database combo ("server3", actually the database is the same Amazon RDS instance but just a new database in the service) but with an empty NetBox database it looks like this:

$ time curl -X GET https://server3/api/ipam/prefixes/1111/ -H "Authorization: token $DEVTOKEN" -s
{"detail":"Not found."}
real    0m0.125s
user    0m0.013s
sys     0m0.000s

while in the dev server ("server2") it looks like this:

$ time curl -X GET https://server2/api/ipam/prefixes/1111/ -H "Authorization: token $DEVTOKEN" -s
{"detail":"Not found."}
real    0m0.394s
user    0m0.004s
sys     0m0.009s

i.e. about three times slower. As far as I see it the servers are configured identically, server2 just has all the prod data dumped in and server3 has a blank database. Also the previously mentioned /circuits/providers/ tests are fast on server3.

So it looks like there is something in the database that destroys the performance with 2.9.x and 2.11.x but not with 2.8.5. But how to find it out...

[jeremystretch]

I can't think of anything that would have this sort of impact in the newer releases. Some suggestions:

• Test with remote authentication disabled
• Enable debugging on both systems and compare the reported metrics

[markkuleinio]

Remote authentication does not seem to affect this. I've enabled DEBUG=True and I see the debugging tools in the GUI but I don't know what exactly to do with it. Both are showing two SQL queries in about 2 ms when trying /api/circuits/providers/111/ (which is not found) in the browser.

(But there is no "111" in this query so it does not show all the queries I guess:

SELECT ••• FROM "django_session" WHERE ("django_session"."expire_date" > '2021-06-24T06:02:07.911404+00:00'::timestamptz AND "django_session"."session_key" = 'xxx') LIMIT 21

SELECT "django_content_type"."id",
       "django_content_type"."app_label",
       "django_content_type"."model"
  FROM "django_content_type"
 WHERE ("django_content_type"."app_label" = 'circuits' AND "django_content_type"."model" = 'provider')
 LIMIT 21

I also verified with tcpdump that the delay is in the app side and not in the loadbalancer (well, the gunicorn high CPU also told that).

[markkuleinio]

I played with redis-cli (DEBUG=False in NetBox), CONFIG RESETSTAT, then the 50-round timeit measurement (timeit.timeit('netbox.circuits.providers.get(name="Elisa")', number=50, setup="from __main__ import netbox")), and INFO STAT.

Server3 (test, 2.11.7 with no data except some manually created objects like this provider "Elisa", about 2 seconds, omitted most of zero outputs here):

127.0.0.1:6379> info stats
# Stats
total_commands_processed:851
total_net_input_bytes:45975
total_net_output_bytes:50505
keyspace_hits:850
keyspace_misses:0

Server2 (dev, 2.11.7 with all the data, about 16 seconds):

127.0.0.1:6379> info stats
# Stats
total_commands_processed:901
total_net_input_bytes:48675
total_net_output_bytes:12038205
keyspace_hits:900
keyspace_misses:0

The notable difference is the total_net_output_bytes which is ~240 times larger in the slowly working server (server2). Btw the same amount of bytes if testing with a 50-round curl in shell. And, when testing with curl, the output data is identical so there is no difference in the returned json data amount.

What should I think about the huge total_net_output_bytes value? Where is that 240 times larger redis output data coming from?

[markkuleinio]

(My testing looks inconsistent so I repeated the timeit measurements with timeit.timeit('netbox.circuits.providers.get(111)', number=50, setup="from __main__ import netbox") i.e. with the non-existent provider. The results are similar, total_net_input_bytes is ~40kB and total_net_output_bytes is ~12MB (in the slow server only), with the same kind of timing difference (~2s and ~15s).)

There is no other usage for these servers during the test runs and the redis-cli results are repeatable.

[markkuleinio]

Next attempt: redis-cli monitor

$ redis-cli flushall
OK
$ redis-cli monitor > monitor

Issue GET /circuits/providers/111/ with curl

^C
$ wc monitor
     68     457 1057400 monitor
$

That's with server2 (over 1MB of data!). With server3 (test) it's only:

$ wc monitor
  42  283 5693 monitor
$

In server2 most of the output is in two lines: both are about 428000 bytes. First one is an "EVALSHA" line and the other one is "lua setex" line. Both contain data that looks like some permission name, like "tenancy.view_tenantgroup" is repeated a lot. There is a lot of hex values so I don't paste anything here for safety. Actually there is a lot of repetitive data, some hex characters and a permission name embedded, the same data all over again. We only have a couple of NetBox users that have specific permissions set up.

But wow, that lead me something: I started using another user for the API calls, and now everything is fast! I'll dig into this more and report back later again.

[markkuleinio]

So here is the solution, please read the intermediate steps from the thread above.

The problematic API user (let's call it "ipamuser") has add+change+delete+view permissions for specific models, not to every model, in NetBox 2.8.5, that's about 210 permissions selected in the list.

Even opening that "ipamuser" in NetBox 2.11.7 configuration screen (after upgrading NetBox) takes several seconds while the permissions are checked/fetched. There are about 210 "ObjectPermission_users" objects in the list, and the same permissions are found in the Permissions configurations as well. Apparently the upgrade migrations created those ~210 separate permissions (like circuits.add_circuit, circuits.change_circuit, ...) and assigned them to "ipamuser", and handling that many permissions for a user is very slow. And the permissions check happens at some level with each API request.

So, I created a new permission (just one permission) that included all the needed actions and objects, and assigned that permission to "ipamuser", and now the API test calls are as fast as expected.

That's a lesson for all NetBox upgraders (from earlier versions to 2.9.x or newer): be sure to check the migrated permission combinations and create optimized permissions as needed. I don't know if this has been already discussed somewhere, but there you go anyway.

[markkuleinio]

The question is still: why the permissions were duplicated in the redis calls? In the redis monitor output there was lot of duplicate data, so maybe there is still some problem under all the symptoms.

[candlerb]

Apparently the upgrade migrations created those ~210 separate permissions (like circuits.add_circuit, circuits.change_circuit, ...)

I found the same. When the permission model changed, the migration exploded the existing permissions into shrapnel, presumably because it would have been to difficult to work out what grouped sets of permissions would have been equivalent.

Since a single permission can reference multiple models, and can also include multiple permission flags, you can most likely replace them with a handful of unified permissions: e.g.

1. can (view|add|change|delete) to models A, B, C, D ... with constraint Q
2. can view to models X, Y, Z with constraint Y
3. perhaps a few special cases like napalm_read

In one production instance, I managed to reduce it from over nearly 300 permissions to just 4. In particular, a single "view_all" permission for read-only users is very straightforward.

[LuPo]

@candlerb following your suggestion, I have noticed that the constraints can only be applied if common to all the classes in models selected. In case of "view_all" permission type it is not possible to filter with ad example "vrf" constraint. Perhaps it could be viable to omit applying filter to the irrelevant classes?

[candlerb]

You'll need to create two permissions:

1. one for objects which have a vrf attribute, where you want to apply some vrf = X condition
2. one for objects which don't have a vrf attribute, where you want to allow all objects to be visible (presumably)

I don't think omitting the filter would be a good idea: it would mean that you might accidentally be granting permission to certain objects which you weren't expecting to grant permissions to.