Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add query performance statistics #7869

Merged
merged 32 commits into from
Nov 21, 2024
Merged

Add query performance statistics #7869

merged 32 commits into from
Nov 21, 2024

Conversation

fantix
Copy link
Member

@fantix fantix commented Oct 16, 2024

This is the 2nd take after #7814, forking the builtin pg_stat_statement extension from the upstream master branch. It's different in a way that we can extract JSON query info only once per query across parse/plan/execute runs (unless reset cleared the hashtable row), and some custom stats columns are directly stored as a hashtable column.

Please review each commit separately.

Add edb_stat_statements Postgres extension (forked from the master
branch of the upstream pg_stat_statement extension) to handle custom
query performance statistics. sys::QueryStats is added as a view of
the statistics.

This is done in a way that, for each stats-significant SQL we send to the
backend, one or more comment lines of "query stats info" JSONs are
prepended for the Postgres extension to ingest and record in the modified
statistics hash table. Among the stats info fields, id: uuid is especially
important to identify different queries and accumulate stats of the same
query onto the same hash table entry, which reflects some settings that
affected the compilation (excluding the user schema version for common
grouping of stats). Particularly, the first-8-bytes of id is also used by
the Postgres extension to replace the underlying queryId of the SQL
statement, so that the same frontend query can be recognized across all
PARSE/EXECUTE operations in Postgres for stats recording.

System queries, DDLs, and unrecognized queries are not recorded.

Refs #7725

* Add query info JSON to EdgeQL-compiled SQL
* Extract info in the extension and track original query
* Add `cache_key` in the stats hash table
* Add view of `sys::QueryStats`
* Add basic test
@fantix fantix marked this pull request as ready for review October 18, 2024 04:11
@fantix fantix requested review from msullivan and elprans October 18, 2024 04:11
Copy link
Member

@msullivan msullivan left a comment

Choose a reason for hiding this comment

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

OK this all looks good except I realize I might not understand the memory management model in play here.

@1st1
Copy link
Member

1st1 commented Nov 12, 2024

As discussed on the call, we need to make a few adjustments.

  • As @elprans mentioned, we want to exclude migration hash from the query id, so that schema migrations don't "reset" the stats. Most of schema migrations are relatively minor for real world application, affecting only a subset of queries anyway.

  • We want to add query "tagging". The motivation for that is to make it easier for users to browse through the query log and identify which queries are coming from EdgeDB extensions like Auth, or from EdgeDB UI (those can be quite slow which could be confusing), or from various parts of the user application.

The plan for tagging is as follows:

  • Add tag: string property to sys::QueryStats.
  • We should use "headers" in our protocol to apply tags on query by query basis. Server should pass the "tag" to the compiler, which should embed it into a SQL query, which the extension can later parse out.
  • Our client libraries will likely get withTag() method, so users will be able to run await client.withTag('myapp').query(...)

Tags should be documented as arbitrary strings. We can reserve "edgedb/" "namespace" for EdgeDB-related things, e.g. "edgedb/ui", "edgedb/auth", etc.

I think we should put a max-length constraint on this field and limit tags to 200-or-something characters.

cc @elprans @msullivan and obviously @fantix

@msullivan
Copy link
Member

I think Elvis wanted to inject the tag on the server side, to avoid compiler round trips.

If the same key exists in multiple lines, the first is effective
while the rest is simply ignored. If all expected keys are found,
the remaining lines are also ignored.
@fantix fantix force-pushed the query-stats-4 branch 2 times, most recently from 4784e0c to 205546a Compare November 19, 2024 18:20
Also, stop using cache_key as the stats entry ID,
calculate hash with the JSON string instead.
Copy link
Member

@msullivan msullivan left a comment

Choose a reason for hiding this comment

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

This looks basically good but I want to make sure I understand the behavior in some of the edge cases where the input might be malformed.

In particular, what happens if uuid_in fails because the id is malformed?

(To some extent, this is just me not knowing postgres internals well. It might be that the answer is simple? Does failure do a longjmp or something and just abort everything?)

JsonParseErrorType parse_rv = pg_parse_json(lex, &sem);
freeJsonLexContext(lex);

if (parse_rv == JSON_SUCCESS)
Copy link
Member

Choose a reason for hiding this comment

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

Does the state get mutated even if there is an error? I guess that's probably fine?

What happens to info_len on an error? Is it still updated with however much got consumed?

