Skip to content

Conversation

@carlopi
Copy link
Contributor

@carlopi carlopi commented Nov 22, 2025

Changes:

  • bump to duckdb v1.4.2
  • pass around ClientContext from various callsites down the stack
  • add a new log type: PostgresQueryLog
  • add DUCKDB_LOGs, logging query (or queries) and duration in ms

Second step, that is passing around ClientContext &context changing a lot of signatures I am less sure, it can probably be reworked, open to feedback.

All in all, this allows for example:

CALL enable_logging(level=trace);
ATTACH 'ducklake:postgres:postgresql:<...>' as ducklake;
CREATE OR REPLACE SECRET secret (TYPE s3, <...>);
FROM ducklake.some_table;
FROM ducklake.some_table;
FROM ducklake.some_table;
FROM duckdb_logs_parsed('PostgresQueryLog');

Here we are attaching to a ducklake backed by Postgres, and run some queries.

┌────────────┬────────────┬───────────────┬────────────────┬──────────┬───────────┬──────────────────────┬──────────────────┬───────────┬─────────────────────────────────────────────────────────┬─────────────┐
│ context_id │   scope    │ connection_id │ transaction_id │ query_id │ thread_id │      timestamp       │       type       │ log_level │                          query                          │ duration_ms │
│   uint64   │  varchar   │    uint64     │     uint64     │  uint64  │  uint64   │ timestamp with tim…  │     varchar      │  varchar  │                         varchar                         │    int64    │
├────────────┼────────────┼───────────────┼────────────────┼──────────┼───────────┼──────────────────────┼──────────────────┼───────────┼─────────────────────────────────────────────────────────┼─────────────┤
│         34 │ CONNECTION │             3 │              8 │        9 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ SELECT version(), (SELECT COUNT(*) FROM pg_settings W…  │         134 │
│         42 │ CONNECTION │             3 │              8 │       11 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ;\n\…  │         602 │
│         42 │ CONNECTION │             3 │              8 │       11 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ \nSELECT pg_namespace.oid AS namespace_id, relname, r…  │         108 │
│         42 │ CONNECTION │             3 │              8 │       11 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ \nSELECT pg_namespace.oid AS namespace_id, relname, r…  │         108 │
│         42 │ CONNECTION │             3 │              8 │       11 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ \nSELECT pg_namespace.oid AS namespace_id, relname, r…  │         108 │
│         47 │ CONNECTION │             3 │              8 │       12 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "key", "value", "scope", "scope_id" FROM…  │         108 │
│         52 │ CONNECTION │             3 │              8 │       13 │      NULL │ 2025-11-22 18:25:1…  │ PostgresQueryLog │ DEBUG     │ COMMIT                                                  │         106 │
│         67 │ CONNECTION │             4 │             11 │       17 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ       │         113 │
│         67 │ CONNECTION │             4 │             11 │       17 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "snapshot_id", "schema_version", "next_c…  │         111 │
│         71 │ CONNECTION │             4 │             11 │       18 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "begin_snapshot", "end_snapshot", "schem…  │         520 │
│         75 │ CONNECTION │             4 │             11 │       19 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "begin_snapshot", "end_snaps…  │         163 │
│         75 │ CONNECTION │             4 │             11 │       19 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "begin_snapshot", "end_snaps…  │         108 │
│         75 │ CONNECTION │             4 │             11 │       19 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "object_id", "begin_snapshot", "end_snap…  │         140 │
│         75 │ CONNECTION │             4 │             11 │       19 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "table_name", "schema_versio…  │         107 │
│         75 │ CONNECTION │             4 │             11 │       19 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "column_id", "begin_snapshot…  │         108 │
│        198 │ CONNECTION │             4 │             11 │       20 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "begin_snapshot", "end_snapshot", "view_…  │         107 │
│        198 │ CONNECTION │             4 │             11 │       20 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "object_id", "begin_snapshot", "end_snap…  │         184 │
│        210 │ CONNECTION │             4 │             11 │       21 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "partition_id", "begin_snapshot", "end_s…  │         107 │
│        210 │ CONNECTION │             4 │             11 │       21 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "partition_id", "partition_key_index", "…  │         108 │
│        217 │ CONNECTION │             4 │             11 │       22 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "record_count", "file_size_b…  │         110 │
│        217 │ CONNECTION │             4 │             11 │       22 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "column_id", "contains_null"…  │         108 │
│        239 │ CONNECTION │             4 │             11 │       23 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "data_file_id", "table_id", "begin_snaps…  │         191 │
│        239 │ CONNECTION │             4 │             11 │       23 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "begin_snapshot", "end_snaps…  │         109 │
│        247 │ CONNECTION │             4 │             11 │       24 │      NULL │ 2025-11-22 18:25:2…  │ PostgresQueryLog │ DEBUG     │ COMMIT                                                  │         107 │
│        258 │ CONNECTION │             5 │             13 │       27 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ       │         132 │
│        258 │ CONNECTION │             5 │             13 │       27 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "snapshot_id", "schema_version", "next_c…  │         200 │
│        274 │ CONNECTION │             5 │             13 │       28 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "data_file_id", "table_id", "begin_snaps…  │         107 │
│        274 │ CONNECTION │             5 │             13 │       28 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "begin_snapshot", "end_snaps…  │         107 │
│        283 │ CONNECTION │             5 │             13 │       29 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COMMIT                                                  │         107 │
│        294 │ CONNECTION │             6 │             15 │       32 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ       │         180 │
│        294 │ CONNECTION │             6 │             15 │       32 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "snapshot_id", "schema_version", "next_c…  │         106 │
│        311 │ CONNECTION │             6 │             15 │       33 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "data_file_id", "table_id", "begin_snaps…  │         108 │
│        311 │ CONNECTION │             6 │             15 │       33 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COPY (SELECT "table_id", "begin_snapshot", "end_snaps…  │         107 │
│        319 │ CONNECTION │             6 │             15 │       34 │      NULL │ 2025-11-22 18:25:3…  │ PostgresQueryLog │ DEBUG     │ COMMIT                                                  │         106 │
├────────────┴────────────┴───────────────┴────────────────┴──────────┴───────────┴──────────────────────┴──────────────────┴───────────┴─────────────────────────────────────────────────────────┴─────────────┤
│ 34 rows                                                                                                                                                                                            11 columns │
└───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

This could allowing a faster feedback cycle: directly from SQL, debug what interactions (and how much latency they bring) are required on the underlying Postgres database. This allows both users to tweak / understand how heavy are certain queries, and developers to get feedback and optimize them.

@carlopi
Copy link
Contributor Author

carlopi commented Nov 23, 2025

Failure is legit, PostgresTransaction outlives ClientContext, and so GetContext() call gives out a nonsensical result.

Solutions:

  1. change duckdb::Transaction from have a weak_ptr to have shared_ptr<ClientContext> (this has been validated to fix the issue here
  2. change signature of GetContext() to return optional_ptr, and check that on usage

Problem on 1 is that requires changes in core, and might change behaviour of what happens at the border (say in destructors). Problem on 2 is that some transactions will not be logged.

@carlopi
Copy link
Contributor Author

carlopi commented Nov 23, 2025

I went for path 2, since can be implemented only duckdb-postgres side, but note that some queries (most likely COMMIT / ROLLBACK) might happen during teardown, so without a ClientContext available.

@carlopi carlopi mentioned this pull request Nov 23, 2025
@carlopi carlopi requested a review from Mytherin November 24, 2025 09:19
@carlopi
Copy link
Contributor Author

carlopi commented Nov 24, 2025

@Mytherin: main risk is this changing a bunch of signatures, but should be sort of OK. Not really urgent.

@Mytherin
Copy link
Contributor

Looks fine to me but let's merge it into the branch for v1.5

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.

2 participants