Enhancement suggestion : log auto-committed statements in a special way

[the-w1nd]

First of all - HUGE thanks to everyone contributing and maintaining P6Spy! I've been using it for ages, but never had a chance to express my appreciation to you! Thanks a lot!

One enhancement I'd like to propose is for P6Spy to log Statements with a special message, which were executed on a Connection that had Auto-Commit flag set to TRUE. Since such Statements do not require explicit calls for "commit", it is hard to figure out the transactional boundaries for such calls, so "marking" them in the log would be a big benefit.

The least intrusive way to make the distinction is by listing the Category for such Statements with a new value (e.g. "statement-autocommitted"). But people more familiar with the P6Spy code and its structure will most likely propose a more elegant solution. Please have a look at the attached patch-file that I generated on 3.8.2 release, and let me know if you have any questions or suggestions.

Thanks again!

[typekpb]

@the-w1nd thanks for the idea. Any chance to raise it as a pull request? it would be easier for tracking I guess.
Regarding the idea of having new category? Don't have a better way comming to my mind for tracking that.

The only thing is, that I guess it should be covered with the feature flag (to be backwards compatible).

@gavlyukovskiy ideas?

[the-w1nd]

@typekpb , the 5 lines that I changed in the code are pretty dumb. so I did not bother with making a pull-request. And considering keeping the backwards compatibility, would have to be implemented in some other way. Perhaps, the "autocommitted" flag can just be added as a new tag in the "CustomLineFormat" class, so everything would be backwards compatible, until someone uses the tag.

[gavlyukovskiy]

I like this idea, thank you!

can just be added as a new tag in the "CustomLineFormat" class

I think it's a good option, the only issue is that autoCommit is only relevant for statement events, but there are also resultset, commit, rollback and few other categories which don't need that. Probably we can come up with something generic, like %(attributes) which may contain fields like autocommit=true;batch=false;prepared=true and for ResultSet there will be different parameters like rowcount=10.
This could also help with #467, so that statement can have attribute parameters=value1,value2. WDYT @typekpb?

[typekpb]

@gavlyukovskiy sounds good. So it would mean that people would have to define the:

customLogMessageFormat=%(currentTime)|%(executionTime)|%(category)|connection%(connectionId)|%(sqlSingleLine)|%(attributes)

to make it happen (or whatever format they preffer), right?
If that is the case, I think this could be really flexible way, that could fit all.

[gavlyukovskiy]

@typekpb that's right, I would only swap %(sqlSingleLine) and %(attributes), because first one usually quite long.
I think we can even change default format to include that, I wouldn't say changing log format breaks backward compatibility.

[typekpb]

OK, for changing the default format, I would be rather worried, as people might be used to existing one. But to have it as an option is fine with me.

…

On Thu, Aug 8, 2019 at 5:44 PM Arthur Gavlyukovskiy < ***@***.***> wrote: @typekpb <https://github.com/typekpb> that's right, I would only swap %(sqlSingleLine) and %(attributes), because first one usually quite long. I think we can even change default format to include that, I wouldn't say changing log format breaks backward compatibility. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#484?email_source=notifications&email_token=AAD2A3GNJK4TYYB4UFBPVZLQDQ5NRA5CNFSM4IKEA2A2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD34BGAA#issuecomment-519574272>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAD2A3E3AC3E3SIMPS4GA2TQDQ5NRANCNFSM4IKEA2AQ> .

[the-w1nd]

Okay ... now it's starting to get into an interesting shape that could be an awesome feature for the library!

But as you mentioned, every Category will have many attributes that would be interesting to see under various circumstances - for example, ResultSet.getFetchSize(), ResultSet.getFetchDirection() and Statement.getUpdateCount() is to name a few. So, the full set of attributes can be overwhelming and could pollute the log with useless information. What do you think about making it a more flexible tag that would allow specifying particular attributes that the user wants to see? Just as an example:

• %(attributes) - would pull all captured attributes of the current Category
• %(attributes:Statement.*) - would log all attributes only for "statement" Category
• %(attributes:ResultSet.getFetchSize,Statement.getUpdateCount,Statement.getAutoCommit) - will print the specified attributes only

