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: -------

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: -------

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: -------

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: -------

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: -------

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: -------

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: -------

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: -------

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: -------

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: -------