Query running for 12 hours

On 05/30/2018 04:37 AM, Yavuz Selim Sertoğlu wrote:

Hi everybody,
*
*
*Today I saw that two queries have been running for more then 12
hours(They are the same query actually).*

/mydb=# select * from pg_stat_activity where state='active' and
state_change < now()-'12 hours'::interval;/

*I've explained this query(I used $1 as now())*

What is the value of $1 in the queries?

*PostgreSQL version is 9.5.3 on CentOS 7.2.1511*

/[root@myserver]# cat /etc/redhat-release/
CentOS Linux release 7.2.1511 (Core)

/mydb=# select version();/
                                                 version
---------------------------------------------------------------------------------------------------------
 PostgreSQL 9.5.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5
20150623 (Red Hat 4.8.5-4), 64-bit
(1 row)

I could not figure out what the problem is.
I would be happy if someone could help me to solve this situation.

--

Saygılarımla

--
Adrian Klaver
adrian.klaver@aklaver.com

I am just a regular dba so I dont know what's sent from application exactly
but I assume now()-1 week.
In the log file, there are two more same queries. And their value is
*2018-05-23
02:00:00*

*Here are todays log lines for that query.*
  tarih=2018-05-30 02:12:19
+03,session_number=1,db=mydb,user=myuser,app=[unknown],client=myip,port=7128,xid=0,sid=5b0ddb70.1bd8
,LOG:  *duration*: *739797.540* ms  execute <unnamed>: select this_.ID as
ID107_1_, this_.islemTuru as islemTuru107_1_, this_.kullanici_ID as
kullanici7_107_1_, this_.loglananIslem as loglanan3_107_1_,
this_.oncekiVeri as oncekiVeri107_1_, this_.tarih as tarih107_1_,
this_.veri as veri107_1_, kullanici2_.ID as ID103_0_, kullanici2_.ad as
ad103_0_, kullanici2_.aktif as aktif103_0_, kullanici2_.dbUser as
dbUser103_0_, kullanici2_.ePosta as ePosta103_0_, kullanici2_.kullaniciAdi
as kullanic6_103_0_, kullanici2_.kullaniciTipiEnum as kullanic7_103_0_,
kullanici2_.parola as parola103_0_, kullanici2_.soyad as soyad103_0_ from
t_log_kaydi this_ left outer join t_kullanici kullanici2_ on
this_.kullanici_ID=kullanici2_.ID where this_.tarih<$1
  tarih=2018-05-30 02:12:19
+03,session_number=2,db=mydb,user=myuser,app=[unknown],client=myip,port=7128,xid=0,sid=5b0ddb70.1bd8
,*DETAIL:  parameters: $1 = '2018-05-23 02:00:00.023'*

  tarih=2018-05-30 08:48:18
+03,session_number=4725,db=mydb,user=myuser,app=[unknown],client=myip,port=24169,xid=0,sid=5b0d365c.5e69
,LOG:  *duration*: *24498773.468 *ms  execute <unnamed>: select this_.ID as
ID4_1_, this_.islemTuru as islemTuru4_1_, this_.kullanici_ID as
kullanici7_4_1_, this_.loglananIslem as loglanan3_4_1_, this_.oncekiVeri as
oncekiVeri4_1_, this_.tarih as tarih4_1_, this_.veri as veri4_1_,
kullanici2_.ID as ID0_0_, kullanici2_.ad as ad0_0_, kullanici2_.aktif as
aktif0_0_, kullanici2_.dbUser as dbUser0_0_, kullanici2_.ePosta as
ePosta0_0_, kullanici2_.kullaniciAdi as kullanic6_0_0_,
kullanici2_.kullaniciTipiEnum as kullanic7_0_0_, kullanici2_.parola as
parola0_0_, kullanici2_.soyad as soyad0_0_ from t_log_kaydi this_ left
outer join t_kullanici kullanici2_ on this_.kullanici_ID=kullanici2_.ID
where this_.tarih<$1
  tarih=2018-05-30 08:48:18
