www.digitalmars.com         C & C++   DMDScript  

digitalmars.D.bugs - [Issue 9581] New: Regression (2.053): Exception takes too much time to show up

reply d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581

           Summary: Regression (2.053): Exception takes too much time to
                    show up
           Product: D
           Version: D2
          Platform: All
        OS/Version: Windows
            Status: NEW
          Keywords: EH, performance
          Severity: regression
          Priority: P2
         Component: DMD
        AssignedTo: nobody puremagic.com
        ReportedBy: andrej.mitrovich gmail.com


--- Comment #0 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-23
18:35:50 PST ---
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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 23 2013
next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #1 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-23
18:36:24 PST ---
And this can be recreated all the way up to 2.062 and 2.063 git-head.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Steven Schveighoffer <schveiguy yahoo.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |schveiguy yahoo.com


--- Comment #2 from Steven Schveighoffer <schveiguy yahoo.com> 2013-02-23
19:24:45 PST ---
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?

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #3 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-23
19:27:56 PST ---
(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); } --------- -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Jonathan M Davis <jmdavisProg gmx.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jmdavisProg gmx.com


--- Comment #4 from Jonathan M Davis <jmdavisProg gmx.com> 2013-02-23 19:40:28
PST ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #5 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-23
19:47:32 PST ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #6 from Steven Schveighoffer <schveiguy yahoo.com> 2013-02-23
20:09:28 PST ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #7 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-23
20:14:06 PST ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #8 from Jonathan M Davis <jmdavisProg gmx.com> 2013-02-23 20:50:30
PST ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 23 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #9 from Steven Schveighoffer <schveiguy yahoo.com> 2013-02-24
06:52:00 PST ---
(In reply to comment #8)
 Exceptions in general are overly slow.

Yeah, but not *4 seconds* slow, that is unacceptable. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Walter Bright <bugzilla digitalmars.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |bugzilla digitalmars.com


--- Comment #10 from Walter Bright <bugzilla digitalmars.com> 2013-02-24
14:34:52 PST ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #11 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-24
14:42:31 PST ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #12 from Jonathan M Davis <jmdavisProg gmx.com> 2013-02-24 14:49:01
PST ---
 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). -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #13 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-24
14:55:05 PST ---
(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 -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #14 from Jonathan M Davis <jmdavisProg gmx.com> 2013-02-24 15:49:48
PST ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Feb 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #15 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-26
13:24:26 PST ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 26 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #16 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-02-26
13:42:41 PST ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Feb 26 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #17 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-03-31
03:56:24 PDT ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Mar 31 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


bearophile_hugs eml.cc changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |bearophile_hugs eml.cc


--- Comment #18 from bearophile_hugs eml.cc 2013-03-31 05:59:55 PDT ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Mar 31 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Damian <damianday hotmail.co.uk> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |damianday hotmail.co.uk


--- Comment #19 from Damian <damianday hotmail.co.uk> 2013-04-16 16:24:26 PDT
---
(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? -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Apr 16 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Martin Nowak <code dawg.eu> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |code dawg.eu


--- Comment #20 from Martin Nowak <code dawg.eu> 2013-04-24 09:01:59 PDT ---
Does disabling Stacktrace resolve the problem?
https://github.com/D-Programming-Language/druntime/blob/4c8fd9dd7b91e735eece5ffc746a0667ccc13dd6/src/core/runtime.d#L585

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Apr 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #21 from Martin Nowak <code dawg.eu> 2013-04-24 09:04:31 PDT ---
(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 -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
Apr 24 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #22 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-05-19
04:52:35 PDT ---
(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? -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
May 19 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #23 from bearophile_hugs eml.cc 2013-05-19 07:50:13 PDT ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
May 19 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #24 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-05-19
10:53:41 PDT ---
(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). -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
May 19 2013
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581



--- Comment #25 from bearophile_hugs eml.cc 2013-05-19 16:09:06 PDT ---
(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. -- Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email ------- You are receiving this mail because: -------
May 19 2013
prev sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=9581


Andrej Mitrovic <andrej.mitrovich gmail.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Severity|regression                  |normal


--- Comment #26 from Andrej Mitrovic <andrej.mitrovich gmail.com> 2013-05-19
17:17:33 PDT ---
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.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
May 19 2013