[pgpool-general: 5286] Re: stuck in active & idle in transaction

Tue Jan 31 20:48:52 JST 2017

Hi,
pstack from the first "stuck" query of a few setups, hoping this is helpful:

*setup #1:*

*postgres*

pstack 3083

#0  0x00007f18d04b9308 in poll () from /lib64/libc.so.6

#1  0x0000000000650547 in WaitLatchOrSocket ()

#2  0x00000000005e5f80 in secure_read ()

#3  0x00000000005ef9db in ?? ()

#4  0x00000000005efdeb in pq_getbyte ()

#5  0x00000000006bb2d5 in PostgresMain ()

#6  0x0000000000662455 in PostmasterMain ()

#7  0x00000000005f3fb8 in main ()

*pgpool*

pstack 30372

#0  0x00007f12d623a5c3 in __select_nocancel () from /lib64/libc.so.6

#1  0x000000000042a7ce in read_packets_and_process ()

#2  0x000000000042cf56 in pool_process_query ()

#3  0x0000000000424200 in do_child ()

#4  0x0000000000406fcd in fork_a_child ()

#5  0x00000000004077c3 in reaper ()

#6  0x0000000000409da5 in pool_sleep ()

#7  0x000000000040c14f in PgpoolMain ()

#8  0x000000000040597f in main ()

*setup #2:*

*postgres*

pstack 10143

Thread 2 (Thread 0x7f062cdcf700 (LWP 30283)):

#0  0x00007f0629c9f930 in sem_wait () from /lib64/libpthread.so.0

#1  0x00007f05ad61643d in v8::internal::LinuxSemaphore::Wait() () from
/usr/lib64/libv8.so.3

#2  0x00007f05ad62e020 in
v8::internal::RuntimeProfiler::WaitForSomeIsolateToEnterJS() () from
/usr/lib64/libv8.so.3

#3  0x00007f05ad617546 in v8::internal::SignalSender::Run() () from
/usr/lib64/libv8.so.3

#4  0x00007f05ad616890 in ?? () from /usr/lib64/libv8.so.3

#5  0x00007f0629c999d1 in start_thread () from /lib64/libpthread.so.0

#6  0x00007f062b33eb6d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f062ceba7c0 (LWP 10143)):

#0  0x00007f062b335343 in poll () from /lib64/libc.so.6

#1  0x0000000000650547 in WaitLatchOrSocket ()

#2  0x00000000005e5f80 in secure_read ()

#3  0x00000000005ef9db in ?? ()

#4  0x00000000005efdeb in pq_getbyte ()

#5  0x00000000006bb2d5 in PostgresMain ()

#6  0x0000000000662455 in PostmasterMain ()

#7  0x00000000005f3fb8 in main ()

*pgpool*

pstack 32569

#0  0x00007f31be38a5c3 in __select_nocancel () from /lib64/libc.so.6

#1  0x0000000000427432 in pool_check_fd ()

#2  0x0000000000453c4d in pool_read ()

#3  0x000000000042863a in do_query ()

#4  0x0000000000446070 in pool_search_relcache ()

#5  0x0000000000443ef3 in system_catalog_walker ()

#6  0x000000000044059a in raw_expression_tree_walker ()

#7  0x00000000004408a8 in raw_expression_tree_walker ()

#8  0x0000000000442aa1 in pool_has_system_catalog ()

#9  0x000000000043f0b8 in pool_where_to_send ()

#10 0x00000000004325af in Parse ()

#11 0x0000000000434891 in ProcessFrontendResponse ()

#12 0x000000000042d047 in pool_process_query ()

#13 0x0000000000424200 in do_child ()

#14 0x0000000000406fcd in fork_a_child ()

#15 0x00000000004077c3 in reaper ()

#16 0x0000000000409da5 in pool_sleep ()

#17 0x000000000040c14f in PgpoolMain ()

#18 0x000000000040597f in main ()

*setup #3*

*postgres*

pstack 5506

#0  0x00007ff783961308 in poll () from /lib64/libc.so.6

#1  0x0000000000650547 in WaitLatchOrSocket ()

#2  0x00000000005e5f80 in secure_read ()

#3  0x00000000005ef9db in ?? ()

#4  0x00000000005efdeb in pq_getbyte ()

