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.

Sign up for GitHub

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

Jump to bottom

query_id in pg_stat_activity is NULL when connecting from JDBC, but not from psql #3166

Open
goranschwarz opened this issue Mar 15, 2024 · 15 comments
Open

query_id in pg_stat_activity is NULL when connecting from JDBC, but not from psql #3166

goranschwarz opened this issue Mar 15, 2024 · 15 comments

Comments

@goranschwarz
Copy link

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 planat 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();
			}
		}
	}
@davecramer
Copy link
Member

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

@goranschwarz
Copy link
Author

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] = ||

@goranschwarz
Copy link
Author

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!

@davecramer
Copy link
Member

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

@goranschwarz
Copy link
Author

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)

>>>> 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] = |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 (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, pid, query, version() from pg_stat_activity where pid = pg_backend_pid()"))
				{
					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) + "|");
						}
					}
				}
			}
		}
	}

@davecramer
Copy link
Member

will do

@davecramer
Copy link
Member

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

@davecramer
Copy link
Member

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

@vlsi
Copy link
Member

vlsi commented Mar 20, 2024

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.

@goranschwarz
Copy link
Author

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

@davecramer
Copy link
Member

davecramer commented Mar 21, 2024 •
edited

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

@davecramer
Copy link
Member

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 :(

@goranschwarz
Copy link
Author

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?

@davecramer
Copy link
Member

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

@vlsi
Copy link
Member

vlsi commented Mar 22, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@vlsi @davecramer @goranschwarz