Thursday 16 December 2010

Ektron: High Indexing Service Processor Usage (Potential) Fix

One of our larger client Ektron sites has had a history of poor performance that always seemed to be related to Indexing immediately after publishing content or syncing content to the live environment.  The site heavily uses indexed smart form fields and indexed metadata fields for ordering/sorting lists of content.

The symptoms were:

  • High CIDAEMON processor usage (95-100% of a processor core)
  • Total Documents to Index in Indexing Service Manager getting stuck
  • Indexing Service ‘Service Too Busy’ exceptions
  • Analysing Crash Dumps of the CIDAEMON process shows the ‘hot’ thread stuck in the QLXFilter.dll module

After performing the basic performance optimisations (removing any unnecessary catalogs such as System and Web) there was no real performance improvements and as more content was added (at quite a high rate) the performance issues quickly became outages.

Fortunately, with support from Ektron, we managed to identify (and fix) the potential cause… a misconfiguration in one of the 3rd Party components the indexing service uses to parse the asset xml files.  This file can be found in:

  • C:\Windows\System32\QLFiltXml.xml
  • C:\Windows\SysWOW64\QLFiltXml.xml (64 bit machines only)

Opening these files in IE (and collapsing to just Top Level nodes) showed the default filters only:

image

There should be a filter for each configured smart form with indexed fields:

image

You can identify which smart form corresponds which filter by checking the ‘Title’ element.

It appears the during the upgrade from v7.6.6->v8.0.1 something went wrong which prevented the Ektron Windows Service from correctly maintaining the configuration file.

Repairing the QLXFilter configuration

