RFR: 8229517: Support for optional asynchronous/buffered logging [v9]

[Xin Liu]

On Thu, 29 Apr 2021 06:56:05 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

> While still taking much too much memory on average, especially in a context like yours where you want to store resolved decorations.

Hi, Thomas, 

Thank you for reviewing the patch. 

I think we should provide accurate log decorations.  I am okay to compromise if accuracy comes at expensive expense. My performance results suggest that is not.

When I make the patch "Accurate Decorations for AsyncLogging", you can see that I deliberately avoid from changing existed code.  That leaves little room for me to support new features. eg. I can't allocate a LogDecorations object using keyword `new`. Global new/delete are forbidden in HotSpot.  That's why I choose a new class LogDecorationRef. The reason I choose refcnt because I found  LogMessageBuffer used a same LogDecorations object while it iterated.  A refcnt can save duplication.  

I made a new revision which just copy LogDecorations for AsyncLogMessage.  My profiling results show that the optimization of refcnt is very limited. 

Here is my experiment.  
1. baseline: dummy version dump without any log. 
> perf stat -r 200 java --version > /dev/null
2. original dump all logs in trace verbosity. 
> perf stat -r 200 java -Xlog:'all=trace:file=hotspot-gold.log:uptime,tid,l,tg:filecount=0' --version
3. original without decoration
> perf stat -r 200 java -Xlog:'all=trace:file=hotspot-none.log:uptime,none:filecount=0' --version
4. asynclogging refcnt
> perf stat -r 200 java -XX:+AsyncLogging -Xlog:'all=trace:file=hotspot-async-refcnt.log:uptime,tid,l,tg:filecount=0' --version
5. asynclogging copy LogDecorations
> perf stat -r 200 java -XX:+AsyncLogging -Xlog:'all=trace:file=hotspot-async-copying.log:uptime,tid,l,tg:filecount=0' --version


|   |               | wall-time(ms) |   |
|---|---------------|---------------|---|
| 1 | baseline      | 30.928        |   |
| 2 | original      | 98.204        |   |
| 3 | original-none | 84.624        |   |
| 4 | async-refcnt  | 82.632        |   |
| 5 | async-copying | 83.71         |   |
|   |               |               |   |

I compare the generated log files, async logging generates the same result as Original's.  

`original` is synchronous logs.  `async-refcnt` does show the best results, which is 15.8% faster compared to original. It takes benefits from a standalone thread.  `async-copying` is my latest patch which just copys LogDecoratons once.  The performance is very close but the implementation is much simpler.  

`original-none` shows that decorations take a small partition of runtime. The main overhead is still the log messages. Copying it isn't expensive. The benefit of multi-threading can overshadow it.  Is that okay I  revert my refcnt version and replace it with straight-forward copying.

-------------

PR: https://git.openjdk.java.net/jdk/pull/3135