Diagnosing a collation issue in a MySql stored procedure

We are using Elmah on production to log problems in our web applications. Elmah logs are stored in a MySql table which structure is a slightly modified version of the elman_error table from the original Elmah script (I changed the engine to InnoDB and added partitioning over TimeUTC column):

  `ErrorId` CHAR(36) NOT NULL ,
  `Application` VARCHAR(60) NOT NULL ,
  `Host` VARCHAR(50) NOT NULL ,
  `Type` VARCHAR(100) NOT NULL ,
  `Source` VARCHAR(60) NOT NULL ,
  `Message` VARCHAR(500) NOT NULL ,
  `User` VARCHAR(50) NOT NULL ,
  `StatusCode` INT(10) NOT NULL ,
  `AllXml` TEXT NOT NULL ,
  PRIMARY KEY (`Sequence`, `TimeUtc`) ,
  INDEX `IX_ErrorId` (`ErrorId`(8) ASC) , -- UNIQUE can't be created if it does not include all partition columns
  INDEX `IX_ELMAH_Error_App_Time_Seql` (`Application`(10) ASC, `TimeUtc` DESC, `Sequence` DESC) ,
  INDEX `IX_ErrorId_App` (`ErrorId`(8) ASC, `Application`(10) ASC) )
partition by range columns(`TimeUtc`)
  partition before20130719 values less than ('2013-07-19 00:00')

Notice also that the default collation is set to latin2 (we sometimes have Polish characters in our logs). We also have a diagnostics dashboard – a simple web application that allows developers to check the Elmah.axd console for each of our applications (I described how it’s configured in another post). When logs got bigger (few daily partitions) the error details screen started to load extremely slowly, sometimes it was even throwing a timeout exception. That was really surprising, especially if you look at the page url which contained an id of the error to show (thus the primary key in the above table). During one of those waits I found the query that was causing the delay:

> select * From information_schema.processlist

SELECT  `AllXml`
    FROM    `elmah_error`
    WHERE   `ErrorId` =  NAME_CONST('Id',_utf8'dd79443e-f7a2-4d45-abff-a57710016f45' COLLATE 'utf8_unicode_ci') AND `Application` =  NAME_CONST('App',_utf8'SomeApp' COLLATE 'utf8_unicode_ci')

EXPLAIN on this query clearly shows the optimizer is not using the IX_ErrorId_App index (or even IX_ErrorId):

id select_type table type possible_keys key key_len ref rows Extra
1 SIMPLE elmah_error ALL (NULL) (NULL) (NULL) (NULL) 2 Using where

I also wasn’t sure why Elmah wrapped each parameter into a NAME_CONST function. I checked Elmah source code only to find out that it is simply calling elmah_GetErrorXml procedure:

// Elmah.MySqlErrorLog.Commands
public static MySqlCommand GetErrorXml(string appName, Guid id)
  MySqlCommand mySqlCommand = new MySqlCommand("elmah_GetErrorXml");
  mySqlCommand.CommandType = CommandType.StoredProcedure;
  MySqlParameterCollection parameters = mySqlCommand.Parameters;
  parameters.Add("Id", MySqlDbType.String, 36).Value = id.ToString();
  parameters.Add("App", MySqlDbType.VarChar, 60).Value = appName.Substring(0, Math.Min(60, appName.Length));
  return mySqlCommand;

The stored procedure does not seem suspicious either:


CREATE PROCEDURE `elmah_GetErrorXml` (
  IN Id CHAR(36),
  IN App VARCHAR(60)
    SELECT  `AllXml`
    FROM    `elmah_error`
    WHERE   `ErrorId` = Id AND `Application` = App;

With no one to blame I started googling and find out that it’s MySql that wraps all parameters used inside a stored procedure into NAME_CONST calls. Another interesting fact is that it also specifies collations for strings (treating strings coming from .NET connector as UTF8). When index key values have different collations than parameters in the where condition, MySql is not able to use index and needs to perform a full scan. In our case an easiest working solution was to modify the elmah_GetErrorXml procedure and force it to use a valid collation:

DROP PROCEDURE IF EXISTS DiagnosticsDB.elmah_GetErrorXml;
CREATE PROCEDURE DiagnosticsDB.`elmah_GetErrorXml`(
  IN Id CHAR(36),
  IN App VARCHAR(60)
    SELECT  `AllXml`
    FROM    `elmah_error`
    WHERE   `ErrorId` = convert(Id using latin2) collate latin2_general_ci AND `Application` = convert(App using latin2) collate latin2_general_ci;

You may also specify UTF8 as a default collation for your elmah_error table – this would be probably even a better solution. To summarize, if you ever encounter lags in your stored procedure calls, make sure that parameters are correctly wrapped by MySql and valid indexes are used. For this purpose you may use a simple SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST query or setup a slow query log.

7 thoughts on “Diagnosing a collation issue in a MySql stored procedure

  1. Federico August 9, 2013 / 13:29

    Thanks for the article, very informative. I have one question, thought: why does Elah use a stored procedure to run a single query?

    • Sebastian Solnica August 9, 2013 / 15:00

      It seems more like a question to Elmah authors 🙂 Sometimes people use stored procedures to have one more abstraction layer in data access (or better security control). In my case thanks to this approach I didn’t need to change Elmah source code to force the collation. Though I normally would use a single query rather than a stored procedure.

      • Federico August 9, 2013 / 15:56

        When you use:
        SELECT … WHERE field=’string’;
        SET @x=’string’;
        …’string’ is encoded with @@session.character_set_connection and @@session.collation_connection. So if you only use latin-2 for your tables/columns, you can change those variables to make your queries use latin-2 and the proper collation, and you don’t need to change anything in the code.
        I hope this helps 🙂

      • Sebastian Solnica August 9, 2013 / 16:02

        Oh, I didn’t know that. Thanks – I will save it for a future queries 🙂

  2. g0rski October 15, 2013 / 08:01

    Awesome. I have to check my code coz there is a big possibility that the same issue timing out my queries 🙂

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )


Connecting to %s