Make accesslogs.logTheRoundTrip async to get lost performance #3152

ryarnyah · 2018-04-08T10:55:00Z

What does this PR do?

Add a async accesslogs.logTheRoundTrip for access logs.

Motivation

On my current project, we use traefik and recently we activate access logs. When i checked the overhead this functionality, i realize that we lost a lot! So i tried to figure why and i found that we use sync io.Writer. So i did that PR #3059 and after some tests i realized that i can do simpler and more effective with this PR(with or without fileFormat per example).

Small benchs:

Base configuration:

[entryPoints]
    [entryPoints.http]
       address = ":8080"
[accessLog]
filePath = 'test'

Without accesslogs from hey (without json format):

$ hey -n 200000 http://127.0.0.1:8080/test
Summary:
  Total:	6.4238 secs
  Slowest:	0.0333 secs
  Fastest:	0.0002 secs
  Average:	0.0016 secs
  Requests/sec:	31134.0972
  
  Total data:	3800000 bytes
  Size/request:	19 bytes

Response time histogram:
  0.000 [1]	|
  0.003 [192996]	|∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  0.007 [6398]	|∎
  0.010 [446]	|
  0.013 [107]	|
  0.017 [39]	|
  0.020 [9]	|
  0.023 [2]	|
  0.027 [0]	|
  0.030 [0]	|
  0.033 [2]	|


Latency distribution:
  10% in 0.0008 secs
  25% in 0.0011 secs
  50% in 0.0014 secs
  75% in 0.0018 secs
  90% in 0.0024 secs
  95% in 0.0030 secs
  99% in 0.0052 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0002 secs, 0.0333 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0191 secs
  resp wait:	0.0013 secs, 0.0001 secs, 0.0232 secs
  resp read:	0.0001 secs, 0.0000 secs, 0.0299 secs

With accesslogs (without json format):

$ hey -n 200000 http://127.0.0.1:8080/test
Summary:
  Total:	20.0173 secs
  Slowest:	0.0261 secs
  Fastest:	0.0002 secs
  Average:	0.0050 secs
  Requests/sec:	9991.3647
  
  Total data:	3800000 bytes
  Size/request:	19 bytes

Response time histogram:
  0.000 [1]	|
  0.003 [2732]	|∎
  0.005 [154054]	|∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  0.008 [32652]	|∎∎∎∎∎∎∎∎
  0.011 [7629]	|∎∎
  0.013 [2026]	|∎
  0.016 [556]	|
  0.018 [177]	|
  0.021 [148]	|
  0.024 [19]	|
  0.026 [6]	|


Latency distribution:
  10% in 0.0041 secs
  25% in 0.0042 secs
  50% in 0.0045 secs
  75% in 0.0053 secs
  90% in 0.0063 secs
  95% in 0.0081 secs
  99% in 0.0115 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0002 secs, 0.0261 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0023 secs
  resp wait:	0.0049 secs, 0.0002 secs, 0.0260 secs
  resp read:	0.0000 secs, 0.0000 secs, 0.0038 secs

With async accesslogs.logTheRoundTrip (with or without json format and with bufferingSize = 262140):

$ hey -n 200000 http://127.0.0.1:8080/test
Summary:
  Total:	9.5298 secs
  Slowest:	0.0992 secs
  Fastest:	0.0002 secs
  Average:	0.0024 secs
  Requests/sec:	20986.9069
  
  Total data:	3800000 bytes
  Size/request:	19 bytes

Response time histogram:
  0.000 [1]	|
  0.010 [198312]	|∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  0.020 [1164]	|
  0.030 [362]	|
  0.040 [80]	|
  0.050 [51]	|
  0.060 [18]	|
  0.070 [5]	|
  0.079 [1]	|
  0.089 [1]	|
  0.099 [5]	|


Latency distribution:
  10% in 0.0008 secs
  25% in 0.0012 secs
  50% in 0.0019 secs
  75% in 0.0028 secs
  90% in 0.0043 secs
  95% in 0.0054 secs
  99% in 0.0093 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0002 secs, 0.0992 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0569 secs
  resp wait:	0.0022 secs, 0.0001 secs, 0.0991 secs
  resp read:	0.0001 secs, 0.0000 secs, 0.0662 secs

More

Added/updated tests
Added/updated documentation: Access Logs

Additional Notes

I think that there is more to do to optimize access logs overhead but it's a first step.
Replace PR #3059.

mmatur

LGTM 👏

ryarnyah · 2018-05-14T22:59:50Z

PR has been rebased.

