From: Adarsh Sharma Date: September 5 2012 5:01am Subject: Re: Understanding Slow Query Log List-Archive: http://lists.mysql.com/mysql/228113 Message-Id: MIME-Version: 1.0 Content-Type: multipart/mixed; boundary=20cf306f7d145b934404c8ed4521 --20cf306f7d145b934404c8ed4521 Content-Type: multipart/alternative; boundary=20cf306f7d145b934004c8ed451f --20cf306f7d145b934004c8ed451f Content-Type: text/plain; charset=ISO-8859-1 Actually that query is not my concern : i have a query that is taking so much time : Slow Log Output : # Overall: 195 total, 16 unique, 0.00 QPS, 0.31x concurrency _____________ # Time range: 2012-09-01 14:30:01 to 2012-09-04 14:13:46 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 80887s 192us 2520s 415s 1732s 612s 80s # Lock time 13ms 0 133us 68us 103us 23us 69us # Rows sent 430.89k 0 17.58k 2.21k 12.50k 3.96k 49.17 # Rows examine 32.30M 0 466.46k 169.63k 440.37k 186.02k 117.95k # Query size 65.45k 6 577 343.70 563.87 171.06 246.02 In the logs output : # Query_time: 488.031783 Lock_time: 0.000041 Rows_sent: 50 Rows_examined: 471150 SET timestamp=1346655789; SELECT t0.id, t0.app_name, t0.status, t0.run, t0.user_name, t0.group_name, t0.created_time, t0.start_time, t0.last_modified_time, t0.end_time, t0.external_id FROM WF_1 t0 WHERE t0.bean_type = 'Workflow' ORDER BY t0.created_time DESC LIMIT 0, 50; The table is near about 30 GB and growing day by day. Attaching the table definition & indexes output. I have a index on bean type column but cann't understand why it examined the all rows of table. Thanks On Wed, Sep 5, 2012 at 12:24 AM, Rick James wrote: > 100 is tantamount to turning off the log. I prefer 2. > > select count(ENTITY_NAME) > from ALERT_EVENTS > where EVENT_TIME > date_sub(now(),INTERVAL 60 MINUTE) > and status=upper('failed') > and ENTITY_NAME='FETL-ImpressionRC-conversion'; > begs for the _compound_ index > INDEX(ENTITY_NAME, EVENT_TIME) > This would be even better: > INDEX(ENTITY_NAME, status, EVENT_TIME) > > COUNT(*) should be used if you don't need to check the column for being > NULL. > > > Rows_examined: 141145 > That is probably the entire table. Will the table grow? If so, the query > will get slower. Meanwhile, the index I suggested will (probably) be much > faster. > > > > -----Original Message----- > > From: Suresh Kuna [mailto:sureshkumarilu@stripped] > > Sent: Saturday, September 01, 2012 1:03 AM > > To: Adarsh Sharma > > Cc: mysql@stripped > > Subject: Re: Understanding Slow Query Log > > > > Disable log-queries-not-using-indexes to log only queries > 100 sec. > > > > Just do "> /var/lib/mysql/slow-queries.log" it will clear the log. > > > > On Sat, Sep 1, 2012 at 12:34 PM, Adarsh Sharma > > wrote: > > > > > Hi all, > > > > > > I am using Mysql Ver 14.14 Distrib 5.1.58 in which i enabled slow > > > query log by setting below parameters in my.cnf : > > > > > > log-slow-queries=/usr/local/mysql/slow-query.log > > > long_query_time=100 > > > log-queries-not-using-indexes > > > > > > I am assuming from the inf. from the internet that long_query_time is > > > in seconds , but i see the slow query log , there are lots of > > > statements ( queries ) : > > > > > > # User@Host: user1[user1] @ abc.dd.aa.com [192.112.111.111] # > > > Query_time: 0.052784 Lock_time: 0.000043 Rows_sent: 1 > > Rows_examined: > > > 141145 > > > SET timestamp=1346409734; > > > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME > > > > date_sub(now(),INTERVAL 60 MINUTE) and status=upper('failed') and > > > ENTITY_NAME='FETL-ImpressionRC-conversion'; > > > # Time: 120831 10:43:14 > > > # User@Host: user1[user1] @ abc.dd.aa.com [192.112.111.111] # > > > Query_time: 0.053599 Lock_time: 0.000079 Rows_sent: 1 > > Rows_examined: > > > 141145 > > > SET timestamp=1346409794; > > > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME > > > > date_sub(now(),INTERVAL 60 MINUTE) and status=upper('failed') and > > > ENTITY_NAME='FETL-click-enhancer-deferred'; > > > # User@Host: user1[user2] @ abc.dd.aa.com [192.112.111.111] # > > > Query_time: 0.054185 Lock_time: 0.000086 Rows_sent: 1 > > Rows_examined: > > > 141145 > > > SET timestamp=1346409794; > > > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME > > > > date_sub(now(),INTERVAL 60 MINUTE) and status=upper('failed') and > > > ENTITY_NAME='FETL-ImpressionRC-conversion'; > > > # Time: 120831 10:43:22 > > > # User@Host: user2[user2] @ abc.dd.aa.com [192.112.111.111] # > > > Query_time: 0.000163 Lock_time: 0.000045 Rows_sent: 1 > > Rows_examined: > > > 13 > > > > > > > > > > > > I don't understand the query time unit in slow query log because i > > > expect queries to be logged that takes > 100 s. I tested with sleep > > > command for 60s , it doesn't logged in slow query log and when i > > sleep > > > for 120 s it logged but i don't why the other queries are logging in > > slow log. > > > > > > # Query_time: 120.000259 Lock_time: 0.000000 Rows_sent: 1 > > Rows_examined: > > > 0 > > > SET timestamp=1346443103; > > > SELECT SLEEP(120); > > > > > > And also my slow log is increasing and decided to purge thorogh below > > > command : > > > > > > cat /dev/null > /var/lib/mysql/slow-queries.log > > > > > > > > > Anyone any ideas about this. > > > > > > > > > Thanks > > > > > > > > > > > -- > > Thanks > > Suresh Kuna > > MySQL DBA > --20cf306f7d145b934004c8ed451f Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Actually that query is not my concern :