Copy link
Member Author

Choose a reason for hiding this comment

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

Does the state get mutated even if there is an error? I guess that's probably fine?

Yes, it'll keep the parsed values and continue to the next line, which I think is fine.

What happens to info_len on an error? Is it still updated with however much got consumed?

On error, info_len will be updated to skip the whole failing line and restart on the next line.

if ((state.found & EDB_STMT_INFO_PARSE_REQUIRED) == EDB_STMT_INFO_PARSE_REQUIRED)
return info->query_id != UINT64CONST(0) ? info : NULL;

info_str += info_len + 1;
Copy link
Member

Choose a reason for hiding this comment

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

The +1 makes me nervous about the case where there isn't a newline at the end of an info line?

Copy link
Member

Choose a reason for hiding this comment

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

I'm not sure if the cases where there are untrusted entries in the query log is that likely, but this is C so I want to be extra careful about our boundary cases.

Copy link
Member Author

Choose a reason for hiding this comment

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

Right, good question. The edbss_extract_info_line() function will tag the \n or the end of the query_str, so this +1 will either skip the \n properly, or go beyond the end of the query_str and cause the next call to edbss_extract_info_line() to return NULL.

Copy link
Member

Choose a reason for hiding this comment

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

Because len is negative, at that point?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes exactly

Comment on lines +701 to +702
Datum id_datum = DirectFunctionCall1(uuid_in, CStringGetDatum(token));
pg_uuid_t *id_ptr = DatumGetUUIDP(id_datum);
Copy link
Member

Choose a reason for hiding this comment

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

Can these fail?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes. The outer-most PG_CATCH in the current session will - like you said - do a longjmp and recover by sending an error to the peer. Such error will be propagated to the client as an edb.errors.InvalidValueError:

ERROR 116169 - 2024-11-20T11:22:27.377 postgres: invalid input syntax for type uuid: "b2f8e457-a4f8-ab73-1979-afb333f9c"
INFO 116169 - 2024-11-20T11:22:27.377 postgres: -- {"query": "select\n    (<__std__::int64>$0 + <__std__::int64>$1)", "type": 1, "extras": "{\"cc\": {\"__internal_no_apply_query_rewrites\": false, \"__internal_query_reflschema\": false, \"__internal_testmode\": false, \"allow_bare_ddl\": \"AlwaysAllow\", \"allow_dml_in_functions\": false, \"allow_user_specified_id\": false, \"apply_access_policies\": true, \"force_database_error\": \"false\", \"query_cache_mode\": \"Default\", \"simple_scoping\": null, \"store_migration_sdl\": \"NeverStore\", \"warn_old_scoping\": null}, \"pv\": [3, 0], \"of\": \"BINARY\", \"e1\": false, \"il\": 101, \"ii\": false, \"in\": true, \"io\": false, \"dn\": \"default\"}", "id": "b2f8e457-a4f8-ab73-1979-afb333f9c"}
INFO 116169 - 2024-11-20T11:22:27.377 postgres: 	SELECT edgedb_v6_2f20a50ab0.__qh_bd20a1eba9bb696335db87182e5b207f(($1)::int8, ($2)::int8)
---------------------------------------------------------------------- Exception occurred: invalid input syntax for type std::uuid: "b2f8e457-a4f8-ab73-1979-afb333f9c" ----------------------------------------------------------------------

1. edb.errors.InvalidValueError: invalid input syntax for type std::uuid: "b2f8e457-a4f8-ab73-1979-afb333f9c"

------------------------------------------------------------------------------------------------------------------ Details -------------------------------------------------------------------------------------------------------------------


edb.errors.InvalidValueError: invalid input syntax for type std::uuid: "b2f8e457-a4f8-ab73-1979-afb333f9c"
ERROR 116111 _localdev 2024-11-20T11:22:27.377 asyncio: an error in edgedb protocol
protocol: <edb.server.protocol.binary.EdgeConnection object at 0x73c6cfabf370>
transport: <uvloop.loop._SSLProtocolTransport object at 0x73c6d48086c0>

@msullivan
Copy link
Member

If you merge this now, please update #7725 with the remaining pending tasks so we can track them

@fantix fantix merged commit f5396fd into master Nov 21, 2024
23 checks passed
@fantix fantix deleted the query-stats-4 branch November 21, 2024 13:51
@fantix fantix mentioned this pull request Nov 21, 2024
7 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants