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):

CREATE TABLE IF NOT EXISTS `elmah_error` (
  `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 ,
  `TimeUtc` DATETIME NOT NULL ,
  `Sequence` INT(10) NOT NULL AUTO_INCREMENT ,
  `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) )
ENGINE InnoDB DEFAULT CHARACTER SET latin2
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:

DELIMITER //

CREATE PROCEDURE `elmah_GetErrorXml` (
  IN Id CHAR(36),
  IN App VARCHAR(60)
)
NOT DETERMINISTIC
READS SQL DATA
BEGIN
    SELECT  `AllXml`
    FROM    `elmah_error`
    WHERE   `ErrorId` = Id AND `Application` = App;
END//

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)
)
    READS SQL DATA
BEGIN
    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;
END;

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.

Advertisement