Bug 9581 – Exceptions are too slow

test.d: ------ module test; void main() { assert(0); } ------ timer.d (or use your favorite timer app): ------ module timer; import std.stdio; import std.process; import std.datetime; void main() { auto sw1 = StopWatch(AutoStart.yes); system("dmd test.d"); system("test"); sw1.stop(); writefln("%s msecs.", sw1.peek.msecs); } ------ DMD 2.052: $ dmd timer.d $ timer > 81 msecs. DMD 2.053: $ dmd timer.d $ timer > 4127 msecs. This is using XP SP3.

And this can be recreated all the way up to 2.062 and 2.063 git-head.

Doesn't this just test the compile time? Not that 4 second compile time is really acceptable, but I don't know if this test does what you think it does. What happens when you remove the compilation line?

(In reply to comment #2) > Doesn't this just test the compile time? Not that 4 second compile time is > really acceptable, but I don't know if this test does what you think it does. > > What happens when you remove the compilation line? Sorry about that, it was a misplaced system call. Without timing the compilation its faster but still 4050 msecs. Here's the newer script: timer.d: --------- module timer; import std.stdio; import std.process; import std.datetime; void main() { system("dmd test.d"); auto sw1 = StopWatch(AutoStart.yes); system("test"); sw1.stop(); writefln("%s msecs.", sw1.peek.msecs); } ---------

If what you're testing is the amount of time that it takes an exception to be thrown and caught, then you shouldn't be doing anything like call system, since then that's testing what system's up to. And even worse, you're starting a different program, meaning that you're testing the amount of time it takes to run the program (including the startup time for druntime). Please test only one thing at a time. If system's too slow, then create a test just for that and a bug report for it. If exceptions are too slow, then cerate a test just for that and bug report for it. If druntime takes too long to startup, then create a test just for that and create a bug report for it. You're testing too many things at once here.

(In reply to comment #4) > If what you're testing is the amount of time that it takes an exception to be > thrown and caught, then you shouldn't be doing anything like call system, since > then that's testing what system's up to. And even worse, you're starting a > different program, meaning that you're testing the amount of time it takes to > run the program (including the startup time for druntime). Please test only one > thing at a time. > > If system's too slow, then create a test just for that and a bug report for it. > If exceptions are too slow, then cerate a test just for that and bug report for > it. If druntime takes too long to startup, then create a test just for that and > create a bug report for it. You're testing too many things at once here. This is the test-case: -------- module test; void main() { assert(0); } --------- You can use `timeit` or some other timing app you may have installed on the system, the 'timer' was just there in case someone doesn't have an alternative to test it with. Anyway you can get 'timeit' from http://www.microsoft.com/en-us/download/details.aspx?id=17657, then the test runs are: 2.052: $ D:\foobar>dmd test.d $ D:\foobar>timeit test core.exception.AssertError@test(5): Assertion failure Version Number: Windows NT 5.1 (Build 2600) Exit Time: 4:45 am, Sunday, February 24 2013 Elapsed Time: 0:00:00.078 Process Time: 0:00:00.031 System Calls: 2121 Context Switches: 456 Page Faults: 678 Bytes Read: 142408 Bytes Written: 0 Bytes Other: 124382 2.053: D:\foobar>dmd test.d D:\foobar>timeit test core.exception.AssertError@test(5): Assertion failure ---------------- 40CE70 40CCE7 40201A 4025C7 4021C3 4120C9 7C817067 ---------------- Version Number: Windows NT 5.1 (Build 2600) Exit Time: 4:46 am, Sunday, February 24 2013 Elapsed Time: 0:00:04.093 Process Time: 0:00:01.265 System Calls: 72733 Context Switches: 38975 Page Faults: 18821 Bytes Read: 17758445 Bytes Written: 8283 Bytes Other: 55317 The system calls should give a hint here, it's an enormous increase from 2121 calls in 2.052 to 72733 calls in 2.053.

Also note, the new version prints a stack trace, while the previous doesn't. Interesting. I wonder if that is what is taking so long.

(In reply to comment #6) > Also note, the new version prints a stack trace, while the previous doesn't. > Interesting. I wonder if that is what is taking so long. Yeah. Considering how long it takes I really wonder if we can improve the speed in some way. E.g. we could provide a switch to disable the stack-trace. Or maybe the real issue is spending time finding dbghelp.dll. If that's the case, we could try to search for a specific environment variable that the user would set so the DLL is quickly found. Anyway that's only guessing that's the actual issue.

Exceptions in general are overly slow. As I understand it, one of the major things that could be done would be to make it so that it doesn't actually determine the strings for the stacktrace when it's constructed but rather when toString is called on it. We currently incur that extra regardless of whether the exception's toString method is ever used. Now, I don't think that it would help any in this case, because the toString method _is_ being used, but it is something that should be done to improve the performance of exceptions. And I'm sure that there are plenty of other things that could be done as well, but I don't know the inner workings of druntime well enough to know what they might be. Java beats the pants of D in exception speed though.

(In reply to comment #8) > Exceptions in general are overly slow. Yeah, but not *4 seconds* slow, that is unacceptable.

This may have something to do with an earlier complaint that dbghelp.dll was searching one's entire hard disk looking for a source file.

(In reply to comment #10) > This may have something to do with an earlier complaint that dbghelp.dll was > searching one's entire hard disk looking for a source file. That specific bug was fixed though (and I can confirm it was fixed). But there's still this delay of several seconds before the message shows up.

> Yeah, but not *4 seconds* slow, that is unacceptable. Of course, though this involves a lot more than simply throwing and catching an exception, which changes the equation a bit (though 4 seconds is still too slow). By the way, I just tried this on Linux for comparison, and it took about 8ms on my machine. So, this is clearly a Windows-only issue (though I just used the time command to time it rather than writing a program; Does Windows not have anything similar? Probably not, given how limited its command line capabilities are).

(In reply to comment #12) > By the way, I just tried this on Linux for comparison, and it took about 8ms on > my machine. I can confirm that, it only takes 3ms in Linux Mint in a VBox. It's a Windows issue. (In reply to comment #12) > Does Windows not have anything similar? It has `timeit` available from http://www.microsoft.com/en-us/download/details.aspx?id=17657

I couldn't find a bug report dealing with the general bad performance of exceptions, so I just created one: bug# 9584 So, that's related to this, but something here is making it far worse in this particular situation. In general, they're taking milliseconds when they should be taking microseconds, whereas here they're taking seconds.

(In reply to comment #0) > DMD 2.053: > $ dmd timer.d > $ timer > > 4127 msecs. You know what? I think my hard drive is dying. It seems just running RDMD itself can sometimes take several seconds. This could be an invalid report. I'll try to boot up into another system on another hard-drive to test this.

(In reply to comment #15) > I'll try to boot up into another system on another hard-drive to test this. Nope, still an issue even on another hard drive.

Well, I'm on Win7 now and things are pretty blazing fast now. I don't experience the speed issue anymore. Maybe we could close this down unless someone else has the same issue.

(In reply to comment #17) > Well, I'm on Win7 now and things are pretty blazing fast now. I don't > experience the speed issue anymore. Maybe we could close this down unless > someone else has the same issue. On Windows Vista 32bit the D exceptions are still very slow.

(In reply to comment #18) > (In reply to comment #17) > > Well, I'm on Win7 now and things are pretty blazing fast now. I don't > > experience the speed issue anymore. Maybe we could close this down unless > > someone else has the same issue. > > On Windows Vista 32bit the D exceptions are still very slow. Just food for thought but, since this is a Windows issue, could it be anti-virus or malware scanner or some such application causing slowdown on access to dbghelp.dll?

Does disabling Stacktrace resolve the problem? https://github.com/D-Programming-Language/druntime/blob/4c8fd9dd7b91e735eece5ffc746a0667ccc13dd6/src/core/runtime.d#L585

(In reply to comment #20) > Does disabling Stacktrace resolve the problem? > https://github.com/D-Programming-Language/druntime/blob/4c8fd9dd7b91e735eece5ffc746a0667ccc13dd6/src/core/runtime.d#L585 And what about completely disabling the dbghelp initalization? I think commenting out the import would suffice. https://github.com/D-Programming-Language/druntime/blob/4c8fd9dd7b91e735eece5ffc746a0667ccc13dd6/src/core/runtime.d#L50

(In reply to comment #18) > (In reply to comment #17) > > Well, I'm on Win7 now and things are pretty blazing fast now. I don't > > experience the speed issue anymore. Maybe we could close this down unless > > someone else has the same issue. > > On Windows Vista 32bit the D exceptions are still very slow. Are they over 4 seconds like they were for me before I switched?

(In reply to comment #22) > Are they over 4 seconds like they were for me before I switched? I have a small benchmark for exceptions, and they are much much slower than equivalent exceptions in Java.

(In reply to comment #23) > (In reply to comment #22) > > > Are they over 4 seconds like they were for me before I switched? > > I have a small benchmark for exceptions, and they are much much slower than > equivalent exceptions in Java. Ok, but is it a regression from an earlier release? We should mark this as a normal bug if not to avoid blocking the 2.063 release (I personally can't recreate the huge slowness anymore).

(In reply to comment #24) > Ok, but is it a regression from an earlier release? We should mark this as a > normal bug if not to avoid blocking the 2.063 release (I personally can't > recreate the huge slowness anymore). I think this bug should not block 2.063, because probably will require a fair amount of work to be fixed, and the situation is probably not a regression any more.

If someone has had their exceptions slow down significantly since 2.053, re-set it as a regression. But I'm lowering it to normal for now.

Is this still a problem? (Came across this on a search) In the last couple years, we've done some changes to the stack trace generation on Windows and Linux which yielded gigantic speedups.

Related: https://issues.dlang.org/show_bug.cgi?id=9584

(In reply to Adam D. Ruppe from comment #27) > Is this still a problem? (Came across this on a search) In the last couple > years, we've done some changes to the stack trace generation on Windows and > Linux which yielded gigantic speedups. On Windows 32 bit I see Java exceptions about twice faster than D ones (compiled with dmd). This means that for many practical purposes D exceptions are fast enough. Benchmark done with the following code, with n = 500000. ldc2 for Windows is about 4 or 5 times slower than DMD in this benchmark. ------------------------ final class Lo_Exception extends Exception { int num = 0; public Lo_Exception(int num) { this.num = num; } } final class Hi_Exception extends Exception { int num = 0; public Hi_Exception(int num) { this.num = num; } } public final class except { static int Lo = 0, Hi = 0; public static void some_function(int n) { try { hi_function(n); } catch (Exception e) { System.out.println("We shouldn't get here: " + e); } } public static void hi_function(int n) throws Hi_Exception, Lo_Exception { try { lo_function(n); } catch (Hi_Exception e) { Hi++; } } public static void lo_function(int n) throws Hi_Exception, Lo_Exception { try { blowup(n); } catch (Lo_Exception e) { Lo++; } } public static void blowup(int n) throws Hi_Exception, Lo_Exception { if ((n % 2) == 0) throw new Lo_Exception(n); else throw new Hi_Exception(n); } public static void main(String args[]) { final int n = Integer.parseInt(args[0]); for (int i = 0; i < n; i++) some_function(i); System.out.println("Exceptions: HI=" + Hi + " / LO=" + Lo); } } -------------------- import std.conv: to; enum bool SLOW = true; // You can change this. static if (SLOW) { import std.stdio: printf = writef; } else { import core.stdc.stdio: printf; } __gshared uint HI, LO; final class HiException : Exception { uint n; this(in uint n) pure nothrow { this.n = n; super(null); } } final class LoException : Exception { uint n; this(in uint n) pure nothrow { this.n = n; super(null); } } void blowup(in uint n) { if (n % 2) throw new LoException(n); else throw new HiException(n); } void loFunction(in uint n) { try { blowup(n); } catch (LoException ex) { LO++; } } void hiFunction(in uint n) { try { loFunction(n); } catch(HiException ex) { HI++; } } void someFunction(in uint n) { try { hiFunction(n); } catch { printf("We shouldn't get here\n"); } } void main(in string[] args) { uint n = args.length > 1 ? args[1].to!uint : 1; while (n--) n.someFunction; printf("Exceptions: HI=%d / LO=%d\n", HI, LO); } --------------------

Yeah we should probably close this.