MySQL Bugs: #94101: Setting logSlowQueries should not automatically enable profileSQL for queries

Bug #94101	Setting logSlowQueries should not automatically enable profileSQL for queries
Submitted:	28 Jan 2019 15:14	Modified:	26 Jun 2019 15:57
Reporter:	Florian Agsteiner (OCA)	Email Updates:
Status:	Closed	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

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

Flamegraph

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

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

Hello Umesh,

I will do that. Thank you!

- Florian

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.

Posted by developer:
 
Added the following entry to the Connector/J 8.0.17, 5.1.48 changelog:

"Enabling logSlowQueries resulted in many unnecessary calls of LogUtils.findCallingClassAndMethod(). With this fix, LogUtils.findCallingClassAndMethod() is called only when profileSQL is true and even in that case, the number of calls are reduced to a minimal to avoid the excessive stack trace data the function used to generate. Thanks to Florian Agsteiner for contributing to the fix."