How MySQL auto log can help performance related troubleshooting?

We are heavily dependent on ORM (Object Relational Mapping ) frameworks for application development. Hibernate is a popular ORM in the Java realm where as ActiveRecords in Ruby in Rails support inbuilt ORM capability.  Many times developer depends only on ORM and use it for all purposes, without trying to understand the advantages and its disadvantages, where to use  and where not to use etc.

Many times developers who are addicted to ORM also believes that it is not necessary to know SQL as it will be taken care by ORM. Those who fall in this trap will create applications which will fire queries unnecessarily.  Most common pitfall I noticed is the tendency of the developer to use database as a local variable.  What I meant is when we use “object1.object2.name” in ORM,  it can (not always) result in generating multiple queries to fetch the information.

Recently one of our application after a release started raising performance issues in production. We are using NewRelic and it really helped us to identify the hotspots. However NewRelic can provide the count of SQL queries and Queries in prepared state (with no actual parameter values). For example NewRelic will only highlight that the query “select * from department where city = ?” is fired 50 times during the execution of a method. It never tells what are the parameters used in 50 calls. However this information from NewRelic itself will help the development team to work on the hotspots.

I was looking for an option to identify the actual queries that are getting fired during the execution of each module in the application. I need all the queries with actual parameter values. We were using MySQL and on checking the documentation I noticed an option for “auto log”.  Enabling this feature can help to log all queries an application is firing in a log which can be later extracted as a SQL statement for performance analysis and further optimization.

Here are the steps one need to do to extract the SQLs fired during the execution of an application module in MYSQL database.

Steps

[1]  SET GLOBAL general_log=’on’;  // Turn on the general_log 

[2] set GLOBAL log_output=’table’; //  Make sure that log is written to a table, so that it can be extracted using SQL.

[3] Unfortunately there is no primary key in the log table. So you need to note down the last event time. So get the last even time recorded in the log.

[code]

select event_time from mysql.general_log order by event_time desc limit 1;

[/code]

 Result

| event_time          |

| 2012-10-27 12:42:23|

[4] Now perform the test in the application. make sure you use a unique user name for the application to connect to MYSQL. This will really help us to extract the correct result from log table.

[5] Use the following query to extract the queries fired by the application during the test

[code]

select event_time,command_type,argument from mysql.general_log

where command_type in (‘Query’,’Execute’) and event_time > ‘2012-10-27 12:42:23’

and user_host like  ‘app_user%’ order by event_time asc
[/code]

In the above example “app_user” is the MYSQL user name used to connected to the database.

The above query will return all the queries that are fired from the application to MYSQL database during the execution of a particular module.

Once this information is obtained we can use it fr performance analysis and improvement.

[6] Once the queries are identified , turn off the logging as I believe it is expensive.

SET GLOBAL general_log=’off’;  // Note sure this will turn off. This is a guess work

 

Hope this will really help the developers who are using ORM heavily to optimize the SQL queries used in the application.

Posted in: Database, Programming

Leave a Comment