i have a query t= hat is taking so much time :
Slow Log Output :
# O= verall: 195 total, 16 unique, 0.00 QPS, 0.31x concurrency _____________
# Time range: 2012-09-01 14:30:01 to 2012-09-04 14:13:46
# A= ttribute =A0 =A0 =A0 =A0 =A0total =A0 =A0 min =A0 =A0 max =A0 =A0 avg =A0 = =A0 95% =A0stddev =A0median
# =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D =A0 =A0 =3D=3D=3D=3D=3D=3D=3D =3D=3D=3D=3D=3D=3D=3D =3D=3D=3D=3D=3D=3D= =3D =3D=3D=3D=3D=3D=3D=3D =3D=3D=3D=3D=3D=3D=3D =3D=3D=3D=3D=3D=3D=3D =3D= =3D=3D=3D=3D=3D=3D
# Exec time =A0 =A0 =A0 =A0 80887s =A0 192us =A0 2520s =A0 =A0415s =A0= 1732s =A0 =A0612s =A0 =A0 80s
# Lock time =A0 =A0 =A0 =A0 =A0 13= ms =A0 =A0 =A0 0 =A0 133us =A0 =A068us =A0 103us =A0 =A023us =A0 =A069us
# Rows sent =A0 =A0 =A0 =A0430.89k =A0 =A0 =A0 0 =A017.58k =A0 2.21= k =A012.50k =A0 3.96k =A0 49.17
# Rows examine =A0 =A0 =A032.30M =A0 =A0 =A0 0 466.46k 169.63k 440.37k= 186.02k 117.95k
# Query size =A0 =A0 =A0 =A065.45k =A0 =A0 =A0 6= =A0 =A0 577 =A0343.70 =A0563.87 =A0171.06 =A0246.02

In the logs output :
# Query_time: 488.031783 =A0Lock_time: 0.000041 Rows_sent: 50 =A0= Rows_examined: 471150
SET timestamp=3D1346655789;
SELEC= T t0.id, t0.app_name, t0.status, t0.run, t0.us= er_name, t0.group_name, t0.created_time, t0.start_time, t0.last_modified_ti= me, t0.end_time, t0.external_id FROM WF_1 t0 WHERE t0.bean_type =3D 'Wo= rkflow' ORDER BY t0.created_time DESC LIMIT 0, 50;

The table is near about 30 GB and growing day by = day.=A0

Attaching the table definition & index= es output. I have a index on bean type column but cann't understand why= it=A0
examined the all rows of table.

Thanks
<= div>


On Wed, Sep 5, 2012 a= t 12:24 AM, Rick James <rjames@stripped> wrote:
100 is tantamount to turning off the log. = =A0I prefer 2.

