Investigate performance issues

[edgarrmondragon]

I debugged this ELT (a log file with 13+ GB of content), and there are no traces of redundancy, every record appears only once.

The target-postgres batch_processing_time is an average of 20 s to each batch, and it sums to ~6 minutes of total COPY operation time, which is acceptable.

The tap-postgres average extraction time interval between records is ~0.001 s, what leads (roughly) to a total of 90 minutes of data reading.

If anyone has ideas, evidence (or even better, a flame graph 😉) as to what's causing this performance problem, they're more than welcome!

Related

• Discovery Performance #284
• Maybe fix: Exclude information_schema and pg_catalog from discovery #551?

Links

• Slack: https://meltano.slack.com/archives/C069A0GE129/p1739276072020269
• Linen: https://discuss.meltano.com/t/26949263/greetings-again-i-am-creating-a-tap-postgres-target-postgres

[bdewilde]

Hi @edgarrmondragon , I've just started looking into this, since I noticed that this variant of tap-postgres is (on my data streams) about 5x slower than the transferwise variant. Unfortunately, I couldn't get viztracer (from the docs) to work when this tap was being run as part of an E+L pipeline via meltano, e.g. viztracer meltano run this-tap some-target. Just double-checking: Would you expect that sort of call to work?

Since so much of this tap's functionality is implemented in the sdk, I started spelunking through code over there. I got as far as def _sync_records() here before stopping -- I can see things that could be slow, but hard to say without a proper tool like viztracer. I'm happy to keep investigating, but could use an assist in actually getting these profiling tools working with my setup. 🙏

[edgarrmondragon]

Hey @bdewilde, thanks for taking the time to dive into the performance problem 🙏

The way I'd approach this is by running this tap in isolation. That is, clone the repo locally and use viztracer like this:

uv run viztracer tap-postgres --config ENV  # assuming you have a .env file with your Postgres instance settings

[edgarrmondragon]

I should also mention https://github.com/benfred/py-spy, which we've used in the past to profile Meltano (see meltano/meltano#8342) and some connectors.

[bdewilde]

Hi @edgarrmondragon , thanks for the pointer! py-spy worked as advertised 🎉

I'm attaching two flamegraphs to this comment, one for a full-refresh run of tap-postgres => target-postgres (both meltanolabs variants), and the other for a log-based incremental run of the same pipeline. As far as I can tell, in both cases, the system quickly gets into an async loop over E+L blocks in ExtractLoadBlocks._start_blocks() here, then spends the vast majority of its time waiting on those blocks to finish in threading.py.

I don't think GitHub lets these SVGs stay interactive, so here's a zoomed-in view of the meltano stack where we're iterating over blocks:

This flamegraph is similar in structure but very different in distribution to the one you linked to in that existing meltano issue. Unfortunately, it doesn't seem like we have great visibility into what's going on, but probably you'll understand what's going on better than I do ☺️

For just a bit more context, here's what the plugin configs look like:

plugins:
  extractors:
    - name: tap-postgres
      variant: meltanolabs
      pip_url: meltanolabs-tap-postgres~=0.3.0
    - name: tap-postgres-foo
      inherit_from: tap-postgres
      config:
        ...
        replication_slot_name: "pipelinewise_utility_common"
        filter_schemas:
          - public
      select:
        # six data streams
        ...
      metadata:
        "*":
          replication_method: LOG_BASED
          replication_key: _sdc_lsn
  loaders:
    - name: target-postgres
      variant: meltanolabs
      pip_url: meltanolabs-target-postgres~=0.4.0
      config:
        ...
        hard_delete: false
        activate_version: true
        add_record_metadata: true
        use_copy: true
        batch_size_rows: 100000

[bdewilde]

Ah, a bit more detail here: When subprocesses are included, you can see the tap/target stacks: