[Performance] 1.8 slower partial parsing than 1.7

[d-cole]

Is this your first time submitting a feature request?

• I have read the expectations for open source contributors
• I have searched the existing issues, and I could not find an existing issue for this feature
• I am requesting a straightforward extension of existing dbt functionality, rather than a Big Idea better suited to a discussion

Performance issue

In a large dbt project we noticed a 26% increase in partial parse time updating from 1.7.3 - 1.8.0. This was replicated in a smaller reproducible project. Measurements below are the median time over 10 runs of the same command:

• Parse time: 24% reduction, 68.46sec -> 52.05sec (-16.41sec). This is great!
• Partial parse time: 26% increase, 6.00sec -> 7.58sec (+1.58sec). While this isn't huge, this is not ideal as our users encounter partial parsing much more frequently than a full parse.

Steps to reproduce

The results can be replicated in a reproducible way using https://github.com/dbt-labs/jaffle_shop_duckdb.

1. Follow setup steps here: https://github.com/dbt-labs/jaffle_shop_duckdb
2. dbt run -r 1.7_parse_timing.txt parse
3. dbt run -r 1.7_partial_parse_timing.txt parse
4. Remove target/ and install 1.8. There may be an issue here with dbt-adapters install so I've included all steps below. I can move this to a separate discussion if needed.

python3 -m pip install dbt-core==1.8.0 #version conflict with dbt-duckdb so install that next and reinstall
pip install dbt-duckdb==1.8.0  
python3 -m pip install dbt-core==1.8.0
# dbt debug results in "ModuleNotFoundError: No module named 'dbt.adapters.factory"
pip uninstall dbt-adapters
pip install dbt-adapters==1.1.1

5. dbt run -r 1.8_parse_timing.txt parse
6. dbt run -r 1.8_partial_parse_timing.txt parse

Results from partial parses are attached below.

1.7_partial_parse_timing.txt
1.8_partial_parse_timing.txt

The results shown in the record timing for dbt-duckdb match what we see in our large dbt project. That is, the parse_manifest time is significantly greater in 1.8 (5.6x greater in duckdb example 0.0568s -> 0.320s). This increase can be broken down into:

• 16x increase in write_manifest (0.00685 -> 0.110). This matches what we see in our real dbt project.
• 4.4x increase in get_full_manifest (0.0464 -> 0.206)

Who will this benefit?

Users of dbt 1.8+

[peterallenwebb]

@d-cole Thank you so much for the exceptional repro steps and analysis! I am looking in to this.

[peterallenwebb]

My local evaluation (on an M1 MacBook) shows that partial parsing of jaffle_shop_duckdb is slightly faster on 1.8 than it was on 1.7.3:

dbt 1.7.3
  dbt parse 1.08s user 0.10s system 87% cpu 1.351 total


dbt 1.8.0
  dbt parse  0.86s user 0.09s system 83% cpu 1.143 total

I think the profiles you attached are correct, but I don't think they give the full picture for this small project.

Python's built-in profiler ignores time spent loading Python modules, which is a significant fraction of dbt's runtime on short runs. In addition, we improved startup time in 1.8 by moving a significant amount of work from module load time to post-load run time. So I think the amount of work stayed about the same, but now the built-in profiler actually notices it.

I believe your claim that partial parsing slowed down for the larger project you described, but I think we'll need more information to get to the bottom of it. If you're able to supply profiles for the larger project, I might be able to find a solution. Ideally, I would recommend you use py-spy to collect the profiles in speedscope format, which would look like this:

pip install py-spy
sudo py-spy record -s -f speedscope -- dbt parse

I'm attaching the profiles I gathered during my investigation for reference. These can be viewed at https://www.speedscope.app/

dbt-1_7_3-parse-no-parrtial-parse.json
dbt-1_7_3-parse-yes-partial-parse.json
dbt-1_8_0-parse-no-partial-parse.json
dbt-1_8_0-parse-yes-partial-parse.json

[d-cole]

@peterallenwebb Thank you!

Python's built-in profiler ignores time spent loading Python modules, which is a significant fraction of dbt's runtime on short runs. In addition, we improved startup time in 1.8 by moving a significant amount of work from module load time to post-load run time. So I think the amount of work stayed about the same, but now the built-in profiler actually notices it.

Makes sense!

On the real dbt project I initially gathered times using a script to wrap a parse call and took the median over 10 runs, I believe this won't have the same issues as the profiler.

start_time = time.time()
subprocess.run(command, shell=True, check=True)
elapsed_time = time.time() - start_time

Using py-spy we see similar results where the write_manifest time is longer in 1.8 (see screenshot below). I've attached the partial parse profiles below. Thanks again for taking a look!

dbt_18_partial_parse.json
dbt_17_partial_parse.json