+03,session_number=4726,db=mydb,user=myuser,app=[unknown],client=myip,port=24169,xid=0,sid=5b0d365c.5e69
,*DETAIL:  parameters: $1 = '2018-05-23 02:00:00'*

*I explain analyzed same query with that value and its completed in 6
seconds.*
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=388.90..60022.26 rows=1165585 width=503) (actual
time=34.951..4338.432 rows=1167885 loops=1)
Output: this_.id, this_.islemturu, this_.kullanici_id,
this_.loglananislem, this_.oncekiveri, this_.tarih, this_.veri,
kullanici2_.id, kullanici2_.ad, kullanici2_.aktif, kullanici2_.dbuser, kull
anici2_.eposta, kullanici2_.kullaniciadi, kullanici2_.kullanicitipienum,
kullanici2_.parola, kullanici2_.soyad
Hash Cond: (this_.kullanici_id = kullanici2_.id)
Buffers: shared hit=29227
-> Seq Scan on public.t_log_kaydi this_ (cost=0.00..43626.00
rows=1165585 width=374) (actual time=0.010..1611.388 rows=1167885 loops=1)
Output: this_.id, this_.islemturu, this_.loglananislem,
this_.oncekiveri, this_.tarih, this_.veri, this_.kullanici_id
Filter: (this_.tarih < '2018-05-23 02:00:00.023'::timestamp
without time zone)
Rows Removed by Filter: 3178
Buffers: shared hit=29034
-> Hash (cost=278.40..278.40 rows=8840 width=129) (actual
time=34.770..34.770 rows=9134 loops=1)
Output: kullanici2_.id, kullanici2_.ad, kullanici2_.aktif,
kullanici2_.dbuser, kullanici2_.eposta, kullanici2_.kullaniciadi,
kullanici2_.kullanicitipienum, kullanici2_.parola, kullanici2_.
soyad
Buckets: 16384 Batches: 1 Memory Usage: 1604kB
Buffers: shared hit=190
-> Seq Scan on public.t_kullanici kullanici2_ (cost=0.00..278.40
rows=8840 width=129) (actual time=0.005..16.630 rows=9134 loops=1)
Output: kullanici2_.id, kullanici2_.ad, kullanici2_.aktif,
kullanici2_.dbuser, kullanici2_.eposta, kullanici2_.kullaniciadi,
kullanici2_.kullanicitipienum, kullanici2_.parola, kullan
ici2_.soyad
Buffers: shared hit=190
* Planning time: 2.331 ms*
* Execution time: 5431.817 ms*

On Wed, May 30, 2018 at 9:54 AM, Yavuz Selim Sertoğlu <
yavuzselim.sertoglu@bisoft.com.tr> wrote:

I am just a regular dba so I dont know what's sent from application
exactly but I assume now()-1 week.
In the log file, there are two more same queries. And their value is *2018-05-23
02:00:00*

*Here are todays log lines for that query.*
tarih=2018-05-30 02:12:19 +03,session_number=1,db=mydb,
user=myuser,app=[unknown],client=myip,port=7128,xid=0,sid=5b0ddb70.1bd8
,LOG: *duration*: *739797.540* ms execute <unnamed>: select this_.ID as
ID107_1_, this_.islemTuru as islemTuru107_1_, this_.kullanici_ID as
kullanici7_107_1_, this_.loglananIslem as loglanan3_107_1_,
this_.oncekiVeri as oncekiVeri107_1_, this_.tarih as tarih107_1_,
this_.veri as veri107_1_, kullanici2_.ID as ID103_0_, kullanici2_.ad as
ad103_0_, kullanici2_.aktif as aktif103_0_, kullanici2_.dbUser as
dbUser103_0_, kullanici2_.ePosta as ePosta103_0_, kullanici2_.kullaniciAdi
as kullanic6_103_0_, kullanici2_.kullaniciTipiEnum as kullanic7_103_0_,
kullanici2_.parola as parola103_0_, kullanici2_.soyad as soyad103_0_ from
t_log_kaydi this_ left outer join t_kullanici kullanici2_ on
this_.kullanici_ID=kullanici2_.ID where this_.tarih<$1
tarih=2018-05-30 02:12:19 +03,session_number=2,db=mydb,
user=myuser,app=[unknown],client=myip,port=7128,xid=0,sid=5b0ddb70.1bd8 ,*DETAIL:
parameters: $1 = '2018-05-23 02:00:00.023'*

