loadtesting: request rate for uploading charts and get index drops a lot with 0.16.0 release

[zmaxyan]

Version:
0.16.0 release

Problem

Using locust to have the loadtesting, the request rate for uploading charts and get index drops a lot.

Description

Previously

Previously chartmuseum release version v0.12.0 with pvc:
locust -f locustfile.py --no-web -L DEBUG -c 200 -r 50 -n 100000 --csv=result
We define posting new charts and get index in locustfile.py. The request rate for uploading charts could arrive 300 req/s and get index 30 req/s

Using 0.16.0
But when we use 0.16.0, the request rate drops to 5 req/s and 0.5 req/s and after the charts arrives 230 or so, the post requests begin to fail.

From the log, you can see the latency is very high, {"L":"INFO","T":"2023-08-11T10:48:11.323Z","M":"[12781] Request served","path":"/api/mychart/charts","comment":"","clientIP":"XXXXX","method":"POST","statusCode":201,"latency":"19m6.78816919s","reqID":"xxxxxxxxxxxx"}

The chartmuseum pod cpu is not high only 50%

Using go tool pprof to get some data:

[scbizu]

I'll look at this , it seems that most of the CPU or latency are reported by gopkg.in/yaml/v2@v2.4.0 . Our v0.16.0 release takes the bumping in at #692 , and I see upstream issue is still open , I have no idea if yaml v3 fixes this issue .

If you can revert the #692 locally and run loadtesting again , it will help us a lot ~

[zmaxyan]

Thanks @scbizu, I will try to revert #692 and run loadtestin. After I have rerun, I will give you the results

[zmaxyan]

Hi @scbizu, revert #692, seems the performance is worse than before.
The following is the pprof result:
go tool pprof heap.out
File: chartmuseum
Type: inuse_space
Time: Aug 30, 2023 at 9:45am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 14.46MB, 68.63% of 21.06MB total
Showing top 10 nodes out of 135
flat flat% sum% cum cum%
2.51MB 11.91% 11.91% 2.51MB 11.91% bufio.NewWriterSize
2MB 9.50% 21.41% 2MB 9.50% helm.sh/helm/v3/pkg/chart/loader.LoadFiles
1.51MB 7.15% 28.56% 1.51MB 7.15% regexp/syntax.(*compiler).inst
1.50MB 7.14% 35.70% 1.50MB 7.14% bufio.NewReaderSize
1.50MB 7.13% 42.82% 1.50MB 7.13% github.com/aws/aws-sdk-go/aws/endpoints.init
1.44MB 6.81% 49.64% 1.44MB 6.81% gopkg.in/yaml%2ev2.yaml_string_write_handler
1MB 4.75% 54.39% 1MB 4.75% runtime.malg
1MB 4.75% 59.14% 1MB 4.75% regexp.(*Regexp).FindStringSubmatch
1MB 4.75% 63.88% 1MB 4.75% context.propagateCancel
1MB 4.75% 68.63% 4MB 18.99% helm.sh/chartmuseum/pkg/repo.ChartVersionFromStorageObject
(pprof) list NewWriterSize
Total: 21.06MB
ROUTINE ======================== bufio.NewWriterSize in /usr/lib64/go/1.20/src/bufio/bufio.go
2.51MB 2.51MB (flat, cum) 11.91% of Total
Error: open /usr/lib64/go/1.20/src/bufio/bufio.go: no such file or directory

