www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - vibe.d & exception performance

reply "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
Dicebot recently posted about the use of exceptions as flow 
control in vibe.d, and how bad it performs:
http://forum.dlang.org/thread/ld0d79$2ife$1 digitalmars.com?page=8#post-lqchrhwplxeitefecwne:40forum.dlang.org

Now I did some tests (very unscientific) with a simple app, 
testing three things:

1) Normal program flow without exceptions

import std.random;
void index(HTTPServerRequest req, HTTPServerResponse res)
{
     auto i = uniform(0, int.max);
     res.render!("index.dt", req, i);
}

The template just outputs the generated random number, nothing 
fancy.

2) Throwing a new exception each time

void index(HTTPServerRequest req, HTTPServerResponse res)
{
     const exc = new HTTPStatusException(HTTPStatus.NotFound);
     throw exc;
}

3) Creating the exception once and reusing it

void index(HTTPServerRequest req, HTTPServerResponse res)
{
     static const exc = new 
HTTPStatusException(HTTPStatus.NotFound);
     throw exc;
}

Each of these variants I tested with two versions of vibe.d:

A) Unmodified vibe.d 0.7.17

B) vibe.d master with the following changes applied:

diff --git a/source/vibe/http/server.d b/source/vibe/http/server.d
index 2110cd2..7e29963 100644
--- a/source/vibe/http/server.d
+++ b/source/vibe/http/server.d
   -1395,10 +1395,11    private bool handleRequest(Stream 
http_stream, TCPConnection tcp_connection, HTT
                 // if no one has written anything, return 404
                 enforceHTTP(res.headerWritten, 
HTTPStatus.notFound);
         } catch (HTTPStatusException err) {
-               logDebug("http error thrown: %s", 
err.toString().sanitize);
-               if (!res.headerWritten) errorOut(err.status, 
err.msg, err.toString(), err);
+
+//             logDebug("http error thrown: %s", 
err.toString().sanitize);
+               if (!res.headerWritten) errorOut(err.status, 
err.msg, /*err.toString()*/"", err);
                 else logDiagnostic("HTTPStatusException while 
writing the response: %s", err.msg);
-               logDebug("Exception while handling request %s %s: 
%s", req.method, req.requestURL, err.toString());
+//             logDebug("Exception while handling request %s %s: 
%s", req.method, req.requestURL, err.toString());
                 if (!parsed || res.headerWritten || 
justifiesConnectionClose(err.status))
                         keep_alive = false;
         } catch (Throwable e) {

This just disables calling `toString()` on the exception to avoid 
creating a backtrace, which according to Adam Ruppe's PR is slow:
https://github.com/D-Programming-Language/druntime/pull/717

Then I compiled with:
dub run --build=release
and used ab2 to benchmark:
ab2 -n 10000 -c 1000 -k -r http://localhost:8080/

The results:

                            A) vibe.d 0.7.17      B) vibe.d patched
1) no exceptions                13000 req/s            13000 req/s
2) dynamic exceptions             200 req/s              800 req/s
3) static exceptions              320 req/s            19000 req/s

(The smaller numbers are subject to a lot of variance. 
Additionally, for B/3 I increased the number of requests to 
100000 instead of 10000.)

Now, it can be clearly seen that not generating a backtrace 
results in 300% gain in throughput (A/2 vs. B/2). Also, reusing 
exceptions also gives us about 60% gain (A/2 vs. A/3). A/1 and 
B/1 are equal, which is to be expected.

But the big surprise is B/3. It seems as if there is no overhead 
at all! I thought this maybe comes from inlining, so I compiled 
with `--build=debug` which doesn't pass `-inline` to dmd, but it 
still served about 13000 req/s.

Does anyone have an idea what's going on here? Why the massive 
performance gain with B/3, when neither A/3 nor B/2 are so much 
faster? This indicates either a bug, or a really great 
opportunity for optimization.

