Import catalog: beware of warning messages

Recently I worked with a support case from a customer. They complained that the catalog import is too slow for them, it took them 6-7 minutes to import 200 entries. Their catalog is about 50k entries, which is not particularly big, but not small neither, and with that rate, it does mean they will have to wait for days for the catalog imported. This is of course not good and I jumped in when I became available. (In the end, I like performance tuning so much that I find it hard to refuse a case like this)

I did try to import their catalog on my development machine – a relatively powerful desktop with Intel Core i7 4790 CPU, 16GB of RAM and 256GB SSD on Windows 10/.NET 4.5.2. Everything went quite well – I achieved a rate of 200 entries per 9-10 seconds, which is, IMO, more than enough. (And this is on Commerce 9, on Commerce 8 then I would suspect it’s 3-4 times slower).

After some conversations with Episerver’s developer support team, it seems that the slowdown only happens with the re-import. I tried it again with re-import. Hmm, something is wrong here. The import is much slower and it eventually stops at some points. The debugger shows that it starts quite well, even faster than a new import (200 entries per 3-4 seconds, a very recent version of Commerce made an improvement of skipping the entries which are not changed to speed up the import), but it slows down by time. Profiling does not show anything obvious, most of the time was spent with loading the MetaObject:s – which is kind of expected.

I was starring at the import tab, and wondering what can be wrong, and suddenly I realized the answer is what I was looking at:

That’s it. When you import a catalog with override, everytime you import an entry, the import will add a warning to your log. When you have a small number of entries, it should be OK. But when you have a sizable amount of entries, it can be a problem. Not just the warnings themselves take up memory in the server, they are transferred back and forth between the server and the browser every time the control above is refreshed. Open up the Browser console, and I saw that 4.4MB was transferred each time, and raised up to 5.5MB some minutes later. At some points, it reached the limit and IIS stops processing the request, with this error (in the log):

System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.Web.HttpException (0x80004005): Maximum request length exceeded.

Now we know the problem, the solution should be easy. I did try to disable the code which adds warnings into the log, and it seems to work much better now:

So you will ask – how can you do if you are in same scenarios. Of course you don’t have the luxury of modifying Episerver code directly – but you can do something else. Skip the catalog import tab in Commerce Manager and write a small import function with ImportJob directly:

var importJob = new ImportJob(AppContext.Current.ApplicationId, CatalogPackagePath, "Catalog.xml", true);
Action<IBackgroundTaskMessage> addMessage = msg =>
 {
     if (msg.MessageType == BackgroundTaskMessageType.Warning && msg.Message.Contains("Overwriting"))
     {
         return;
     }
     var isError = msg.MessageType == BackgroundTaskMessageType.Error;
     var percent = (int)Math.Round(msg.GetOverallProgress() * 100);
     var message = msg.Exception == null
         ? msg.Message
         : string.Format("{0} {1}", msg.Message, msg.ExceptionMessage);
     _progressMessenger.AddProgressMessageText(message, isError, percent);
 };
 importJob.Execute(addMessage, CancellationToken.None);

where _progressMessenger is a simple implementation of IProgressMessenger, like this:

private class WebProgressMessenger : IProgressMessenger
{
    public string Progress { get; private set; }
    public int CurrentPercentage { get; private set; }
 
    public void AddProgressMessageText(string message, bool error, int percent)
    {
        var timeStamp = string.Format("{0:T}", DateTime.Now);
        CurrentPercentage = percent > 0 ? percent : CurrentPercentage;
        Progress = timeStamp + " : " + message + "<br />" + Progress;
    }
}

Now you can import your “big” catalog with overwrite without worrying about it will slow your site down, or even end up in error.

This is of course something Episerver should look into to make the import control configurable in such cases.

UPDATE: This was registered as http://world.episerver.com/support/Bug-list/bug/COM-1426 and should be fixed in upcoming Commerce 9.12 release. If you’re on 9.12 or later, ignore the trick above.