tarih=2018-05-30 08:48:18 +03,session_number=4725,db=
mydb,user=myuser,app=[unknown],client=myip,port=24169,xid=0,sid=5b0d365c.5e69
,LOG: *duration*: *24498773.468 *ms execute <unnamed>: select this_.ID
as ID4_1_, this_.islemTuru as islemTuru4_1_, this_.kullanici_ID as
kullanici7_4_1_, this_.loglananIslem as loglanan3_4_1_, this_.oncekiVeri as
oncekiVeri4_1_, this_.tarih as tarih4_1_, this_.veri as veri4_1_,
kullanici2_.ID as ID0_0_, kullanici2_.ad as ad0_0_, kullanici2_.aktif as
aktif0_0_, kullanici2_.dbUser as dbUser0_0_, kullanici2_.ePosta as
ePosta0_0_, kullanici2_.kullaniciAdi as kullanic6_0_0_,
kullanici2_.kullaniciTipiEnum as kullanic7_0_0_, kullanici2_.parola as
parola0_0_, kullanici2_.soyad as soyad0_0_ from t_log_kaydi this_ left
outer join t_kullanici kullanici2_ on this_.kullanici_ID=kullanici2_.ID
where this_.tarih<$1
tarih=2018-05-30 08:48:18 +03,session_number=4726,db=
mydb,user=myuser,app=[unknown],client=myip,port=24169,xid=0,sid=5b0d365c.5e69
,*DETAIL: parameters: $1 = '2018-05-23 02:00:00'*

*I explain analyzed same query with that value and its completed in 6
seconds.*
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
-----------------
------------------------------------------------------------
---------------------------------------------------
Hash Left Join (cost=388.90..60022.26 rows=1165585 width=503) (actual
time=34.951..4338.432 rows=1167885 loops=1)
Output: this_.id, this_.islemturu, this_.kullanici_id,
this_.loglananislem, this_.oncekiveri, this_.tarih, this_.veri,
kullanici2_.id, kullanici2_.ad, kullanici2_.aktif, kullanici2_.dbuser, kull
anici2_.eposta, kullanici2_.kullaniciadi, kullanici2_.kullanicitipienum,
kullanici2_.parola, kullanici2_.soyad
Hash Cond: (this_.kullanici_id = kullanici2_.id)
Buffers: shared hit=29227
-> Seq Scan on public.t_log_kaydi this_ (cost=0.00..43626.00
rows=1165585 width=374) (actual time=0.010..1611.388 rows=1167885 loops=1)
Output: this_.id, this_.islemturu, this_.loglananislem,
this_.oncekiveri, this_.tarih, this_.veri, this_.kullanici_id
Filter: (this_.tarih < '2018-05-23 02:00:00.023'::timestamp
without time zone)
Rows Removed by Filter: 3178
Buffers: shared hit=29034
-> Hash (cost=278.40..278.40 rows=8840 width=129) (actual
time=34.770..34.770 rows=9134 loops=1)
Output: kullanici2_.id, kullanici2_.ad, kullanici2_.aktif,
kullanici2_.dbuser, kullanici2_.eposta, kullanici2_.kullaniciadi,
kullanici2_.kullanicitipienum, kullanici2_.parola, kullanici2_.
soyad
Buckets: 16384 Batches: 1 Memory Usage: 1604kB
Buffers: shared hit=190
-> Seq Scan on public.t_kullanici kullanici2_
(cost=0.00..278.40 rows=8840 width=129) (actual time=0.005..16.630
rows=9134 loops=1)
Output: kullanici2_.id, kullanici2_.ad, kullanici2_.aktif,
kullanici2_.dbuser, kullanici2_.eposta, kullanici2_.kullaniciadi,
kullanici2_.kullanicitipienum, kullanici2_.parola, kullan
ici2_.soyad
Buffers: shared hit=190
* Planning time: 2.331 ms*
* Execution time: 5431.817 ms*

