Skip to content
This repository has been archived by the owner on Nov 4, 2021. It is now read-only.

batch plugin logs on postgres #486

Merged
merged 15 commits into from
Jul 13, 2021
Merged

batch plugin logs on postgres #486

merged 15 commits into from
Jul 13, 2021

Conversation

yakkomajuri
Copy link
Contributor

@yakkomajuri yakkomajuri commented Jun 24, 2021

Changes

Addresses #424 and supersedes #431.

This makes log inserts to Postgres from plugins happen in batches every second. Didn't implement batching for other logs but should be easy to do so later if we feel there's a need. Big improvements from this locally. No slow query warnings, and despite the buffer, the logs actually appear faster (since they're not "stuck in traffic").

Checklist

  • Updated Settings section in README.md, if settings are affected
  • Jest tests

Copy link
Contributor

@neilkakkar neilkakkar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

Surprised though that this solves the underlying issue.

In effect, were we making too many queries in succession to postgres? We're still making about 1/second. So does this imply earlier, we were even faster than that?

Copy link
Collaborator

@mariusandra mariusandra left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Very nice! Just two thoughts:

  • even though we flush every second, perhaps for posterity it makes sense to also flush this buffer in teardown/shutdown mode? it's yet another stream/buffer/service/etc, so might make sense to control in a similar way...
  • it looks like you're always inserting to postgres, even if kafka is enabled.

src/worker/vm/extensions/console.ts Outdated Show resolved Hide resolved
src/utils/db/db.ts Outdated Show resolved Hide resolved
@yakkomajuri
Copy link
Contributor Author

@mariusandra re

even though we flush every second, perhaps for posterity it makes sense to also flush this buffer in teardown/shutdown mode? it's yet another stream/buffer/service/etc, so might make sense to control in a similar way...

yeah that'd make sense

@yakkomajuri
Copy link
Contributor Author

@Twixes thread-level batching now

@Twixes Twixes self-requested a review July 3, 2021 18:07
@yakkomajuri
Copy link
Contributor Author

friendly ping @Twixes

Copy link
Member

@Twixes Twixes left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like this works so if unbatched Postgres log insertion is a hair-on-fire problem, it's okay, but still has this thing where Kafka logs are now batched two-fold – first via addLog and then via queueMessage. Not ideal since that only increases the time in which a log entry gets into ClickHouse, without benefits. Basically ideally createPluginLogEntries should queue a Kafka message (which it already does) or queue a Postgres row, instead of LogsBuffer creating an additional buffer layer above createPluginLogEntries.

tests/postgres/e2e.test.ts Outdated Show resolved Hide resolved
tests/postgres/vm.test.ts Outdated Show resolved Hide resolved
@yakkomajuri
Copy link
Contributor Author

That's a good point - addLog can just directly throw it in Kafka if that's available

@yakkomajuri
Copy link
Contributor Author

done @Twixes

@yakkomajuri yakkomajuri added the bump patch Bump patch version when this PR gets merged label Jul 6, 2021
Copy link
Member

@Twixes Twixes left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry for dragging this on a bit, but my initial point still stands unfortunately 😅

src/utils/logs-buffer.ts Outdated Show resolved Hide resolved
src/utils/db/db.ts Outdated Show resolved Hide resolved
@yakkomajuri
Copy link
Contributor Author

apologies for the lazy updates on the existing system instead of just rearchitecting in the first place :D

@Twixes

server.instanceId
)
source: PluginLogEntrySource.System,
type: PluginLogEntryType.Info,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why the change to Info?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

great catch! probably lingered from a copy paste

Copy link
Member

@Twixes Twixes left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Benissimo

@Twixes Twixes merged commit d1a43fe into master Jul 13, 2021
@Twixes Twixes deleted the batch-logs branch July 13, 2021 17:17
fuziontech pushed a commit to PostHog/posthog that referenced this pull request Oct 12, 2021
)

* batch plugin logs on postgres

* remove comment

* batch at the thread level

* fixes

* await logs flushing in e2e tests

* update tests

* flush immediately on tests

* fix vm tests

* update setupPlugin tests

* immediately add to kafka queue if available

* rearchitect

* Make code subjectively a bit cleaner in a few places

* info -> error

Co-authored-by: Michael Matloka <dev@twixes.com>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bump patch Bump patch version when this PR gets merged
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants