[pgpool-general: 1664] Re: Pgpool insert_lock not maintaining serial sequences between multiple back ends

[Karsten Düsterloh]

Steve Kuekes wrote:
> We have a test Pgpool system running Pgpool 3.2.3 and Postgres 9.1.
> 
> The configuration is one master postgres and one slave postgres in 
> replication mode with load balancing and a separate system running pgpool.

So do we, although pgpool is running on one of the nodes.

> When there are multiple systems that are inserting rows into tables that 
> contain a "serial" datatype the values of the serials sometimes get 
> different values on the different back end systems.  We have enabled 
> insert_lock in the config file and created the insert_lock table. 
> According to a debugging trace it appears that inserts to these tables 
> are using the insert_lock table to lock a row by the oid of the 
> destination table.

Our problem with 3.2.3 is more the other way around:
We're running an OTRS 3.2.x (first .1, upgrade to .6 didn't help)
installation against the pgpool cluster, but since upgrading from pgpool
3.2.1/pg 8.3 to pgpool 3.2.3/pg 9.1, the insert_lock just blocks, as can
be seen in logs:

pgpool.log:
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: BEGIN
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: Parse: 
>             DELETE FROM sessions
>             WHERE session_id = $1
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: B message
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: D message
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: Execute: 
>             DELETE FROM sessions
>             WHERE session_id = $1
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: COMMIT
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: 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')
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: 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
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: BEGIN
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: 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'
> Apr 25 13:29:56 pg0 pgpool[2516]: DB node id: 0 backend pid: 12051 statement: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
… and then nothing happens anymore.

postgresql.log:
> 2013-04-25 13:29:56.840 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.029 ms  statement: BEGIN
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.069 ms  parse <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.091 ms  bind <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 DETAIL:  parameters: $1 = '13d5e9574e332cb8efd4cfb756dedc007'
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.059 ms  execute <unnamed>: 
>                     DELETE FROM sessions
>                     WHERE session_id = $1
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 DETAIL:  parameters: $1 = '13d5e9574e332cb8efd4cfb756dedc007'
> 2013-04-25 13:29:56.841 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.025 ms  statement: COMMIT
> 2013-04-25 13:29:56.845 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.522 ms  parse pgpool2516: 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-04-25 13:29:56.845 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.066 ms  bind pgpool2516/pgpool2516: SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND d.adsrc ~ 'nextval' A
> ND c.oid = pgpool_regclass('sessions')
> 2013-04-25 13:29:56.846 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.964 ms  execute pgpool2516/pgpool2516: 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-04-25 13:29:56.847 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.896 ms  parse pgpool2516: 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.p
> g_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-04-25 13:29:56.847 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.095 ms  bind pgpool2516/pgpool2516: 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-04-25 13:29:56.848 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.805 ms  execute pgpool2516/pgpool2516: SELECT attname, d.adsrc, coalesce((d.adsrc LIKE '%now()%' OR d.adsrc LIKE '%''now''::text%') AND (a.atttypid = 'timestam
> p'::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.attnu
> m
> 2013-04-25 13:29:56.848 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.030 ms  statement: BEGIN
> 2013-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.447 ms  parse pgpool2516: 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-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.076 ms  bind pgpool2516/pgpool2516: SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpo
> ol_catalog' AND relname = 'insert_lock'
> 2013-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.040 ms  execute pgpool2516/pgpool2516: SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'p
> gpool_catalog' AND relname = 'insert_lock'
> 2013-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.231 ms  parse pgpool2516: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
> 2013-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.049 ms  bind pgpool2516/pgpool2516: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
> 2013-04-25 13:29:56.849 CEST [12051] [unknown] 00000 LOG:  00000: duration: 0.033 ms  execute pgpool2516/pgpool2516: SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pgpool_regclass('sessions') FOR UPDATE
… and then nothing happens anymore.

Maybe something broke in insert_lock?


Karsten