Event property counter #7500

mariusandra · 2021-12-03T10:43:33Z

Changes

Creates the foundation to resolve Event filters: suggest properties that actually have data #4166
Creates a table EventProperty, and populates it during ingestion:
This PR also includes support for detecting datetime formats for Allow filtering with date/time properties #6619, but not many format types are parsed yet.
I opted to make a new table instead of reusing "property definitions", because 1) adding indexes to existing huge tables can be brutal, 2) I think this deserves its own tightly optimised table, 3) I think in the interface we still want to have one "description" field per property, not one per event & property. Now we can just show "this property is used by events X, Y and Z"

How did you test this code?

Wrote tests to test the new functionality. Plenty of local testing as well.

macobo · 2021-12-03T12:22:44Z

timgl · 2021-12-03T14:54:40Z

Code and data > discussion. In favour of running this on cloud behind an env var and seeing what happens. Would be good to define the metrics that we are worried about before.

pauldambra · 2021-12-07T16:50:14Z

posthog/migrations/0187_event_properties.py

+                        null=True,
+                    ),
+                ),
+                ("property_type_format", models.CharField(max_length=100, null=True)),


should we constrain the allowed formats too? Each format will need custom query code...

paolodamico

Some comments inline but in general looking pretty good to me, very similar approach to last_seen_at which we already tested successfully

paolodamico · 2021-12-16T03:57:21Z

posthog/models/event_property.py

+    property_type: models.CharField = models.CharField(
+        max_length=20, choices=PropertyType.choices, default=PropertyType.STRING, null=True
+    )
+    property_type_format: models.CharField = models.CharField(max_length=100, null=True)


Should we really store this? I think we could intelligently parse as either a timestamp or ISO-8601 and discard everything else ?

paolodamico · 2021-12-16T03:57:51Z

posthog/models/event_property.py

+    event: models.CharField = models.CharField(max_length=400, null=False)
+    property: models.CharField = models.CharField(max_length=400, null=False)
+
+    # contains e.g. the date format


Nit: I think the comment is more confusing than helpful, attribute seems pretty clear to me

paolodamico · 2021-12-16T03:58:38Z

posthog/models/event_property.py

+        # "event_properties" is a field on Team, so have to call this "event_properties_model"
+        Team,
+        on_delete=models.CASCADE,
+        related_name="event_properties_model",


I think we could drop this, doesn't seem to add more clarity/simplicity to Django's default.

paolodamico · 2021-12-16T03:59:44Z

posthog/models/event_property.py

+
+    # things we keep track of
+    total_volume: models.BigIntegerField = models.BigIntegerField(default=None, null=True)
+    created_at: models.DateTimeField = models.DateTimeField(default=timezone.now, null=True)


Should this be null? It's a new model

paolodamico · 2021-12-16T04:01:17Z

posthog/settings.py

@@ -450,7 +450,7 @@ def get_list(text: str) -> List[str]:
 # https://docs.djangoproject.com/en/2.2/ref/settings/#databases

 if TEST or DEBUG:
-    DATABASE_URL = os.getenv("DATABASE_URL", "postgres://localhost:5432/posthog")
+    DATABASE_URL = os.getenv("DATABASE_URL", "postgres://posthog:posthog@localhost:5432/posthog")


Not sure about this change, by default some local installations have an empty password and the default OS username (e.g. Postgres.app)

This got updated in master anyway...

paolodamico · 2021-12-16T04:02:57Z

plugin-server/src/config/config.ts