The steps to repair the file are fairly straightforward (but make sure Ektron support is at hand for any unforeseen complications!).

  1. Delete all Catalogs from the Indexing Service (via Indexing Service Manager)
  2. Stop the Indexing Service
  3. Ensure that QLXFilter.dll is properly registered.  Open a command prompt and execute
    regsvr32 c:\Windows\System32\QLXFilter.dll
  4. Locate your ‘FriendlyNamesDefinition.txt (check the ‘DefaultColumnFile’ property value of the ‘[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\ContentIndexCommon]’ key) and remove any of the non-standard  columns (indexed smart form fields, etc).

    A list of standard column definitions is:
       1: [Names]
       2: DateCreated (VT_FILETIME) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktDateCreated
       3: DateModified (VT_FILETIME) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktDateModified
       4: GoLiveDate (VT_FILETIME) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktGoLiveDate
       5: ExpiryDate (VT_FILETIME) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktExpiryDate
       6: ExpiryType (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktExpiryType
       7: TaxCategory (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktTaxCategory
       8: ContentID (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktContentID
       9: ContentLanguage (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktContentLanguage
      10: ContentType (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktContentType 
      11: FolderId (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktFolderId
      12: QuickLink (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktQuickLink
      13: FolderName (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktFolderName 
      14: MapLongitude (DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktLongitude 
      15: MapLatitude (DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktLatitude 
      16: MapAddress (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktAddress 
      17: EDescription (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktEDescription 
      18: Keywords (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktKeywords 
      19: Title (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktTitle 
      20: MetaInfo (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktMetaInfo
      21: CMSPath (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktCMSPath
      22: CMSSize (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktCMSSize
      23: InPerm (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktInPerm
      24: Searchable (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktSearchable
      25: description  (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae  Ektdescription
      26: MapDate (VT_FILETIME) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktMapDate
      27: ContentID64 (DBTYPE_I8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktContentID64
      28: FolderId64 (DBTYPE_I8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktFolderId64
      29: EProductType (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktProductType
      30: ESkuNumber(DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktSkuNumber
      31: ESizeMeasure (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktSizeMeasure
      32: EHeight(DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktHeight
      33: EWidth(DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktWidth
      34: ELength(DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktLength
      35: EWeight(DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktWeight
      36: EWeightMeasure (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktWeightMeasure
      37: EUnitsInStock (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktUnitsInStock
      38: EUnitsOnOrder (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktUnitsOnOrder
      39: EReorderLevel (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktReorderLevel
      40: EPurchased (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktPurchased
      41: EImage(DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktImage 
      42: ECurrencyId (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktCurrencyId 
      43: EListPrice (DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktListPrice 
      44: ESalePrice (DBTYPE_R8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktSalePrice 
      45: EBuyable (DBTYPE_I4) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktBuyable 
      46: xmlconfigid (DBTYPE_I8) = d5cdd505-2e9c-101b-9397-08002b2cf9ae Ektxmlconfigid
      47: DisabledTaxCategory (DBTYPE_WSTR | DBTYPE_BYREF) = d5cdd505-2e9c-101b-9397-08002b2cf9ae EktDisabledTaxCategory
  5. Run the Ektron ‘SearchConfigUI’ utility to ‘Create New Catalogs’ (after checking all the settings are correct). 
  6. Once ‘SearchConfigUI’ has passed the ‘Updating XML Configuration for XML Content’ step then you can ensure that:
    1. The QLFiltXml.xml file to ensure the correct filters have been installed
    2. The FriendlyNamesDefinition.txt to ensure that your indexed properties have been restored
  7. Once ‘SearchConfigUI’ has completed then you should be able to monitor the Indexing Service scanning the files in a more reasonable and consistent manner

The performance issue should now be fixed/reduced, hope this helps.

Thursday 18 November 2010

EKTRON: Diagnosing 8.0 Extension Strategy Loading Failures

I’ve recently hit a problem with deploying  Ektron Extensions (the 8.0 replacement for Plugins), essentially every time my Extension ‘Strategy’ was called the workarea would display an error similar to:

Value cannot be null. Parameter name: type

Fortunately, in the Application Event log (for the CMS400 Source) there’s a bit more information:

   1: Timestamp: 18/11/2010 18:43:01
   2: Message: Could not load the MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring.UserMonitoringStrategy, MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring implementation from the configuration file
   3: Category: Error
   4: Priority: -1
   5: EventId: 0
   6: Severity: Error

This shows that the declaration in the web.config is correct:

   1: <objectFactory>
   2:     <objectStrategies>
   3:         <add name="User">
   4:             <strategies>
   5:                 <add name="UserMonitoringStrategy"
   6:                          type="MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring.UserMonitoringStrategy, MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring"/>
   7:             </strategies>
   8:         </add>
   9:     </objectStrategies>
  10:     <objectImplementations>
  11:     </objectImplementations>
  12: </objectFactory>

Fortunately, the next logged error reveals another vital clue:

   1: Timestamp: 18/11/2010 18:43:22
   2: Message: Exception thrown from: /WorkArea/login.aspx
   3: Value cannot be null.
   4: Parameter name: type   at System.Activator.CreateInstance(Type type, Boolean nonPublic)
   5:    at Ektron.Cms.ObjectFactory.GetStrategyList[T](String objectName)
   6:    at Ektron.Cms.User.EkUser.get_StrategyList()
   7:    at Ektron.Cms.User.EkUser.OnBeforeLogin(UserData userData)
   8:    at Ektron.Cms.User.EkUser.logIn(String username, String Password, String ServerName, String Domain, String Protocol, Boolean autologin, AutoAddUserTypes AutoAddType, Boolean ForceLogin)    at System.Activator.CreateInstance(Type type, Boolean nonPublic)
   9:    at Ektron.Cms.ObjectFactory.GetStrategyList[T](String objectName)
  10:    at Ektron.Cms.User.EkUser.get_StrategyList()
  11:    at Ektron.Cms.User.EkUser.OnBeforeLogin(UserData userData)
  12:    at Ektron.Cms.User.EkUser.logIn(String username, String Password, String ServerName, String Domain, String Protocol, Boolean autologin, AutoAddUserTypes AutoAddType, Boolean ForceLogin)
  13: Last 1 events
  14: [EventName]: [Timestamp] - ([UserID],[VisitorID])
  15: OnBeforeUserLogin: 18/11/2010 18:43:01 - (0, b7461b16-72f8-4631-b180-29e128d87184)
  16:  
  17: Category: Error
  18: Priority: -1
  19: EventId: 0
  20: Severity: Error

The reference to ‘Activator’ means that the issue is the .Net cannot find the referenced strategy through the type description.

This is a bit puzzling as the declaration is correct, so I need a bit more information on what’s causing the problem and why I can’t see it in the log, so that means  breaking out Reflector and digging into the API.  Fortunately, the problem method (GetStrategyList<T>) is easy to find and fairly simple to understand.  Here’s the code that’s failing:

   1: try
   2: {
   3:     type = Type.GetType(element2.Type, true);
   4: }
   5: catch (TypeLoadException)
   6: {
   7:     EkException.WriteToEventLog(string.Format("Could not load the {0} implementation from the configuration file", element2.Type), EventLogEntryType.Error);
   8: }
   9: strategy = (T) Activator.CreateInstance(type);    

Essentially, the first log entry is written in response to the actual problem (but doesn’t record it!) and the second, more detailed error is caused by the failure to assign the type variable.

What we really need to get hold of is the original TypeLoadException and capture the reason for the failure. There are two ways to do this:

  1. You could use the Visual Studio Exceptions dialog (Debug->Exceptions and check the ‘Thrown’ checkbox for System.TypeLoadException under ‘Common Language Runtime Exceptions) and use the debugger to inspect the error:image
  2. Create a test bed report to reproduce the strategy loading procedure with an increased amount of logging

My first brush attempt was using Option 1, but I found that it was a bit unreliable and would be limited to debugging my development machine.  The second option is more work, but is reusable and direct.  My weapon of choice for this type of report is a custom HttpHandler which can be added/removed through a simple configuration change:

   1: using System;
   2: using System.Configuration;
   3: using System.Web;
   4: using global::Ektron.Cms;
   5:  
   6: namespace MartinOnDotNet.Helpers.Ektron.Extensibilty
   7: {
   8:     /// <summary>
   9:     /// Diagnostic handler to test loading Extensions
  10:     /// </summary>
  11:     public class ValidateStrategiesHandler : IHttpHandler
  12:     {
  13:  
  14:         /// <summary>
  15:         /// Enables processing of HTTP Web requests by a custom HttpHandler that implements the <see cref="T:System.Web.IHttpHandler"/> interface.
  16:         /// </summary>
  17:         /// <param name="context">An <see cref="T:System.Web.HttpContext"/> object that provides references to the intrinsic server objects (for example, Request, Response, Session, and Server) used to service HTTP requests.</param>
  18:         public void ProcessRequest(HttpContext context)
  19:         {
  20:             context.Response.ContentType = "text/plain";
  21:             System.IO.TextWriter output = context.Response.Output;
  22:             output.WriteLine("Configured Extension Strategy Test\n");
  23:             ObjectFactorySection factorySection = (ObjectFactorySection)ConfigurationManager.GetSection("objectFactory");
  24:             foreach (ObjectStrategyConfigElement strategies in factorySection.ObjectStrategies)
  25:             {
  26:                 output.WriteLine("{0} (found {1})", strategies.Name, strategies.Strategies.Count);
  27:                 foreach (StrategyConfigElement strategy in strategies.Strategies)
  28:                 {
  29:                     RenderStrategyLoadingOutcome(output, strategy);
  30:                 }
  31:             }
  32:             output.WriteLine("\nLoaded Assemblies");
  33:             foreach (System.Reflection.Assembly ass in System.AppDomain.CurrentDomain.GetAssemblies())
  34:             {
  35:                 output.WriteLine(ass.FullName);
  36:             }
  37:  
  38:         }
  39:  
  40:         [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1804:RemoveUnusedLocals", MessageId = "type")]
  41:         private void RenderStrategyLoadingOutcome(System.IO.TextWriter output, StrategyConfigElement strategy)
  42:         {
  43:             output.Write("\t{0,-20}\t{1,-40}\t", strategy.Name, strategy.Type);
  44:             try
  45:             {
  46:                 Type type = Type.GetType(strategy.Type, true);
  47:                 Type baseType = type.BaseType;
  48:                 output.WriteLine("{0}\tOK!", baseType.Name);
  49:             }
  50:             catch (Exception tle)
  51:             {
  52:                 output.WriteLine("Failed! ({0}:{1})", tle.GetType().Name, tle.Message);
  53:                 System.Diagnostics.Trace.TraceError("Failed to Load Strategy '{0}'\n{1}", strategy.Type, tle.ToString());
  54:             }
  55:         }
  56:  
  57:        /// <summary>
  58:        /// Gets a value indicating whether another request can use the <see cref="T:System.Web.IHttpHandler"/> instance.
  59:        /// </summary>
  60:        /// <value></value>
  61:        /// <returns>true if the <see cref="T:System.Web.IHttpHandler"/> instance is reusable; otherwise, false.
  62:        /// </returns>
  63:        public bool IsReusable
  64:        {
  65:            // Return false in case your Managed Handler cannot be reused for another request.
  66:            // Usually this would be false in case you have some state information preserved per request.
  67:            get { return true; }
  68:        }
  69:     }
  70: }

This can simply be registered in the system.webServer/handlers section of the web.config (assuming IIS 7 and Integrated Pipeline):

   1: <add name="Verify Strategy Handler"
   2:      verb="GET"
   3:      path="secure/validatestrategies.ashx"
   4:      type="MartinOnDotNet.Helpers.Ektron.Extensibilty.ValidateStrategiesHandler"
   5:      preCondition="integratedMode,runtimeVersionv2.0" />

This report can now be called using /secure/validatestrategies.ashx">http://<website>/secure/validatestrategies.ashx and will render a report similar to:

   1: Configured Extension Strategy Test
   2:  
   3: Content (found 1)
   4:     LoggingStrategy          MartinOnDotNet.Helpers.Ektron.Extensibilty.LoggingContentStrategy, MartinOnDotNet.Helpers.Ektron    ContentStrategy    OK!
   5:  
   6: User (found 1)
   7:     UserMonitoringStrategy    MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring.UserMonitoringStrategy, MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring    Failed! (TypeLoadException:Could not load type MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring.UserMonitoringStrategy' from assembly MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring'.)
   8:  
   9: Loaded Assemblies
  10: ** Ommitted as there's hundreds **

With the full exception logged to Trace.  

What the report immediately showed was that the Extensions that had worked were in assemblies that were listed in the ‘Loaded Assemblies’ report.  The ones that failed weren’t.

This is odd as the library was definitely in the websites /bin folder, and a little more digging and investigation revealed that the one of the class libraries dependencies couldn’t be resolved correctly due to version number mismatch.  When that was fixed, the Strategies were loaded as expected!  Result.

   1: Configured Extension Strategy Test
   2:  
   3: Content (found 1)
   4:     LoggingStrategy          MartinOnDotNet.Helpers.Ektron.Extensibilty.LoggingContentStrategy, MartinOnDotNet.Helpers.Ektron    ContentStrategy    OK!
   5: User (found 1)
   6:     UserMonitoringStrategy    MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring.UserMonitoringStrategy, MartinOnDotNet.Helpers.Ektron.Extensions.Monitoring    UserStrategy    OK!
   7:  
   8: Loaded Assemblies
   9: ** Ommitted as there's hundreds **

Hopefully, this report/test bench handler will help others with similar issues.