juliens

Thanks for this PR!

juliens · 2018-05-16T13:55:15Z

middlewares/accesslog/logger.go

+	close(l.stopCh)
+	l.wg.Wait()
+	close(l.logHandlerChan)
+	l.drainChannel()


Instead of a stopCh, drainChannel() and WaitGroup, WDYT about just create a for/range on the logHandlerChan and in the Close(), just close this chan?

That might be a great enhancement! Thanks for that!

nmengin

@ryarnyah

Many thanks for this awesome PR.

Few remarks.

nmengin · 2018-05-16T16:26:44Z

docs/configuration/logs.md

@@ -124,6 +124,13 @@ filePath = "/path/to/access.log"
 format = "json"
 ```

+To write the logs in async, specify `bufferingSize` as the format (must be >0):


If I understand right the code, the buffer size is about the number of lines to bufferize before to write them into the log file.
As usualy the buffer size can concern a number of bytes, I guess it should be nice to precise in the documentation that the buffer size is about a number of access logs and not a number of bytes.

WDYT?

That's not exactly the number of access logs lines, but the number of access log lines to process in a buffered way. => I will precise it.

nmengin · 2018-05-16T16:29:20Z

docs/configuration/logs.md

+```toml
+[accessLog]
+filePath = "/path/to/access.log"
+bufferingSize = 262140


WDYT to use a smaller size in the example (50 or 100)?

Might be better than a random number like i wrote :D

ryarnyah

Commit will follow. @nmengin & @juliens Is that better this way?

Do you prefer that i rebase my commit after your review or that i let it this way?

ryarnyah · 2018-05-16T18:47:11Z

middlewares/accesslog/logger.go

+	close(l.stopCh)
+	l.wg.Wait()
+	close(l.logHandlerChan)
+	l.drainChannel()


That might be a great enhancement! Thanks for that!

ryarnyah · 2018-05-16T18:48:07Z

docs/configuration/logs.md

+```toml
+[accessLog]
+filePath = "/path/to/access.log"
+bufferingSize = 262140


Might be better than a random number like i wrote :D

ryarnyah · 2018-05-16T18:49:15Z

docs/configuration/logs.md

@@ -124,6 +124,13 @@ filePath = "/path/to/access.log"
 format = "json"
 ```

+To write the logs in async, specify `bufferingSize` as the format (must be >0):


That's not exactly the number of access logs lines, but the number of access log lines to process in a buffered way. => I will precise it.

ldez · 2018-05-16T20:34:25Z

@ryarnyah thanks for your work.

If you could not rebase and address the review comments in terms of additional commits, this is very useful for us because it facilitates the review.

https://github.com/containous/traefik/blob/master/CONTRIBUTING.md#content

Address review comments in terms of additional commits.

Do not amend/squash existing ones unless the PR is trivial.

ryarnyah · 2018-05-16T21:53:08Z

@ldez That's what i did. I only rebase on master on my last push (sorry for this rebase). I was just asking if i must squash all of them after reviews :D

ldez · 2018-05-16T22:13:56Z

@ryarnyah you don't need to rebase or merge master, we have a bot to handle that 🤖

juliens · 2018-05-17T08:29:12Z

middlewares/accesslog/logger.go

@@ -83,6 +92,18 @@ func NewLogHandler(config *types.AccessLog) (*LogHandler, error) {
 		}
 	}

