Performance issues when lots of silent exceptions are raised

[obones]

Hello,

We are using madExcept version 4.0.12 on all our recent applications, under Delphi XE7.
We have one "old" application that stayed in D2007 and madExcept 3.0k until recently where we migrated it to Delphi XE7
We suddenly experienced strong performance issues in one part of the application where run time when from 30 seconds to over 6 minutes.
Using a sampling profiler, I found out that 60% of that time is spent in calls to ntdll.dll functions that originate from madTools.FindModule method.
Removing any trace of madExcept usage allowed to come back to the original runtime, at the expense of not having any bugreport facility.
So, debugging it, I saw that those calls come from MadException.Destroy which seemed odd at first because the breakpoint I put inside MadException.Create never got stopped upon.
But I soon realized that this was because Exception.Destroy is hooked by madExcept and replaced by MadException.Destroy.
Further research lead me to discover that commenting out the call to CleanupStackInfoProc gives back normal run times.
And so my quest continued onto what's inside OnExceptionCleanupStack especially the call to IsValidException
I could not remove it altogether as it crashed the application quickly after startup but analyzing it lead me to remove the following elements from the assignment:

IsValidObject(exceptObject)
(IsClass(exceptObject, 'MadException') or IsClass(exceptObject, 'Exception'))

Those were clearly the culprits and I could not find any issue by removing them.
However, it felt weird, so I went a bit further to analyze what they are doing. As it turns out, IsValidObject and IsClass both call IsValidObjectEx which means that there are three calls to IsValidObjectEx on the same exceptObject. One of these could be avoided by putting Exception in front of MadException in the or clause because it's the most likely case.
But inside the IsValidObjectEx, there is another issue. It always calls IsValidObject2 twice because with XE7, it's always the newSelfPtr that should be used.
And that's the IsValidObject2 that is calling FindModule that in turns calls GetModuleFileNameW which is a lengthy API call followed by a very costly call to WideToAnsiEx. It is costly because the length is already returned by GetModuleFileNameW and also because it converts back to ANSI.
Wouldn't it be easier and faster to always call GetModuleFileNameA ? At least it would save calls to GetVersion and to WideToAnsiEx

Now, all these add up to a quite significant delay on every single exception raised, which normally, is no big deal because raising an exception is a rare event.

Unfortunately in our case, we are using a third party library (PAXCOMPILER) that uses exceptions as its normal behavior. They all inherit from EAbort and are trapped by PAXCOMPILER itself before going further out.
This means that we are suffering from a delay that has no point at all for us because the exception will never ever trigger madExcept exception dialog.

Modifying PAXCOMPILER so that it does uses exception on a routine basis is not an option, it's really too difficult. Getting rid of it completely is also a very difficult solution, albeit more probable in the long run.

But in the end, would there be an option somewhere in madExcept that we could turn on so that EAbort exceptions (or derived exceptions from it) are completely excluded from the hook mechanism?

[madshi]

This is a difficult topic. Let me drop some comments first:

1) I've recently had another customer complaining about performance problems in the exact same situation as yours. Well, the other customer didn't use PAXCOMPILER, but had lots of "silent exceptions" in his own code. So at the time I did some of the same analyzation you did. In my research I found that the biggest performance hog by far was the call to "VirtualQuery()". That cost much more time in my tests that GetModuleFileW or AnsiToWideEx. Unfortunately the call to VirtualQuery can't really be avoided. It's necessary to avoid crashes which otherwise might (in rare situations) occur when madExcept is asked to handle an invalid exception object.

2) madExcept has to deal with a lot of different situations. E.g. exceptions might not originate from our own EXE file. They could have been raised by some DLL, which might have been created by a different Delphi version, or even by a BCB DLL. Because of that I can't just use the "newSelfPtr", I always have to check both the "old" and "new" variations, because whatever DLL the exception came from might have been compiled by a different Delphi version.

3) In my tests I've found that madExcept takes about 0.4 milliseconds to handle one "silent exception". I think that's not so very dramatic. You could have a hundred exceptions, and it would still only cost 40 milliseconds, which is not usable by any user. Of course if you have hundreds of thousands of exceptions, a slowdown will start to be noticeable - but let's be fair here: If your program raises hundreds of thousands of silent exceptions then something is simply not right, IMHO.

4) I've no problem with adding special behaviour for EAbort. But the problem is how can I safely find out whether an exception is EAbort or not, if I haven't even tested yet whether the exceptObject is really a valid Delphi object at all? If I just check for "if ExceptONject is EAbort", that will already crash if the except object is not a valid object. That's the very reason why I first start with "IsValidObject" etc...