T
*wo things:*
*From your explain, it looks like you need an index on this_.tarih, since
it is doing a sequential scan when it should be using an index.*

*Also, your main problem is that when you have two exact same queries
executing at the same time, they will cause contention in*

*the disk, and neither one will make much progress.*

--
*Melvin Davidson*
*Maj. Database & Exploration Specialist*
*Universe Exploration Command – UXC*
Employment by invitation only!

On 05/30/2018 06:54 AM, Yavuz Selim Sertoğlu wrote:

I am just a regular dba so I dont know what's sent from application
exactly but I assume now()-1 week.
In the log file, there are two more same queries. And their value is
*2018-05-23 02:00:00*

And these queries are not showing up in pg_stat_activity as still active?

*
*I explain analyzed same query with that value and its completed in 6
seconds.*
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------
 Hash Left Join  (cost=388.90..60022.26 rows=1165585 width=503) (actual
time=34.951..4338.432 rows=1167885 loops=1)
   Output: this_.id, this_.islemturu, this_.kullanici_id,
this_.loglananislem, this_.oncekiveri, this_.tarih, this_.veri,
kullanici2_.id, kullanici2_.ad, kullanici2_.aktif, kullanici2_.dbuser, kull
anici2_.eposta, kullanici2_.kullaniciadi, kullanici2_.kullanicitipienum,
kullanici2_.parola, kullanici2_.soyad
   Hash Cond: (this_.kullanici_id = kullanici2_.id)
   Buffers: shared hit=29227
   ->  Seq Scan on public.t_log_kaydi this_  (cost=0.00..43626.00
rows=1165585 width=374) (actual time=0.010..1611.388 rows=1167885 loops=1)
         Output: this_.id, this_.islemturu, this_.loglananislem,
this_.oncekiveri, this_.tarih, this_.veri, this_.kullanici_id
         Filter: (this_.tarih < '2018-05-23 02:00:00.023'::timestamp
without time zone)
         Rows Removed by Filter: 3178
         Buffers: shared hit=29034
   ->  Hash  (cost=278.40..278.40 rows=8840 width=129) (actual
time=34.770..34.770 rows=9134 loops=1)
         Output: kullanici2_.id, kullanici2_.ad, kullanici2_.aktif,
kullanici2_.dbuser, kullanici2_.eposta, kullanici2_.kullaniciadi,
kullanici2_.kullanicitipienum, kullanici2_.parola, kullanici2_.
soyad
         Buckets: 16384  Batches: 1  Memory Usage: 1604kB
         Buffers: shared hit=190
         ->  Seq Scan on public.t_kullanici kullanici2_
(cost=0.00..278.40 rows=8840 width=129) (actual time=0.005..16.630
rows=9134 loops=1)
               Output: kullanici2_.id, kullanici2_.ad,
kullanici2_.aktif, kullanici2_.dbuser, kullanici2_.eposta,
kullanici2_.kullaniciadi, kullanici2_.kullanicitipienum,
kullanici2_.parola, kullan
ici2_.soyad
               Buffers: shared hit=190
* Planning time: 2.331 ms*
* Execution time: 5431.817 ms*
*
*

--
Adrian Klaver
adrian.klaver@aklaver.com

On 05/30/2018 07:00 AM, Melvin Davidson wrote:

T*wo things:
*
*From your explain, it looks like you need an index on this_.tarih,
since it is doing a sequential scan when it should be using an index.*
*
*
*Also, your main problem is that when you have two exact same queries
executing at the same time, they will cause contention in*
*the disk, and neither one will make much progress.

I am having a hard time seeing how two SELECT queries that on average
take ~6 secs each can stay in contention for 12+ hours, especially with:

waiting | f

*

--
*Melvin Davidson**
Maj. Database & Exploration Specialist**
Universe Exploration Command – UXC***
Employment by invitation only!

--
Adrian Klaver
adrian.klaver@aklaver.com

