[pgpool-general: 1684] insert_lock hangs

Mon May 6 22:18:29 JST 2013

Hi!

We're running pgpool 3.2.x against two Postgresql 9.1.y servers under
Debian 6 with several databases used by several distinct services like
the ticket system OTRS.

With one of their last updates, they added SERIAL columns to some tables
used in prepared statements, and now pgpool hangs when trying to
executes those.

The OTRS system itself is "just" a bunch of perl scripts inside an
Apache installation. When trying log into the ticket system, a
session_id shall be written into a 'sessions' table, but this hangs:

pgpool.log:
> 2013-05-06 14:22:02.235 CEST [13003] [unknown] 00000 LOG:  duration: 0.035 ms  statement: BEGIN
> 2013-05-06 14:22:02.235 CEST [13003] [unknown] 00000 LOG:  duration: 0.070 ms  parse <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-05-06 14:22:02.236 CEST [13003] [unknown] 00000 LOG:  duration: 0.088 ms  bind <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-05-06 14:22:02.236 CEST [13003] [unknown] 00000 DETAIL:  parameters: $1 = '1eae4e7eb3f0adf2e2bc3f50f1446530f'
> 2013-05-06 14:22:02.236 CEST [13003] [unknown] 00000 LOG:  duration: 0.063 ms  execute <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-05-06 14:22:02.236 CEST [13003] [unknown] 00000 DETAIL:  parameters: $1 = '1eae4e7eb3f0adf2e2bc3f50f1446530f'
> 2013-05-06 14:22:02.236 CEST [13003] [unknown] 00000 LOG:  duration: 0.024 ms  statement: COMMIT
> 2013-05-06 14:22:02.238 CEST [13003] [unknown] 00000 LOG:  duration: 0.426 ms  parse pgpool12980: SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND d.adsrc ~ 'nextval' AND c.oid = pgpool_regclass('sessions')
> 2013-05-06 14:22:02.238 CEST [13003] [unknown] 00000 LOG:  duration: 0.054 ms  bind pgpool12980/pgpool12980: SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND d.adsrc ~ 'nextval' AND c.oid = pgpool_regclass('sessions')
> 2013-05-06 14:22:02.239 CEST [13003] [unknown] 00000 LOG:  duration: 0.993 ms  execute pgpool12980/pgpool12980: SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND d.adsrc ~ 'nextval' AND c.oid = pgpool_regclass('sessions')
> 2013-05-06 14:22:02.240 CEST [13003] [unknown] 00000 LOG:  duration: 0.757 ms  parse pgpool12980: SELECT attname, d.adsrc, coalesce((d.adsrc LIKE '%now()%' OR d.adsrc LIKE '%''now''::text%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum = d.adnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = pgpool_regclass('sessions') ORDER BY a.attnum
> 2013-05-06 14:22:02.240 CEST [13003] [unknown] 00000 LOG:  duration: 0.087 ms  bind pgpool12980/pgpool12980: SELECT attname, d.adsrc, coalesce((d.adsrc LIKE '%now()%' OR d.adsrc LIKE '%''now''::text%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum = d.adnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = pgpool_regclass('sessions') ORDER BY a.attnum
> 2013-05-06 14:22:02.241 CEST [13003] [unknown] 00000 LOG:  duration: 0.787 ms  execute pgpool12980/pgpool12980: SELECT attname, d.adsrc, coalesce((d.adsrc LIKE '%now()%' OR d.adsrc LIKE '%''now''::text%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum = d.adnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = pgpool_regclass('sessions') ORDER BY a.attnum
> 2013-05-06 14:22:02.241 CEST [13003] [unknown] 00000 LOG:  duration: 0.026 ms  statement: BEGIN
> 2013-05-06 14:22:02.263 CEST [13003] [unknown] 00000 LOG:  duration: 21.331 ms  parse pgpool12980: SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpool_catalog' AND relname = 'insert_lock'
> 2013-05-06 14:22:02.263 CEST [13003] [unknown] 00000 LOG:  duration: 0.067 ms  bind pgpool12980/pgpool12980: SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpool_catalog' AND relname = 'insert_lock'
> 2013-05-06 14:22:02.263 CEST [13003] [unknown] 00000 LOG:  duration: 0.038 ms  execute pgpool12980/pgpool12980: SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpool_catalog' AND relname = 'insert_lock'
> 2013-05-06 14:22:02.264 CEST [13003] [unknown] 00000 LOG:  duration: 0.231 ms  parse pgpool12980: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
> 2013-05-06 14:22:02.264 CEST [13003] [unknown] 00000 LOG:  duration: 0.044 ms  bind pgpool12980/pgpool12980: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
> 2013-05-06 14:22:02.267 CEST [13003] [unknown] 00000 LOG:  duration: 3.819 ms  execute pgpool12980/pgpool12980: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
(… then nothing happens in this thread anymore.)

The original hanging query isn't logged by pgpool, not even when turning
on pgpool's extensive debug output, but running OTRS against postgresql
directly (without pgpool) shows this as the offending query:
> 2013-05-06 14:47:10.487 CEST [14141] [unknown] 00000 LOG:  duration: 0.068 ms  parse <unnamed>: INSERT INTO sessions (session_id, data_key, data_value, serialized) VALUES ($1,$2,$3,$4)
> 2013-05-06 14:47:10.487 CEST [14141] [unknown] 00000 LOG:  duration: 0.045 ms  bind <unnamed>: INSERT INTO sessions (session_id, data_key, data_value, serialized) VALUES ($1,$2,$3,$4)
> 2013-05-06 14:47:10.487 CEST [14141] [unknown] 00000 DETAIL:  parameters: $1 = '11a98dce334f5dd318594a76edf08819b', $2 = 'LastScreenOverview', $3 = 'Action=AgentTicketQueue;QueueID=9;View=', $4 = '0'
> 2013-05-06 14:47:10.487 CEST [14141] [unknown] 00000 LOG:  duration: 0.106 ms  execute <unnamed>: INSERT INTO sessions (session_id, data_key, data_value, serialized) VALUES ($1,$2,$3,$4)
> 2013-05-06 14:47:10.487 CEST [14141] [unknown] 00000 DETAIL:  parameters: $1 = '11a98dce334f5dd318594a76edf08819b', $2 = 'LastScreenOverview', $3 = 'Action=AgentTicketQueue;QueueID=9;View=', $4 = '0'

The context of this query suggests that no other query is using/blocking
pgpool's insert_lock table at this moment, especially not for
minutes/hours, hence I'm quite at a loss here.
The problem exists both with pgpool 3.2.1 and 3.2.3.

Any suggestions what might be the problem?
I can provide pgpool debug output if needed.

Karsten