I’ve been profiling my app to identify places to improve performance. One of my parts is a XML file loader. I’m seeing some odd issues with the profiler operation when combined with the XMLReader. I’m loading a very large file into my application to stress the system and generate longer duration timings. My code is as follows:
Var oXML As New CStatLoader( oCSW )
oCSW.CurrentFile = File
oXML.Parse( File, True )
oXML.oCSW = Nil
oCSW.RebuildColumnDictionaries
' Now build any ColumnDefinition formulas
For nColumn As Integer = 0 To oCSW.LastColumn
If oCSW.ColDefs( nColumn ).Derived Then
oCSW.ColDefs( nColumn ).oFormula = New FormulaEngine.FormulaClass( oCSW, nColumn, oCSW.ColDefs( nColumn ).Formula )
End If
Next
Overall the process takes about 45 seconds.
StartElement seems to take 27 seconds.
Leaving about 18 seconds, which apparently is used up in the above function. Stepping through the code all of the time taken is actually in the StartElement and EndDocument events. None of the code in the function takes more than a second at best. So is the profiler wrong or am I missing something. I’ve stripped out some of the details inside the StartElement function for clarity.
Hmm… like talking to the the rubber duck I think I may have answered my own question. If the StartElement function I have the following code:
If DateTime.Now.SecondsFrom1970 - LastYield > 0.1 Then
oCSW.LoadFileThread.YieldToNext
LastYield = DateTime.Now.SecondsFrom1970
End If
This is there to allow the main thread to update it’s progress bar. I’m starting to think this is perhaps were the time is going.
Edit: Hmm… maybe not directly, changing the code to the following doesn’t change the time required to run, even though it yields 10 times less often.
If DateTime.Now.SecondsFrom1970 - LastYield > 1.0 Then
oCSW.LoadFileThread.YieldToNext
LastYield = DateTime.Now.SecondsFrom1970
End If
OK, commenting it out entirely doesn’t change the math. Also, confusingly the progress bar on the interface still updates. Which I’m pretty sure it never used to do. XMLReader used to block all threads, has that changed recently?
The Profiler is inconsistent when measuring threads.
See <https://xojo.com/issue/10072> (reported in 2009 - Edit to add: the FB case has comments asking if this behavior has been fixed - it’s been so long that I really can’t say, maybe it was? )
To add confusion, some of the Xojo frameworks do thread yields internally (and are not documented as doing so, nor can you turn off yielding).
We have had rather spicy arguments over this in the past. My point of view: the framework should never yield without it being documented, and if it yields, it should be optional so we can opt out of yielding behavior.
If you are on macOS, then try using the Instruments app (part of Xcode) to do accurate time measurements using the Time Profiler template.
OK, I’m sort of wrong about it yielding. It seems to when in the debugger but not when built to a true application. Perhaps the yield is an artefact of profiling.
OK, there’s some fun. Turning off the profiler makes the code very fast:
With the profiler:
The progress bar works happily without yielding.
It takes 45 seconds to load the file.
Without it:
You must yield to get a progress bar update.
It takes 18 seconds to load the file.
The profiler is still very useful, but shouldn’t be used an a way of timing they true performance of the application. It is great at pointing out how often things are called and how long they take on average. Relatively speaking, as in compared to other things in that run of the code.
It wasn’t that it slows the code down that was the major problem. It was that it didn’t tell me what the overhead was. It would appear the yield that causes the discrepancy.