Re: New driver logging proposal

​​Hi Daniel, first of all, thank you for offering to improve the Driver
logging. My comments are between lines:​

On Fri, Apr 7, 2017 at 11:13 PM, Daniel Migowski <dmigowski(at)ikoffice(dot)de>
wrote:

> Hello,
>
>
>
> this is my proposal for a new PostgreSQL JDBC Driver logging. The aim for
> this is to merge the efforts done in integrating common logging frameworks
> while keeping the performance we had before logging frameworks were
> introduced. Also this proposal should add the functionality to identify
> connections in the logging output, a feature that was lost when a switch to
> logging frameworks was made.
>

​+1 for the functionality to identify connections, it was on my TODO list.​

>
>
> *Current (and previous) state:*
>
>
>
> I assume that people who do logging already use a logging framework of
> their choice, either because they configured it themselves or by using the
> one provided by the container they use. In either way they know how to
> configure logging on the platform they chose.
>

​Sadly you should never "assume"​ anything of what people use, I still know
people that uses System.out.println() to debug.

>
>
> Before logging framework support was introduced we had a single logging
> related Driver parameter called “loglevel”. This could be set to “0” for
> zero logging, to “1” for a log level corresponding to “DEBUG” in modern
> logging frameworks, and to “2” for “TRACE” level logging. There was (and
> seemingly isn’t) a need for higher severity log levels like “INFO”, “WARN”,
> “ERROR” or “FATAL” because events that would cause these are thrown as
> exceptions in the error case while warnings and infos are not generated at
> all from the driver. Logout was written to a LogWriter when this was set on
> the driver, which would in most cases be used to redirect logout to the
> logging framework one had chosen.
>
>
>
> The newer versions of the driver allow the parameters “loggerLevel” and
> “loggerFile”. These choices are intended to interfere with the logging
> framework one uses because change the loglevel programmatically on the
> logging category “org.postgresql”. Also with “loggerFile” one is able to
> configure a special logfile for the logging category. The default value for
>

​These options are to facilitate the configuration of the logger for those
people that don't know or just want an easy way to enable logging.​

>
>
> The current implementation has the side effect that creating a single
> connection will change the log level of ALL connections (loaded by the same
> ClassLoader to be specific) because the loggers are statically defined in
> the classes which is how loggers are used today. Also, although can be
> given as connection parameters, they are not connection specific at all.
> This might not be a problem when one uses only a single connection pool
> where all connections are created equally, but interferes when one has an
> application that occasionally has to fetch data from multiple data sources.
>

​Do you intent to initialize a logger f​or each connection?
You don't need to use connection parameters to use the logger, you can also
use a properties file too.

