Way to optimize logging(old). Memory leaking in depending on requests count.

[wusikijeronii]

I have two problems when logging is enabled:

• Bad performance
• Some connections are refused. In the terminal and error.log I see:

HTTP connection handler has thrown: Connection closed while writing data.

sock error 104

From debug.log:

[2021-08-27 23:19:39.521 main(twjn) ERR] HTTP connection handler has thrown: Connection closed while writing data.
[2021-08-27 23:19:39.539 main(twjn) dbg] Full error: object.Exception@../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/net.d(785): Connection closed while writing data.
[2021-08-27 23:19:39.539 main(twjn) dbg] ----------------
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/net.d:785 @safe ulong vibe.core.net.TCPConnection.write(in ubyte[], eventcore.driver.IOMode) [0x55b9403ba5f2]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-312:312 @safe ulong vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy.ProxyImpl!(vibe.core.net.TCPConnection).ProxyImpl.__mixin8.__mixin3.__mixin3.__mixin3.__mixin3.__mixin3.__mixin2.write(void[], const(ubyte[]), eventcore.driver.IOMode) [0x55b9402715e5]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-201:201 @safe ulong vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy.__mixin22.__mixin2.write(const(ubyte[]), eventcore.driver.IOMode) [0x55b940388c52]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/stream/vibe/stream/counting.d:185 @safe ulong vibe.stream.counting.CountingOutputStream.write(in ubyte[], eventcore.driver.IOMode) [0x55b9403a3393]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/stream.d:302 @safe void vibe.core.stream.OutputStream.write(in ubyte[]) [0x55b9403c5ce6]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-312:312 @safe void vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy.ProxyImpl!(vibe.internal.freelistref.FreeListRef!(vibe.stream.counting.CountingOutputStream, true).FreeListRef).ProxyImpl.__mixin8.__mixin2.write(void[], const(ubyte[])) [0x55b9402bfa88]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-201:201 @safe void vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy.__mixin22.__mixin2.write(const(ubyte[])) [0x55b940388c99]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/stream/vibe/stream/wrapper.d:385 @safe void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy, 256uL).StreamOutputRange.writeToStream(in ubyte[]) [0x55b94029cdb1]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/stream/vibe/stream/wrapper.d:334 @safe void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy, 256uL).StreamOutputRange.flush() [0x55b94029c9e1]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/stream/vibe/stream/wrapper.d:353 @safe void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.OutputStream).InterfaceProxy, 256uL).StreamOutputRange.put(const(ubyte)[]) [0x55b94029cab0]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/common.d:610 @safe void vibe.http.common.ChunkedOutputStream.writeChunk(in ubyte[]) [0x55b94024ec86]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/common.d:579 @safe void vibe.http.common.ChunkedOutputStream.flush() [0x55b94024e9db]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/common.d:588 @safe void vibe.http.common.ChunkedOutputStream.finalize() [0x55b94024ea53]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/server.d:1696 @safe void vibe.http.server.HTTPServerResponse.finalize() [0x55b94025c847]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/server.d:2330 @safe bool vibe.http.server.handleRequest(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy, vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext, ref vibe.http.server.HTTPServerSettings, ref bool, scope stdx.allocator.IAllocator) [0x55b9402df149]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/server.d:253 @trusted void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext).__lambda14() [0x55b9402dcd57]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/server.d:245 @safe void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext) [0x55b9402dc954]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-d-0.9.3/vibe-d/http/vibe/http/server.d:2048 nothrow @safe void vibe.http.server.listenHTTPPlain(vibe.http.server.HTTPServerSettings, void delegate(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) @safe).doListen(vibe.http.server.HTTPServerContext, bool, bool, bool, bool).__lambda7(vibe.core.net.TCPConnection) [0x55b94025eb4e]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/task.d:718 nothrow void vibe.core.task.TaskFuncInfo.set!(void delegate(vibe.core.net.TCPConnection) nothrow @safe, vibe.core.net.TCPConnection).set(ref void delegate(vibe.core.net.TCPConnection) nothrow @safe, ref vibe.core.net.TCPConnection).callDelegate(ref vibe.core.task.TaskFuncInfo) [0x55b940407c2c]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/task.d:739 void vibe.core.task.TaskFuncInfo.call() [0x55b9403d6701]
[2021-08-27 23:19:39.539 main(twjn) dbg] ../../../.dub/packages/vibe-core-1.20.0/vibe-core/source/vibe/core/task.d:446 nothrow void vibe.core.task.TaskFiber.run() [0x55b9403d59b3]
[2021-08-27 23:19:39.539 main(twjn) dbg] ??:? void core.thread.context.Callable.opCall() [0x55b9404b57e0]
[2021-08-27 23:19:39.539 main(twjn) dbg] ??:? fiber_entryPoint [0x55b94051a217]

