Bug #70677 Connector J with profileSQL - log contains lots of STACKTRACE data
Submitted: 21 Oct 2013 18:27 Modified: 24 May 18:45
Reporter: Robert Sandiford (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S4 (Feature request)
Version:5.1.23 OS:Any
Assigned to: Alexander Soklakov CPU Architecture:Any

[21 Oct 2013 18:27] Robert Sandiford
Description:
In Connector J 5.1.23, when you configure the db url to include "profileSQL=true", the resulting log contains a STACKTRACE with lots of data for each and every statement logged.  This did not happen in 5.1.18.  Looks like the issue was introduced with this commit:
===============
Committer: mark 
Date: 2013-01-08 14:51:34 UTC 
Revision ID: mark-20130108145134-tkr4fe6dsvh6dz7j 

Fix for Bug#67954, stack trace used for point-of-origin in log and exception messages causes permgen leak with webapp classloader on application redeploy. We no longer store the entire stack trace, only the calling class and method, and even then, that only when using the usage advisor or when profiling.
===============
See attachment for more detail.

How to repeat:
As far as I can tell, just change the connection url from something like this:
   jdbc:mysql://localhost:3306/eresource
to this:
   jdbc:mysql://localhost:3306/eresource?profileSQL=true

Suggested fix:
None, really.  I debugged through the two versions of code to see the differences, but don't have a suggestion on a resolution...
[21 Oct 2013 18:28] Robert Sandiford
Shows old / new code change, and old / new log sample

Attachment: profileSQL.output.txt (text/plain), 8.77 KiB.

[22 Oct 2013 10:18] Alexander Soklakov
Hi Robert,
Thanks for your report.

However I don't think it is a bug, "profileSQL=true" is not intended to be used in production environment and for profiling case stacktraces could be useful.

Please inform us whether you have reasons to estimate it as a bug.
[22 Oct 2013 13:19] Robert Sandiford
Thanks for the feedback.  I would fully agree that this is not to be used in production.  However - if all I want to see is the SQL that's being executed, it's now a lot harder, and the log file (even for development) can get very, very large very, very quickly.

I also see the value in being able to determine exactly what code is generating any given SQL.

I suppose it's a tension between being able to see just what SQL is being executed, and understanding where said SQL is coming from.

So - I suppose rather than a bug, this could become an enhancement request - the ability to determine whether profileSQL includes or excludes the execution stack with each SQL statement displayed.  (perhaps make profileSQL more than just a boolean - an enumeration instead, something like 'true' and 'false' (current behaviour for people who are used to it), and 'sqlonly' or some such to suppress the stack trace?)  For my purposes, I know where or can find where the SQL is coming from (almost always :)), and was wanting to see just what the actual generated SQL statements were...

Thanks!
[22 Oct 2013 13:29] Alexander Soklakov
Ok, verified as a feature request.
[2 Jan 2015 20:08] Justin Cranford
Hi,

+1 for this feature request.

The name of LogUtils.expandProfilerEventIfNecessary says it all - "expand profiler event if necessary". Stack traces are not always necessary, so I would also like the option to suppress them.

Instead of always creating a "new Throwable()" at LogUtils.java:49, add support for a new Connector/J property to override it. Default is to include it like now, but override could inject a null, empty string, dummy string, or anything else required to suppress printing of stack traces.

Stack traces are not always necessary.

Thanks,
Justin
[11 Nov 2015 0:26] Kenji Matsuoka
+1 for this, it makes debugging really difficult.
[22 May 2017 8:49] Anders Eknert
Here's another +1 for this feature request. The 'useUsageAdvisor' property exhibits the same behaviour when set to true. All this does really is to hide the information that one was interested in to begin with.
[24 May 18:45] Daniel So
Posted by developer:
 
Added the following entry to the Connector/J 8.0.17 and 5.1.48 changelogs:

"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. "