>
>
> Also, the current implementation makes have use of TRACE level logging in
> all getXXX functions of PgResultSet. A typical line is this:
>
>
>
> *LOGGER*.log(Level.*FINEST*, " getString columnIndex: {0}",
> columnIndex);
>
>
>
> This innocent looking line should do no harm at a first glance, because if
> tracing is disabled the function should leave immediately and no
> performance is lost. One minor problem is the usage of the columnIndex as
> parameter, which is autoboxed into an Integer while passed to the log
> function (involves a hidden call to Integer.valueOf(int), which even
> creates new Objects depending on how aggressive the VM is tuned and on the
> number of columns in the result set.
>

​This has to be backed up by a benchmark​, the autobox should be cheap and
Integer.valueOf(int) will always cache values in the range -128 to 127,
inclusive.

> More important is the implementation of the log function itself, which is
> relative fast when a good Logging Framework is used, and disastrously slow
> in many other cases like when Logback is used. In that case an expensive
> log event is created and passed to the really used logging framework just
> to be discarded there, but this can IMHO be considered an artefact of a
> badly configured framework (still throws a bad light on PostgreSQL JDBC
> performance).
>

​The logging framework currently used is *java.util.logging*, ​so if you
use the Simple Logging Facade (slf4j) and redirect to another
implementation using a bridge then there will be some overhead, with
Logback for instance you need to configure the LevelChangePropagator
<https://logback.qos.ch/manual/configuration.html#LevelChangePropagator>.

>
>
> *Proposed state:*
>
>
>
> I believe the common case is that logging for the driver is disabled. For
> this I propose a Boolean configuration parameter “logging” that can be
> truly configured per connection. Except for a few places where no reference
> to a connection exists, this will silent at least all connection specific
> logging.
>

​I'm not sure why introduce another parameter when the logLevel = OFF can
be used for the same. Do you have an idea about how "truly configured per
connection" can be archived? If I simply don't use the connection
parameters and use the method of configuration provided by my app-server,
how will that work?
​

>
>
> The log level and log destination should be configured by the normal means
> of the logging framework,
> ​​
> exactly how it is done in every other library that provides some means of
> logging.
>
>
​What is the normal means of the logging framework? and exactly how it's
done in every other library that provides some means of logging?
​

>
>
> I saw from the discussion while introducing logging frameworks that there
> was demand for programmatic configuration of log levels and log
> destinations, but since the current implementation does that on the Driver
> level anyway, this should be done by calling static functions on it, not by
> giving connection parameters (this can be discussed). The reason that
> connection pools can be configured easier when these parameters are
> available to the connection is not valid, because either the connection
> pool is created in a container, and then logging is configurable in the
> same textual way anyway and the container user is used to it, or the
> connection pool is created programmatically, and then one is also able to
> configure the driver programmatically on a driver level. Therefore we can
> drop the parameters “loggerLevel” and “loggerFile”, replacing them with
> helper methods on Driver that just configure the java.util.Logging
> framework.
>

​The connection parameters are there to facilitate the configuration of the
logger, and just for those rare cases when there is a need to enable and
discard scenarios, it's not the recomended aproach and not intended to be
used in production.
​

>
>
> Finally it might be nice to be able to identify the connection that logs.
> I like the idea of ??? to encode it in the logging category.
>

​Yes, it might be nice to identify the connection, what do you mean by ???​

> Also usually when logging is used the category is the package that logs.
> It is common to have different logging categories to be able to filter the
> log messages. To be able to combine both I propose a fixed set of logging
> categories (<id> is the connection id):
>
>
>
> org.postgresql.connect.<id> ß Logs connecting and disconnecting
> events. Can log more or less depending on Level. Level INFO logs simple
> connection/disconnection. Level DEBUG also logs parameters given to
> connection. Level TRACE logs the whole connection setup including default
> parameter settings. This also logs WARN messages when connections are
> finalized without having been closed explicitly.
>
> org.postgresql.sql.<id> ß Logs the SQL queries executed on the
> backend. Also logs Bind, Prepare and Execute for PreparedStatements. Level
> INFO logs all SQL here. Level DEBUG could also log all the parameters given
> to statements. Level TRACE could even log the returned results.
>
> org.postgresql.api.<id> ß Logs all interaction with the driver
> through externally callable functions.
>
> org.postgresql.protocol.<id> ß Logs on the protocol level. Should
> always use TRACE level.
>
> org.postgresql.pool.<id> ß Logs connection pool related events. On
> Level INFO we could print simple pool usage like retrieving or releasing
> connections. Maybe there is useful logging on DEBUG level but I don’t know
> for now.
>
> org.postgresql.XXX ß Some more internal logging categories for places
> where we don’t have access to the connection itself. These will always log
> at TRACE level and are not called very often. I will remove potentially
> expensive logging in place called often like in static helper functions of
> BooleanTypeUtil.
>

​I really like the idea of have a fixed set of logging categories. +1
​

>
>
> The connection id could , depending on your use case, simply be an Integer
> used to identify the connection. This could be made optional and even
> configurable because maybe one wants to encode more information in it. I
> propose a Driver-level ConnectionIdFactory that by default just returns
> uses an incrementing id for the connection, but personally I’d like to have
> the database name in it also. Not only a ConnectionLevel Id might be used
> but also a DataSource id. Is also required to intentify for datasource
> specific logging.
>

​I'm not sure if introduce a connection id it's a good idea, just for the
record the logs of the Drivers should be used to debug the driver mostly,
and with this it seems to fix a problem that it's not related to the
Driver.​

>
>
> At least in my application I found it useful to set the log level for all
> third party libraries to WARN, while would also effectively discard most
> logging from the JDBC driver even in the case where logging is disabled.
> With the above categories I now could specifically describe what I am
> interested in, and I believe I covered most use cases one would use logging
> for in it. It got SQL logging for the end user, protocol logging for the
> driver developers, API logging for the end users and application profilers,
> stuff to detect connection leaks and parameters for an administrator. ​
>

>
>
>
> *Implementation details:*
>
>
>
> To achive all this I propose to replace most of the loggers currently used
> with a PgLogger implementation that wraps the usual. We could have a Null
> Logger here that does nothing, and I hope for the VM to simply drop all
> calls to it in compiled code completely when we won’t ever instantiate any
> other implementations of PgLogger, so this will allow for peak performance
> in the default case. This class will have log functions for each level so
> we spare the Level-argument in calls to the functions.
>

​This smells like the "custom logging abstraction" anti-pattern.​

>
>
> Other implementations of that class really do logging. Depending on if we
> want connection level logging we could have individual instances of the
> Loggers per connection and category or just by category.
>

​Do you intent to change to SLF4J?​

>
>
> Depending on the comments to this mail I might do the work.
>
>
>
> Regards,
>
> Daniel Migowski
>
>
>