Tests by wrk:

1. Without logs:

Running 30s test @ http://localhost:8010
  12 threads and 500 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   105.58ms  177.03ms   1.75s    96.65%
    Req/Sec   534.62    128.54     1.70k    84.05%
  178845 requests in 30.10s, 456.42MB read
  Socket errors: connect 0, read 0, write 0, timeout 186
Requests/sec:   5941.86
Transfer/sec:     15.16MB

2. Access log is turned off but for each request I log string "Event" as logInfo:

Running 30s test @ http://localhost:8010
  12 threads and 500 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   155.99ms   95.30ms   2.00s    74.65%
    Req/Sec   251.87    105.43   808.00     76.84%
  82169 requests in 30.09s, 209.70MB read
  Socket errors: connect 0, read 0, write 0, timeout 264
Requests/sec:   2730.78
Transfer/sec:      6.97MB

For the next tests, I disabled the info log.

3. Access log is turned on:

Running 30s test @ http://localhost:8010
  12 threads and 500 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   844.38ms  195.48ms   1.15s    80.61%
    Req/Sec    55.68     43.27   480.00     68.01%
  17176 requests in 30.10s, 43.83MB read
Requests/sec:    570.66
Transfer/sec:      1.46MB

4. Access file log is disabled but it is to allowed to log access requests in the terminal:

Running 30s test @ http://localhost:8010
  12 threads and 500 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   148.42ms   84.53ms   2.00s    82.10%
    Req/Sec   227.32    119.46     1.01k    75.10%
  72083 requests in 30.10s, 183.96MB read
  Socket errors: connect 0, read 0, write 0, timeout 271
Requests/sec:   2394.94
Transfer/sec:      6.11MB

Is there a way to optimize logging in vibe-d? Maybe can I put logging to a separate thread?

[s-ludwig]

I don't think I have ever really used the HTTP logger personally, but the numbers look awful. It looks like there is some heavy lock contention going on, rendering the multiple threads completely useless.

When looking at the implementation, one of the issues that stands out most is that FileStream.write is being used directly with small chunks and FileStream.flush is issued for every line logged. So I'd combine using a StreamOutputRange together with a dedicated task used for writing (using Channel!T for communication). flush would then only be called whenever there are no more log messages pending in the channel.

In addition to that, it would make sense to reuse a per-thread Allocator instance instead of one for all threads, so that the formatting can happen outside of a locked mutex.

There are some other issues, such as HTTPLogger not using shared methods, while still potentially being used with multiple threads, so I'd also really like to make some API adjustments there, but that's independent of this issue.

[wusikijeronii]

I don't think I have ever really used the HTTP logger personally, but the numbers look awful. It looks like there is some heavy lock contention going on, rendering the multiple threads completely useless.

I didn't mess with log's core business, but I think mutex, thread, TaskPool are too difficult for native vibe-d logs. I think writing logs to files just happens synchronously as you wrote after and I added a few code lines: function:

int logging(HTTPMethod m, int s, string p)
{
    appendToFile("logs/access.log", format("\nMethod: %s Status: %s Path: %s", m, s, p));
	return 1;
}

After each request, I call logging function:

runWorkerTask(&logging,  req.method, res.statusCode, req.path);

I think it is a solution so far 'cos now results have become much better (a few tests. There are req/sec below):

min	avg	max
7786.69	7268.79	7188.13

Note: I have set my project as a reverse proxy/HTTP server to compare results and get more real numbers. Nginx under the same configuration (location, rewrite rules, etc) using HTTPS protocol gets 1500-2000 req/sec less than vibe-d. Using HTTP protocol nginx results get 1500-3000 higher than vibe-d. Yep, numbers are different. I ran destination host to a few threads via runWorkerTaskDist.