Thoughts?

[obones]

First of all, let me say that I've been a bit blunt with regards to PaxCompiler, it only uses exceptions systematically when the "Exit" function is called inside a script. And in our case, the Exit function was called all the time, which was not a good thing.
Fortunately, the call to it was easily removed and the issue has been worked around, but I'd like to continue this discussion so that I understand a bit better what's going on.

4. You are right, it's "the snake that bites its own tail" as we say around here.

1 & 3. I did not investigate in big details which function was the slowest, but I'll trust you here. Thing is, the delay that I noticed was more in the order of 50ms than 0.4ms hence the noticeable slowdown for 6000 exceptions raised. That's why I pushed my analysis as much on possible improvements.

2. Unless I'm completely mistaken, I believe an exception can ever reach the host if sharemem or runtime packages are used. I mean, I have a system here that uses DLLs built with FPC, I had to make sure that all exceptions are caught inside the DLL or it would break havoc in the host exe file.
When using runtime packages, the DLL/BPL and the host must share the same RTL, and so the same VMT layout. So, we are left with the sharemem situation, which, to me, should be quite rare. That means that the IsValidObject2 call should be made first using the SelfPtr appropriate for the host and only if that fails should it try to use the other one. This would short-circuit lots of useless calls and should give better performance as well.
In the end, I tried the various optimizations I'm talking about here and found this out:

Changing FindModule so that it calls the A version has next to no impact, you were definitely right here.
Removing the call to VirtualQuery has an impact but it's not that big (10%)
However, rewriting IsValidException and IsValidObjectEx is the major source of improvements.

Here is my version of IsValidException :

Code: Select all

    result := (exceptObject <> nil) and
              (IsClass(exceptObject, 'Exception') or IsClass(exceptObject, 'MadException')) and
              (exceptObject.InstanceSize >= 28) and
              (MadException(exceptObject).StackInfo <> nil) and
              ReadProcessMemory(GetCurrentProcess, MadException(exceptObject).StackInfo, @i64, 8, c1) and
              (i64 = $6d61644578707434);

Basically, I call IsClass on 'Exception' first and don't call IsValidObject because IsClass returns False if it's not a valid object.

Then, here is my win32 version of IsValidObjectEx :

Code: Select all

  const
    {$ifdef d2009}
      vmtDefaultSelfPtr = vmtNewSelfPtr;
    {$else}
      vmtDefaultSelfPtr = vmtOldSelfPtr;
    {$endif}
    vmtAlternateSelfPtr = vmtOldSelfPtr + vmtNewSelfPtr - vmtDefaultSelfPtr;

      result := IsValidObject2(vmtDefaultSelfPtr, obj, className, baseClass);
      if not result then
        result := IsValidObject2(vmtAlternateSelfPtr, obj, className, baseClass);

And isNewObjectType is set inside IsValidObject2 like this:

Code: Select all

                if result then begin
                  className := s1;
                  isNewObjectType := vmtSelfPtr = vmtNewSelfPtr;
                end;

With all these changes, I'm going from 6 minutes to a little under 2 minutes. Removing the VirtualQuery on top of those optimizations shaves off an extra 10 seconds.
That's still far from the 30 seconds that I get without any exceptions.
To me, the last way to optimize this would be to somehow cache the results of IsValidObject2 code that works on the class itself. If the boolean result could be cached with the classname, that would save lots of API calls.
For the sake of the argument, I replaced the code inside IsValidObjectEx with a simple Result := True and ran it like that. This gives a runtime of 40 seconds, which definitely is an acceptable overhead.
But then again, creating the cache and maintaining it might prove to be a bit more costly, maybe vmtAutoTable could be (ab)used for that:

http://hallvards.blogspot.fr/2007/05/ha ... rt-ii.html

Well, here are my thoughts, and in the end, it is clear that one should avoid using exceptions as a normal behavior.

[madshi]

Thanks, I'll have a look at your performance optimization ideas and implement them in madExcept, if I don't see any problems with them.

I do wonder why you're seeing 50ms when I'm seeing 0.4ms. My PC is fast, but it's very unlikely to be over 100x faster than yours, especially not in such a single threaded situation. Have you been benchmarking inside of outside of the IDE debugger? Any other idea why the performance drop was so very much smaller in my tests? If you can create a test project with which I could reproduce a 50ms penalty for every silent exception then I could definitely want to analyze and improve that!

