DSS NRID Performance Issues: High Latency and Contention for ISA Queries

[wing-utm-sharing-airspace]

Describe the bug
When running the NRID USS Qualifier, we've noticed GET and PUT ISA operations returning DEADLINE EXCEEDED errors (taking longer than 10s).

Looking at the CRDB console, I'm seeing a good amount of contention and transaction restarts around the same time.

Should be noted we use this instance for SCD load testing as well but have primarily seen timeouts around NRID requests.

To Reproduce
Steps to reproduce the behavior:
This can be reproduced using the NRID Heavy Traffic Concurrent USS Qualifier test scenario - we can get a passing result occasionally but this scenario seems to be failing more often than not.

Expected behavior
I would expect the DSS to be able to handle USS Qualifier levels of traffic without excessive contention/timeouts.

Additional context
Logs from our DSS deployment around the time of some of these timeouts
downloaded-logs-20250812-125143.json

[BenjaminPelletier]

Thanks for this report -- that looks like great info to me. Interestingly, it seems like the problem is strongly linked to transaction restarts, but doesn't seem to be nearly as related to contention most of the time. We don't see failures in the CI, but the CI does not yet use a multi-node cluster, some aspect of which is presumably responsible for the problem. @barroco when you do deployment verification for a dss release next, could you make sure the verification tests include the mentioned scenario? That way we can see if the problem is reproducible in general or if we need to pursue getting more deployment-specific information. I'm happy to help construct an appropriate test configuration if that can help.

@mickmis or @the-glu do you have an ideas or suggestions on next troubleshooting steps before we make our own deployment to attempt to reproduce? Glancing at the logs seems to suggest CRDB is compacting on at least one of the affected nodes at the relevant time (though I see compacting on a different node that never has problems also, so not definitive). Can you check into what is supposed to happen (presumably CRDB is engineered to never have delays like this under normal circumstances, even when maintenance operations are being performed) and how this situation might differ from that? Assuming compaction is the issue and putting aside that it shouldn't affect ops like this, can you guess whether we expect compaction to actually be needed very often during normal use of the DSS? I would have expected we should not actually be putting that much stress on the system (even with "high" volume in the tests) and therefore I wouldn't have expected something like compaction to happen very often. That seems inconsistent with the observation that the load tests fail most of the time if compaction or similar is responsible for the failures.

@wing-utm-sharing-airspace what version of DSS software is being used?

[wing-utm-sharing-airspace]

We're running cockroach v24.1.3 and DSS v0.19.0 on this instance

[BradNicolle]

We've identified a possible contributing factor - it appears that subscriptions garbage collection is not working correctly on the main instance seeing this issue. For example, counting the total number of subscriptions:

root@localhost:26257/rid> SELECT COUNT(*) FROM subscriptions;
  count
---------
  16388
(1 row)

Counting the total number of subscriptions older than today's date:

root@localhost:26257/rid> SELECT COUNT(*) FROM subscriptions WHERE ends_at < CURRENT_DATE;
  count
---------
  15577
(1 row)

The oldest subscriptions date back about 5 months:

root@localhost:26257/rid> SELECT ends_at FROM subscriptions ORDER BY ends_at ASC LIMIT 1;
             ends_at
---------------------------------
  2025-03-08 02:39:30.858141+00
(1 row)

Looking at the garbage collector function, it seems like this could only ever delete one subscription at a time and then return an error, as the loop returns if subOut != nil. We're not even seeing this error in the logs though - we just see Successful delete expired records every 30mins from main.go. So it seems like either ListExpiredSubscriptions is returning an empty list, or DeleteSubscription is not actually deleting and returning anything.

I haven't yet been able to gather any evidence that this large subscriptions list actually causes any of the issues we're seeing. It's conceivable though that a large subscriptions table could slow down queries enough to cause contention under load.

[mickmis]

We've identified a possible contributing factor - it appears that subscriptions garbage collection is not working correctly on the main instance seeing this issue.

@BradNicolle thanks for the findings, there is definitely something fishy going on here.

I went through the code and I agree that this looks like this is going to be deleting 1 record at a time, be it an ISA or a subscription. IMO the original intent was to return an error if the ISA/subscription was deleted in the meantime by some other means, but that the condition == nil got reversed to != nil by mistake.
That's a first thing to address. We should probably just accumulate any error encountered and proceed with the deletion of the remaining subscriptions.

Looking at the garbage collector function, it seems like this could only ever delete one subscription at a time and then return an error, as the loop returns if subOut != nil. We're not even seeing this error in the logs though - we just see Successful delete expired records every 30mins from main.go. So it seems like either ListExpiredSubscriptions is returning an empty list, or DeleteSubscription is not actually deleting and returning anything.

Do you ever see in your logs Fail to delete expired records? This is what should be logged when the garbage collector has deleted one record:

dss/cmds/core-service/main.go

Line 402 in e56fefb

logger.Warn("Fail to delete expired records", zap.Error(err))

Now, the DSS instance will only delete expired record of its own, identified by the writer column which should match its configured locality. I suspect the ~15k subscriptions you report have a writer that does not match the locality of your DSS instance, i.e. they belong to another DSS instance or the locality changed at some point. Would you mind checking if that is the case?
In any case, for the garbage collector, it would probably makes sense to follow the same approach as for the scd store and remove all expired entities, even ones that don't belong to the current instance. Thoughts @BenjaminPelletier ?

Overall, since:

• the probability that the accumulation of records is the cause of or contributes to the latency/contention issues initially reported is high enough, and that
• fixing this accumulation is straightforward enough and will benefit us in any case,

I think we should just go ahead with fixing it and resume the troubleshooting later if that does not.

[BradNicolle]

@mickmis strangely, we don't see Fail to delete expired records at all in the logs, only Successful delete expired records. That indicates to me that perhaps we're not even getting into that loop, or alternatively DeleteSubscription is returning nil for all records. It looks like DeleteSubscription is doing some further filtering on the updated_at field, so maybe the results are somehow excluded by that filter?

I've checked the writer of the subscriptions with:

SELECT DISTINCT writer FROM subscriptions;

This shows the same writer (i.e. instance-3) for all subscriptions in the DB, which seems strange as there are also two other localities (i.e. instance-1 and instance-2). The instance-3 locality does still exist in our cluster though, and is reporting the Successful delete expired records log as expected.

I also plan on making a separate bug report regarding scd once I've gathered evidence, but we also see a large number of subscriptions there too:

root@localhost:26257/scd> SELECT COUNT(*) FROM scd_subscriptions WHERE ends_at < CURRENT_DATE;
  count
---------
  30025
(1 row)

We also see 5xx errors (albeit at a lower rate) from scd-related APIs. Does the scd garbage collection work differently to rid? I couldn't find a reference to it in my brief search of the codebase.

[mickmis]

We also see 5xx errors (albeit at a lower rate) from scd-related APIs. Does the scd garbage collection work differently to rid? I couldn't find a reference to it in my brief search of the codebase.

Yes, see https://github.com/interuss/dss/tree/master/cmds/db-manager/cleanup for how to do it and #1074 for some additional context on the approach taken. TL;DR: for scd a CLI tool is available to perform the cleanup, which may be called manually or setup to be invoked by a scheduled job.

IMO having garbage collection not aligned between rid and scd stores is confusing and should be addressed in any case.

[mickmis]

For anyone investigating this issue: it is worth looking at the code on interuss/dss/v0.19.0 tag and not on master as relevant changes happened in the meantime.

One of those changes being that we have in v.0.19.0 different store implementation depending on the version of the rid schema, and one of them (for schema versions < 4.0.0) always return an empty list when listing expired subscriptions:

dss/pkg/rid/store/cockroach/subcriptions_v3.go

Lines 277 to 280 in 2c0ff28

	// ListExpiredSubscriptions returns empty. We don't support this function in store v3.0 because db doesn't have 'writer' field.
	func (c *subscriptionRepoV3) ListExpiredSubscriptions(ctx context.Context, writer string) ([]*ridmodels.Subscription, error) {
	return make([]*ridmodels.Subscription, 0), nil
	}

(the comment is actually wrong, versions 3.1.0 and 3.1.1 of the schema do have the writer column)
So, @BradNicolle could you check what is the version of your schema? SELECT schema_version FROM schema_versions should do.

That indicates to me that perhaps we're not even getting into that loop, or alternatively DeleteSubscription is returning nil for all records.

This could be explained by the fact that you have a schema version 3.1.0 or 3.1.1.
Now that would not explain why only instance-3 seems to have expired entities not cleaned up, except if that's the only instance creating them.

It looks like DeleteSubscription is doing some further filtering on the updated_at field, so maybe the results are somehow excluded by that filter?

Since we are passing directly to DeleteSubscription the output of ListExpiredSubscriptions, I would expect not, although not impossible.

This shows the same writer (i.e. instance-3) for all subscriptions in the DB, which seems strange as there are also two other localities (i.e. instance-1 and instance-2). The instance-3 locality does still exist in our cluster though, and is reporting the Successful delete expired records log as expected.

Could you check that the locality is correctly set on the instance? The issue could be explained if somehow the locality was left empty or wrong or changed at some point. It is set by the CLI flag locality.

[BradNicolle]

@mickmis - the RID schema version on that instance is 4.0.0:

root@localhost:26257/rid> SELECT * FROM schema_versions;
  onerow_enforcer | schema_version
------------------+-----------------
         t        | v4.0.0