2018-05-30 17:02 GMT+03:00 Adrian Klaver <adrian.klaver@aklaver.com>:

On 05/30/2018 06:54 AM, Yavuz Selim Sertoğlu wrote:

I am just a regular dba so I dont know what's sent from application
exactly but I assume now()-1 week.
In the log file, there are two more same queries. And their value is
*2018-05-23 02:00:00*

And these queries are not showing up in pg_stat_activity as still active?

*>> I think these were completed so they are not in pg_stat_activity.*

On 05/30/2018 07:19 AM, Yavuz Selim Sertoğlu wrote:

2018-05-30 17:02 GMT+03:00 Adrian Klaver <adrian.klaver@aklaver.com
<mailto:adrian.klaver@aklaver.com>>:

On 05/30/2018 06:54 AM, Yavuz Selim Sertoğlu wrote:

I am just a regular dba so I dont know what's sent from
application exactly but I assume now()-1 week.
In the log file, there are two more same queries. And their
value is *2018-05-23 02:00:00*

And these queries are not showing up in pg_stat_activity as still
active?

*>> I think these were completed so they are not in pg_stat_activity.*

Remaining suggestions/questions:

1) If it still exists look in Postgres log around 2018-05-30 02:00:00,
the time the problematic queries started, to see if there are any
entries of note.

2) You are on Postgres 9.5.3 and the most recent release 9.5.13. There
have been a lot of bug fixes in the interim and it would be a good idea
to upgrade. It is minor release upgrade but I would go through the
release notes first:

https://www.postgresql.org/docs/9.5/static/release.html

as there some thing that might require your action.

3) I suggest 2) because a quick scan of the release notes found this:

https://www.postgresql.org/docs/9.5/static/release-9-5-11.html

"

Cope with failure to start a parallel worker process (Amit Kapila,
Robert Haas)

Parallel query previously tended to hang indefinitely if a worker could
not be started, as the result of fork() failure or other low-probability
problems.
"

Is it possible that parallel query:

https://www.postgresql.org/docs/10/static/when-can-parallel-query-be-used.html

is in use?

--
Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

--
Adrian Klaver
adrian.klaver@aklaver.com

Major upgrade would be very painful because there are many application
running on different servers but same database server.
Their tests would take too much time.
So I will try to go with minor upgrade.

Thanks for your help, have a good day.

On 05/30/2018 07:41 AM, Yavuz Selim Sertoğlu wrote:

Major upgrade would be very painful because there are many application
running on different servers but same database server.

FYI, 9.5.3 --> 9.5.13 is considered a minor upgrade.

Their tests would take too much time.
So I will try to go with minor upgrade.

Thanks for your help, have a good day.

Remaining suggestions/questions:

1) If it still exists look in Postgres log around  2018-05-30
02:00:00, the time the problematic queries started, to see if there
are any entries of note.

2) You are on Postgres 9.5.3 and the most recent release 9.5.13.
There have been a lot of bug fixes in the interim and it would be a
good idea to upgrade. It is minor release upgrade but I would go
through the release notes first:

https://www.postgresql.org/docs/9.5/static/release.html
<https://www.postgresql.org/docs/9.5/static/release.html&gt;

as there some thing that might require your action.

3) I suggest 2) because a quick scan of the release notes found this:

https://www.postgresql.org/docs/9.5/static/release-9-5-11.html
<https://www.postgresql.org/docs/9.5/static/release-9-5-11.html&gt;

"

Cope with failure to start a parallel worker process (Amit Kapila,
Robert Haas)

Parallel query previously tended to hang indefinitely if a worker
could not be started, as the result of fork() failure or other
low-probability problems.
"

Is it possible that parallel query:

https://www.postgresql.org/docs/10/static/when-can-parallel-query-be-used.html
<https://www.postgresql.org/docs/10/static/when-can-parallel-query-be-used.html&gt;

is in use?

    --     Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
<mailto:adrian.klaver@aklaver.com
<mailto:adrian.klaver@aklaver.com>>

--
Adrian Klaver
adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>

--
Adrian Klaver
adrian.klaver@aklaver.com