Quadratic runtime for Delphi XML (MSXML) routines

Question

At work, we're using a XML log file. Each log message is a <message> block with <date> and <time> subnodes, there are <submessage> blocks, <table> constructs and so on and the log file can be transformed to a localized HTML using some Delphi processing and XSLT later.

For medium sized log files (around 2 MB), we got performance problems (up to a minute for loading the XML and doing some basic manipulations) and I could reduce them to a test project like this (EDIT: Updated the code and added measurements):

procedure TForm1.PrepareTest(MessageCount : integer);
var
  XML : IXMLDocument;
  i : integer;
begin
  XML := NewXMLDocument;
  XML.DocumentElement := XML.CreateNode('root');
  for i := 1 to MessageCount do
  begin
    XML.DocumentElement.AddChild('message').Text := 'Test Text';
  end;
  XML.SaveToFile(XML_NAME);
end;

procedure TForm1.XMLTest;
var
  StartTime : Cardinal;
  XML : IXMLDocument;
begin
  StartTime := GetTickCount();
  XML := NewXMLDocument;
  XML.LoadFromFile(XML_NAME);
  Memo1.Lines.Add('Node count: ' + IntToStr(XML.DocumentElement.ChildNodes.Count));
  Memo1.Lines.Add('Time: ' + FloatToStr((GetTickCount() - StartTime) / 1000) + ' seconds');
end;

This results in the following time measurements (node count is increased by 25% per column, all times in milliseconds):

Node count      8000    10000   12500   15625   19531   24413   30516   38145   47681
Base test time  484     781     1140    1875    2890    4421    6734    10672   16812
Variation 1                             32      47      62      78      78      141
Variation 2     2656    3157    3906    5015    6532    8922    12140   17391   24985
  (delta Base)   2172    2376    2766    3140    3642    4501    5406    6719    8173

Note the two variations, the first is LoadFromFile only and the second one is additionally adding 10000 more nodes to the beginning (!) of the XML like PrepareTest does, which is worst case but looking at the delta to the base test, even this doesn't show quadratic effects. Also note that counting the nodes can be replaced with any other operation, so it looks like there is some delayed initialization/validation of the XML file involved that causes the problem and any manipulation afterwards shows expected behaviour.

Memory usage is not high, the last test case (47681 nodes) has a peak memory usage of 39 MB, its XML filesize is 1.3 MB.

The first thing that is done after loading the XML (e.g. reading or writing some nodes or accessing node count) is slow and it shows quadratic runtime behaviour, so any log file above 10 MB is unusable.

We already solved the performance problems along with some other things by parsing small chunks of 100 messages, and I'm aware that the Delphi XML routines are not suited/overkill for this use case - using a different XML library would most likely stop the performance problems. So I'm not asking for a solution for the problem (although it would be interesting to know if the problem can be solved without using a different XML library).

My question is: What is the reason for the quadratic runtime behaviour of the Delphi XML routines, respectively MSXML? I can't imagine things that would lead to this in XML loading/parsing/validating, besides really "stupid" things like managing the nodes in a linked list instead of a tree, but I might be overlooking something, perhaps DOM related.

Answer 1

I agree with mj2008 that XML isn't a good fit for logging. That said, this problem and large XML files in general, could get processed faster by using SAX, it throws events while parsing the incoming stream of XML data, which lets you process the items as they are read from disk, in effect mitigating the exponentiality of loading it all in memory before handing it to XSLT.

I regret I have not done SAX in Delphi (yet), but I suspect the hardest part is implementing the required SAX interfaces (e.g. ISAXContentHandler), but Delphi has TInterfacedObject and TAutoObject and other just for that.

Answer 2

Your question in a nutshell: Why is the binary library MSXML so slow? Who knows. Who cares. Are you going to disassemble it? Break into Microsoft and grab its source code? This isn't Delphi here, this is microsoft code.

While XML is a bad choice for logging, OmniXML is probably a better choice than MSXML.

However, a far better choice is called "open text file for append, write line, close text file". Notice the inherent scalability, and the lack of parsing required.

Answer 3

Contrary to the comments of others, I think XML is an excellent format for logging. The Delphi VCL wrappers for XML are very core memory greedy, so this may explain the poor performance of pure TXMLDocument processing at scale.

I would instead recommend posting to your XML log by using a simple XSLT transform. I haven't measured the performance of this solution at scale, but I believe it will be a vast improvement over what you are currently reporting.

The style-sheet.

For example, suppose our log looks something like this...

<log>
  <message>This is the first message<message/> 
</log>  

This simple XSLT 1.0 style-sheet, with parameter addend-message ...

<xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform">
<xsl:output indent="yes" omit-xml-declaration="yes" />
<xsl:strip-space elements="*" />  
<xsl:param name="addend-message" select="''" />

<xsl:template match="@*|node()">
  <xsl:copy>
    <xsl:apply-templates select="@*|node()" />
  </xsl:copy>
</xsl:template>  

<xsl:template match="log">
  <xsl:copy>
    <xsl:apply-templates select="@*|node()" />
    <message><xsl:value-of select="$addend-message" /></message>
  </xsl:copy>
</xsl:template>  

... will append a message to the log.

The language binding

To achieve this in Delphi, use the following declarations...

ITransform = interface
  procedure AddParameter( const sParamBaseName, sParamValue, sNamespaceURI: string);
  procedure Transform;
  property  InputDocumentFileName : string;
  property  OutputDocumentFileName: string;
end;

function MS_Transform( const sStylesheet: string): ITransform;