(1 row)

I've double-checked both the CLI flag reported by Kubernetes, but also by getting a shell on the instance and checking the process invocation i.e.:

/ # ps | cat
PID   USER     TIME  COMMAND
    1 root     20:25 core-service --accepted_jwt_audiences=<redacted>,<redacted> --addr=:8080 --cockroach_host=cockroachdb-balanced.dss-main --cockroach_port=26257 --cockroach_ssl_dir=/cockroach/cockroach-certs --cockroach_ssl_mode=verify-full --cockroach_user=root --dump_requests=true --enable_scd=true --garbage_collector_spec=@every 30m --gcp_prof_service_name= --jwks_endpoint=<redacted> --jwks_key_ids=1 --locality=instance-3 --public_key_files=

I've also compared that against the other instances, and their args only differ in the accepted_jwt_audiences and locality as expected.

It also appears that instance-3 is still managing to write entries with its given locality indicating it is correctly configured as of today, e.g. the most recent row in subscriptions has:

|           starts_at           |            ends_at            |          updated_at           |
| 2025-08-26 02:29:48.009897+00 | 2025-08-26 02:32:48.009897+00 | 2025-08-26 02:29:48.465289+00 |

[mickmis]

Not this then! Thanks

With the upgrade to DB schema v4, the DB name for rid changed (from defaultdb to rid). There is some logic in the code for retrocompatiblity about this, however it seems brittle and it could be falling back to defaultdb instead of rid when it should not (e.g. during a transient network issue at startup of the DSS instance):

dss/cmds/core-service/main.go

Lines 109 to 139 in 11c42cd

	func createRIDServers(ctx context.Context, locality string, logger *zap.Logger) (*rid_v1.Server, *rid_v2.Server, error) {
	connectParameters := flags.ConnectParameters()
	connectParameters.DBName = "rid"
	ridCrdb, err := datastore.Dial(ctx, connectParameters)
	if err != nil {
	// TODO: More robustly detect failure to create RID server is due to a problem that may be temporary
	if strings.Contains(err.Error(), "connect: connection refused") {
	return nil, nil, stacktrace.PropagateWithCode(err, codeRetryable, "Failed to connect to CRDB server for remote ID store")
	}
	return nil, nil, stacktrace.Propagate(err, "Failed to connect to remote ID database; verify your database configuration is current with https://github.com/interuss/dss/tree/master/build#upgrading-database-schemas")
	}
	ridStore, err := ridc.NewStore(ctx, ridCrdb, connectParameters.DBName, logger)
	if err != nil {
	// try DBName of defaultdb for older versions.
	ridCrdb.Pool.Close()
	connectParameters.DBName = "defaultdb"
	ridCrdb, err := datastore.Dial(ctx, connectParameters)
	if err != nil {
	return nil, nil, stacktrace.Propagate(err, "Failed to connect to remote ID database for older version <defaultdb>; verify your database configuration is current with https://github.com/interuss/dss/tree/master/build#upgrading-database-schemas")
	}
	ridStore, err = ridc.NewStore(ctx, ridCrdb, connectParameters.DBName, logger)
	if err != nil {
	// TODO: More robustly detect failure to create RID server is due to a problem that may be temporary
	if strings.Contains(err.Error(), "connect: connection refused") || strings.Contains(err.Error(), "database has not been bootstrapped with Schema Manager") {
	ridCrdb.Pool.Close()
	return nil, nil, stacktrace.PropagateWithCode(err, codeRetryable, "Failed to connect to CRDB server for remote ID store")
	}
	return nil, nil, stacktrace.Propagate(err, "Failed to create remote ID store")
	}
	}

I don't expect that to be the cause, because while it could explain some issues, but that would probably cause some others, but just to be sure, could you check what DB instance-3 is using? And if you have or not a defaultdb DB present and if it has a schema and data?

This is one additional thing that should be fixed in any case.

[mickmis]

In addition, what is the uptime of this instance? The version of the DB schema determined at runtime is queried once and remains the same throughout the life of the instance. If a migration was done while it was live, that could be an issue. Any chance this has happened?

Edit: I see that the version of the store is determined when either Interact and Transact are called. The garbage collector gets a store with a single call of Interact at startup. All other calls made during the runtime of the instance will be determining again what is the version of the store. If a migration is made during the lifetime of an instance and that this instance is not restarted, we will end up in a situation where different code paths of the instance will be using different versions of the store. One more thing to address somehow in any case. I will open up issues about those findings.

[BradNicolle]

The defaultdb DB does exist, however does not contain any tables:

root@localhost:26257/defaultdb> \dt
List of relations:
  Schema | Name | Type | Owner
---------+------+------+--------
(0 rows)

GKE regularly restarts these pods, so the pods in this case are about 3 days old.