Re: Query running for 12 hours

On Wed, May 30, 2018 at 9:54 AM, Yavuz Selim Sertoğlu <
yavuzselim(dot)sertoglu(at)bisoft(dot)com(dot)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!