search

carvel-dev / ytt

YAML templating tool that works on YAML structure instead of text
https://carvel.dev/ytt
Apache License 2.0
1.66k stars 135 forks source link

Diagnosing low performance #918

Open cpg314 opened 3 months ago

cpg314 commented 3 months ago

What steps did you take:

I have a fairly small ytt configuration, with 36 files and 1600 lines. Among these, 20 files are values (totaling 1100 lines).

-------------------------------------------------------------------------------
Language                     files          blank        comment           code
-------------------------------------------------------------------------------
YAML                            36             48            289           1618

The templates (which I unfortunately cannot share) do not do anything I would consider heavy. They just generate manifests for regular Kubernetes resources.

What happened: It takes 3.9 seconds to generate the 5700 lines of output on a fairly beefy Lenovo P1 machine.

I tried to remove all values files and add them back one by one, and one can see the generation time dramatically increasing:

381ms 748µs 771ns
421ms 23µs 781ns
556ms 209µs 636ns
625ms 745µs 631ns
804ms 283µs 465ns
811ms 94µs 171ns
917ms 907µs 756ns
1sec 33ms 792µs 286ns
1sec 142ms 491µs 30ns
1sec 768ms 729µs 36ns
2sec 135ms 703µs 219ns
3sec 869ms 202µs 205ns

What did you expect: With a fairly small configuration, I would expect the generation to be almost instantaneous.

Anything else you would like to add: Is there a way to diagnose where ytt spends the generation time? The --debug flag is generating a lot of lines that are difficult to inspect.

Environment:

Vote on this request

This is an invitation to the community to vote on issues, to help us prioritize our backlog. Use the "smiley face" up to the right of this comment to vote.

👍 "I would like to see this addressed as soon as possible" 👎 "There are other more important things to focus on right now"

We are also happy to receive and review Pull Requests if you want to help working on this issue.

prembhaskal commented 3 months ago

can you share output of ytt with time command
time ytt <your-input-files-directories>

cpg314 commented 3 months ago

Like this?

8.18user 0.34system 0:02.73elapsed 311%CPU (0avgtext+0avgdata 34200maxresident)k
0inputs+0outputs (0major+26311minor)pagefaults 0swaps
real    0m2.723s
user    0m7.866s
sys     0m0.340s
cpg314 commented 3 months ago

I also tried looking into the output of --debug, but it's 7038466 lines long... What is maybe suspicious (or totally normal) is that the ### ast (templated) line appears 27k times. 

$ rg "ast" err.txt | wc -l
27655

When grepping for the ## file lines, I see many repetitions. I'm not sure if this is expected

$ rg "## file (.*?) \\(opts" -o -r '$1' |  sort | uniq -c |sort -nr
   7150 err.txt:_ytt_lib/main/volumes.lib.yaml
   7150 err.txt:_ytt_lib/main/service.lib.yaml
   3900 err.txt:_ytt_lib/main/container.lib.yaml
   3250 err.txt:_ytt_lib/main/ingress.lib.yaml
   1950 err.txt:_ytt_lib/main/schema.yaml
   1950 err.txt:_ytt_lib/main/pod.lib.yaml
   1950 err.txt:_ytt_lib/main/job.yaml
   1950 err.txt:_ytt_lib/main/deployment.yaml
   1300 err.txt:_ytt_lib/main/configmap.lib.yaml
    650 err.txt:_ytt_lib/main/config.lib.yaml
     39 err.txt:values.yaml
     39 err.txt:resources/test.yaml
prembhaskal commented 3 months ago

ok I was trying to see if ytt is spending more time on I/O. I need to check the output of time command later, I think you can also run the ytt command through blk trace or iotop to get more details.

One thing though can you tell how many files is ytt generating in output in your setup?

cpg314 commented 3 months ago

It's just three files:

$ ytt -f . --output-files out
creating: out/status.yaml
creating: out/main.yaml
creating: out/secret.yaml

The secret is taken as-is, main.yaml contains a loop over the values, creating one resource for each, and status.yaml is similar.

iotop shows basically no I/O: https://gist.github.com/cpg314/59f196c6a749c43c830bff0c939730ab (it does show for other unrelated processes).

What I could try to do is get a flamegraph after recompiling ytt.

cpg314 commented 3 months ago

This is the flamegraph: image In text form:

File: ytt
Type: cpu
Time: Jun 11, 2024 at 10:24pm (CEST)
Duration: 3.52s, Total samples = 8.18s (232.44%)
Showing nodes accounting for 6.68s, 81.66% of 8.18s total
Dropped 373 nodes (cum <= 0.04s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%      4.44s 54.28%  runtime.systemstack
     0.01s  0.12%  0.12%      4.27s 52.20%  runtime.gcBgMarkWorker
         0     0%  0.12%      4.19s 51.22%  runtime.gcBgMarkWorker.func2
     0.69s  8.44%  8.56%      4.19s 51.22%  runtime.gcDrain
         0     0%  8.56%      3.23s 39.49%  carvel.dev/ytt/pkg/template.(*CompiledTemplate).eval
         0     0%  8.56%      3.22s 39.36%  carvel.dev/ytt/pkg/template.(*CompiledTemplate).Eval
     0.01s  0.12%  8.68%      3.22s 39.36%  carvel.dev/ytt/pkg/workspace.(*TemplateLoader).EvalYAML
     0.01s  0.12%  8.80%      3.18s 38.88%  github.com/k14s/starlark-go/starlark.(*Function).CallInternal
         0     0%  8.80%      3.18s 38.88%  github.com/k14s/starlark-go/starlark.Call
         0     0%  8.80%      3.17s 38.75%  github.com/k14s/starlark-go/starlark.(*Program).Init
         0     0%  8.80%      3.11s 38.02%  carvel.dev/ytt/pkg/workspace.(*LibraryExecution).eval
         0     0%  8.80%      3.10s 37.90%  carvel.dev/ytt/pkg/workspace.(*LibraryExecution).Eval
         0     0%  8.80%      3.09s 37.78%  carvel.dev/ytt/pkg/workspace.(*libraryValue).Eval
         0     0%  8.80%      3.06s 37.41%  carvel.dev/ytt/pkg/workspace.(*libraryValue).AsStarlarkValue.ErrDescWrapper.func3
         0     0%  8.80%      3.06s 37.41%  carvel.dev/ytt/pkg/workspace.(*libraryValue).AsStarlarkValue.ErrWrapper.func4
         0     0%  8.80%      3.01s 36.80%  github.com/k14s/starlark-go/starlark.(*Builtin).CallInternal
         0     0%  8.80%      2.90s 35.45%  carvel.dev/ytt/pkg/cmd/template.(*Options).Run
         0     0%  8.80%      2.90s 35.45%  carvel.dev/ytt/pkg/cmd/template.(*Options).RunWithFiles
         0     0%  8.80%      2.84s 34.72%  carvel.dev/ytt/pkg/cmd.NewCmd.func1
         0     0%  8.80%      2.82s 34.47%  github.com/cppforlife/cobrautil.DisallowExtraArgs.WrapRunEForCmd.func2.1
         0     0%  8.80%      2.81s 34.35%  carvel.dev/ytt/pkg/cmd.NewYttCmd.WrapRunEForCmd.func2.1
         0     0%  8.80%      2.80s 34.23%  github.com/spf13/cobra.(*Command).execute
         0     0%  8.80%      2.77s 33.86%  github.com/spf13/cobra.(*Command).ExecuteC
         0     0%  8.80%      2.74s 33.50%  github.com/spf13/cobra.(*Command).Execute
         0     0%  8.80%      2.74s 33.50%  main.main
         0     0%  8.80%      2.71s 33.13%  runtime.main
     0.34s  4.16% 12.96%      2.65s 32.40%  runtime.scanobject
         0     0% 12.96%      2.38s 29.10%  carvel.dev/ytt/pkg/workspace.(*TemplateLoader).Load
         0     0% 12.96%      2.26s 27.63%  runtime.gcDrainMarkWorkerDedicated (inline)
         0     0% 12.96%      1.93s 23.59%  runtime.gcDrainMarkWorkerIdle (inline)
     0.11s  1.34% 14.30%      1.58s 19.32%  runtime.greyobject
     0.25s  3.06% 17.36%      1.28s 15.65%  runtime.mallocgc
         0     0% 17.36%      1.06s 12.96%  carvel.dev/ytt/pkg/workspace.(*LibraryExecution).eval.func1
         0     0% 17.36%      0.85s 10.39%  github.com/k14s/starlark-go/syntax.(*parser).parseStmt
         0     0% 17.36%      0.82s 10.02%  github.com/k14s/starlark-go/syntax.(*parser).parseFile
prembhaskal commented 3 months ago

ok, I can take a guess that some library is being loaded repeatedly probably in a loop or recursion. Since you cannot share the yaml files, can you double check from your side. Since I am not that familiar with code yet so I don't know if an evaluated yaml function / part would be cached or not, I would need some time to dig into this.
but @cppforlife can throw a light on this.

cpg314 commented 3 months ago

I load the library in a main.yaml file that loops over all resources defined in the values, and calls the library with these values: 

#@ main = library.get("main")

#@ for r in data.values.resources:
--- #@ template.replace(main.with_data_values(r).eval())
#@ end

So I am indeed evaluating the library repeatedly in the loop (with 23 elements), but I am calling library.get only once. Is there a more efficient way to do this?

prembhaskal commented 3 months ago

23 elements is quite less I think (I guess your library is not too big since overall lines you said is 1600 lines).
I am not too well versed with the template.replace part, if you are ok can you start a thread on the slack channel to get more attention from @cppforlife .