Subject: [pgjdbc/pgjdbc] issue #3166: query_id in pg_stat_activity is NULL when connecting from JDBC, but not from psql

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Fri, 15 Mar 2024 19:50:24 +0000

**Describe the issue**
`query_id` in `pg_stat_activity` is NULL when connecting from JDBC, but not from `psql`

**Driver Version?** 
42.7.2    (postgresql-42.7.2.jar)

**Java Version?**
21.0.1  (or any)

**OS Version?**
Windows 11  (I guess any here as well)

**PostgreSQL Version?**
16.2 on CentOS 9

**To Reproduce**
* from one session do: select pg_sleep(44)
* from another session: select query_id, * from pg_stat_activity where query like '%pg_sleep%'

**Expected behaviour**
* `query_id` should not be NULL

**Logs**
nothing in the logs

**Why I need this**
In my monitoring tool (https://github.com/goranschwarz/DbxTune)    
I get query_plan information from the errorlog using `auto_explain` and then cache that plan in memory.   
If a new query comes with the same `query_id` I can now show the query plan in "Active Statements", with `pev2` or som other Query Plan Viewer   
Note: It would be **even** better if I could retrive the `query plan`at runtime...   
Meaning: `select get_query_plan_for_current_running_pid(###)` , but that isn't around, so have to come up with something...   
But now I trapped over that that all JDBC connections just do not show the `query_id`... bummer :(

**Reproducable code**
```
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;

public class PgQueryIdRepro 
{
	public static void main(String[] args) throws Exception
	{
		String url = "jdbc:postgresql://hostname:5432/postgres";

		Properties props = new Properties();
		props.setProperty("user"    , "dbxtune");
		props.setProperty("password", "some-secret-password");

		// Kick of a 'pg_sleep'
		PgSleep pgSleep = new PgSleep(3, url, props);
		pgSleep.start();

		try (Connection conn = DriverManager.getConnection(url, props))
		{
			// Then get records from pg_stat_activity
			try (Statement statement = conn.createStatement())
			{
				try (ResultSet rs = statement.executeQuery("select query_id, * from pg_stat_activity where query like '%pg_sleep%'"))
				{
					int colCount = rs.getMetaData().getColumnCount();
					int row = 0;

					while( rs.next() )
					{
						row++;
						int     queryId       = rs.getInt(1);
						boolean queryIdIsNull = rs.wasNull();
						
						if (queryIdIsNull)
						{
							System.out.println(">>>> ERROR: row[" + row + "], column 'query_id', shouldn't be NULL, it has a value if the statement was initiated from 'psql'...");
						}

						for (int c = 1; c <= colCount; c++)
						{
							System.out.println("PG-STAT-ACTIVITY: row[" + row + "], col[" + c + "] = |" + rs.getString(c) + "|");
						}
					}
				}
			}
		}
	}

	private static class PgSleep
	extends Thread
	{
		private int        _sleepTime;
		private String     _url;
		private Properties _props;

		public PgSleep(int sleepTime, String url, Properties props)
		{
			_sleepTime = sleepTime;
			_url       = url;
			_props     = props;
		}

		@Override
		public void run()
		{
			System.out.println("Starting PgSleep...");
			try
			{
				try (Connection conn = DriverManager.getConnection(_url, _props))
				{
					try (Statement statement = conn.createStatement())
					{
						try (ResultSet rs = statement.executeQuery("select pg_sleep(" + _sleepTime + ")"))
						{
							int colCount = rs.getMetaData().getColumnCount();
							int row = 0;

							while( rs.next() )
							{
								row++;
								for (int c = 1; c <= colCount; c++)
								{
									System.out.println("PG-SLEEP-RS: row[" + row + "], col[" + c + "] = |" + rs.getString(c) + "|");
								}
							}
						}
					}
				}
			}
			catch (SQLException ex)
			{
				ex.printStackTrace();
			}
		}
	}
```

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Mon, 18 Mar 2024 20:42:13 +0000

I just tested your code and 
`PG-STAT-ACTIVITY: row[3], col[1] = |-3416356442043621232|`
seems to work fine.

---

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Mon, 18 Mar 2024 21:35:50 +0000

I see that you get the "correct" row at row 3   (is that a JDBC Connection or "something else")   
What does the previous rows say?

Below is my full output (only 2 rows)
```
Starting PgSleep...
>>>> ERROR: row[1], column 'query_id', shouldn't be NULL, it has a value if the statement was initiated from 'psql'...
PG-STAT-ACTIVITY: row[1], col[1] = |null|
PG-STAT-ACTIVITY: row[1], col[2] = |5|
PG-STAT-ACTIVITY: row[1], col[3] = |postgres|
PG-STAT-ACTIVITY: row[1], col[4] = |1442795|
PG-STAT-ACTIVITY: row[1], col[5] = |null|
PG-STAT-ACTIVITY: row[1], col[6] = |16384|
PG-STAT-ACTIVITY: row[1], col[7] = |dbxtune|
PG-STAT-ACTIVITY: row[1], col[8] = |PostgreSQL JDBC Driver|
PG-STAT-ACTIVITY: row[1], col[9] = |192.168.0.161|
PG-STAT-ACTIVITY: row[1], col[10] = |null|
PG-STAT-ACTIVITY: row[1], col[11] = |54781|
PG-STAT-ACTIVITY: row[1], col[12] = |2024-03-18 22:27:06.602158+01|
PG-STAT-ACTIVITY: row[1], col[13] = |2024-03-18 22:27:07.742059+01|
PG-STAT-ACTIVITY: row[1], col[14] = |2024-03-18 22:27:07.742851+01|
PG-STAT-ACTIVITY: row[1], col[15] = |2024-03-18 22:27:07.742852+01|
PG-STAT-ACTIVITY: row[1], col[16] = |Timeout|
PG-STAT-ACTIVITY: row[1], col[17] = |PgSleep|
PG-STAT-ACTIVITY: row[1], col[18] = |active|
PG-STAT-ACTIVITY: row[1], col[19] = |null|
PG-STAT-ACTIVITY: row[1], col[20] = |2235|
PG-STAT-ACTIVITY: row[1], col[21] = |null|
PG-STAT-ACTIVITY: row[1], col[22] = |select pg_sleep(3)|
PG-STAT-ACTIVITY: row[1], col[23] = |client backend|
>>>> ERROR: row[2], column 'query_id', shouldn't be NULL, it has a value if the statement was initiated from 'psql'...
PG-STAT-ACTIVITY: row[2], col[1] = |null|
PG-STAT-ACTIVITY: row[2], col[2] = |5|
PG-STAT-ACTIVITY: row[2], col[3] = |postgres|
PG-STAT-ACTIVITY: row[2], col[4] = |1442794|
PG-STAT-ACTIVITY: row[2], col[5] = |null|
PG-STAT-ACTIVITY: row[2], col[6] = |16384|
PG-STAT-ACTIVITY: row[2], col[7] = |dbxtune|
PG-STAT-ACTIVITY: row[2], col[8] = |PostgreSQL JDBC Driver|
PG-STAT-ACTIVITY: row[2], col[9] = |192.168.0.161|
PG-STAT-ACTIVITY: row[2], col[10] = |null|
PG-STAT-ACTIVITY: row[2], col[11] = |54782|
PG-STAT-ACTIVITY: row[2], col[12] = |2024-03-18 22:27:06.604805+01|
PG-STAT-ACTIVITY: row[2], col[13] = |2024-03-18 22:27:07.739081+01|
PG-STAT-ACTIVITY: row[2], col[14] = |2024-03-18 22:27:07.745152+01|
PG-STAT-ACTIVITY: row[2], col[15] = |2024-03-18 22:27:07.745153+01|
PG-STAT-ACTIVITY: row[2], col[16] = |null|
PG-STAT-ACTIVITY: row[2], col[17] = |null|
PG-STAT-ACTIVITY: row[2], col[18] = |active|
PG-STAT-ACTIVITY: row[2], col[19] = |null|
PG-STAT-ACTIVITY: row[2], col[20] = |2235|
PG-STAT-ACTIVITY: row[2], col[21] = |null|
PG-STAT-ACTIVITY: row[2], col[22] = |select query_id, * from pg_stat_activity where query like '%pg_sleep%'|
PG-STAT-ACTIVITY: row[2], col[23] = |client backend|
PG-SLEEP-RS: row[1], col[1] = ||
```

---

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Mon, 18 Mar 2024 21:44:53 +0000

If it's a config issue... here are my config for version `PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit`    
Note: all config is done via `ALTER SYSTEM SET ...` so nothing in `postgresql.conf` is changed...
```
[postgres@pg-3a-cos9 data]$ more postgresql.auto.conf
# Do not edit this file manually!
# It will be overwritten by the ALTER SYSTEM command.
wal_keep_size = '128'
cluster_name = 'pg-3a-cos9'
listen_addresses = '*'
port = '5432'
max_connections = '300'
superuser_reserved_connections = '3'
password_encryption = 'scram-sha-256'
huge_pages = 'try'
shared_buffers = '1317MB'
work_mem = '16MB'
maintenance_work_mem = '131MB'
effective_io_concurrency = '200'
wal_compression = 'on'
wal_log_hints = 'on'
wal_buffers = '64MB'
checkpoint_completion_target = '0.9'
archive_mode = 'on'
archive_command = '/bin/true'
random_page_cost = '1.1'
effective_cache_size = '4096MB'
cpu_tuple_cost = '0.03'
logging_collector = 'on'
log_destination = 'stderr,csvlog'
log_checkpoints = 'on'
log_min_duration_statement = '3000'
log_line_prefix = '%m [%p]: u=[%u] db=[%d] app=[%a] c=[%h] s=[%c:%l] tx=[%v:%x] '
log_lock_waits = 'on'
log_statement = 'ddl'
log_temp_files = '0'
log_connections = 'on'
log_disconnections = 'on'
log_autovacuum_min_duration = '0'
autovacuum_max_workers = '5'
autovacuum_vacuum_cost_limit = '5000'
idle_in_transaction_session_timeout = '180min'
lc_messages = 'C'
track_functions = 'pl'
track_io_timing = 'on'
track_wal_io_timing = 'on'
track_activity_query_size = '4096'
max_prepared_transactions = '300'
compute_query_id = 'on'
pg_stat_statements.max = '10000'
pg_stat_statements.track = 'all'
pg_stat_statements.track_utility = 'on'
pg_stat_statements.track_planning = 'off'
pg_stat_statements.save = 'on'
pg_wait_sampling.history_size = '5000'
pg_wait_sampling.history_period = '10'
pg_wait_sampling.profile_period = '10'
pg_wait_sampling.profile_pid = 'true'
pg_wait_sampling.profile_queries = 'true'
auto_explain.log_analyze = 'on'
auto_explain.log_buffers = 'on'
auto_explain.log_format = 'json'
auto_explain.log_level = 'log'
auto_explain.log_min_duration = '3000'
auto_explain.log_nested_statements = 'on'
auto_explain.log_parameter_max_length = '-1'
auto_explain.log_settings = 'on'
auto_explain.log_timing = 'on'
auto_explain.log_triggers = 'on'
auto_explain.log_verbose = 'on'
auto_explain.log_wal = 'on'
auto_explain.sample_rate = '1'
shared_preload_libraries = 'pg_stat_statements, auto_explain, pg_wait_sampling'
wal_level = 'replica'
[postgres@pg-3a-cos9 data]$
```

I could **not** attach my shell script here (shell scripts wasn't supported) that installs a new Postgres 16.x instance on a "clean" CentOS-9 or RHEL 9 VM
But if I can send it to you in some other way, you may have a reproducible case!

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Tue, 19 Mar 2024 19:54:09 +0000

There should be no reason that query_id can't be read by JDBC. It does nothing different.

---

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Tue, 19 Mar 2024 21:07:20 +0000

I totally agree with you!
There should be **no** difference if I execute `select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()` from `psql` or from a `JDBC` Connection!   
And yet I see a difference!

Executing the above SQL from `psql` yields this result (query_id has a value)
```
[postgres@pg-3a-cos9 ~]$ psql --expanded --command="select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()"
-[ RECORD 1 ]------------------------------------------------------------------------------------------------------
query_id | 6627523495344870092
pid      | 1662866
query    | select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()
version  | PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit
```

Executing the same SQL from JDBC yields this result (query_id is NULL)
```
PG-STAT-ACTIVITY: row[1], col[1] = |null|
PG-STAT-ACTIVITY: row[1], col[2] = |1664602|
PG-STAT-ACTIVITY: row[1], col[3] = |select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()|
PG-STAT-ACTIVITY: row[1], col[4] = |PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit|
```

I simplified my Java repro code in the following way, so if you can try that *simplification* on your server and post the output
```
	public static void main(String[] args) throws Exception
	{
		String url = "jdbc:postgresql://pg-3a-cos9:5432/postgres"; // Postgres 16.2

		Properties props = new Properties();
		props.setProperty("user"    , "postgres");
		props.setProperty("password", "xxxxxxxxxxxxx");

				try (ResultSet rs = statement.executeQuery("select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()"))

					while( rs.next() )
					{
						row++;
						
						if (queryIdIsNull)
						{

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Tue, 19 Mar 2024 21:51:30 +0000

will do

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 20 Mar 2024 11:46:06 +0000

Ok, well that is beyond bizarre, will figure this out.

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Wed, 20 Mar 2024 12:42:32 +0000

Ok, so here's what is happening. The driver uses Extended Protocol so normally it does 
```
2024-03-20 07:50:31.785 EDT [12162] LOG:  duration: 2.311 ms  parse <unnamed>: select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()
2024-03-20 07:50:31.787 EDT [12162] LOG:  duration: 2.062 ms  bind <unnamed>: select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()
2024-03-20 07:50:31.792 EDT [12162] LOG:  duration: 0.552 ms  execute <unnamed>: select query_id, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()
```
And apparently query_id is not calculated for that.

Add `PGProperty.PREFER_QUERY_MODE.set(props, "simple");` to your code and it works fine.

Dave

---

From: "vlsi (@vlsi)" <[email-masked]>
Date: Wed, 20 Mar 2024 13:05:46 +0000

> Add PGProperty.PREFER_QUERY_MODE.set(props, "simple"); to your code and it works fine.

I would treat simple query mode as a workaround only, and I would refrain from recommending "simple" by default.

> And apparently query_id is not calculated for that.

Do you mean backend does not produce query_id for extended queries? It sounds strange.

---

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Wed, 20 Mar 2024 16:46:16 +0000

I can verify that `preferQueryMode=simple` does change the behavior (`query_id` now has a value)
Then: **why** isn't `simple` the *default* (**probably** for some other good reason: like *performance* or *something else*)

If I should go ahead and change the jdbc URL for *all* involved client (appservers/and-various-tools), which is doable but not really the **preferred way**   
Is there anyway to *force* the changes on the server side?   

I would still **question** why `query_id` is NULL in `pg_stat_activity` even when the default setting for `preferQueryMode=extended`   
When I investigate even further I can see that `queryid` in `pg_stat_statements` **does** have a value... (so the calculation *seems* to happen, but not just for `pg_stat_activity`)    

And I agree with @vlsi that it's strange that `pg_stat_activity.query_id` isn't calculated by the server/backend, with `preferQueryMode=extended`

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Thu, 21 Mar 2024 14:40:12 +0000

> Do you mean backend does not produce query_id for extended queries? It sounds strange.

That is correct. Known issue. https://postgrespro.com/list/thread-id/2652444

Dave

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Thu, 21 Mar 2024 14:45:04 +0000

> I can verify that `preferQueryMode=simple` does change the behavior (`query_id` now has a value) Then: **why** isn't `simple` the _default_ (**probably** for some other good reason: like _performance_ or _something else_)

To avoid SQL injection
> 
> If I should go ahead and change the jdbc URL for _all_ involved client (appservers/and-various-tools), which is doable but not really the **preferred way** Is there anyway to _force_ the changes on the server side?

No
> 
> I would still **question** why `query_id` is NULL in `pg_stat_activity` even when the default setting for `preferQueryMode=extended` When I investigate even further I can see that `queryid` in `pg_stat_statements` **does** have a value... (so the calculation _seems_ to happen, but not just for `pg_stat_activity`)

see https://postgrespro.com/list/thread-id/2652444
> And I agree with @vlsi that it's strange that `pg_stat_activity.query_id` isn't calculated by the server/backend, with `preferQueryMode=extended` 
Well .... we don't control everything :(

---

From: "goranschwarz (@goranschwarz)" <[email-masked]>
Date: Thu, 21 Mar 2024 16:31:13 +0000

> To avoid SQL injection

So a pretty good reason to **not** go to `preferQueryMode=simple`   

> Well .... we don't control everything :(

But a bug/feature-request for the issue can be raised???   
Has it been done?

---

From: "davecramer (@davecramer)" <[email-masked]>
Date: Fri, 22 Mar 2024 14:09:18 +0000

You can add a request onto the email thread I referenced, but I wouldn't get my hopes up.

---

From: "vlsi (@vlsi)" <[email-masked]>
Date: Fri, 22 Mar 2024 14:20:23 +0000

> To avoid SQL injection

Technically speaking, `simple` mode should protect from SQL injections, so the use of `simple` mode with up-to-date driver should have the same level of security as regular `extended` mode.

---

From: "yszzu1 (@yszzu1)" <[email-masked]>
Date: Wed, 26 Feb 2025 08:26:09 +0000

> I met a problem, a SQL statement is execute very fast in psql, but if run in the java code, the execution is very slow, so I think the jdbc driver have some issue.
> 
> can't try each perperty in org.postgresql.PGProperty

not related to this issue.  java client read long text/varchar (200k chars) spent a lot of time, psql is tested in cloud server which is much closer to DB.

not easy to find the route cause,  it may be easyer if has query_id