Thread: Finding values of bind variables
I noticed 100s of waiting sessions in my production DB yesterday. Upon troubleshooting, I found an insert statement (idle in transaction) that was blocking.
This is what I saw in pg_stat_activity:
site=# select * from pg_stat_activity where pid=62334;
-[ RECORD 1 ]----+------------------------------------------------------------------------------------------------------------------------
datid | DBID
datname | DBNAME
pid | 62334
usesysid | 44490
usename | USERNAME
application_name | APPNAME
client_addr | CLIENTIP
client_hostname | HOSTNAME
client_port | 51987
backend_start | 2015-04-06 20:55:07.921089-07
xact_start | 2015-04-06 21:16:26.820822-07
query_start | 2015-04-06 21:16:26.834017-07
state_change | 2015-04-06 21:16:26.834144-07
waiting | f
state | idle in transaction
query | INSERT into distributed_events (type, action, id, properties) VALUES ($1, $2, $3, $4) RETURNING "distributed_event_id"
I found this blocking session and killed it and the locks cleared within a second.
After I killed it, this is all I saw in the postgresql.log:
Apr 7 14:26:50 site-db01a postgres[62334]: [11-1] app=APPNAME,user=USERNAME,db=DBNAME,ip=CLIENTIP FATAL: terminating connection due to administrator command
When I sent this information to the dev team, they came back saying that there was no error in the application logs and asked for the value of the bind variables to help them troubleshoot further.
My question: Is there a way to find out the value of bind variables executed in a current session (show them in pg_stat_activity)? Or to log it in the postgresql.log or a table after the session was killed? I know that bind variables of completed queries will be logged in postgresql.log. But what about the ones that were killed or terminated for any reason?
Thank you for your help
Ramya
state | idle in transaction
query | INSERT into distributed_events (type, action, id, properties) VALUES ($1, $2, $3, $4) RETURNING "distributed_event_id"
idle means its NOT executing any query... thats just the LAST query it executed. idle in transaction means someone/something started a transaction but isn't actively doing anything so there's a pending transaction thats idle.
backend_start | 2015-04-06 20:55:07.921089-07
this client connected on that date/time
xact_start | 2015-04-06 21:16:26.820822-07
the transaction started at that date/time (about 21 minutes after creating the connection)
query_start | 2015-04-06 21:16:26.834017-07
the last query started about 0.014 seconds after creating the transaction
state_change | 2015-04-06 21:16:26.834144-07
the state_change to idle-in-transaction took place about 0.0001 seconds later (so the insert took all of a millisecond).
What date/time was it when you did that select from pg_stat_activity ? thats how long this transaction has been pending, which if its more than a few seconds to at most a minute, is almost certainly a 'very bad thing' unless the transaction is actively crunching data.
if you're using a client such as JDBC which autowraps queries in transactions by default, you need to invoke COMMIT's when you're done doing that unit of work.
-- john r pierce, recycling bits in santa cruz
Thank You John.
> the state_change to idle-in-transaction took place about 0.0001 seconds later (so the insert took all of a millisecond).
Yes, the DML “finished” but stayed uncommitted.
> What date/time was it when you did that select from pg_stat_activity ? thats how long this transaction has been pending, which if its more than a few seconds to at most a minute, is almost certainly a 'very bad thing' unless the transaction is actively crunching data.
2015-04-07 14:25 – ~17 hours after the DML ran.
Agreed, it was bad. There was nothing happening with this transaction since 2015-04-06 21:16:26. It was just sitting there.
> if you're using a client such as JDBC which autowraps queries in transactions by default, you need to invoke COMMIT's when you're done doing that unit of work.
This is what I am trying to confirm from the application side. It will help the dev team if they have the value for bind variables apparently.
Any idea on how to get the values for bind variables for a transaction like this?
Thank You RamyaOn Apr 8, 2015, at 3:43 PM, Vasudevan, Ramya <ramya.vasudevan@classmates.com> wrote:Thank You John.> the state_change to idle-in-transaction took place about 0.0001 seconds later (so the insert took all of a millisecond).Yes, the DML “finished” but stayed uncommitted.
> What date/time was it when you did that select from pg_stat_activity ? thats how long this transaction has been pending, which if its more than a few seconds to at most a minute, is almost certainly a 'very bad thing' unless the transaction is actively crunching data.
2015-04-07 14:25 – ~17 hours after the DML ran.Agreed, it was bad. There was nothing happening with this transaction since 2015-04-06 21:16:26. It was just sitting there.
> if you're using a client such as JDBC which autowraps queries in transactions by default, you need to invoke COMMIT's when you're done doing that unit of work.
This is what I am trying to confirm from the application side. It will help the dev team if they have the value for bind variables apparently.
Any idea on how to get the values for bind variables for a transaction like this?Thank YouRamya
>Any idea on how to get the values for bind variables for a transaction like this?
To clarify - I understand that there is no way I can recover the value for this session. But, for help with troubleshooting in the future, is there any way I can find (or log) it when the query is running?
Thank You Ramya