go tool pprof allocs.out
File: chartmuseum
Type: alloc_space
Time: Aug 30, 2023 at 9:46am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 117.63GB, 88.76% of 132.52GB total
Dropped 424 nodes (cum <= 0.66GB)
Showing top 10 nodes out of 96
flat flat% sum% cum cum%
83.14GB 62.73% 62.73% 90.67GB 68.42% gopkg.in/yaml%2ev2.yaml_emitter_emit
9.12GB 6.88% 69.61% 9.12GB 6.88% gopkg.in/yaml%2ev2.(*parser).node
7.53GB 5.68% 75.30% 7.53GB 5.68% gopkg.in/yaml%2ev2.yaml_string_write_handler
3.62GB 2.73% 78.03% 3.62GB 2.73% bytes.growSlice
3.29GB 2.48% 80.51% 3.52GB 2.66% regexp.(*Regexp).backtrack
3.22GB 2.43% 82.94% 6.60GB 4.98% regexp.(*Regexp).FindStringSubmatch
2.94GB 2.22% 85.16% 2.94GB 2.22% gopkg.in/yaml%2ev2.read
1.68GB 1.27% 86.43% 1.68GB 1.27% reflect.mapassign
1.61GB 1.21% 87.64% 8.20GB 6.19% github.com/Masterminds/semver/v3.NewVersion
1.49GB 1.12% 88.76% 1.49GB 1.12% strconv.cloneString
(pprof) list yaml_emitter_emit
Total: 132.52GB
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
83.14GB 90.67GB (flat, cum) 68.42% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_block_mapping_key in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 1.88GB (flat, cum) 1.42% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_block_mapping_value in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 4.57GB (flat, cum) 3.45% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_block_sequence_item in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 1.08GB (flat, cum) 0.82% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_document_start in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 512.02kB (flat, cum) 0.00037% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_node in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 6.30GB (flat, cum) 4.75% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory
ROUTINE ======================== gopkg.in/yaml%2ev2.yaml_emitter_emit_scalar in /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go
0 6.30GB (flat, cum) 4.75% of Total
Error: open /root/go/pkg/mod/gopkg.in/yaml.v2@v2.4.0/emitterc.go: no such file or directory

go tool pprof profile.out
File: chartmuseum
Type: cpu
Time: Aug 30, 2023 at 9:47am (UTC)
Duration: 5.18s, Total samples = 2.43s (46.87%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1180ms, 48.56% of 2430ms total
Dropped 96 nodes (cum <= 12.15ms)
Showing top 10 nodes out of 165
flat flat% sum% cum cum%
250ms 10.29% 10.29% 540ms 22.22% runtime.scanobject
230ms 9.47% 19.75% 230ms 9.47% runtime.memmove
190ms 7.82% 27.57% 190ms 7.82% runtime.memclrNoHeapPointers
140ms 5.76% 33.33% 140ms 5.76% runtime.pageIndexOf (inline)
110ms 4.53% 37.86% 170ms 7.00% gopkg.in/yaml%2ev2.yaml_emitter_analyze_scalar
60ms 2.47% 40.33% 460ms 18.93% runtime.mallocgc
50ms 2.06% 42.39% 50ms 2.06% gopkg.in/yaml%2ev2.is_blankz
50ms 2.06% 44.44% 160ms 6.58% gopkg.in/yaml%2ev2.yaml_parser_scan_flow_scalar
50ms 2.06% 46.50% 70ms 2.88% runtime.findObject
50ms 2.06% 48.56% 50ms 2.06% runtime.writeHeapBits.flush
(pprof) list scanobject
Total: 2.43s
ROUTINE ======================== runtime.scanobject in /usr/lib64/go/1.20/src/runtime/mgcmark.go
250ms 540ms (flat, cum) 22.22% of Total
Error: open /usr/lib64/go/1.20/src/runtime/mgcmark.go: no such file or directory

[scbizu]

Hi @zmaxyan , I try to reproduce this use our HEAD via our loadtesting script and my Mac(local storage), but I do not see the lots of latency dopped as you provide .

Can you provide your CM startup commands and which storage you are using ?

[zmaxyan]

We used PVC as storage and just using "chartmuseum" as startup command. We using a chart yaml setting with some env parameters etc. @scbizu

[scbizu]

PVC can be various storage provision , and the storage throughout differs from the providers . Did you run it on AKS and use s3 as backend , or just run on local k8s cluster and use local-storage as backend ?

[zmaxyan]

This case we used the network storage with storageclass type RBD to dynamically create PVC.

[scbizu]

@zmaxyan Can you somehow monitor your disk I/O ? It seems like the bottleneck is the disk I/O or the network.