Re: Query running for 12 hours

From: Yavuz Selim Sertoğlu <yavuzselim(dot)sertoglu(at)bisoft(dot)com(dot)tr>
To: Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com>
Cc: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: Re: Query running for 12 hours
Date: 2018-05-30 13:54:59
Message-ID: CAJTnKsp1+0GP8GBtOfeq5zyCd9mGE+U6_hG8J0n5iM=CXoNR0A@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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*

In response to

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Melvin Davidson 2018-05-30 14:00:16 Re: Query running for 12 hours
Previous Message Adrian Klaver 2018-05-30 13:37:09 Re: Update rules on views