In general: Is it even safe to reuse exceptions? Even assuming 
that caught exceptions arent't kept around, what would happen if 
the throwing function were called via different code paths? Would 
the stack trace be cached and kept around, and thus be 
potentially wrong? Does the language specification give any 
guarantees?
Feb 09 2014
next sibling parent "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
Btw, I tried doing the tests with LDC too, but the program always 
segfaulted on the first request.
Feb 09 2014
prev sibling next sibling parent reply "Daniel Murphy" <yebbliesnospam gmail.com> writes:
void index(HTTPServerRequest req, HTTPServerResponse res)
{
     static const exc = new
HTTPStatusException(HTTPStatus.NotFound);
     throw exc;
}

exc is created at compile time and put the tls init data.  No gc heap 
activity is ever involved in creating it.
Feb 09 2014
parent reply "Jakob Ovrum" <jakobovrum gmail.com> writes:
On Sunday, 9 February 2014 at 11:31:12 UTC, Daniel Murphy wrote:

 void index(HTTPServerRequest req, HTTPServerResponse res)
 {
     static const exc = new
 HTTPStatusException(HTTPStatus.NotFound);
     throw exc;
 }

 exc is created at compile time and put the tls init data.  No 
 gc heap activity is ever involved in creating it.


It's actually put in global storage, not TLS, as of last I 
checked (as of the original pull by Igor). It's the reason 
mutable instances are currently disallowed.
Feb 09 2014
parent "Daniel Murphy" <yebbliesnospam gmail.com> writes:
"Jakob Ovrum"  wrote in message news:xsquzbnoqxjdokzvukqc forum.dlang.org...

 It's actually put in global storage, not TLS, as of last I checked (as of 
 the original pull by Igor). It's the reason mutable instances are 
 currently disallowed.


So it is!
Feb 09 2014
prev sibling next sibling parent reply "Dicebot" <public dicebot.lv> writes:
You seem to forget that actually writing data to socket takes 
time and this time is longer than one needed for most simple 
stack unwinding. Fun fact - even if you copy rendering code to 
static exception example it will still be ~5-10% faster because 
it will cancel pending async socket output and terminate fiber 
early.

But yes, those results match my earlier observations - 
pre-allocated exceptions with no stack trace generation are of 
fast enough to not be a concern. Impact of both of those factors 
is huge enough to provide DoS vector.
Feb 09 2014
parent reply "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
On Sunday, 9 February 2014 at 13:04:20 UTC, Dicebot wrote:

 You seem to forget that actually writing data to socket takes 
 time and this time is longer than one needed for most simple 
 stack unwinding. Fun fact - even if you copy rendering code to 
 static exception example it will still be ~5-10% faster because 
 it will cancel pending async socket output and terminate fiber 
 early.


Oh, I'm not surprised that it can be faster than the 
non-exception version, after all, it does less work.

What troubles me is the large speedup if you use both a 
statically allocated exception, and don't generate a stack trace. 
Neither of them alone makes that much of a difference. I would 
have expected the combined performance gain to be the sum of both 
for themselves, more or less.

But the difference actual difference is so much larger. Where 
does it come from? It might mean that there is some costly 
operation that both `new` and `toString()` perform. Or it might 
actually be a bug, and when fixed, would have worse performance. 
It seems almost too good to be true...


 But yes, those results match my earlier observations - 
 pre-allocated exceptions with no stack trace generation are of 
 fast enough to not be a concern. Impact of both of those 
 factors is huge enough to provide DoS vector.


Yes, if it is really safe to use, vibe.d should introduce a 
"production" mode, where it neither outputs nor logs stack traces 
by default. That's a good idea anyway, to keep internal 
information from leaking out to a potential attacker.
Feb 09 2014
next sibling parent reply "Jakob Ovrum" <jakobovrum gmail.com> writes:
On Sunday, 9 February 2014 at 16:07:52 UTC, Marc Schütz wrote:

 But the difference actual difference is so much larger. Where 
 does it come from? It might mean that there is some costly 
 operation that both `new` and `toString()` perform. Or it might 
 actually be a bug, and when fixed, would have worse 
 performance. It seems almost too good to be true...