#5  0x00000000006bb2d5 in PostgresMain ()

#6  0x0000000000662455 in PostmasterMain ()

#7  0x00000000005f3fb8 in main ()

*pgpool*

pstack 25347

#0  0x00007fa6b0ee05c3 in __select_nocancel () from /lib64/libc.so.6

#1  0x000000000042a7ce in read_packets_and_process ()

#2  0x000000000042cf56 in pool_process_query ()

#3  0x0000000000424200 in do_child ()

#4  0x0000000000406fcd in fork_a_child ()

#5  0x00000000004077c3 in reaper ()

#6  0x0000000000409da5 in pool_sleep ()

#7  0x000000000040c14f in PgpoolMain ()

#8  0x000000000040597f in main ()

*setup #4*

*postgres*

pstack 1754

Thread 2 (Thread 0x7f7c04932700 (LWP 1808)):

#0  0x00007f7c0177a930 in sem_wait () from /lib64/libpthread.so.0

#1  0x00007f7b6463143d in v8::internal::LinuxSemaphore::Wait() () from
/usr/lib64/libv8.so.3

#2  0x00007f7b64649020 in
v8::internal::RuntimeProfiler::WaitForSomeIsolateToEnterJS() () from
/usr/lib64/libv8.so.3

#3  0x00007f7b64632546 in v8::internal::SignalSender::Run() () from
/usr/lib64/libv8.so.3

#4  0x00007f7b64631890 in ?? () from /usr/lib64/libv8.so.3

#5  0x00007f7c017749d1 in start_thread () from /lib64/libpthread.so.0

#6  0x00007f7c02e19b6d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f7c049957c0 (LWP 1754)):

#0  0x00007f7c02e10343 in poll () from /lib64/libc.so.6

#1  0x0000000000650547 in WaitLatchOrSocket ()

#2  0x00000000005e5f80 in secure_read ()

#3  0x00000000005ef9db in ?? ()

#4  0x00000000005efdeb in pq_getbyte ()

#5  0x00000000006bb2d5 in PostgresMain ()

#6  0x0000000000662455 in PostmasterMain ()

#7  0x00000000005f3fb8 in main ()

*pgpool*

pstack 19895

#0  0x00007f2a75fc75c3 in __select_nocancel () from /lib64/libc.so.6

#1  0x0000000000427432 in pool_check_fd ()

#2  0x0000000000453c4d in pool_read ()

#3  0x000000000042863a in do_query ()

#4  0x0000000000446070 in pool_search_relcache ()

#5  0x0000000000442d4e in temp_table_walker ()

#6  0x0000000000440793 in raw_expression_tree_walker ()

#7  0x0000000000440782 in raw_expression_tree_walker ()

#8  0x0000000000440782 in raw_expression_tree_walker ()

#9  0x0000000000440782 in raw_expression_tree_walker ()

#10 0x0000000000440782 in raw_expression_tree_walker ()

#11 0x0000000000440782 in raw_expression_tree_walker ()

#12 0x0000000000440782 in raw_expression_tree_walker ()

#13 0x0000000000440782 in raw_expression_tree_walker ()

#14 0x0000000000440782 in raw_expression_tree_walker ()

#15 0x0000000000440782 in raw_expression_tree_walker ()

#16 0x0000000000440782 in raw_expression_tree_walker ()

#17 0x0000000000440782 in raw_expression_tree_walker ()

#18 0x0000000000440782 in raw_expression_tree_walker ()

#19 0x0000000000440782 in raw_expression_tree_walker ()

#20 0x0000000000440782 in raw_expression_tree_walker ()

#21 0x0000000000440782 in raw_expression_tree_walker ()

#22 0x0000000000440782 in raw_expression_tree_walker ()

#23 0x0000000000440782 in raw_expression_tree_walker ()

#24 0x0000000000440782 in raw_expression_tree_walker ()

#25 0x0000000000440782 in raw_expression_tree_walker ()

#26 0x0000000000440782 in raw_expression_tree_walker ()

#27 0x0000000000440782 in raw_expression_tree_walker ()

#28 0x0000000000440782 in raw_expression_tree_walker ()

#29 0x0000000000440782 in raw_expression_tree_walker ()

#30 0x0000000000440782 in raw_expression_tree_walker ()