@@ -15,9 +15,9 @@ export function getDefaultConfig(): PluginsServerConfig {
    return {
        CELERY_DEFAULT_QUEUE: 'celery',
        DATABASE_URL: isTestEnv
-            ? 'postgres://localhost:5432/test_posthog'
+            ? 'postgres://posthog:posthog@localhost:5432/test_posthog'


Same comment as for settings.py

For test/dev environments, this is good and aligns with our new "developing locally" guidelines.

paolodamico · 2021-12-16T04:04:10Z

plugin-server/package.json

@@ -33,7 +33,7 @@
        "prepublishOnly": "yarn build",
        "setup:dev:clickhouse": "cd .. && export DEBUG=1 PRIMARY_DB=clickhouse && python manage.py migrate_clickhouse",
        "setup:test:ee": "yarn setup:test:postgres && yarn setup:test:clickhouse",
-        "setup:test:postgres": "cd .. && (dropdb test_posthog || echo 'no db to drop') && createdb test_posthog && DATABASE_URL=postgres://localhost:5432/test_posthog DEBUG=1 python manage.py migrate",
+        "setup:test:postgres": "cd .. && (PGPASSWORD=posthog dropdb -h localhost -U posthog test_posthog || echo 'no db to drop') && PGPASSWORD=posthog createdb -h localhost -U posthog test_posthog && DATABASE_URL=postgres://posthog:posthog@localhost:5432/test_posthog DEBUG=1 python manage.py migrate",


Should we update deployment docs then? Seems like we need to create this username with a specific password, also to detail what permissions are needed.

paolodamico · 2021-12-16T04:06:49Z

plugin-server/src/main/pluginsServer.ts

+            flushLastSeenAtCacheJob = schedule.scheduleJob('10 * * * * *', async () => {
+                await piscina!.broadcastTask({ task: 'flushLastSeenAtCache' })
+            })


You know better here, don't have all the context to make the right call

paolodamico · 2021-12-16T04:14:05Z

plugin-server/src/worker/ingestion/event-property-counter.ts

+export function detectDateFormat(value: string): string | void {
+    if (value.match(/^\d{4}-\d{2}-\d{2}$/)) {
+        return 'YYYY-MM-DD'
+    }
+
+    if (value.match(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(.\d{1,3}?Z?|)$/)) {
+        return 'ISO8601 UTC'
+    }
+
+    if (value.match(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(.\d{1,3}|)\+\d{2}:\d{2}$/)) {
+        return 'ISO8601 TZ'
+    }
+}


I think timestamps are pretty common too. I added a comment elsewhere, do wonder if this is required or CH is smart enough to parse them correctly when used.

paolodamico · 2021-12-16T04:15:08Z

plugin-server/src/worker/ingestion/event-property-counter.ts

+            }
+            this.eventPropertiesBuffer.totalVolume += 1
+
+            propertyBuffer.propertyType =


What happens when we have outlier property values? e.g. I have a bug that every once in a while I send an invalid value (e.g. for a timestamp)? Can we base this based on the format of the majority instead of the latest?

macobo · 2021-12-16T12:47:48Z

plugin-server/src/worker/ingestion/event-property-counter.ts

+            const elapsedTime = DateTime.now().diff(startTime).as('milliseconds')
+            this.statsd?.set('flushEventPropertyCounter.Size', cacheSize)
+            this.statsd?.set('flushEventPropertyCounter.QuerySize', columns[0].length)
+            this.statsd?.timing('flushEventPropertyCounter', elapsedTime)


Note: postgresQuery automatically has this, so this is kind of redundant.

macobo

Added a few fly-by comments since a review was requested.

All good to ship from my end, but didn't also dig too deeply from the correctness side of things.

I still think this task lends itself well to having really loose constraints (e.g. do you really need exact volume counts or exact timestamps) and done independently from pg, but as agreed before this can be revisited when it blows up.

macobo · 2021-12-16T12:48:20Z

plugin-server/src/worker/ingestion/event-property-counter.ts

+            await this.db.postgresQuery(
+                `INSERT INTO posthog_eventproperty(team_id, event, property, property_type, property_type_format, total_volume, created_at, last_seen_at)
+                SELECT * FROM UNNEST ($1::int[], $2::text[], $3::text[], $4::text[], $5::text[], $6::bigint[], $7::timestamp with time zone[], $8::timestamp with time zone[])
+                ON CONFLICT ON CONSTRAINT posthog_eventproperty_team_id_event_property_10910b3b_uniq DO UPDATE SET


Worth giving the index a name in the migration instead?

mariusandra

So after more testing, I've gotten deadlocks locally. Yikes.

In the existing implementation we flush all event property buffers, on all threads, on all instances, at exactly 20 seconds past each minute. This means we upload a buffer of up to 50k event properties with an insert on conflict update statement to postgres on every plugin server thread at precisely the same moment.

When I got the deadlock it was uploading two batches of 1800 items. One inserted in a second, the other deadlocked and died. You don't need to do much math to assume that even with a few more orders of magnitude of performance, and with added measures to spread out the flushes, we'll be in trouble... unless we retry and are in luck. 🍀

This turns out to be a common thing with concurrent upserts. The recommended approach is to 1) sort the keys (apparently doesn't help) 2) just retry.

Obviously this won't scale.

The main point of doing this task was to match events with the properties used by these events. The secondary goal was to also sort the properties by usage and e.g. lower the property in the list if it hasn't been seen in a while. Detecting the type and counting the events was an added bonus.

I have now removed everything but the code to track events & property pairs. It works similar to how the existing event and property definition tracker worked: it keeps a track of all team&event&property pairs it has seen, and if there are new ones, it inserts them in a loop. This is run synchronously during ingestion, just like it has been for the existing trackers.

This should eliminate the possibility of deadlocks. I think it'll perform fine as well. However the only thing I'm now concerned about is memory usage.

Assuming 100k unique team/event combos (select count(*) from posthog_eventdefinition), a back of the envelope calculation with ~20 properties per event gives an added 100k2020 = 40MB of memory per thread. It should be less than that in reality, as we only cache these properties for active teams, but this might nevertheless become the next pain point. 🤔

mariusandra · 2021-12-16T15:18:37Z

plugin-server/package.json

@@ -33,7 +33,7 @@
        "prepublishOnly": "yarn build",
        "setup:dev:clickhouse": "cd .. && export DEBUG=1 PRIMARY_DB=clickhouse && python manage.py migrate_clickhouse",
        "setup:test:ee": "yarn setup:test:postgres && yarn setup:test:clickhouse",
-        "setup:test:postgres": "cd .. && (dropdb test_posthog || echo 'no db to drop') && createdb test_posthog && DATABASE_URL=postgres://localhost:5432/test_posthog DEBUG=1 python manage.py migrate",
+        "setup:test:postgres": "cd .. && (PGPASSWORD=posthog dropdb -h localhost -U posthog test_posthog || echo 'no db to drop') && PGPASSWORD=posthog createdb -h localhost -U posthog test_posthog && DATABASE_URL=postgres://posthog:posthog@localhost:5432/test_posthog DEBUG=1 python manage.py migrate",


However I solved this now by replacing

"setup:test:postgres": "cd .. && (PGPASSWORD=posthog dropdb -h localhost -U posthog test_posthog || echo 'no db to drop') && PGPASSWORD=posthog createdb -h localhost -U posthog test_posthog && DATABASE_URL=postgres://posthog:posthog@localhost:5432/test_posthog DEBUG=1 python manage.py migrate",

With

"setup:test:postgres": "cd .. && python manage.py setup_test_environment",

mariusandra · 2021-12-16T15:19:21Z

plugin-server/src/config/config.ts

@@ -15,9 +15,9 @@ export function getDefaultConfig(): PluginsServerConfig {
    return {
        CELERY_DEFAULT_QUEUE: 'celery',
        DATABASE_URL: isTestEnv
-            ? 'postgres://localhost:5432/test_posthog'
+            ? 'postgres://posthog:posthog@localhost:5432/test_posthog'


For test/dev environments, this is good and aligns with our new "developing locally" guidelines.

mariusandra · 2021-12-16T21:43:50Z

posthog/settings.py

@@ -450,7 +450,7 @@ def get_list(text: str) -> List[str]:
 # https://docs.djangoproject.com/en/2.2/ref/settings/#databases

 if TEST or DEBUG:
-    DATABASE_URL = os.getenv("DATABASE_URL", "postgres://localhost:5432/posthog")
+    DATABASE_URL = os.getenv("DATABASE_URL", "postgres://posthog:posthog@localhost:5432/posthog")


This got updated in master anyway...

macobo

Had some comments, but looks operationally just as sane as before. Didn't dig too deeb for correctness though

plugin-server/package.json

macobo · 2021-12-17T11:36:55Z

plugin-server/src/worker/ingestion/team-manager.ts

+        this.eventDefinitionsCache = new Map()
+        this.eventPropertiesCache = new LRU({
+            max: serverConfig.EVENT_PROPERTY_LRU_SIZE, // keep in memory the last 10k team+event combos we have seen
+            maxAge: 60 * 60 * 1000, // and each for up to 1 hour


Worth extracting to constants.ts given it's used in another file as well?

Hmm... I guess we can. Moved ONE_HOUR to a new file called constants.ts, and imported in the 4 places it's used.

While all 4 places do reference the time diff of 60601000 milliseconds, they're not connected, and having them all use the same const feels funny. Ideally the constants could be called something like EVENT_PROPERTY_LRU_MAX_AGE... and then moved out of contants.ts into config.ts with the other envs... but I'm going to draw a line here.

macobo · 2021-12-17T11:37:31Z

plugin-server/src/worker/ingestion/team-manager.ts

@@ -106,18 +118,31 @@ export class TeamManager {
            ingested: team.ingested_event,
        })

-        await this.cacheEventNamesAndProperties(team.id)
+        await this.cacheEventNamesAndProperties(team.id, event)


🤔 Should we use await Promise.all([ ... ]) here?

I'm afraid this can substantially increase the number of open postgres connections in short bursts. Thus safer, for now, to keep this sequential.

The first function here should anyway run before all the others, but the sync-s could be done in parallel in the future, though, again, I'm a bit afraid of excess postgres parallelisation.

Also, since this should only be run the first time a unique event or property is ever seen, we might just be prematurely optimising here.

macobo · 2021-12-17T11:38:47Z

plugin-server/src/worker/ingestion/team-manager.ts

+        for (const property of propertyKeys) {
+            if (!properties.has(property)) {
+                properties.add(property)
+                await this.db.postgresQuery(


It we could do this insert in a batch instead of per-property 🤔

That's pretty much what I was doing in the original implementation, leading to the deadlocks mentioned above. Even if we go from ON CONFLICT DO UPDATE to ON CONFLICT DO NOTHING, I'm going to have to implement code to retry the transactions if the block deadlocks, and all other complexities that come with it.

It would much safer since we're no longer updating the rows that are already in the database, and not running all flush operations at precisely the same moment on every thread, but these deadlocks can't be avoided --> the same new event may come in 10 times in the same millisecond, be handled by 4 threads, which all insert the same properties at precisely the same moment.

Thus, while a bit slower, I think ~20 simple inserts for each new event the first time it's seen will scale much better.

posthog/models/event_property.py

mariusandra added 12 commits December 3, 2021 10:13

create event property model

598c213

add null

b609261

rename cache vars

01307be

update event properties table on ingestion

37aad8c

match date formats

ed359ea

match date formats

8f80f87

better string handling

17cb696

property type can be null too

304a740

pass event timestamp

586c39b

update property type later

d738f9b

perform all updates through a buffer object

4cbc1cc

move to EventPropertyCounter

1ad5949

mariusandra mentioned this pull request Dec 3, 2021

Event filters: suggest properties that actually have data #4166

Closed

pauldambra reviewed Dec 7, 2021

View reviewed changes

pauldambra mentioned this pull request Dec 9, 2021

Query events by date for properties known to be dates #7608

Merged

mariusandra added 13 commits December 14, 2021 14:08

Merge branch 'master' into event-property-counter

b9be65f

fix migration

2227052

improve flush last seen at job

4a1da7c

flush job periodically + env

e64062a

upsert all event properties in 1 query

129532b

log to statsd

ba1b831

enable property counter only if experimental mode enabled

2c3c27d

use now() instead of event timestamp

f69e68c

fix seconds

1c2a777

Merge branch 'master' into event-property-counter

356d341

add user/pass for default postgres

6215919

add tests

30ddc74

use big integers

48842e1

paolodamico reviewed Dec 16, 2021

View reviewed changes

macobo reviewed Dec 16, 2021

View reviewed changes

macobo approved these changes Dec 16, 2021

View reviewed changes

mariusandra added 10 commits December 16, 2021 16:17

simpler test setup

523fddd

different contraint name

97fdd2d

refactor team manager

7a5a8a0

greatly simplify the system

a61884b

fetch cached event properties

20e893b

fix team manager and timestamps

3ce42cc

add cached entry

0d42e92

also don't cache event properties for teams that have it disabled

fbe080e

remove indexes that are not going to be used

8e961b8

Merge branch 'master' into event-property-counter

aa638e7

mariusandra commented Dec 16, 2021

View reviewed changes

mariusandra added 5 commits December 16, 2021 22:55

remove unused imports

e7772ab

blacked

8b01a16

remember event properties with a LRU cache

d070faa

fix eslint

f0f4f36

clean up the last bits

a39253a

mariusandra requested review from macobo, paolodamico and pauldambra December 17, 2021 09:52

mariusandra mentioned this pull request Dec 17, 2021

Event properties in filter #7718

Merged

macobo reviewed Dec 17, 2021

View reviewed changes

posthog/models/event_property.py Outdated Show resolved Hide resolved

mariusandra added 3 commits December 17, 2021 12:58

move ONE_HOUR to constants

cd463f4

use sane_repr

5db0f2d

fix typo

c5469cd

mariusandra merged commit 151f759 into master Dec 17, 2021

mariusandra deleted the event-property-counter branch December 17, 2021 12:54

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Event property counter #7500

Event property counter #7500

mariusandra commented Dec 3, 2021 •

edited

Loading

macobo commented Dec 3, 2021

timgl commented Dec 3, 2021

pauldambra Dec 7, 2021

paolodamico left a comment

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

mariusandra Dec 16, 2021

paolodamico Dec 16, 2021

mariusandra Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

paolodamico Dec 16, 2021

macobo Dec 16, 2021

macobo left a comment

macobo Dec 16, 2021

mariusandra left a comment •

edited

Loading

mariusandra Dec 16, 2021

mariusandra Dec 16, 2021

mariusandra Dec 16, 2021

macobo left a comment

macobo Dec 17, 2021

mariusandra Dec 17, 2021

macobo Dec 17, 2021

mariusandra Dec 17, 2021

mariusandra Dec 17, 2021

macobo Dec 17, 2021

mariusandra Dec 17, 2021 •

edited

Loading

Event property counter #7500

Event property counter #7500

Conversation

mariusandra commented Dec 3, 2021 • edited Loading

Changes

How did you test this code?

macobo commented Dec 3, 2021

timgl commented Dec 3, 2021

Choose a reason for hiding this comment

paolodamico left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

macobo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mariusandra left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

macobo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mariusandra Dec 17, 2021 • edited Loading

Choose a reason for hiding this comment

mariusandra commented Dec 3, 2021 •

edited

Loading

mariusandra left a comment •

edited

Loading

mariusandra Dec 17, 2021 •

edited

Loading