+	if config.BufferingSize > 0 {
+		go func() {
+			for {


WDYT about moving the for/range here?

If you move it here, don't you need to wait until goroutine end to close file (with WaitGroup per example)?(might already need to)

You're right, you need to add a WaitGroup in order to be sure that Close wait for the drain of logs.

In addition, FYI ok==true until the chan is empty, so with this code, you will still loop until the chan is empty.

I have moved for loop range to goroutine and add sync.WaitGroup to ensure stream is empty before closed file.

juliens · 2018-05-17T15:48:15Z

middlewares/accesslog/logger.go

@@ -83,6 +92,18 @@ func NewLogHandler(config *types.AccessLog) (*LogHandler, error) {
 		}
 	}

+	if config.BufferingSize > 0 {
+		go func() {
+			for {


You're right, you need to add a WaitGroup in order to be sure that Close wait for the drain of logs.

In addition, FYI ok==true until the chan is empty, so with this code, you will still loop until the chan is empty.

juliens

👏

nmengin

LGTM 👏 🎉

…sure stream is empty before close file

traefiker added area/logs area/middleware size/S status/0-needs-triage labels Apr 8, 2018

ryarnyah mentioned this pull request Apr 8, 2018

Add accesslog async writer #3059

Closed

2 tasks

ryarnyah changed the title ~~Make accesslogs.logTheRoundTrip async to get lost performance (replace https://github.com/containous/traefik/pull/3059)~~ Make accesslogs.logTheRoundTrip async to get lost performance Apr 8, 2018

ryarnyah force-pushed the feat/use-chan-for-accesslogs branch from a175c6c to 1d77686 Compare April 8, 2018 11:01

ldez added status/1-needs-design-review and removed status/0-needs-triage labels Apr 8, 2018

ldez assigned mmatur Apr 8, 2018

ldez added the kind/enhancement a new or improved feature. label Apr 8, 2018

juliens added status/2-needs-review and removed status/1-needs-design-review labels Apr 12, 2018

mmatur added this to the 1.7 milestone Apr 12, 2018

mmatur approved these changes May 14, 2018

View reviewed changes

ryarnyah force-pushed the feat/use-chan-for-accesslogs branch from 1d77686 to 4712c19 Compare May 14, 2018 22:43

juliens requested changes May 16, 2018

View reviewed changes

traefiker added the contributor/waiting-for-corrections label May 16, 2018

nmengin requested changes May 16, 2018

View reviewed changes

ryarnyah commented May 16, 2018

View reviewed changes

ryarnyah force-pushed the feat/use-chan-for-accesslogs branch from 4712c19 to 5fde503 Compare May 16, 2018 19:06

juliens requested changes May 17, 2018

View reviewed changes

juliens approved these changes May 18, 2018

View reviewed changes

traefiker removed the contributor/waiting-for-corrections label May 18, 2018

nmengin approved these changes May 23, 2018

View reviewed changes

nmengin added status/3-needs-merge and removed status/2-needs-review labels May 23, 2018

traefiker added the status/4-merge-in-progress label May 23, 2018

ryarnyah added 3 commits May 23, 2018 14:28

Make accesslogs.logTheRoundTrip async to get lost performance

41ee913

Precise doc on bufferingSize usage and enhance logHandlerChan goroutine.

d266b05

Move for range loop to primary goroutine and add sync.WaitGroup to en…

69ec30d

…sure stream is empty before close file

traefiker force-pushed the feat/use-chan-for-accesslogs branch from e53b787 to 69ec30d Compare May 23, 2018 14:28

traefiker removed the status/4-merge-in-progress label May 23, 2018

traefiker merged commit c09febf into traefik:master May 23, 2018

traefiker removed the status/3-needs-merge label May 23, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make accesslogs.logTheRoundTrip async to get lost performance #3152

Make accesslogs.logTheRoundTrip async to get lost performance #3152

ryarnyah commented Apr 8, 2018 •

edited

Loading

mmatur left a comment

ryarnyah commented May 14, 2018

juliens left a comment

juliens May 16, 2018

ryarnyah May 16, 2018

nmengin left a comment

nmengin May 16, 2018

ryarnyah May 16, 2018

nmengin May 16, 2018

ryarnyah May 16, 2018

ryarnyah left a comment •

edited

Loading

ryarnyah May 16, 2018

ryarnyah May 16, 2018

ryarnyah May 16, 2018

ldez commented May 16, 2018

ryarnyah commented May 16, 2018 •

edited

Loading

ldez commented May 16, 2018

juliens May 17, 2018

ryarnyah May 17, 2018 •

edited

Loading

juliens May 17, 2018

ryarnyah May 17, 2018

juliens May 17, 2018

juliens left a comment

nmengin left a comment

Make accesslogs.logTheRoundTrip async to get lost performance #3152

Make accesslogs.logTheRoundTrip async to get lost performance #3152

Conversation

ryarnyah commented Apr 8, 2018 • edited Loading

What does this PR do?

Motivation

More

Additional Notes

mmatur left a comment

Choose a reason for hiding this comment

ryarnyah commented May 14, 2018

juliens left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nmengin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ryarnyah left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ldez commented May 16, 2018

ryarnyah commented May 16, 2018 • edited Loading

ldez commented May 16, 2018

Choose a reason for hiding this comment

ryarnyah May 17, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

juliens left a comment

Choose a reason for hiding this comment

nmengin left a comment

Choose a reason for hiding this comment

ryarnyah commented Apr 8, 2018 •

edited

Loading

ryarnyah left a comment •

edited

Loading

ryarnyah commented May 16, 2018 •

edited

Loading

ryarnyah May 17, 2018 •

edited

Loading