#31 0x0000000000440782 in raw_expression_tree_walker ()

#32 0x0000000000440782 in raw_expression_tree_walker ()

#33 0x0000000000440782 in raw_expression_tree_walker ()

#34 0x0000000000440782 in raw_expression_tree_walker ()

#35 0x0000000000440782 in raw_expression_tree_walker ()

#36 0x0000000000440782 in raw_expression_tree_walker ()

#37 0x0000000000440782 in raw_expression_tree_walker ()

#38 0x0000000000440782 in raw_expression_tree_walker ()

#39 0x0000000000440782 in raw_expression_tree_walker ()

#40 0x0000000000440782 in raw_expression_tree_walker ()

#41 0x0000000000440782 in raw_expression_tree_walker ()

#42 0x0000000000440782 in raw_expression_tree_walker ()

#43 0x0000000000440782 in raw_expression_tree_walker ()

#44 0x0000000000440782 in raw_expression_tree_walker ()

#45 0x000000000044059a in raw_expression_tree_walker ()

#46 0x00000000004408a8 in raw_expression_tree_walker ()

#47 0x0000000000442a62 in pool_has_temp_table ()

#48 0x000000000043f4e3 in pool_where_to_send ()

#49 0x00000000004325af in Parse ()

#50 0x0000000000434891 in ProcessFrontendResponse ()

#51 0x000000000042d047 in pool_process_query ()

#52 0x0000000000424200 in do_child ()

#53 0x0000000000406fcd in fork_a_child ()

#54 0x00000000004077c3 in reaper ()

#55 0x0000000000409da5 in pool_sleep ()

#56 0x000000000040c14f in PgpoolMain ()

#57 0x000000000040597f in main ()

*setup #5:*

*postgres*

pstack 8751

#0  0x00007ff6807e2308 in poll () from /lib64/libc.so.6

#1  0x0000000000650547 in WaitLatchOrSocket ()

#2  0x00000000005e5f80 in secure_read ()

#3  0x00000000005ef9db in ?? ()

#4  0x00000000005efdeb in pq_getbyte ()

#5  0x00000000006bb2d5 in PostgresMain ()

#6  0x0000000000662455 in PostmasterMain ()

#7  0x00000000005f3fb8 in main ()

*pgpool*

pstack 10002

#0  0x00007f2317c375c3 in __select_nocancel () from /lib64/libc.so.6

#1  0x000000000042a7ce in read_packets_and_process ()

#2  0x000000000042cf56 in pool_process_query ()

#3  0x0000000000424200 in do_child ()

#4  0x0000000000406fcd in fork_a_child ()

#5  0x000000000040baa7 in PgpoolMain ()

#6  0x000000000040597f in main ()

On Tue, Jan 31, 2017 at 9:42 AM, Rolan Yadlin <rolan3 at gmail.com> wrote:

> Hi,
> in many setups in our labs we have "stuck" connections:
> some fit the FAQ, but they seem to remain in "active" state forever (until
> we restart pgpool):
> this is reproducing all the time but the scenario is unknown.
>
> examples the output was copied today a few minutes ago from a few setups:
> *setup 1:*
> node #1:
>  psql -Upostgres -h172.18.255.41 -p5432 -c "SELECT
> pid,state,query_start,query,waiting FROM pg_catalog.pg_stat_activity
> WHERE state !='idle' AND query_start < current_timestamp - interval '30
> minutes' ORDER BY query_start;"
>  pid  | state  |          query_start          | query  | waiting
> ------+--------+-------------------------------+------------
> ------------------------------------------------------------
> ------------------------------------------------------------
> -------------------------+---------
>  3083 | active | 2017-01-29 15:16:16.907158+00 | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
>  6526 | active | 2017-01-29 15:17:28.657637+00 | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
>  6527 | active | 2017-01-29 15:17:28.657663+00 | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
> (3 rows)
>
> *node #2:*
>  psql -Upostgres -h172.18.255.42 -p5432 -c "SELECT
> pid,state,query_start,query,waiting FROM pg_catalog.pg_stat_activity
> WHERE state !='idle' AND query_start < current_timestamp - interval '30
> minutes' ORDER BY query_start;"
>   pid  |        state        |          query_start          |    query  |
> waiting
> -------+---------------------+------------------------------
> -+----------------------------------------------------------
> ------------------------------------------------------------
> ------------------------------------------------------------
> ---------------------------------------------------------------
>  26340 | idle in transaction | 2017-01-29 21:56:29.025673+00 | select
> count(*) as cnt from (select this_.id as id1_4_0_, this_.version as
> version2_4_0_, this_.update_date as update_d3_4_0_, this_.trigger_date as
> trigger_4_4_0_, this_.occurrence_date as occurren5_4_0_,
> this_.state_user_id as state_us6_4
> _0_, this_.action_user_id as action_u7_4_0_, this_.resource_id as
> resource8_4_0_, this_.parameter01 a
> s paramete9_4_0_, this_.parameter02 as paramet10_4_0_, this_.parameter03
> as paramet11_4_0_, this_.par
> ameter04 as paramet12_4_0_, this_.parameter05 as paramet13_4_0_,
> this_.note as note14_4_0_, this_.ala
> rm_definition_id as alarm_d15_4_0_, this_.severity as severit16_4_0_,
> this_.domain_id as domain_17_4_
> 0_, this_.state as state18_4_0_, this_.invoking_controller as
> invokin19_4_0_, this_.invoking_element
> as invokin20_4_0_, this_.sub_module_id as sub_mod21_4_0_,
> this_.sub_instance_id as sub_ins22_4_0_, th
> is_.resource_element_id as resourc23_4_0_, this_.resource_parent_element_id
> as resourc24_4_0_ from al
> arms this_ where this_.resource_id in ($1, $2, $3, $4, $5, $6, $7, $8, $9,
> $ | f (1 row)
>
>
> *setup 2 (currently has only 1 postgres/pgpool node):*
> psql -Upostgres -h172.18.255.41 -p5432 -c "SELECT
> pid,state,query_start,query,waiting FROM pg_catalog.pg_stat_activity
> WHERE state !='idle' AND query_start < current_timestamp - interval '30
> minutes' ORDER BY query_start;"
>   pid  |        state        |          query_start          |
>           query
>  | waiting
> -------+---------------------+------------------------------
> -+----------------------------------------------------------
> ------------------------------------------------------------
> -----------+---------
>  10143 | idle in transaction | 2017-01-26 13:34:48.460062+00 | select
> submodule0_.id as id1_22_0_, submodule0_.name as name2_22_0_ from
> events_sub_modules submodule0_ where submodule0_.id=$1 | f
>  10134 | idle in transaction | 2017-01-26 14:15:46.345789+00 | select
> submodule0_.id as id1_22_0_, submodule0_.name as name2_22_0_ from
> events_sub_modules submodule0_ where submodule0_.id=$1 | f
> (2 rows)
>
>
> *setup 3:*
> node1:
> psql -Upostgres -h172.18.255.41 -p5432 -c "SELECT
> pid,state,query_start,query,waiting FROM pg_catalog.pg_stat_activity
> WHERE state != 'idle' AND query_start < current_timestamp - interval '30
> minutes' ORDER BY query_start;"
>  pid  | state  |          query_start          |
> query   | waiting
> ------+--------+-------------------------------+------------
> ------------------------------------------------------------
> ------------------------------------------------------------
> -------------------------+---------
>  5506 | active | 2017-01-31 00:04:39.128256+00 | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
>  5466 | active | 2017-01-31 00:04:39.12857+00  | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
>  5465 | active | 2017-01-31 00:04:39.129839+00 | SELECT count(*) FROM
> pg_class AS c, pg_namespace AS n WHERE c.oid =
> to_regclass('"pg_description"') AND c.relnamespace = n.oid AND n.nspname
> = 'pg_catalog' | f
> (3 rows)
>
> unfortunately, there are more examples, some with more than 10 stuck
> connections, sometimes it gets autovacuum "stuck" in active state,
> we also had instances in which stuck connections were doing updates and
> caused many transaction waiting for them to end and release locks, but we
> haven't encountered this in a dew days.
>
> if you need us to provide more information, just let us know.
> Please help us :-)
>
> we are using:
> Postgres 9.5.5
> PG-Pool 3.6.1
> Hibernate/JDBC
>
> Rolan.
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20170131/1415236e/attachment.htm>