But I still wanna test behavior using separate threads. I think with different threads we can reach even more performance. I haven't understood how can I separate logging and server functions into different threads 'cos for now I set certain threads to the whole server but logging is the part of that server.

[wusikijeronii]

When looking at the implementation, one of the issues that stands out most is that FileStream.write is being used directly with small chunks and FileStream.flush is issued for every line logged. So I'd combine using a StreamOutputRange together with a dedicated task used for writing (using Channel!T for communication). flush would then only be called whenever there are no more log messages pending in the channel.

So, I wanna tell about this way and my attempts for realization 'em. At first, I created a custom similar approach to logging. I've created a shared buffer and got data from the buffer via the Fiber call. I got better results. I tested on redirect to function instead of a reverse proxy. My results:

nginx	No logging	Buffer	Synchronously	Async
70000	85000	40000	25000	28000

But buffer requires a lot of memory count. About a 2.2 G.

Then I've tried to use Channel!T. I get similar results as the approach with buffer gets, but now the executable requires 3 G RAM.

I think storing logs (part of logs) in the RAM is a bad idea. Also with Filestream / StreamOutputRange I have a problem with logging. When vibe-d gets too many requests in the terminal I get a sock 104 error and then a part of the logline is not full. It looks something like this:

Hello World! Hello World! HelloHello World! Hello World!

But with native D functions I don't face such a problem. For now, I will use async calling of logs 'cos this one get the best requests/ram ratio.

UPD: Today I've played with buffers. I set two checks:

• Checks every 2 seconds if there is data in the buffer.
• Checks if the buffer is filled.

With log formatting (see below), I got about a 45,000-50,000 req/sec using the approach at the bottom of the comment.

Channel!T is the good component, but I had a problem with that. If count of requests < 10,000 per sec. everything works. But when vibe-d accepts many counts of requests (like this test [30,000 ... 70,000] per sec) vibe-d just stops responding. No one page doesn't respond. In a Web browser, I get a timeout error. I also tried to use my custom shared buffer but even with a limit of 1000 loglines in the buffer, this buffer requires a lot of memory count. But I've got a solution to reach better performance: I tried to optimize logging removing one of its job - file reading.

File logStream;

void initLog()
{
    logStream = File("logs/test.log", "a");
}

void main()
{
  ......
  runWorkerTaskDist(&initLog);
  .....
}

And then when I loaded file to each thread, after each request I call:

auto d = Clock.currTime();
    string[] t = [
        "Time: " ~ format("%s-%s-%s %s:%s", d.year, d.month, d.day, d.hour,
                d.minute), "Method: " ~ to!string(req.method),
        "Status: " ~ to!string(res.statusCode), "IP: " ~ req.peer, "Path: " ~ req.path
    ];
    if ("User-Agent" in req.headers)
        t ~= "User-Agent: " ~ req.headers["User-Agent"];
    logStream.writefln("%-(%s %)", t);
    logStream.flush();

Now I get 38,000-42,000 req/sec

UPD: With pointers, a custom alternative of Channel!T, and native C functions (fwrite) I reached results almost without losses but I discovered a problem with memory leaking. Seems it is a problem with vibe-d 'cos I tested on an empty project. I tried:

• res.write()
• proxy
• send()
• diet template

In any case, memory grows up in depends on requests count. I've looked at issues in this repository. I've seen issues the same problems since 2015. I set EventCoreLeakTrace flag and also reduced the keep-alive timeout. When wrk stops Vibe-D application memory remains with the same value. This behavior is exactly memory leaking.

I also tried to test eventcore examples. Even if I destroy client when IOStatus is not Ok the problem remains. It doesn't matter which backend I use. I have tried:

• libevent
• libasync
• vibe-core

[wusikijeronii]

Today I tried to use two frameworks for testing. Node-JS and Django. Node-JS works fine without any problem but Django has the same problem. I googled some solutions and I saw an article. Solution is to restart workers (connection manager) to reset connections. Can I set the same limit in vibe-d? And vibe-d under Nginx doesn't increase memory