Thread: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
I tried to paste an image with a profile, but my email was rejected. It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls? Thanks
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Looking at the stacktrace of the profile though, it seems it passes this code:
if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:
Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server'stime
Looking at the stacktrace of the profile though, it seems it passes this code:
if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:
Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
On 22/03/17 17:32, Dave Cramer wrote:
I'm confused when you say it passes this, does it return or continue after this if statement ?On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server'stime
On 22/03/17 17:32, Dave Cramer wrote:
I'm confused when you say it passes this, does it return or continue after this if statement ?On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) { return; }
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:
I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:
I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:
Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of myserver's time
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:
Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Hi, after configuring propagator, the time it takes to run some heavy queries dropped from 5s to 1.7s !
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/
configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.
org [mailto:pgsql-jdbc-owner@ postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com
> wrote: I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com
> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Hi, after configuring propagator, the time it takes to run some heavy queries dropped from 5s to 1.7s !
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/
configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.
org [mailto:pgsql-jdbc-owner@ postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com
> wrote: I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com
> wrote: I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
It is useful that you can plug arbitrary logging frameworks into it. I don’t know if that was possible before. But it is correct, this comes with overhead, which I measured also. I didn’t compare it thought.
Daniel Migowski
Von: davecramer@gmail.com [mailto:davecramer@gmail.com] Im Auftrag von Dave Cramer
Gesendet: Donnerstag, 23. März 2017 14:23
An: Konstantinos Kougios <kostas.kougios@googlemail.com>
Cc: Daniel Migowski <dmigowski@ikoffice.de>; Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: AW: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
So as someone who doesn't use logging in this way. Is having java.util.logging useful ? The old logging mechanism didn't have these problems
Dave Cramer
davec@postgresintl.com
On 23 March 2017 at 09:21, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
Hi, after configuring propagator, the time it takes to run some heavy queries dropped from 5s to 1.7s !
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
It is useful that you can plug arbitrary logging frameworks into it. I don’t know if that was possible before. But it is correct, this comes with overhead, which I measured also. I didn’t compare it thought.
Daniel Migowski
Von: davecramer@gmail.com [mailto:davecramer@gmail.com] Im Auftrag von Dave Cramer
Gesendet: Donnerstag, 23. März 2017 14:23
An: Konstantinos Kougios <kostas.kougios@googlemail.com>
Cc: Daniel Migowski <dmigowski@ikoffice.de>; Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: AW: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
So as someone who doesn't use logging in this way. Is having java.util.logging useful ? The old logging mechanism didn't have these problems
Dave Cramer
davec@postgresintl.com
On 23 March 2017 at 09:21, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
Hi, after configuring propagator, the time it takes to run some heavy queries dropped from 5s to 1.7s !
Indeed a boolean will even make things faster, so I will update as soon as it is ready, thanks
On 23/03/17 13:19, Daniel Migowski wrote:Hello,
At first: Did you configure the Level Change Propagator? https://logback.qos.ch/manual/configuration.html
Also: I am currently working on a patch that does exactly that for ResultSets, because not only can evaluating the log level be very slow when not using the same logging framework than the intented one, but also most of the log statements in PgConnection and PgResultSet have hidden object creation issues because primitive types are passed to calls that expect objects.
I would implement that in a way where the log level is only evaluated at query start, and then cached until the next query. Should be good enough for most scenarios and make the driver 5% faster out of the box. Expect some substantial performance improvements from this.
I will need a few days to be able to have this ready for a pull request, please standby.
Regards,
Daniel Migowski
Von: pgsql-jdbc-owner@postgresql.org [mailto:pgsql-jdbc-owner@postgresql.org] Im Auftrag von Konstantinos Kougios
Gesendet: Mittwoch, 22. März 2017 18:35
An: Dave Cramer <pg@fastcrypt.com>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
It continues. It must be a misconfig of logback+common logging
On 22/03/17 17:32, Dave Cramer wrote:I'm confused when you say it passes this, does it return or continue after this if statement ?
Dave Cramer
davec@postgresintl.com
On 22 March 2017 at 13:24, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I am using logback and I don't see any postgres-driver related logging, so I assume it should be off
Looking at the stacktrace of the profile though, it seems it passes this code:if (!isLoggable(level)) {return;}
So it seems as if it is ON though it doesn't log anything.
On 22/03/17 17:21, Jorge Solórzano wrote:Have you enabled the Logger with a FINEST (TRACE) level?
On Wed, Mar 22, 2017 at 11:13 AM, Konstantinos Kougios <kostas.kougios@googlemail.com> wrote:
I tried to paste an image with a profile, but my email was rejected.
It seems logging is called in places like row.getInt(), row.getString() etc without a check for the logging level. Then it takes a lot of time for those to be processed, especially for queries that get a lot of data. It goes down to parsing strings and locale and it just is slow. I see postgres processing a query for 1 sec but on the java side it takes 5 secs to get the data back to my code. Part of this slowdown is due to the logging. Can it be optimized, i.e. having a boolean to true/false if logging is enabled and then do the calls?
Thanks
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
Hallo Vladimir,
OK, I will provide. Just give me a few days, because I am very full of work at the moment.
Regards,
Daniel Migowski
Von: Vladimir Sitnikov [mailto:sitnikov.vladimir@gmail.com]
Gesendet: Sonntag, 16. April 2017 12:59
An: Daniel Migowski <dmigowski@ikoffice.de>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>; Dave Cramer <pg@fastcrypt.com>; Konstantinos Kougios <kostas.kougios@googlemail.com>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
Daniel,
Would you please share your benchmarks?
I don't se how did you arrive at 30% overhead for the logging.
My benchmarks show no overhead attributed to java.util.logging.
I did try org.postgresql.benchmark.statement.ProcessResultSet.bindExecuteFetch, JDK 1.8.0_102,
columnIndexType = INDEX, getter = BEST, ncols = 5, nrows = 100, reuseStatement = false, type = BOOL, unique = false.
The results are:
9.4.1212:
150±8 us / op, 42032 bytes allocated / op
where op is "bind, execute, and fetch resultset of 100 rows, 5 bool columns each"
42.0.0:
120±8 us / op, 18032 bytes allocated / op
Note: bools are faster in 42.0.0 thanks to Jorge's improvement in https://github.com/pgjdbc/pgjdbc/commit/e69e4a1d5502319bc810e0e4529611ba52ea386c
String results are exactly the same:
9.4.1212:
140±6 us / op, 54103 bytes allocated / op
42.0.0:
140±3 us / op, 54103 bytes allocated / op
That basically means, logging is a no-op provided it is not activated.
JFR recordings show no evidence of java.util.logging on the hot methods list.
logging.isLoggable is rather simple method (it does not walk logger hierarchy), so current logging is expected to be lightweight.
Vladimir
Hallo Vladimir,
OK, I will provide. Just give me a few days, because I am very full of work at the moment.
Regards,
Daniel Migowski
Von: Vladimir Sitnikov [mailto:sitnikov.vladimir@gmail.com]
Gesendet: Sonntag, 16. April 2017 12:59
An: Daniel Migowski <dmigowski@ikoffice.de>
Cc: Jorge Solórzano <jorsol@gmail.com>; List <pgsql-jdbc@postgresql.org>; Dave Cramer <pg@fastcrypt.com>; Konstantinos Kougios <kostas.kougios@googlemail.com>
Betreff: Re: [JDBC] 42.0.0.jre7, driver logging takes 30-40% of my server's time
Daniel,
Would you please share your benchmarks?
I don't se how did you arrive at 30% overhead for the logging.
My benchmarks show no overhead attributed to java.util.logging.
I did try org.postgresql.benchmark.statement.ProcessResultSet.bindExecuteFetch, JDK 1.8.0_102,
columnIndexType = INDEX, getter = BEST, ncols = 5, nrows = 100, reuseStatement = false, type = BOOL, unique = false.
The results are:
9.4.1212:
150±8 us / op, 42032 bytes allocated / op
where op is "bind, execute, and fetch resultset of 100 rows, 5 bool columns each"
42.0.0:
120±8 us / op, 18032 bytes allocated / op
Note: bools are faster in 42.0.0 thanks to Jorge's improvement in https://github.com/pgjdbc/pgjdbc/commit/e69e4a1d5502319bc810e0e4529611ba52ea386c
String results are exactly the same:
9.4.1212:
140±6 us / op, 54103 bytes allocated / op
42.0.0:
140±3 us / op, 54103 bytes allocated / op
That basically means, logging is a no-op provided it is not activated.
JFR recordings show no evidence of java.util.logging on the hot methods list.
logging.isLoggable is rather simple method (it does not walk logger hierarchy), so current logging is expected to be lightweight.
Vladimir
Hi Vladimir, here are the results from my test of PosgtresSQL JDBC 9.4.1212 vs 42.0.0 (as I mentioned on github). It is a single run in a VM but it is ease to have several runs. IMO the results don't show performance degradation at least for the tested simple testcases - yes, there are some fluctuations but nothing significant. The computer I'm running the VM is using very modest Intel Celeron N3150. If someone has access to more powerful hardware it will be good to run the tests also - the current setup is not so good in detecting small changes in performance - too much time is spend in CPU emulation in the VM. I'm using the code base of TFB and particularly the Java/servlet implementation. The code is NOT having a logging framework in the classpath. At least I'm not aware of it and I've checked the maven dependencies. The servlet container is Resin 4.0.48. If anyone wish to take a look don't forget to provide the correct maven profile (-P v42 or -P v9). The logs of the run are here: https://github.com/zloster/logs/tree/master/FrameworkBenchmarks/postgreJDBC-9.4.1212-vs-42.0.0 The numbers are here: https://github.com/zloster/logs/blob/master/FrameworkBenchmarks/postgreJDBC-9.4.1212-vs-42.0.0/results.json The servlet implementation is here: https://github.com/zloster/FrameworkBenchmarks/tree/postgrejdbc/frameworks/Java/servlet The branch is here: https://github.com/zloster/FrameworkBenchmarks/tree/postgrejdbc For other details consult the logs or ask me. About https://github.com/pgjdbc/pgjdbc/issues/793 - it should be fairly easy to have a servlet with Log4j logger and some servlet with some other logger also. Even if the test tables are very small there are quite a lot of resultset processing. If there is performance degradation maybe it will show up as a difference. Cheers, zloster