[obones]

Well, ok, once again, I should have checked by myself instead of relying on hearsay.
In the end, there are over 1 million exceptions raised in that particular case, so the overhead is completely explainable by the extra 0.4 ms
In my case it's even only 0.3 so that confirms we have machines with similar specs.

Once again, sorry for wasting your time with this non existent overhead, but I'm glad about the discussion and the fact that some of the optimizations will be considered for future versions.

[madshi]

I'm glad to hear that. So you agree that the amount of time spent by madExcept on these silent exceptions is acceptable? I will have a look at your optimizations in any case, of course (better performance never hurts).

[obones]

Yes, that is correct.
With my optimizations, I went from 0.4 to 0.3 ms and I believe it should be possible to go as low as 0.2 ms
But that is not a blocking issue for us anymore, so no emergency here.

[wpostma]

This is causing me pretty severe performance pain as well. I have reverted to the prior madexcept version due to this. I am seeing much more expense than 0.4 msec. My early numbers suggest it's adding up to 50 or even 100 millisecond delay per exception. The greater time might be because in our case, the software is running on a VM which is experiencing memory pressure. This VirtualQuery may be degrading VM performance by up to 100 msec per call.

I am a bit surprised that getting INFORMATION back by VirtualQuery is causing a side effect of making some certain bug or failure case go away or something. Can you give more details please Matthias?

Warren

[madshi]

Well, so it seems that on your PC there are 2 things happening which normally shouldn't happen:

1) Your VM needs 100ms per VirtualQuery.
2) You have lots and lots of silent exceptions.

It's not very fair to fault madExcept for that...

Anyway, I have this still on my to do list, maybe I'll find a way to get rid of the problem altogether. Not sure yet, no promises.

What details about what exactly are you looking for, Warren?

[zunzster]

FYI, we're being hit by this one as well - big slowdowns due to silent exceptions since upgrading to madExcept 4.0.12. However, we don't have any VMs involved.

Are there any of the changes proposed above you'd like us to test?

For now, we're going to have to revert to the earlier madExcept in production and test since we definitely can't ship with this and it's hampering our testing efforts too since our testers keep reporting slowdowns due to this.

The problem is a blocker for our SQL Engine. The SQL parser is built using a Delphi port of ANTLR (http://www.antlr.org/). The generated parsing code uses exceptions to implement lexer and parser backtracking which is a core part of the LL(*) parsing algorithm.

All these exception derive from a RecognitionException base class which I think is an EAbort derivative itself so we might explore some way to prevent the catastrophic slowdown.

[madshi]

Can you try whether this beta build solves the performance problem for you?

http://madshi.net/madCollectionBeta.exe (2.7.11.6)

[zunzster]

Sure - will do. We've currently patched our 4.0.12 code to be like to 4.0.11 to make forward progress but that's easily reverted.

As an aside, would it be possible to add a checkbox to your installer that avoids the IDE packages installation and just installed the source?
We build our own design-time packages containing madExcept rather than using the pre-built ones.

Cheers,
Paul.

[madshi]

You can press and hold the Ctrl key while the installer starts. You can release it when the component selection screen appears. That way the installer will switch into "extract only" mode. Alternatively you can only start the installer with the "-extractOnly" parameter.

[zunzster]

OK, I've had some time to apply and try out the new patch.

Unfortunately, just changing the hidden exception handling without changing IsClass doesn't return the performance to 4.0.11 levels.
It seems directly linked to the increase to 6 calls of what IsValidObject2 essentially does over the single call that 4.0.11 had.

4.0.11 calls IsValidObject once.

4.0.12 calls IsValidObject which calls IsValidObject2 *twice* - once for vmtOldSelfPtr and once for vmtNewSelfPtr and then the two IsClass tests for MadException and Exception both call IsValidObjectEx twice for another four calls to IsValidObject2 for an overall total of 6 calls for which the I suspect the last combination (vmtNewSelf/'Exception') will succeed.

Maybe reordering those tests to try 'Exception' before 'MadException' and vmtNewSelfPtr before vmtOldSelfPtr might reduce the effective number of calls but I'm not sure if they are ordered that way for a reason.

Maybe this support for guarding against DLLs from earlier versions of Delphi or madExcept could be optional? We could turn it off since we don't do that in our app.

[madshi]

Ok, next try:

http://madshi.net/madCollectionBeta.exe (installer 2.7.11.8)