Create an ITransform, passing in the stylesheet as a string. Set both filename properties to the filename of the log. Every time you need to add a message to the log, call AddParameter() and then Transform().

Solution implementation details

One possible implementation for the aforementioned language binding might be ...

uses XMLIntf, msxml, msxmldom, sysutils;

type
  ITransform = interface
    ['{1004AE9A-D4AE-40E1-956D-AD98801AF7C1}']
      procedure SetInputDocumentFileName ( const sValue: string);
      procedure SetOutputDocumentFileName( const sValue: string);
      procedure AddParameter( const sParamBaseName, sParamValue, sNamespaceURI: string);
      procedure Transform;

      property InputDocumentFileName : string    write SetInputDocumentFileName;
      property OutputDocumentFileName: string    write SetInputDocumentFileName;
    end;

    TMS_XSLT = class( TInterfacedObject, ITransform)
    private
      FStylesheet: IXSLTemplate;
      FStylesheetAsDoc: IXMLDOMDocument2;
      FInputFN, FOutputFN: string;
      FProcessor: IXSLProcessor;;

      procedure SetInputDocumentFileName ( const sValue: string);
      procedure SetOutputDocumentFileName( const sValue: string);
      procedure MakeProcessor;

    publc
      constructor Create( const sStylesheet: string);
      procedure AddParameter( const sParamBaseName, sParamValue, sNamespaceURI: string);
      procedure Transform;

      property InputDocumentFileName : string    write SetInputDocumentFileName;
      property OutputDocumentFileName: string    write SetInputDocumentFileName;
    end;

  function MS_Transform( const sStylesheet: string): ITransform


function MS_Transform( const sStylesheet: string): ITransform
begin
result := TMS_XSLT.Create( sStylesheet)
end;

constructor TMS_XSLT.Create( const sStylesheet: string);
begin
  FStyleSheet := msxml.CoXSLTemplate60.Create;
  FStylesheetAsDoc := msxml.CoFreeThreadedDOMDocument60.Create;
  FStylesheetAsDoc.loadXML( sStyleSheetContent);
  FStylesheet.stylesheet := FStylesheetAsDoc  
end;

procedure TMS_XSLT.MakeProcessor;
begin
if not assigned( FProcessor) then
  FProcessor := FStylesheet.createProcessor
end;

procedure TMS_XSLT.SetInputDocumentFileName( const sValue: string);
begin
FInputDoc := sValue
end;

procedure TMS_XSLT.SetOutputDocumentFileName( const sValue: string);
begin
FOutputDoc := sValue
end;

procedure TMS_XSLT.AddParameter( const sParamBaseName, sParamValue, sNamespaceURI: string);
begin
MakeProcessor;
FProcessor.addParameter( sParamBaseName, sParamValue, sNamespaceURI)
end;

procedure TMS_XSLT.Transform;
var
  Doc: TXMLDocument;
  DocIntf: IXMLDocument;
  oXMLDOMNode: IXMLDOMNodeRef;
  sOutput: string;
begin
MakeProcessor;
try
  Doc  := TXMLDocument.Create( nil);
  Doc.Options := [doNodeAutoCreate, doNodeAutoIndent, doAttrNull, doAutoPrefix, doNamespaceDecl];
  Doc.DOMVendor := GetDOMVendor( 'MSXML');
  DocIntf := Doc;
  DocIntf.LoadFromFile( FInputFN);
  DocIntf.Active := True;
  if Supports( DocIntf.Node.DOMNode, IXMLDOMNodeRef, XMLDOMNode) then
    FProcessor.input := XMLDOMNode.GetXMLDOMNode;
  FProcessor.transform;
  while oProcessor.readyState <> 4 do sleep(1);
  sOutput := FProcessor.output;
  if sOutput = '' then exit;
  WriteToFile( sFOutputFN, sOutput);
  // Alternate way..
  //  Doc  := TXMLDocument.Create( nil);
  //  Doc.Options := [doNodeAutoCreate, doNodeAutoIndent, doAttrNull, doAutoPrefix, doNamespaceDecl];
  //  Doc.DOMVendor := GetDOMVendor( 'MSXML');
 //   DocIntf := Doc;
  //  DocIntf.LoadFromXML( sOutput);
  //  DocIntf.Active := True;
  //  DocIntf.SaveToFile( FOutputFN)
finally
  FProcessor := nil
  end
end;

This binds to Microsoft's MS XML library and XSLT engine. Regrettably, I do not know of any convenient way to bind Saxon's XSLT processor to Delphi code.

Alternative implementation

An alternative implementation for leveraging MS's XSLT engine is given by my answer here. The disadvantage of this method is that parameterisation is not native. To parameterise the style sheet, your would have to roll your own, by doing a string replace on the stylesheet before transformation.

Performance considerations

If you are doing a lot of logging quickly, it may be a good strategy to cache messages to be logged in memory, and then at regular but not too frequent intervals, purge your cache with a single XSLT transform to write all your messages.

Answer 4

Are you using the term "exponential" in a mathematical sense, or just in a popular sense? It would be interesting to know for example whether it's really quadratic, or whether it's some kind of function where the performance is fairly linear until you hit some threshold (memory size) at which point it suddenly degrades.

If it's taking a minute to process 2Mb then something is very badly wrong indeed. I don't know your environment well enough to start making guesses, but this should take at most a second. You need to drill down to find where the time is going. Start by establishing whether it's spending its time parsing the XML, or processing the XML after parsing is complete.