select =A0count(ENTITY_NAME)
=A0 =A0 from =A0ALERT_EVENTS
=A0 =A0 where =A0EVENT_TIME > date_sub(now(),INTERVAL 60 MINUTE)
=A0 =A0 =A0 and =A0status=3Dupper('failed')
=A0 =A0 =A0 and =A0ENTITY_NAME=3D'FETL-ImpressionRC-conversion';
begs for the _compound_ index
INDEX(ENTITY_NAME, EVENT_TIME)
This would be even better:
INDEX(ENTITY_NAME, status, EVENT_TIME)

COUNT(*) should be used if you don't need to check the column for being= NULL.

> Rows_examined: 141145
That is probably the entire table. =A0Will the table grow? =A0If so, the qu= ery will get slower. =A0Meanwhile, the index I suggested will (probably) be= much faster.


> -----Original Message-----
> From: Suresh Kuna [mailto:= sureshkumarilu@stripped]
> Sent: Saturday, September 01, 2012 1:03 AM
> To: Adarsh Sharma
> Cc: mysql@stripped=
> Subject: Re: Understanding Slow Query Log
>
> Disable log-queries-not-using-indexes to log only queries > 100 sec= .
>
> Just do "> /var/lib/mysql/slow-queries.log" it will clear= the log.
>
> On Sat, Sep 1, 2012 at 12:34 PM, Adarsh Sharma
> <eddy.adarsh@stripped= >wrote:
>
> > Hi all,
> >
> > I am using Mysql Ver 14.14 Distrib 5.1.58 in which i enabled slow=
> > query log by setting below parameters in my.cnf :
> >
> > log-slow-queries=3D/usr/local/mysql/slow-query.log
> > long_query_time=3D100
> > log-queries-not-using-indexes
> >
> > I am assuming from the inf. from the internet that long_query_tim= e is
> > in seconds , but i see the slow query log , =A0there are lots of<= br> > > statements ( queries ) :
> >
> > # User@Host: user1[user1] @ abc.dd.aa.com [192.112.111.111] #
> > Query_time: 0.052784 =A0Lock_time: 0.000043 Rows_sent: 1
> Rows_examined:
> > 141145
> > SET timestamp=3D1346409734;
> > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME >=
> > date_sub(now(),INTERVAL 60 MINUTE) and status=3Dupper('failed= ') and
> > ENTITY_NAME=3D'FETL-ImpressionRC-conversion';
> > # Time: 120831 10:43:14
> > # User@Host: user1[user1] @ abc.dd.aa.com [192.112.111.111] #
> > Query_time: 0.053599 =A0Lock_time: 0.000079 Rows_sent: 1
> Rows_examined:
> > 141145
> > SET timestamp=3D1346409794;
> > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME >=
> > date_sub(now(),INTERVAL 60 MINUTE) and status=3Dupper('failed= ') and
> > ENTITY_NAME=3D'FETL-click-enhancer-deferred';
> > # User@Host: user1[user2] @ abc.dd.aa.com [192.112.111.111] #
> > Query_time: 0.054185 =A0Lock_time: 0.000086 Rows_sent: 1
> Rows_examined:
> > 141145
> > SET timestamp=3D1346409794;
> > select count(ENTITY_NAME) from ALERT_EVENTS where EVENT_TIME >=
> > date_sub(now(),INTERVAL 60 MINUTE) and status=3Dupper('failed= ') and
> > ENTITY_NAME=3D'FETL-ImpressionRC-conversion';
> > # Time: 120831 10:43:22
> > # User@Host: user2[user2] @ abc.dd.aa.com [192.112.111.111] #
> > Query_time: 0.000163 =A0Lock_time: 0.000045 Rows_sent: 1
> Rows_examined:
> > 13
> >
> >
> >
> > I don't =A0understand the query time unit in slow query log b= ecause i
> > expect queries to be logged that takes > 100 s. I tested with = sleep
> > command for 60s , it doesn't logged in slow query log and whe= n i
> sleep
> > for 120 s it logged but i don't why the other queries are log= ging in
> slow log.
> >
> > # Query_time: 120.000259 =A0Lock_time: 0.000000 Rows_sent: 1
> Rows_examined:
> > 0
> > SET timestamp=3D1346443103;
> > SELECT SLEEP(120);
> >
> > And also my slow log is increasing and decided to purge thorogh b= elow
> > command :
> >
> > cat /dev/null > /var/lib/mysql/slow-queries.log
> >
> >
> > Anyone any ideas about this.
> >
> >
> > Thanks
> >
>
>
>
> --
> Thanks
> Suresh Kuna
> MySQL DBA

--20cf306f7d145b934004c8ed451f-- --20cf306f7d145b934404c8ed4521--