This would bring the possibility of peeking the Metadata of the Connection and pulling some interesting attributes out of it - it's been a long struggle for me to separate a single log file for multiple ConnectionPools in the AppServer. Since every ConnectionPool connects to its own schema, if I could retrieve and log Statement.getConnection().getMetadata().getUserName() value, that would solve my troubles.

I better stop before I get carried away. :)

[typekpb]

@the-w1nd well, I have a bad news here. For the things you mentioned, you should better introduce the custom implementation programically, using:

logMessageFormat=foo.bar.WhateverYourFormatIsFormat

As going for the full configurability moves us the way towards reflection and parsing the string => makes things sloooow.

Now as you moved it a bit forward, I wonder if introducing %(attributes) brings any value at all. As people are probably interested in the specific values only and logging only a selected set might not fit anyone anyway.

@gavlyukovskiy ideas?

[the-w1nd]

Reflection is definitely not what I had in mind, because it will definitely drag the ... performance down. I was more thinking about caching the particular attribute values within ConnectionInformation, StatementInformation and ResultSetInformation objects, so they can be retrieved directly as long as the requested %(attributes) are pre-parsed and "mapped" to the corresponding cached values once (or every time the format string changes). If you don't see a good way of implementing it, then I should not venture in trying it, since you're the most familiar with the class hierarchy and dependencies.

Regarding writing a custom logger class - it would not have necessary access to the actual objects, because it gets a fixed set of property values (see the com.p6spy.engine.spy.appender.MessageFormattingStrategy interface).

[gavlyukovskiy]

@the-w1nd you can actually go deeper and override LoggingEventListener itself, see EventListenerServiceLoaderTest as reference.

it's been a long struggle for me to separate a single log file for multiple ConnectionPools in the AppServer

probably this can be solved with Slf4JLogger if we make logger name configurable (e.g. p6spy-), then you can route logs to different appenders if your logging library supports that.

@typekpb I agree that we can't fulfill everyone's needs with default format, including too much will definitely hurt performance. Even now I'm not really happy that CustomLineFormat does replaceAll with bunch of staff that is could even not be in the pattern, like replaceAll(Pattern.quote(SQL_SINGLE_LINE), Matcher.quoteReplacement(P6Util.singleLine(sql))). I would say it should be lazy at least and if we try to get some meta information it should be cached on a proper level.
Anyway current interface MessageFormattingStrategy wipes out most interesting information so can be barely used to create custom implementation without access to ConnetionInformation, StatementInformation and ResultSetInformation. But probably for advanced usage it's just easier to suggest to override LoggingEventListener instead.

[typekpb]

@gavlyukovskiy sounds like this one might be a candidate for closing.
Or do you see a realistic way to make this happen?

[the-w1nd]

If you guys don't see an easy way to approach or implement the feature, I'll try to take a stab at it when I get some spare time.

[the-w1nd]

I'll give it a shot. If something good is going to come out, I'll create a pull request for review.

[typekpb]

@the-w1nd perfect, thanks!

[the-w1nd]

Guys, after some learning curve, I believe I created my first ever GitHub Pull Request #485 . Let me know if I did something wrong in the Pull, and please share any comments you might have on the code changes. They are just a proof-of-concept for now and need your guidance if they are in the right direction.

Thanks!

[the-w1nd]

Have you had a chance to take a look at the changes? Just wondering if you need more time, or if I did something wrong with the draft pull request? My intention was to collect any comments and suggestions before continuing changing the code. Any guidance would be appreciated.

[typekpb]

hello, sorry for no response on that. I'm super-busy these days to be honest. can't promise any timeline yet.

[the-w1nd]

No worries and no rush. Since this was my first pull request on GitHub, I was worried if I did something wrong with it. Please do take your time and let me know what you think about it.

[gavlyukovskiy]

@the-w1nd looked at this a long time ago and the problem was that it changes too many interfaces that people can use. It makes it impossible to do this change without breaking changes and I don't think this feature worth it. I've spent couple of days trying to figure out how to do it, but gave up. Although parameter url was added in 2018 - #446, it caused issues for some folks - #452
I don't really like how it's done right now, when getSql/getSqlWithValues is implemented by all three ConnectionInformation, StatementInformation and ResultSetInformation and only values of those methods are passed to our MessageFormattingStrategy. I think the best way would be introducing new interface that has access to *Information allowing people to write more complex implementation and for us to evolve it in a backward compatible way.