logbook icon indicating copy to clipboard operation
logbook copied to clipboard

Performance tests

Open whiskeysierra opened this issue 8 years ago • 23 comments

Since we are logging the message body most users will rightly question how fast this is and what performance penalty they should expect.

  • [x] implement tests
  • [ ] put results in the readme

whiskeysierra avatar May 23 '16 06:05 whiskeysierra

So would it make sense to first go with a JMH style benchmarking and then perhaps later move on to a full spring boot example app + load testing tool like Gatling?

The overall impact in a full spring boot app will probably be relatively low, perhaps 10%.

skjolber avatar Mar 12 '18 14:03 skjolber

So would it make sense to first go with a JMH style benchmarking and then perhaps later move on to a full spring boot example app + load testing tool like Gatling?

Absolutely.

whiskeysierra avatar Mar 14 '18 22:03 whiskeysierra

I'm not absolutely sure about what a performance test would bring here. Primarily it would measure buffer to I/O copying. What should it be compared against, and what should a value tell the logbook user?

tkrop avatar Mar 19 '18 09:03 tkrop

What should it be compared against

Against not using logbook. Users should have a clue how big the penalty is.

whiskeysierra avatar Mar 20 '18 07:03 whiskeysierra

Against not using logbook. Users should have a clue how big the penalty is.

Does not really make sense in my opinion, especially as logbook provides many customization switches and inefficiencies. Either users need to log or they do not need to log. The only aspects, that makes sense to test in my view, are to compare whether the selected solution has more overhead than another default or handwritten solution, or to find out whether the solution has an efficiency problem.

For the latter one I would use small micro-performance tests on the utilized components that will not have any meaning for the users. By the way, if we really care about performance and penalties, we should start by optimizing the formatters - in this classes I can just see the inefficiencies by reviewing the code.

tkrop avatar Mar 20 '18 09:03 tkrop

compare whether the selected solution has more overhead than another default or handwritten solution

That's the biggest motivator for me. Comparing against https://github.com/zalando/logbook#alternatives, for example.

whiskeysierra avatar Mar 20 '18 09:03 whiskeysierra

Note on JsonHttpLogFormatter - it slows it down first calling prepare(..) then format(..) (in StructuredHttpLogFormatter), that should really be a single step for converting right to JSON.

skjolber avatar May 16 '19 10:05 skjolber

You mean the intermediate map is too heavy?

whiskeysierra avatar May 16 '19 11:05 whiskeysierra

Well at least wasteful. A JsonWriter or (even faster) a StringBuilder is preferable.

skjolber avatar May 16 '19 11:05 skjolber

Well. I believe we have bigger issues. Or at least I'd like to make sure that this is the biggest performance issue we have :stuck_out_tongue_winking_eye:

whiskeysierra avatar May 16 '19 12:05 whiskeysierra

These jackson objects are a bit heavy, so my guess is that this will be in the 10 percent range improvement. Filtering the payloads will be the most demanding part I think. I've written this filter for XML:

https://github.com/skjolber/xml-log-filter

But have yet to see a similar JSON log filter using the same approach.

So would a gradle-based approach with JMH and a visualizer be a good starting point? Like https://github.com/skjolber/java-jwt-benchmark ?

skjolber avatar May 16 '19 12:05 skjolber

So would a gradle-based approach with JMH and a visualizer be a good starting point? Like https://github.com/skjolber/java-jwt-benchmark ?

I'd love that! :heart:

whiskeysierra avatar May 16 '19 12:05 whiskeysierra

@whiskeysierra okey, can you create a repository like logbook-benchmark, logbook-jmh etc? I'll drop in the project sceleton (copy from java-jwt-benchmark) with a few PoC tests. I cant promise to write very many tests, outside the JSON-related parts, but probably this will get the ball rolling.

skjolber avatar May 16 '19 14:05 skjolber

Can we create those as modules within this repository?

whiskeysierra avatar May 16 '19 14:05 whiskeysierra

Should be possible, for project setup the most important is to get a jmh-visualizer (i.e. https://github.com/jzillmann/jmh-visualizer) automatically hooked into JMH output and being able to run just a subset of the benchmarks at a time.

It is possible to do with pure text, but a visualization is really better.

skjolber avatar May 16 '19 14:05 skjolber

I've not found a maven plugin for this jmh visualizer yet though.

skjolber avatar May 16 '19 14:05 skjolber

Leave the visualizer to me. Maybe I will produce it by hand specifically for this project.

Doesn't look so hard https://github.com/jzillmann/gradle-jmh-report/blob/master/src/main/kotlin/io/morethan/jmhreport/gradle/task/JmhReportTask.kt

whiskeysierra avatar May 16 '19 14:05 whiskeysierra

Is this your first Maven plugin? :chart_with_downwards_trend: There is always drag'n drop to https://jmh.morethan.io.

skjolber avatar May 19 '19 23:05 skjolber

I'll have to split this into multiple PRs. First a new module logbook-jmh and a README with some instructions. I think release and unit test coverage should be dropped from the new module.

There might be issues with competing implementations down the road, but lets cross that bridge then.

You will in general have to accept PRs with baseline benchmarks before actually accepting PRs with performance-enhancing changing.

Results so far:

  • Logbook is more fast than slow.
  • Default HttpLogFormatter is slow, however performance can be improved a lot.
  • JsonHttpLogFormatter is faster than expected.
  • JsonMediaType runs a lot of times, its performance can be improved a lot.
  • There is a JSON filter for filtering a JWT client credentials request by default.

This might be a good time to discuss benchmarking in this project:

  • Inevitably, faster implementations will be more complex than the base implementations.
    • balance excellent performance against trashing the codebase.
    • Simpler implementations might still be kept around as part of unit testing.
  • Running operations multiple thousand times a second might seem overkill, but it does make sense to relate the time spent as
    • improved response time (we're going to run the code > 10 times in some cases)
    • alternative use of CPU time, both internally and externally
  • checklist for submitting benchmarks

skjolber avatar May 20 '19 00:05 skjolber

Added https://github.com/zalando/logbook/pull/511. Have a few improvements after it lands. Lets just go with the online visualizer for now.

skjolber avatar May 20 '19 11:05 skjolber

The current merge(left, right) pattern makes collecting multiple operations into one, like remove or replace headers, impossible. So each operation needs to create new objects (like TreeMap) which slows performance down.

skjolber avatar May 22 '19 10:05 skjolber

FYI an 'ugly' rewrite of the Json HTTP Logger did improve performance, but no more than 10-25%.

https://github.com/zalando/logbook/compare/master...skjolber:jmhJsonHttpLogFormatter

I am guessing you think thats is not worth it.

skjolber avatar Jun 04 '19 11:06 skjolber

I suspect SplunkHttpLogFormatter would see a significant performance improvement by moving to using a StringBuilder, if anyone (@nsmolenskii) is interested in giving it a go.

skjolber avatar Jun 14 '19 13:06 skjolber