They both allocate GC memory, which can cause a collection cycle. 
Could that be it?
Feb 09 2014
parent "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
On Sunday, 9 February 2014 at 16:12:30 UTC, Jakob Ovrum wrote:

 On Sunday, 9 February 2014 at 16:07:52 UTC, Marc Schütz wrote:

 But the difference actual difference is so much larger. Where 
 does it come from? It might mean that there is some costly 
 operation that both `new` and `toString()` perform. Or it 
 might actually be a bug, and when fixed, would have worse 
 performance. It seems almost too good to be true...


 They both allocate GC memory, which can cause a collection 
 cycle. Could that be it?


No, I just checked this by allocating another exception in 
addition to the one being thrown, and it made no difference.

But I think I've found the explanation, see my previous post.
Feb 09 2014
prev sibling next sibling parent "Dicebot" <public dicebot.lv> writes:
On Sunday, 9 February 2014 at 16:07:52 UTC, Marc Schütz wrote:

 But the difference actual difference is so much larger. Where 
 does it come from? It might mean that there is some costly 
 operation that both `new` and `toString()` perform. Or it might 
 actually be a bug, and when fixed, would have worse 
 performance. It seems almost too good to be true...


Both "new" and stack trace generation ("toString") are rather 
costly operations on their own. And both can trigger GC 
collection cycles. It is not wonder that removing both results in 
such an improvement.

I think proposal to omit stack traces in release builds is a good 
idea.
Feb 09 2014
prev sibling parent "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
 But the difference actual difference is so much larger. Where 
 does it come from? It might mean that there is some costly 
 operation that both `new` and `toString()` perform. Or it might 
 actually be a bug, and when fixed, would have worse 
 performance. It seems almost too good to be true...


An interesting observation:

const HTTPStatusException[10000] exc;

static this() {
     for(auto i = 0; i < exc.length; i++)
         exc[i] = new HTTPStatusException(HTTPStatus.NotFound);
}

void index(HTTPServerRequest req, HTTPServerResponse res)
{
     throw exc[uniform(0, exc.length-1)];
}



When I run this several times, I get (req/s):

  933.01
1269.78
1606.49
2087.57
2512.23
2976.09
4240.72
4900.27
6136.00
6412.73
7657.19
8442.30

See a pattern? This probably means that the runtime is caching 
things in the exception objects when they are thrown for the 
first time. This might cause problems when they are later 
rethrown from somewhere else, but I'm not sure; maybe it's 
intelligent enough to recognize that case.

But notice that this still works:

auto makeExceptions(size_t n) {
     auto result = new HTTPStatusException[n];
     foreach(immutable i; 0 .. n)
         result[i] = new HTTPStatusException(HTTPStatus.NotFound);
     return result;
}

immutable(HTTPStatusException)[] exc = 
assumeUnique(makeExceptions(10000));

void index(HTTPServerRequest req, HTTPServerResponse res)
{
     throw exc[uniform(0, exc.length-1)];
}

If the runtime really does what I suspect, it modifies immutable 
objects... So, is it legal to throw immutable (or const) 
exceptions?
Feb 09 2014
prev sibling parent "Marc =?UTF-8?B?U2Now7x0eiI=?= <schuetzm gmx.net> writes:
 The results:

                          A) vibe.d 0.7.17      B) vibe.d patched
 1) no exceptions              13000 req/s          13000 req/s
 2) dynamic exceptions           200 req/s            800 req/s
 3) static exceptions            320 req/s          19000 req/s


New numbers with DMD/Druntime/Phobos git (includes the patch by 
Adam Ruppe):

                          A) vibe.d 0.7.17      B) vibe.d patched
1) no exceptions              15000 req/s          16000 req/s
2) dynamic exceptions           120 req/s          19000 req/s
3) static exceptions            120 req/s          19000 req/s

Dynamic and static exceptions are now equally fast, provided 
`toString()` is not called on them.
Feb 26 2014