julienvincent
12/05/2023, 10:05 AMLookupResources
to query a resource type with a response size of around 1.1K resources;
I am seeing response times of around 300-500ms. This seems very high to me for the order of mag I am dealing with. Is this expected or does something seem wrong?
I am seeing the same order of mag when running spice on our prod environment (with spanner) and locally (with postgres)vroldanbet
12/05/2023, 1:15 PMjulienvincent
12/05/2023, 1:48 PMvroldanbet
12/05/2023, 1:56 PMvroldanbet
12/05/2023, 1:56 PMvroldanbet
12/05/2023, 1:57 PMjulienvincent
12/05/2023, 2:18 PMjulienvincent
12/05/2023, 2:19 PMjulienvincent
12/05/2023, 2:21 PMvroldanbet
12/05/2023, 2:38 PMvroldanbet
12/05/2023, 2:38 PMvroldanbet
12/05/2023, 2:38 PMvroldanbet
12/05/2023, 2:48 PMjulienvincent
12/05/2023, 2:53 PMjulienvincent
12/05/2023, 2:53 PMjulienvincent
12/05/2023, 2:54 PMvroldanbet
12/05/2023, 2:54 PMvroldanbet
12/05/2023, 2:55 PMvroldanbet
12/05/2023, 2:55 PMimage
in your SpiceDBCluster
objectvroldanbet
12/05/2023, 2:55 PMmigrate
for youjulienvincent
12/05/2023, 2:57 PMvroldanbet
12/05/2023, 2:57 PMvroldanbet
12/05/2023, 2:58 PMvroldanbet
12/05/2023, 2:58 PMjulienvincent
12/05/2023, 2:58 PMlookup-resources location read user<id>
julienvincent
12/05/2023, 2:58 PMvroldanbet
12/05/2023, 2:59 PMfull_consistency
you'll see the true cost of your request, as cache won't be usedjulienvincent
12/05/2023, 2:59 PMjulienvincent
12/05/2023, 2:59 PMvroldanbet
12/05/2023, 3:00 PMvroldanbet
12/05/2023, 3:01 PMat_least_as_fresh
is the recommended way to call SpiceDB is you are keeping zedtokens aroundjulienvincent
12/05/2023, 3:01 PMjulienvincent
12/05/2023, 3:01 PMjulienvincent
12/05/2023, 3:01 PMvroldanbet
12/05/2023, 3:02 PMvroldanbet
12/05/2023, 3:02 PMvroldanbet
12/05/2023, 3:02 PMvroldanbet
12/05/2023, 3:03 PMvroldanbet
12/05/2023, 3:04 PMjulienvincent
12/05/2023, 3:07 PMjulienvincent
12/05/2023, 3:11 PMvroldanbet
12/05/2023, 3:19 PMjulienvincent
12/05/2023, 3:26 PMgo_sched_gomaxprocs_threads
metric it seems to be reported as 4. Can I trust this?julienvincent
12/05/2023, 3:27 PMvroldanbet
12/05/2023, 3:29 PMvroldanbet
12/05/2023, 3:30 PMvroldanbet
12/05/2023, 3:31 PMvroldanbet
12/05/2023, 3:31 PMvroldanbet
12/05/2023, 3:32 PMjulienvincent
12/05/2023, 3:34 PMvroldanbet
12/05/2023, 3:36 PMvroldanbet
12/05/2023, 3:38 PMjulienvincent
12/05/2023, 3:39 PM--enable-experimental-watchable-schema-cache
flag? and then Also in conjunction with --datastore-schema-watch-heartbeat
?vroldanbet
12/05/2023, 3:39 PMjulienvincent
12/05/2023, 3:40 PMvroldanbet
12/05/2023, 3:41 PMvroldanbet
12/05/2023, 3:41 PMvroldanbet
12/05/2023, 3:41 PMvroldanbet
12/05/2023, 3:42 PMWriteSchema
then the cache will back off until it has caught up with the new schema revisionsjulienvincent
12/06/2023, 1:09 PM{at_least_as_fresh}
consistency token
Seeing random frequent spikes of 5s+ (sometimes 8s+) for queries against spicedb. Example, see attached image:
https://cdn.discordapp.com/attachments/1181536779006918676/1181945533691084800/image.png?ex=6582e78e&is=6570728e&hm=c29284b5290132333bd66c81f6076762bc1fc23e2b68b4d9d0fc1a18caf86854&julienvincent
12/06/2023, 1:09 PMjulienvincent
12/06/2023, 1:11 PMvroldanbet
12/06/2023, 1:14 PMzed backup
and send it over to us.vroldanbet
12/06/2023, 1:14 PMzed
?julienvincent
12/06/2023, 1:16 PMvroldanbet
12/06/2023, 1:16 PMvroldanbet
12/06/2023, 1:17 PMvroldanbet
12/06/2023, 1:17 PMjulienvincent
12/06/2023, 1:17 PMjulienvincent
12/06/2023, 1:18 PMvroldanbet
12/06/2023, 1:19 PMjulienvincent
12/06/2023, 1:19 PMjulienvincent
12/06/2023, 1:20 PMvroldanbet
12/06/2023, 1:20 PMjulienvincent
12/06/2023, 1:20 PMvroldanbet
12/06/2023, 1:21 PMvroldanbet
12/06/2023, 1:21 PMvroldanbet
12/06/2023, 1:22 PMcheck --explain
?julienvincent
12/06/2023, 1:22 PMvroldanbet
12/06/2023, 1:22 PMjulienvincent
12/06/2023, 1:22 PMjulienvincent
12/06/2023, 1:23 PMjulienvincent
12/06/2023, 1:23 PMvroldanbet
12/06/2023, 1:23 PMfully-consistency
semantics, does it always reproduce the issue?julienvincent
12/06/2023, 1:23 PMjulienvincent
12/06/2023, 1:24 PMjulienvincent
12/06/2023, 1:24 PMjulienvincent
12/06/2023, 1:25 PMvroldanbet
12/06/2023, 1:25 PMvroldanbet
12/06/2023, 1:25 PMvroldanbet
12/06/2023, 1:29 PMvroldanbet
12/06/2023, 1:36 PMjulienvincent
12/06/2023, 1:36 PMjulienvincent
12/06/2023, 1:37 PMjulienvincent
12/06/2023, 1:37 PMjulienvincent
12/06/2023, 1:37 PMjulienvincent
12/06/2023, 1:38 PMvroldanbet
12/06/2023, 1:38 PMvroldanbet
12/06/2023, 1:39 PMvroldanbet
12/06/2023, 1:39 PMjulienvincent
12/06/2023, 1:40 PMvroldanbet
12/06/2023, 1:40 PMjulienvincent
12/06/2023, 1:40 PMvroldanbet
12/06/2023, 1:41 PMvroldanbet
12/06/2023, 1:41 PMvroldanbet
12/06/2023, 1:41 PMjulienvincent
12/06/2023, 1:42 PMjulienvincent
12/06/2023, 1:43 PMvroldanbet
12/06/2023, 1:43 PMvroldanbet
12/06/2023, 1:43 PMvroldanbet
12/06/2023, 1:46 PMvroldanbet
12/06/2023, 1:46 PMvroldanbet
12/06/2023, 1:50 PMjulienvincent
12/06/2023, 1:50 PM--datastore-conn-uri="projects/project-id/instances/instance-id/databases/database-id"
- what do I use here for local spanner?vroldanbet
12/06/2023, 1:51 PMjulienvincent
12/06/2023, 1:51 PMvroldanbet
12/06/2023, 1:51 PMvroldanbet
12/06/2023, 1:51 PMvroldanbet
12/06/2023, 1:51 PMjulienvincent
12/06/2023, 1:51 PMjulienvincent
12/06/2023, 1:51 PMvroldanbet
12/06/2023, 1:52 PMspanner() {
docker run -d -p 9010:9010 -p 9020:9020 gcr.io/cloud-spanner-emulator/emulator
gcloud config configurations activate emulator
gcloud spanner instances create test-instance --config=emulator-config --description="Test Instance" --nodes=1
gcloud spanner databases create spicedb --instance=test-instance
gcloud config configurations activate default
}
julienvincent
12/06/2023, 1:53 PMjulienvincent
12/06/2023, 1:54 PMjulienvincent
12/06/2023, 1:54 PMjulienvincent
12/06/2023, 1:54 PMvroldanbet
12/06/2023, 1:54 PMvroldanbet
12/06/2023, 1:55 PMvroldanbet
12/06/2023, 1:55 PMvroldanbet
12/06/2023, 1:55 PMgcloud config configurations create emulator
gcloud config set auth/disable_credentials true
gcloud config set project your-project-id
gcloud config set api_endpoint_overrides/spanner http://localhost:9020/
`
vroldanbet
12/06/2023, 2:00 PMjulienvincent
12/06/2023, 2:20 PMjulienvincent
12/06/2023, 2:20 PMjulienvincent
12/06/2023, 2:21 PMjulienvincent
12/06/2023, 2:21 PMvroldanbet
12/06/2023, 2:21 PMjulienvincent
12/06/2023, 2:26 PMjulienvincent
12/06/2023, 2:26 PMvroldanbet
12/06/2023, 2:28 PMvroldanbet
12/06/2023, 2:28 PMjulienvincent
12/06/2023, 2:31 PMjulienvincent
12/06/2023, 2:32 PMSummary:
Total: 41.3156 secs
Slowest: 1.9387 secs
Fastest: 0.2805 secs
Average: 0.4968 secs
Requests/sec: 120.5356
Total data: 174894300 bytes
Size/request: 35190 bytes
Response time histogram:
0.281 [1] |
0.446 [4410] |â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â– â–
0.612 [19] |
0.778 [0] |
0.944 [0] |
1.110 [0] |
1.275 [0] |
1.441 [117] |â–
1.607 [85] |â–
1.773 [172] |â– â–
1.939 [166] |â– â–
Latency distribution:
10% in 0.3342 secs
25% in 0.3428 secs
50% in 0.3553 secs
75% in 0.3738 secs
90% in 1.3484 secs
95% in 1.7319 secs
99% in 1.8761 secs
Load test summary - the distribution matches what I am seeing in prod. Same rough proportion of random spikesvroldanbet
12/06/2023, 2:33 PMjulienvincent
12/06/2023, 2:33 PMjulienvincent
12/06/2023, 2:33 PMjulienvincent
12/06/2023, 2:33 PMjulienvincent
12/06/2023, 2:34 PMvroldanbet
12/06/2023, 2:34 PMNotable limitations:
The emulator only allows one read-write transaction or schema change at a time. Any concurrent transaction will be aborted. Transactions should always be wrapped in a retry loop. This recommendation applies to the Cloud Spanner service as well.
vroldanbet
12/06/2023, 2:34 PMvroldanbet
12/06/2023, 2:34 PMvroldanbet
12/06/2023, 2:34 PMjulienvincent
12/06/2023, 2:36 PMjulienvincent
12/06/2023, 2:37 PMzed
cli toojulienvincent
12/06/2023, 2:37 PMhyperfine 'parallel -j {threads} -n0 zed permission lookup-resources --skip-version-check location read user:acc_fR2nH4wdUkFmo4ZG1bdQGAjsjbDe ::: {1..{threads}}' -P threads 5 20 -D 5
julienvincent
12/06/2023, 2:38 PMBenchmark 4: parallel -j 20 -n0 zed permission lookup-resources --skip-version-check location read user:acc_fR2nH4wdUkFmo4ZG1bdQGAjsjbDe ::: {1..20}
Time (mean ± σ): 502.7 ms ± 657.9 ms [User: 431.6 ms, System: 471.7 ms]
Range (min … max): 288.6 ms … 2375.0 ms 10 runs
See the massive min->max rangevroldanbet
12/06/2023, 2:39 PMvroldanbet
12/06/2023, 2:39 PMjulienvincent
12/06/2023, 2:40 PMjulienvincent
12/06/2023, 2:41 PMvroldanbet
12/06/2023, 2:42 PMjulienvincent
12/06/2023, 2:42 PMvroldanbet
12/06/2023, 2:44 PMvroldanbet
12/06/2023, 2:44 PMzed
calls? or it has to be a load testvroldanbet
12/06/2023, 2:44 PMjulienvincent
12/06/2023, 2:45 PMjulienvincent
12/06/2023, 2:45 PMvroldanbet
12/06/2023, 2:45 PMjulienvincent
12/06/2023, 2:45 PMvroldanbet
12/06/2023, 2:45 PMjulienvincent
12/06/2023, 2:46 PMjulienvincent
12/06/2023, 2:46 PMjulienvincent
12/06/2023, 2:47 PMhyperfine 'parallel -j 20 -n0 zed permission lookup-resources --skip-version-check location read user:acc_fR2nH4wdUkFmo4ZG1bdQGAjsjbDe --consistency-at-least=GhUKEzE3MDE4NzI5MDAwMDAwMDAwMDA= ::: {1..20}' --runs 1000
julienvincent
12/06/2023, 2:47 PMzed
cli with a configurable concurrencyjulienvincent
12/06/2023, 2:47 PMjulienvincent
12/06/2023, 2:49 PMvroldanbet
12/06/2023, 2:52 PMvroldanbet
12/06/2023, 2:52 PMminimize_latency
I get a 500ms spike when the quantization window elapses and SpiceDB discards the cachesvroldanbet
12/06/2023, 2:54 PMReverseQueryRelationships
. I see the queries taking 60msvroldanbet
12/06/2023, 2:54 PMvroldanbet
12/06/2023, 2:54 PMjulienvincent
12/06/2023, 2:59 PM--consistency-full
triggers it every request. I guess that means it's just the emulator being slow and not actually what I am seeing in prod?julienvincent
12/06/2023, 2:59 PMvroldanbet
12/06/2023, 3:00 PMjulienvincent
12/06/2023, 3:03 PMjulienvincent
12/06/2023, 3:03 PMvroldanbet
12/06/2023, 3:53 PMvroldanbet
12/06/2023, 3:54 PMLookupResources
and invoke CheckPermission
it leads to 200ms requests, where Spanner queries are taking somewhere between 20ms up to 70msjulienvincent
12/06/2023, 4:29 PMjulienvincent
12/06/2023, 4:30 PMjulienvincent
12/07/2023, 12:04 AMparallel -j 1000 -n0 'hyperfine --runs 50 "zed permission lookup-resources --skip-version-check location read user:acc_fR2nH4wdUkFmo4ZG1bdQGAjsjbDe --consistency-at-least GhUKEzE3MDE5MDM4OTAwMDAwMDAwMDA="' ::: {1..10}
And adjusting the concurrency from 1..x.
Concurrency of 1
Time (mean ± σ): 46.8 ms ± 32.9 ms [User: 27.0 ms, System: 20.5 ms]
Range (min … max): 34.5 ms … 280.5 ms 100 runs
Concurrency of 10
Time (mean ± σ): 133.4 ms ± 76.0 ms [User: 28.9 ms, System: 18.9 ms]
Range (min … max): 68.5 ms … 511.9 ms 50 runs
Concurrency of 20
Time (mean ± σ): 257.4 ms ± 124.4 ms [User: 34.9 ms, System: 16.7 ms]
Range (min … max): 70.4 ms … 760.2 ms 50 runs
Concurrency of 50
Time (mean ± σ): 707.5 ms ± 481.3 ms [User: 36.9 ms, System: 19.8 ms]
Range (min … max): 81.2 ms … 2365.0 ms 50 runs
Concurrency of 100
Time (mean ± σ): 1.307 s ± 0.987 s [User: 0.038 s, System: 0.022 s]
Range (min … max): 0.000 s … 4.543 s 50 runs
These results were all against spanner, but using postgres shows rather similar results.
Do these results seem expected or surprising?
I find the rapid increase in p90 latency to be a bit surprising. I also find that the latency when using --consistency-full
being around 200-300ms to be surprising given the low volume of data.
It seems spicedb doesn't deal with concurrency very well. Even on relatively beefy VM's.
Thoughts?vroldanbet
12/07/2023, 9:52 AMjulienvincent
12/07/2023, 10:08 AMJoey
12/07/2023, 5:42 PMJoey
12/07/2023, 5:42 PMjulienvincent
12/08/2023, 11:16 AMjulienvincent
12/08/2023, 11:16 AMjulienvincent
12/08/2023, 3:20 PM~$ time parallel -j 2000 -n0 'curl -X POST -d "@./data.json" -H "authorization: Bearer dev" http://localhost:8443/v1/permissions/resources --silent | wc -l' ::: {1..3}
3227
3227
3227
real 0m1.463s
user 0m0.150s
sys 0m0.110s
3 concurrent requests reduces this instance to a 1.5s latencyJoey
12/08/2023, 4:16 PMJoey
12/08/2023, 4:16 PMjulienvincent
12/08/2023, 4:19 PMJoey
12/08/2023, 4:40 PMJoey
12/08/2023, 4:40 PMjulienvincent
12/08/2023, 4:42 PMjulienvincent
12/08/2023, 4:42 PMJoey
12/08/2023, 4:58 PMJoey
12/08/2023, 4:58 PMJoey
12/08/2023, 5:00 PMjulienvincent
12/08/2023, 5:01 PMjulienvincent
12/08/2023, 5:02 PMJoey
12/08/2023, 5:02 PMJoey
12/08/2023, 5:02 PMjulienvincent
12/08/2023, 5:02 PMJoey
12/08/2023, 5:03 PMJoey
12/08/2023, 5:03 PMjulienvincent
12/08/2023, 5:04 PMjulienvincent
12/08/2023, 5:04 PMjulienvincent
12/08/2023, 5:05 PMJoey
12/08/2023, 5:05 PMJoey
12/08/2023, 5:06 PMjulienvincent
12/08/2023, 5:07 PMJoey
12/08/2023, 5:08 PMjulienvincent
12/08/2023, 5:08 PMJoey
12/08/2023, 5:09 PMjulienvincent
12/08/2023, 5:09 PMJoey
12/08/2023, 5:09 PMjulienvincent
12/08/2023, 5:09 PMJoey
12/08/2023, 5:09 PMJoey
12/08/2023, 5:10 PMjulienvincent
12/08/2023, 5:10 PMjulienvincent
12/08/2023, 5:10 PMJoey
12/08/2023, 5:10 PMJoey
12/08/2023, 5:10 PMjulienvincent
12/08/2023, 5:10 PMJoey
12/08/2023, 5:10 PMJoey
12/08/2023, 5:11 PMJoey
12/08/2023, 5:11 PMjulienvincent
12/08/2023, 5:11 PMJoey
12/08/2023, 5:12 PMjulienvincent
12/08/2023, 5:12 PMJoey
12/08/2023, 5:12 PMJoey
12/08/2023, 5:12 PMJoey
12/08/2023, 5:12 PMjulienvincent
12/08/2023, 5:12 PMJoey
12/08/2023, 5:12 PMJoey
12/08/2023, 5:14 PMjulienvincent
12/08/2023, 5:14 PMJoey
12/08/2023, 5:15 PMJoey
12/08/2023, 5:15 PMjulienvincent
12/08/2023, 5:15 PMJoey
12/08/2023, 5:15 PMjulienvincent
12/08/2023, 5:16 PMjulienvincent
12/08/2023, 5:16 PMJoey
12/08/2023, 5:16 PMjulienvincent
12/08/2023, 5:20 PMJoey
12/08/2023, 5:22 PMjulienvincent
12/08/2023, 5:28 PMjulienvincent
12/08/2023, 5:29 PMjulienvincent
12/08/2023, 5:29 PMJoey
12/08/2023, 5:29 PMJoey
12/08/2023, 5:30 PMjulienvincent
12/08/2023, 5:30 PMjulienvincent
12/08/2023, 5:30 PMjulienvincent
12/08/2023, 5:31 PMjulienvincent
12/08/2023, 5:31 PMJoey
12/08/2023, 5:33 PMjulienvincent
12/08/2023, 5:34 PMJoey
12/08/2023, 5:34 PMjulienvincent
12/08/2023, 5:35 PMjulienvincent
12/08/2023, 5:35 PMjulienvincent
12/08/2023, 5:35 PMJoey
12/08/2023, 5:36 PMJoey
12/08/2023, 5:36 PMJoey
12/08/2023, 5:37 PMJoey
12/08/2023, 5:37 PMjulienvincent
12/08/2023, 5:37 PMjulienvincent
12/08/2023, 5:37 PM{fitler: {}, paginate: {offset: 100, limit: 10}}
then I would need to re-iterate over all previous results in order to respondjulienvincent
12/08/2023, 5:39 PMJoey
12/08/2023, 5:39 PMJoey
12/08/2023, 5:39 PMJoey
12/08/2023, 5:39 PMJoey
12/08/2023, 5:39 PMjulienvincent
12/08/2023, 5:40 PMjulienvincent
12/08/2023, 5:40 PMJoey
12/08/2023, 5:40 PMJoey
12/08/2023, 5:41 PMJoey
12/08/2023, 5:41 PMlimit
items and store the offset in the returned cursorJoey
12/08/2023, 5:41 PMjulienvincent
12/08/2023, 5:42 PMjulienvincent
12/08/2023, 5:42 PMjulienvincent
12/08/2023, 5:42 PMJoey
12/08/2023, 5:43 PMjulienvincent
12/08/2023, 5:44 PMjulienvincent
12/08/2023, 5:45 PMjulienvincent
12/08/2023, 5:45 PMjulienvincent
12/08/2023, 5:46 PMJoey
12/08/2023, 5:46 PMJoey
12/08/2023, 5:47 PMJoey
12/08/2023, 5:47 PMjulienvincent
12/08/2023, 5:48 PMjulienvincent
12/08/2023, 5:49 PMjulienvincent
12/08/2023, 5:49 PMvroldanbet
12/11/2023, 9:07 AMjulienvincent
12/11/2023, 2:52 PMjulienvincent
12/11/2023, 2:55 PMLookupResources
just makes that completely unviable. If there was some way to filter the results from SpiceDB based on relationships or properties on the resources this would help a lot to mitigate this.vroldanbet
12/11/2023, 6:11 PMWHERE IN
clauses in your database will become very slow or cause load spikes that will affect every other workload relying on it.