Performance regression in code generation after upgrading to v4.19.0

[RikiyaFujii]

After upgrading to sqlboiler v4.19.0, I've noticed that running the following command takes significantly longer than in previous versions:

$ sqlboiler psql -c ./sqlboiler.toml

I’ve reviewed the release notes, but I wasn’t able to find any explanation for this behavior.

Here is my sqlboiler.toml configuration:

no-tests = true
add-enum-types = true

[psql]
  dbname  = "postgres"
  host    = "localhost"
  port    = 5432
  user    = "postgres"
  pass    = "password"
  sslmode = "disable"

I’d really appreciate it if you could investigate this issue, or let me know if there are any known changes that might affect generation performance in v4.19.0.

Thank you.

[stephenafamo]

What version did you upgrade from? Did anything else change in your setup? Can you confirm that the performance is different using these 2 commands:

go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml
go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml

[RikiyaFujii]

Thank you for the reply, @stephenafamo .

I upgraded from v4.18.0 to v4.19.0.
I measured the execution time using the time command and would like to share the results:

$ time go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml
go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml  0.62s user 0.88s system 176% cpu 0.851 total

$ time go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml
go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml  325.89s user 2942.84s system 723% cpu 7:32.05 total

It seems that the execution time has increased quite a bit after the upgrade.
I hope this helps with the investigation.

[stephenafamo]

Looking at the merged PRs in the new release, the only change that could cause this would be #1438

Can you kindly take a look at this @eklatzer ?

[eklatzer]

I reverted the three commits in https://github.com/eklatzer/sqlboiler/tree/ek/revert-imports-processing

@RikiyaFujii Could you please provide a comparison of this three versions?

time go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml
time go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml
time go run github.com/eklatzer/sqlboiler/v4@c238e32f41f8d9b919acb88f8f81321dbd24761f psql -c ./sqlboiler.toml

[RikiyaFujii]

$ time go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml -o go/model -p model                        
go run github.com/volatiletech/sqlboiler/v4@v4.19.0 psql -c ./sqlboiler.toml   327.42s user 2960.58s system 729% cpu 7:30.46 total

$ time go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml                                  
go run github.com/volatiletech/sqlboiler/v4@v4.18.0 psql -c ./sqlboiler.toml  0.67s user 0.83s system 159% cpu 0.939 total

$ time go run github.com/eklatzer/sqlboiler/v4@c238e32f41f8d9b919acb88f8f81321dbd24761f psql -c ./sqlboiler.toml
go run github.com/eklatzer/sqlboiler/v4@c238e32f41f8d9b919acb88f8f81321dbd24761f psql -c ./sqlboiler.toml  0.69s user 0.90s system 94% cpu 1.687 total

Thank you for the reply, @eklatzer .
I tried running it.

As a result, the performance of https://github.com/volatiletech/sqlboiler/tree/v4.18.0 and https://github.com/eklatzer/sqlboiler/tree/ek/revert-imports-processing was almost the same.

[eklatzer]

@RikiyaFujii @stephenafamo I had a deeper dive into the handling of imports.Process and added the following two improvements in master...eklatzer:sqlboiler:ek/adjust-imports-processing

• imports.Process internally already calls format.Source, so I removed the duplicate call in the output processing of sqlboiler
• imports.Process tries to resolve the requested imports in multiple steps. One of the steps is to process local files in the provided path. When providing the path to the models, this satisfies the usage of var dialect (e.g. dialect.LQ). As this info was not provided in the initial implementation the reference was not found and therefore further sources for imports were checked, that were not required.

@RikiyaFujii Could you please try it with the version with these two fixes? I my example it reduced the execution time to about a third of the time of v4.19.0. The commit hash is 5ffaccc17c2c6c95875e4ecb7262db959e591e87.

Even though about a third sounds nice in the beginning, this is still about five times slower compared to v4.18.0 in my case. Therefore, I made some further analysis of the root cause. Regarding to the CPU profile most of the execution time is just parsing the other files in the provided path:

This is also the reason, why the processing gets longer and longer, the more models are written, as all others models have to be parsed as well. I also compared the execution to running goimports -w ., which internally uses the same handling. This resulted in a similar execution time when executed for the generated models.

Therefore I would propose to revert the change of #1438 and reopen #1279.

[RikiyaFujii]

@eklatzer
Thank you for looking into it.
When I ran 5ffaccc17c2c6c95875e4ecb7262db959e591e87 on my end, the execution time was reduced to about one-third to one-fourth.

This is also the reason, why the processing gets longer and longer, the more models are written, as all others models have to be parsed as well.

Thank you. I understand that the execution time increases as the number of files grows.

Therefore I would propose to revert the change of #1438 and reopen #1279.

I agree with reverting #1438.

[robinlindhout]

We have similar problems with performance, would be great if this could get reverted!

[stephenafamo]

Released v4.19.1

[RikiyaFujii]

@stephenafamo
Thank you for addressing the issue.
I’ve confirmed that the update resolved the execution time problem.

@eklatzer
Thank you for all the investigations you’ve done.