Bug #94101 Setting logSlowQueries should not automatically enable profileSQL for queries
Submitted: 28 Jan 15:14 Modified: 29 Jan 12:54
Reporter: Florian Agsteiner (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:Connector / J Severity:S5 (Performance)
Version:8.0.14 OS:Any (Java Connector)
Assigned to: CPU Architecture:Any
Tags: logSlowQueries

[28 Jan 15:14] Florian Agsteiner
Description:
Hello fellow developers!

I was analysing a couple of flame graphs with the setting logSlowQueries enabled and saw the following method was very frequently called: LogUtils.findCallingClassAndMethod

When using a lot of short queries the stack trace gathering accounted for 30-40% of the samples.

The methods in question are:
1.) com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(Query, NativePacketPayload, int, boolean, String, ColumnDefinition, GetProfilerEventHandlerInstanceFunction, ProtocolEntityFactory<T, NativePacketPayload>)
2.) com.mysql.cj.jdbc.StatementImpl.StatementImpl(JdbcConnection, String)

I looked around and in the other places I've found where profileSQL is used. It is handled separate from logSlowQueries. It seems like in the two places it was just left there out of convenience.

In my humble option should findCallingClassAndMethod should only be called if profiling/usageAdvisor is enabled or if logSlowQueries is enabled and a slow query is detected.

I provided a pull request that would change the following:

In 1.) i remove logSlowQueries from the boolean expression since it is not used later on anyway.
In 2.) I removed logSlowQueries from the outer if to run only if both are enabled, and call findCallingClassAndMethod only once.

Kind regards
Florian

How to repeat:
* Enabled logSlowQueries and disabled profileSQL
* Run 10.000 queries where none is slow
* LogUtils.findCallingClassAndMethod is called even though the result is not used

Suggested fix:
The methods in question are:
1.) com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(Query, NativePacketPayload, int, boolean, String, ColumnDefinition, GetProfilerEventHandlerInstanceFunction, ProtocolEntityFactory<T, NativePacketPayload>)
2.) com.mysql.cj.jdbc.StatementImpl.StatementImpl(JdbcConnection, String)

In my humble option should findCallingClassAndMethod should only be called if profiling/usageAdvisor is enabled or if logSlowQueries is enabled and a slow query is detected.

I provided a pull request that would change the following:

In 1.) i remove logSlowQueries from the boolean expression since it is not used later on anyway.
In 2.) I removed logSlowQueries from the outer if to run only if both are enabled, and call findCallingClassAndMethod only once.

It can be found here: https://github.com/mysql/mysql-connector-j/pull/31
[28 Jan 15:15] Florian Agsteiner
Flamegraph

Attachment: flame_html.png (image/png, text), 1.33 MiB.

[29 Jan 11:14] Umesh Shastry
Hello Florian,

Thank you for the report.
Please note that in order to submit contributions you must first sign the Oracle Contribution Agreement (OCA). For additional information please check http://www.oracle.com/technetwork/community/oca-486395.html.
If you have any questions, please contact the MySQL community team https://dev.mysql.com/community/

regards,
Umesh
[29 Jan 12:54] Florian Agsteiner
Hello Umesh,

I will do that. Thank you!

- Florian
[30 Jan 14:00] Florian Agsteiner
Changes

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: patch.diff (application/octet-stream, text), 3.37 KiB.