dbt-fal v1.3.12 – Finding the cause of a subtle bug

We recently released our dbt adapter, dbt-fal. Since then, members of the community got the chance to try out the adapter and give us some very valuable feedback. One of the issues raised was a noticeable slowness when users run dbt seed. Our v1.3.12 release is mainly to fix that problem.

We thought our debugging process to investigate this issue was interesting enough that we wanted to share more details with the community.

#723

Several people reported that they noticed slowness:

Anecdotally dbt seed seems much slower with the adapter.  On dbt 1.3.2 dbt seed of a 6k/267-line/4-column CSV takes ~0.1s while on dbt-fal adapter it takes ~22s

We're noticing an odd behavior when running dbt seed commands: the speed of inserts decreases drastically when updating profiles.yml to use fal. Has anyone experienced this issue?

We went right into an investigation and found that it was actually happening for other dbt commands too. The problem was just more noticeable for dbt seed, it will become clear why later.

After adding log Jinja functions in the dbt seed materialization, we were able to corner the problem to a small section. The culprit was a piece of Jinja code that adds commas to SQL statements.

({%- for column in agate_table.column_names -%}
    {{ get_binding_char() }}
    {%- if not loop.last%},{%- endif %}
{%- endfor -%})

So, the problem must be in the get_binding_char macro:

{% macro get_binding_char() -%}
  {{ adapter.dispatch('get_binding_char', 'dbt')() }}
{%- endmacro %}


{% macro default__get_binding_char() %}
  {{ return('%s') }}
{% endmacro %}

At this point, the code path starts becoming adapter specific. If the the adapter implements the postgres__get_binding_char() macro, adapter.dispatch uses that macro; or it defaults to the default__get_binding_char() shown above.

So we started looking into the adapter-specific macro-finding mechanisms and nothing stood out. Shortly after, a member of our community (i.e. our Slack channel in dbt’s Slack), Dave Worth from Statype, reached out. He pointed out that the problem started in the v1.3.8 release of dbt-fal, and that the PR #691 introducing a inspect.stack() call on every check of adapter.type() may be the culprit. This makes sense! The dbt seed command calls adapter.type() for every column in every row in the CSV file. And this is why all commands were slower too, they all need the adpter.type() at some point, but dbt seed uses it a lot.

But why did dbt-fal adapter need to inspect the call stack to begin with? dbt-fal adapter only runs the Python models in a dbt project and delegates the SQL models to the underlying SQL adapter. In order to maintain compatibility with the rest of the dbt ecosystem the adapter.type() calls have to return the underlying SQL adapter’s type (eg. postgres), when the call originates from a SQL model. To be able to detect the origin of the call we had to use Python’s inspect.stack() call.

Now certain of the root cause, we looked for a faster approach to inspecting the stack and found an answer that helped us go from 17 seconds to 0.8 seconds in our tests without losing any capabilities.