Thread: Log a sample of transactions

Log a sample of transactions

From
Adrien Nayrat
Date:
Hello,

Per idea of Nikolay Samokhvalov[1] I propose this patch to add the possibility
to log all statements from a fraction of transactions.

I have several questions:
  * Do we want this feature?
  * How can I add tests? I seems hard to handle tests when a there is duration
in the output.
  * Should I handle the case when someone try to change the setting *inside* a
transaction:

# SET client_min_messages to LOG;
SET
# SET log_transaction_sample_rate to 1;
SET
# BEGIN;
LOG:  duration: 0.364 ms  statement: BEGIN;
BEGIN
# SELECT 1;
LOG:  duration: 0.530 ms  statement: SELECT 1;
-[ RECORD 1 ]
?column? | 1

# SET log_transaction_sample_rate to 0;
LOG:  duration: 0.333 ms  statement: SET log_transaction_sample_rate to 0;
SET
# SELECT 1;
LOG:  duration: 0.586 ms  statement: SELECT 1;
-[ RECORD 1 ]
?column? | 1

Thanks

[1]:
https://www.postgresql.org/message-id/CANNMO%2BLg65EFqHb%2BZYbMLKyE2y498HJzsdFrMnW1dQ6AFJ3Mpw%40mail.gmail.com


--
Adrien NAYRAT

Attachment

Re: Log a sample of transactions

From
Peter Eisentraut
Date:
On 12/12/2018 22:32, Adrien Nayrat wrote:
> Per idea of Nikolay Samokhvalov[1] I propose this patch to add the possibility
> to log all statements from a fraction of transactions.
> 
> I have several questions:
>   * Do we want this feature?

It's not clear to me what the use is.  The per-statement sampling allows
you to capture slow queries without overwhelming the logs.  We don't
have any logging of slow transactions or any other transaction scope
logging, so what will this sample?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


Re: Log a sample of transactions

From
Adrien Mobile
Date:
Le 4 janvier 2019 13:20:09 GMT+01:00, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> a écrit :
>On 12/12/2018 22:32, Adrien Nayrat wrote:
>> Per idea of Nikolay Samokhvalov[1] I propose this patch to add the
>possibility
>> to log all statements from a fraction of transactions.
>>
>> I have several questions:
>>   * Do we want this feature?
>
>It's not clear to me what the use is.  The per-statement sampling
>allows
>you to capture slow queries without overwhelming the logs.  We don't
>have any logging of slow transactions or any other transaction scope
>logging, so what will this sample?
>
>--
>Peter Eisentraut              http://www.2ndQuadrant.com/
>PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hello,
When you troubleshoot applicative issues with multi-statements transaction, you may have to log all queries to find all
statementsof one transaction. With high throughput, it could be hard to log all queries without causing troubles.  
The goal of this patch is to be able to log a sample of transactions. I agree the use case is specific.
Regards
--
Sent from my Android phone with K-9 Mail. Please excuse my brevity.


RE: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear Adrien,

I applied your file and faced a bug-candidate.
(I have not read your source yet. Sorry.)

When I tried to use tab-complition, some dirty messages were appeared.

Messages I faced are attached in this mail.

Best Regards,
Hayato Kuroda
Fujitsu LIMITED


Attachment

Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/15/19 9:00 AM, Kuroda, Hayato wrote:
> Dear Adrien,
> 
> I applied your file and faced a bug-candidate.
> (I have not read your source yet. Sorry.)
> 
> When I tried to use tab-complition, some dirty messages were appeared.
> 
> Messages I faced are attached in this mail.
> 
> Best Regards,
> Hayato Kuroda
> Fujitsu LIMITED
> 

Hello,

Thanks for your review ;)

Your messages looks normal to me, you will have same messages if you put 
log_min_duration to 0.

However, my compiler warn me of multiple definition of xact_is_sampled. 
I fix it in this 2nd patch.

Regards,

Attachment

Re: Log a sample of transactions

From
Masahiko Sawada
Date:
On Sat, Jan 5, 2019 at 12:57 AM Adrien Mobile
<adrien.nayrat@anayrat.info> wrote:
>
> Le 4 janvier 2019 13:20:09 GMT+01:00, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> a écrit :
> >On 12/12/2018 22:32, Adrien Nayrat wrote:
> >> Per idea of Nikolay Samokhvalov[1] I propose this patch to add the
> >possibility
> >> to log all statements from a fraction of transactions.
> >>
> >> I have several questions:
> >>   * Do we want this feature?
> >
> >It's not clear to me what the use is.  The per-statement sampling
> >allows
> >you to capture slow queries without overwhelming the logs.  We don't
> >have any logging of slow transactions or any other transaction scope
> >logging, so what will this sample?
> >
> >--
> >Peter Eisentraut              http://www.2ndQuadrant.com/
> >PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>
> Hello,
> When you troubleshoot applicative issues with multi-statements transaction, you may have to log all queries to find
allstatements of one transaction. With high throughput, it could be hard to log all queries without causing troubles. 

Hm, can we use log_min_duration_statement to find slow queries of a
transaction instead? Could you please elaborate on the use-case?

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/15/19 11:42 AM, Masahiko Sawada wrote:
>> When you troubleshoot applicative issues with multi-statements transaction, you may have to log all queries to find
allstatements of one transaction. With high throughput, it could be hard to log all queries without causing troubles.
 
> Hm, can we use log_min_duration_statement to find slow queries of a
> transaction instead? Could you please elaborate on the use-case?

Hello,

The goal is not to find slow queries in a transaction, but troubleshoot 
applicative issue when you have short queries.

Sometimes you want to understand what happens in a transaction, either 
you perfectly know your application, either you have to log all queries 
and find ones with the same transaction ID (%x). It could be problematic 
if you have a huge traffic with fast queries.


Thanks,


RE: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear Adrien,

> Your messages looks normal to me, you will have same messages if you put 
> log_min_duration to 0.

That was my lack of understanding. Sorry.

By the way, I think the name of this parameter should be changed.
In the Cambridge dictionary, the word "rate" means as follows:

the speed at which something happens or changes, 
or the amount or number of times it happens or changes in a particular period.

This parameter represents "probability" whether it log, 
therefore this name is inappropriate.
You should use "probability" or "ratio", I think.


Next week I will give you some comments about your good source.

Best Regards,
Hayato Kuroda
Fujitsu LIMITED

Re: Log a sample of transactions

From
Michael Paquier
Date:
On Tue, Jan 15, 2019 at 06:03:36PM +0100, Adrien NAYRAT wrote:
> The goal is not to find slow queries in a transaction, but troubleshoot
> applicative issue when you have short queries.
>
> Sometimes you want to understand what happens in a transaction, either you
> perfectly know your application, either you have to log all queries and find
> ones with the same transaction ID (%x). It could be problematic if you have
> a huge traffic with fast queries.

Looks like a sensible argument to me.  High log throughput can cause
Postgres performance to go down by a couple of percents, which kills
the purpose of tracking down performance problems as this could impact
directly the application.
--
Michael

Attachment

Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/16/19 1:40 AM, Kuroda, Hayato wrote:
> By the way, I think the name of this parameter should be changed.
> In the Cambridge dictionary, the word "rate" means as follows:
> 
> the speed at which something happens or changes,
> or the amount or number of times it happens or changes in a particular period.
> 
> This parameter represents "probability" whether it log,
> therefore this name is inappropriate.
> You should use "probability" or "ratio", I think.

Hum, I am not an english native speaker, I choosed "rate" because it is 
already used for auto_explain.sample_rate and for log_statement_sample_rate

> 
> 
> Next week I will give you some comments about your good source.

Thanks!


Re: Log a sample of transactions

From
Masahiko Sawada
Date:
On Wed, Jan 16, 2019 at 2:03 AM Adrien NAYRAT
<adrien.nayrat@anayrat.info> wrote:
>
> On 1/15/19 11:42 AM, Masahiko Sawada wrote:
> >> When you troubleshoot applicative issues with multi-statements transaction, you may have to log all queries to
findall statements of one transaction. With high throughput, it could be hard to log all queries without causing
troubles.
> > Hm, can we use log_min_duration_statement to find slow queries of a
> > transaction instead? Could you please elaborate on the use-case?
>
> Hello,
>
> The goal is not to find slow queries in a transaction, but troubleshoot
> applicative issue when you have short queries.
>
> Sometimes you want to understand what happens in a transaction, either
> you perfectly know your application, either you have to log all queries
> and find ones with the same transaction ID (%x). It could be problematic
> if you have a huge traffic with fast queries.
>

Thank you for the explain! I understood the use case of this patch.
This feature would be helpful for troubleshooting.

Since we set xact_is_sampled only when transaction starts and see it
during transaction we cannot disable logging during transaction and
vice versa. I can imagine the use case where user wants to disable
logging during transaction. So it might be better to also check if
log_xact_sample_rate > 0 in check_log_duration().

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/16/19 10:09 AM, Masahiko Sawada wrote:
> Since we set xact_is_sampled only when transaction starts and see it
> during transaction we cannot disable logging during transaction and
> vice versa. I can imagine the use case where user wants to disable
> logging during transaction. So it might be better to also check if
> log_xact_sample_rate > 0 in check_log_duration().

I Agree, here is third patch.

Thanks!


Attachment

Re: Log a sample of transactions

From
Peter Eisentraut
Date:
On 15/01/2019 18:03, Adrien NAYRAT wrote:
> The goal is not to find slow queries in a transaction, but troubleshoot 
> applicative issue when you have short queries.
> 
> Sometimes you want to understand what happens in a transaction, either 
> you perfectly know your application, either you have to log all queries 
> and find ones with the same transaction ID (%x). It could be problematic 
> if you have a huge traffic with fast queries.

But if you have trouble with a specific transaction, how will a setting
help that randomly logs transactions, not necessarily the one you are
concerned about?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/18/19 9:03 AM, Peter Eisentraut wrote:
> But if you have trouble with a specific transaction, how will a setting
> help that randomly logs transactions, not necessarily the one you are
> concerned about?

Yes, it assumes your application performs same type of transaction. 
Maybe the use case is too specific to have this feature in core?



RE: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear Adrien,

> Hum, I am not an english native speaker, I choosed "rate" because it is 
> already used for auto_explain.sample_rate and for log_statement_sample_rate

If the community agree those name, renaming parameters are not needed.
Consistency is the most important in a DBMS. :-)

I read your source code and I thought it is generally good.
Here are some minor suggestions, but you don't have to follow strictly:

---- config.sgml ----
You must document the behavior when users change the parameter during a transaction.
あやしい・・・
 
---- postgres.c ----
I give you three comments.

> /* flag for logging statements in this transaction */
I think "a" or the plural form should be used instead of "this"

* xact_is_sampled is left at the end of a transaction.
Should the parameter be set to false at the lowest layer of the transaction system?
I understand it is unnecessary for the functionality, but it have more symmetry.

* check_log_duration should be used only when postgres check the duration.
But I'm not sure a new function such as check_is_sampled is needed because A processing in new function will be as
almostsame as check_log_duration.
 


Best Regards,
Hayato Kuroda
Fujitsu LIMITED

Re: Log a sample of transactions

From
Robert Haas
Date:
On Fri, Jan 18, 2019 at 8:23 AM Adrien NAYRAT
<adrien.nayrat@anayrat.info> wrote:
> On 1/18/19 9:03 AM, Peter Eisentraut wrote:
> > But if you have trouble with a specific transaction, how will a setting
> > help that randomly logs transactions, not necessarily the one you are
> > concerned about?
>
> Yes, it assumes your application performs same type of transaction.
> Maybe the use case is too specific to have this feature in core?

It doesn't sound too crazy to me.  Say you log a sample of statements.
But then you're like, wow, this is hard to interpret, because I don't
know what happened earlier in the transaction.  So then you use this
feature instead.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 1/23/19 3:12 AM, Kuroda, Hayato wrote:
> Dear Adrien,

Hello Kuroda-san

> 
> 
> ---- config.sgml ----
> You must document the behavior when users change the parameter during a transaction.
> あやしい・・・

Agreed, I added a wording.

>   
> ---- postgres.c ----
> I give you three comments.
> 
>> /* flag for logging statements in this transaction */
> I think "a" or the plural form should be used instead of "this"

Fixed

> 
> * xact_is_sampled is left at the end of a transaction.
> Should the parameter be set to false at the lowest layer of the transaction system?
> I understand it is unnecessary for the functionality, but it have more symmetry.

Yes, it is not necessary. I wonder what is more important : keep some 
kind of symmetry or avoid unnecessary code (which can be source of mistake)?

> 
> * check_log_duration should be used only when postgres check the duration.
> But I'm not sure a new function such as check_is_sampled is needed because A processing in new function will be as
almostsame as check_log_duration.
 

I agree, I asked myself the same question and I preferred to keep code 
simple.

Here is 4th patch.

Thanks!

Attachment

RE: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear Adrien,

>> * xact_is_sampled is left at the end of a transaction.
>> Should the parameter be set to false at the lowest layer of the transaction system?
>> I understand it is unnecessary for the functionality, but it have more symmetry.
>
> Yes, it is not necessary. I wonder what is more important : keep some 
>kind of symmetry or avoid unnecessary code (which can be source of mistake)?

>> 
>> * check_log_duration should be used only when postgres check the duration.
>> But I'm not sure a new function such as check_is_sampled is needed because A processing in new function will be as
almostsame as check_log_duration.
 

> I agree, I asked myself the same question and I preferred to keep code 
simple.

I think your point is also correct.
You should inquire superior reviewers or committers because I cannot judge which one is better.


BTW, I give you a suggestion about a test.
This parameter enables users to log statements randomly, hence adding some tests is very difficult.
Perhaps Only three cases are available:

* When log_transaction_sample_rate is set to 1, all statements are logged.
* When the parameter is set to 0, they are never logged.
* When the parameter change to 0 inside the transaction, logging is immediately stopped.


Best Regards,
Hayato Kuroda
Fujitsu LIMITED


Re: Log a sample of transactions

From
Adrien Nayrat
Date:
On 1/28/19 2:53 AM, Kuroda, Hayato wrote:
> BTW, I give you a suggestion about a test.
> This parameter enables users to log statements randomly, hence adding some tests is very difficult.
> Perhaps Only three cases are available:
>
> * When log_transaction_sample_rate is set to 1, all statements are logged.
> * When the parameter is set to 0, they are never logged.
> * When the parameter change to 0 inside the transaction, logging is immediately stopped.

I agree we should add tests, my main problem is log output contains duration
information:

postgres=# select 1;
LOG:  duration: 0.539 ms  statement: select 1;

I did not find any test for log_min_duration that could help me. LCOV indicate
there is no tests on this part (look check_log_duration()):
https://coverage.postgresql.org/src/backend/tcop/postgres.c.gcov.html

I will look how to test this properly with test infrastructure. Maybe a simple
regex to remove duration part will be enough.


Attachment

Re: Log a sample of transactions

From
Michael Paquier
Date:
On Sun, Feb 03, 2019 at 12:23:00PM +0100, Adrien Nayrat wrote:
> I did not find any test for log_min_duration that could help me. LCOV indicate
> there is no tests on this part (look check_log_duration()):
> https://coverage.postgresql.org/src/backend/tcop/postgres.c.gcov.html

These would take time to execute, even if you need to measure one
second, and may be hard to make stable on slow machines.

Moved to next CF.
--
Michael

Attachment

Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 2/4/19 3:26 AM, Michael Paquier wrote:
> These would take time to execute, even if you need to measure one
> second, and may be hard to make stable on slow machines.
> 

Could it be acceptable if I set log_min_duration_statement = 0?

> Moved to next CF.

Thanks


Re: Log a sample of transactions

From
Michael Paquier
Date:
On Mon, Feb 04, 2019 at 04:32:05PM +0100, Adrien NAYRAT wrote:
> Could it be acceptable if I set log_min_duration_statement = 0?

At least this has the merit to make the behavior not rely on
randomness.  I have not looked at the patch in details so I cannot say
for sure, but I am not sure if it is worth the extra cycles to have
tests integrated so they may be removed from the final commit if they
are too expensive for little value.  It is always helpful to have
deterministic tests to give a shot at the feature and ease review of
course.
--
Michael

Attachment

Re: Log a sample of transactions

From
Andres Freund
Date:
Hi,

On 2019-01-26 11:44:58 +0100, Adrien NAYRAT wrote:
> +     <varlistentry id="guc-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
> +      <term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
> +      <indexterm>
> +       <primary><varname>log_transaction_sample_rate</varname> configuration parameter</primary>
> +      </indexterm>
> +      </term>
> +       <listitem>
> +        <para>
> +         Set the fraction of transactions whose statements are logged. It applies
> +         to each new transaction regardless of their duration. The default is
> +         <literal>0</literal>, meaning do not log statements from this transaction.
> +         Setting this to <literal>1</literal> logs all statements for all transactions.
> +         Logging can be disabled inside a transaction by setting this to 0.
> +         <varname>log_transaction_sample_rate</varname> is helpful to track a
> +         sample of transaction.
> +        </para>
> +       </listitem>
> +      </varlistentry>
> +
>       </variablelist>

I wonder if this doesn't need a warning, explaining that using this when
there are large transactions could lead to slowdowns.


>      <para>
> diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
> index 7c3a9c1e89..1a52c10c39 100644
> --- a/src/backend/access/transam/xact.c
> +++ b/src/backend/access/transam/xact.c
> @@ -1821,6 +1821,9 @@ StartTransaction(void)
>      s->state = TRANS_START;
>      s->transactionId = InvalidTransactionId;    /* until assigned */
>  
> +    /* Determine if we log statements in this transaction */
> +    xact_is_sampled = random() <= log_xact_sample_rate * MAX_RANDOM_VALUE;
> +
>      /*
>       * initialize current transaction state fields
>       *
> diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
> index e773f20d9f..a11667834e 100644
> --- a/src/backend/tcop/postgres.c
> +++ b/src/backend/tcop/postgres.c
> @@ -100,7 +100,8 @@ int            max_stack_depth = 100;
>  /* wait N seconds to allow attach from a debugger */
>  int            PostAuthDelay = 0;
>  
> -
> +/* flag for logging statements in a transaction */
> +bool        xact_is_sampled = false;

It seems pretty weird to have this in postgres.c, given you declared it
in xact.h?


> @@ -2218,7 +2221,8 @@ check_log_statement(List *stmt_list)
>  int
>  check_log_duration(char *msec_str, bool was_logged)
>  {
> -    if (log_duration || log_min_duration_statement >= 0)
> +    if (log_duration || log_min_duration_statement >= 0 ||
> +        (xact_is_sampled && log_xact_sample_rate > 0))

Why are both of these checked? ISTM once xact_is_sampled is set, we
ought not to respect a different value of log_xact_sample_rate for the
rest of that transaction.


As far as I can tell xact_is_sampled is not properly reset in case of
errors?


Greetings,

Andres Freund


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 2/14/19 9:14 PM, Andres Freund wrote:
> Hi,
> 

Hello Andres,

> On 2019-01-26 11:44:58 +0100, Adrien NAYRAT wrote:
>> +     <varlistentry id="guc-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
>> +      <term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
>> +      <indexterm>
>> +       <primary><varname>log_transaction_sample_rate</varname> configuration parameter</primary>
>> +      </indexterm>
>> +      </term>
>> +       <listitem>
>> +        <para>
>> +         Set the fraction of transactions whose statements are logged. It applies
>> +         to each new transaction regardless of their duration. The default is
>> +         <literal>0</literal>, meaning do not log statements from this transaction.
>> +         Setting this to <literal>1</literal> logs all statements for all transactions.
>> +         Logging can be disabled inside a transaction by setting this to 0.
>> +         <varname>log_transaction_sample_rate</varname> is helpful to track a
>> +         sample of transaction.
>> +        </para>
>> +       </listitem>
>> +      </varlistentry>
>> +
>>        </variablelist>
> 
> I wonder if this doesn't need a warning, explaining that using this when
> there are large transactions could lead to slowdowns.

Yes, I will add some wording

> 
> 
>>       <para>
>> diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
>> index 7c3a9c1e89..1a52c10c39 100644
>> --- a/src/backend/access/transam/xact.c
>> +++ b/src/backend/access/transam/xact.c
>> @@ -1821,6 +1821,9 @@ StartTransaction(void)
>>       s->state = TRANS_START;
>>       s->transactionId = InvalidTransactionId;    /* until assigned */
>>   
>> +    /* Determine if we log statements in this transaction */
>> +    xact_is_sampled = random() <= log_xact_sample_rate * MAX_RANDOM_VALUE;
>> +
>>       /*
>>        * initialize current transaction state fields
>>        *
>> diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
>> index e773f20d9f..a11667834e 100644
>> --- a/src/backend/tcop/postgres.c
>> +++ b/src/backend/tcop/postgres.c
>> @@ -100,7 +100,8 @@ int            max_stack_depth = 100;
>>   /* wait N seconds to allow attach from a debugger */
>>   int            PostAuthDelay = 0;
>>   
>> -
>> +/* flag for logging statements in a transaction */
>> +bool        xact_is_sampled = false;
> 
> It seems pretty weird to have this in postgres.c, given you declared it
> in xact.h?

Yes, I have to revise my C. I will move it to 
src/backend/access/transam/xact.c

> 
> 
>> @@ -2218,7 +2221,8 @@ check_log_statement(List *stmt_list)
>>   int
>>   check_log_duration(char *msec_str, bool was_logged)
>>   {
>> -    if (log_duration || log_min_duration_statement >= 0)
>> +    if (log_duration || log_min_duration_statement >= 0 ||
>> +        (xact_is_sampled && log_xact_sample_rate > 0))
> 
> Why are both of these checked? ISTM once xact_is_sampled is set, we
> ought not to respect a different value of log_xact_sample_rate for the
> rest of that transaction.

I added theses checks to allow to disable logging during a sampled 
transaction, per suggestion of Masahiko Sawada:
https://www.postgresql.org/message-id/CAD21AoD4t%2BhTV6XfK5Yz%3DEocB8oMyJSYFfjAryCDYtqfib2GrA%40mail.gmail.com

> 
> 
> As far as I can tell xact_is_sampled is not properly reset in case of
> errors?
> 

Yes, I wonder where we should reset it? Is it in AbortTransaction() or 
CleanupTransaction()?

Thanks!


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
Hello,

On 2/15/19 3:24 PM, Adrien NAYRAT wrote:
> On 2/14/19 9:14 PM, Andres Freund wrote:
>> I wonder if this doesn't need a warning, explaining that using this when
>> there are large transactions could lead to slowdowns.
> 
> Yes, I will add some wording

Warning added.

>> It seems pretty weird to have this in postgres.c, given you declared it
>> in xact.h?
> 
> Yes, I have to revise my C. I will move it to 
> src/backend/access/transam/xact.c

Fixed

>> Why are both of these checked? ISTM once xact_is_sampled is set, we
>> ought not to respect a different value of log_xact_sample_rate for the
>> rest of that transaction.
> 
> I added theses checks to allow to disable logging during a sampled 
> transaction, per suggestion of Masahiko Sawada:
> https://www.postgresql.org/message-id/CAD21AoD4t%2BhTV6XfK5Yz%3DEocB8oMyJSYFfjAryCDYtqfib2GrA%40mail.gmail.com 

I added a comment to explain why transaction logging is rechecked.

>>
>> As far as I can tell xact_is_sampled is not properly reset in case of
>> errors?
>>
> 

I am not sure if I should disable logging in case of errors. Actually we 
have:

postgres=# set log_transaction_sample_rate to 1;
SET
postgres=# set client_min_messages to 'LOG';
LOG:  duration: 0.392 ms  statement: set client_min_messages to 'LOG';
SET
postgres=# begin;
LOG:  duration: 0.345 ms  statement: begin;
BEGIN
postgres=# select 1;
LOG:  duration: 0.479 ms  statement: select 1;
  ?column?
----------
         1
(1 row)

postgres=# select * from missingtable;
ERROR:  relation "missingtable" does not exist
LINE 1: select * from missingtable;
                       ^
postgres=# select 1;
ERROR:  current transaction is aborted, commands ignored until end of 
transaction block
postgres=# rollback;
LOG:  duration: 11390.295 ms  statement: rollback;
ROLLBACK

If I reset xact_is_sampled (after the first error inside 
AbortTransaction if I am right), "rollback" statement will not be 
logged. I wonder if this "statement" should be logged?

If the answer is no, I will reset xact_is_sampled in AbortTransaction.



Patch attached with fix mentioned above, but without xact_is_sampled reset.

Cheers,



Attachment

Re: Re: Log a sample of transactions

From
David Steele
Date:
Hi Hayato,

On 3/1/19 10:17 PM, Adrien NAYRAT wrote:
> 
> Patch attached with fix mentioned above, but without xact_is_sampled reset.

Are you planning to review this patch?  If not I remove you from the 
reviewers so perhaps somebody else will have a look.

Regards,
-- 
-David
david@pgmasters.net


RE: Re: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear David,

I have a will and already read the patch, but I thought it's not my turn.
Sorry.


Adrien,

>  I did not find any test for log_min_duration that could help me. LCOV indicate
> there is no tests on this part (look check_log_duration()):
> https://coverage.postgresql.org/src/backend/tcop/postgres.c.gcov.html

I understand the unnecessarily of some test case. It's OK.

Finally, how do you think about the deviation of randomness?
If this parameter is set very low, nobody may be output because of the deviation.
we can avoid this phenomenon by counting up internal parameter for each transactions and output to log file if the
parameterbecomes  more than 1.
 

After consideration for this case and rebasing, I think this patch is enough.
Do I have to measure the change of throughput?


Best Regards,
Hayato Kuroda
Fujitsu LIMITED



Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 3/26/19 1:54 AM, Kuroda, Hayato wrote:
> Dear David,
> 
> I have a will and already read the patch, but I thought it's not my turn.
> Sorry.
> 
> 

Hello,

> Adrien,
> 
>>   I did not find any test for log_min_duration that could help me. LCOV indicate
>> there is no tests on this part (look check_log_duration()):
>> https://coverage.postgresql.org/src/backend/tcop/postgres.c.gcov.html
> 
> I understand the unnecessarily of some test case. It's OK.
> 
> Finally, how do you think about the deviation of randomness?
> If this parameter is set very low, nobody may be output because of the deviation.
> we can avoid this phenomenon by counting up internal parameter for each transactions and output to log file if the
parameterbecomes  more than 1.
 

I don't understand what you want to do and I am afraid of the cost it 
could add.

There was a long discussion about random, maybe the thread could answer 
some of your questions?
https://www.postgresql.org/message-id/3859.1545849900%40sss.pgh.pa.us

Furthermore, I wonder if it is really necessary : the goal of this patch 
is to log a sample of transaction, not to perform precise stats 
computation. FIY we do not perform this kind of checks for 
log_statement_sample_rate.


> 
> After consideration for this case and rebasing, I think this patch is enough.
> Do I have to measure the change of throughput?
> 

I don't think it is necessary or maybe I am missing something. I already 
perform performance test for log_statement_sample_rate:
https://www.postgresql.org/message-id/8a608ccf-f78b-dfad-4c5f-8e6fd068c59c%40anayrat.info

It should be less expensive as we call random() for new transaction 
only. log_statement_sample_rate call it for each statement.

I don't know if there is cases where random() call could be slow?

There is still a point raised by Andres:


>> As far as I can tell xact_is_sampled is not properly reset in case of
>> errors?
>>
> 
> I am not sure if I should disable logging in case of errors. Actually we have:
> 
> postgres=# set log_transaction_sample_rate to 1;
> SET
> postgres=# set client_min_messages to 'LOG';
> LOG:  duration: 0.392 ms  statement: set client_min_messages to 'LOG';
> SET
> postgres=# begin;
> LOG:  duration: 0.345 ms  statement: begin;
> BEGIN
> postgres=# select 1;
> LOG:  duration: 0.479 ms  statement: select 1;
>  ?column?
> ----------
>         1
> (1 row)
> 
> postgres=# select * from missingtable;
> ERROR:  relation "missingtable" does not exist
> LINE 1: select * from missingtable;
>                       ^
> postgres=# select 1;
> ERROR:  current transaction is aborted, commands ignored until end of transaction block
> postgres=# rollback;
> LOG:  duration: 11390.295 ms  statement: rollback;
> ROLLBACK
> 
> If I reset xact_is_sampled (after the first error inside AbortTransaction if I am right), "rollback" statement will
notbe logged. I wonder if this "statement" should be logged?
 
> 
> If the answer is no, I will reset xact_is_sampled in AbortTransaction.


Thanks!


Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 3/27/19 10:22 AM, Adrien NAYRAT wrote:
> Hello,
> 
> On 3/27/19 7:05 AM, Masahiko Sawada wrote:
>>>>> Why are both of these checked? ISTM once xact_is_sampled is set, we
>>>>> ought not to respect a different value of log_xact_sample_rate for the
>>>>> rest of that transaction.
>>>> I added theses checks to allow to disable logging during a sampled
>>>> transaction, per suggestion of Masahiko Sawada:
>>>> https://www.postgresql.org/message-id/CAD21AoD4t%2BhTV6XfK5Yz%3DEocB8oMyJSYFfjAryCDYtqfib2GrA%40mail.gmail.com 
>>>>
>>> I added a comment to explain why transaction logging is rechecked.
>> Umm, I'm inclined to think that we should not disable logging within
>> the transaction. If we allow that, since users can disable the logging
>> within the transaction by setting it to 0 they may think that we can
>> change the rate during the transaction, which is wrong. If we want
>> this behavior we should document it but we can make user not being
>> able to change the rate during the transaction to avoid confusion. And
>> the latter looks more understandable and straightforward. This is
>> different comment what I did before, I'm sorry for confusing you.
> 
> Don't worry, I will change that.
> 
> 
>>
>>>>> As far as I can tell xact_is_sampled is not properly reset in case of
>>>>> errors?
>>>>>
>>> I am not sure if I should disable logging in case of errors. Actually we
>>> have:
>>>
>>> postgres=# set log_transaction_sample_rate to 1;
>>> SET
>>> postgres=# set client_min_messages to 'LOG';
>>> LOG:  duration: 0.392 ms  statement: set client_min_messages to 'LOG';
>>> SET
>>> postgres=# begin;
>>> LOG:  duration: 0.345 ms  statement: begin;
>>> BEGIN
>>> postgres=# select 1;
>>> LOG:  duration: 0.479 ms  statement: select 1;
>>>    ?column?
>>> ----------
>>>           1
>>> (1 row)
>>>
>>> postgres=# select * from missingtable;
>>> ERROR:  relation "missingtable" does not exist
>>> LINE 1: select * from missingtable;
>>>                         ^
>>> postgres=# select 1;
>>> ERROR:  current transaction is aborted, commands ignored until end of
>>> transaction block
>>> postgres=# rollback;
>>> LOG:  duration: 11390.295 ms  statement: rollback;
>>> ROLLBACK
>>>
>>> If I reset xact_is_sampled (after the first error inside
>>> AbortTransaction if I am right), "rollback" statement will not be
>>> logged. I wonder if this "statement" should be logged?
>>>
>>> If the answer is no, I will reset xact_is_sampled in AbortTransaction.
>>>
>> FWIW, I'd prefer to log "rollback" as well so as user can recognize
>> the end of transaction.
> 
> Ok.
> 
>>
>> +       /* Determine if statements are logged in this transaction */
>> +       xact_is_sampled = random() <= log_xact_sample_rate * 
>> MAX_RANDOM_VALUE;
>>
>> If log_xact_sample_rate is 1 we always log all statement in the
>> transaction regardless of value of random(). Similarly if it's 0, we
>> never log. I think we can avoid unnecessary random() call in both case
>> like log_statement_sample_rate does.
> 
> I agree, I will change that.
> 
>>
>>                  {"log_statement_sample_rate", PGC_SUSET, LOGGING_WHEN,
>>                          gettext_noop("Fraction of statements over
>> log_min_duration_statement to log."),
>>                          gettext_noop("If you only want a sample, use a
>> value between 0 (never "
>> -                                                "log) and 1.0 (always 
>> log).")
>> +                                                "log) and 1 (always 
>> log).")
>>                  },
>>                  &log_statement_sample_rate,
>>                  1.0, 0.0, 1.0,
>>                  NULL, NULL, NULL
>>          },
>>
>> This change is not relevant with log_transaction_sample_rate feature
>> but why do we need this change? In postgresql.conf.sample the
>> description of both log_statement_sample_rate and
>> log_transaction_sample_rate use 1.0 instead of 1, like "1.0 logs all
>> statements from all transactions, 0 never logs". If we need this
>> change I think it should be a separate patch.
> 
> 
> Sorry, I changed that, someone suggest using either "0" and "1", or 
> "0.0" and "1.0" but not mixing both. I will remove this change.
> 
> Thanks for your review.
> 
> 
> 

Patch attached with all changes requested.

Attachment

Re: Log a sample of transactions

From
Masahiko Sawada
Date:
Thank you for updating the patch!

On Wed, Mar 27, 2019 at 10:28 PM Adrien NAYRAT
<adrien.nayrat@anayrat.info> wrote:
>
> On 3/27/19 10:22 AM, Adrien NAYRAT wrote:
> > Hello,
> >
> > On 3/27/19 7:05 AM, Masahiko Sawada wrote:
> >>>>> Why are both of these checked? ISTM once xact_is_sampled is set, we
> >>>>> ought not to respect a different value of log_xact_sample_rate for the
> >>>>> rest of that transaction.
> >>>> I added theses checks to allow to disable logging during a sampled
> >>>> transaction, per suggestion of Masahiko Sawada:
> >>>> https://www.postgresql.org/message-id/CAD21AoD4t%2BhTV6XfK5Yz%3DEocB8oMyJSYFfjAryCDYtqfib2GrA%40mail.gmail.com
> >>>>
> >>> I added a comment to explain why transaction logging is rechecked.
> >> Umm, I'm inclined to think that we should not disable logging within
> >> the transaction. If we allow that, since users can disable the logging
> >> within the transaction by setting it to 0 they may think that we can
> >> change the rate during the transaction, which is wrong. If we want
> >> this behavior we should document it but we can make user not being
> >> able to change the rate during the transaction to avoid confusion. And
> >> the latter looks more understandable and straightforward. This is
> >> different comment what I did before, I'm sorry for confusing you.
> >
> > Don't worry, I will change that.
> >
> >
> >>
> >>>>> As far as I can tell xact_is_sampled is not properly reset in case of
> >>>>> errors?
> >>>>>
> >>> I am not sure if I should disable logging in case of errors. Actually we
> >>> have:
> >>>
> >>> postgres=# set log_transaction_sample_rate to 1;
> >>> SET
> >>> postgres=# set client_min_messages to 'LOG';
> >>> LOG:  duration: 0.392 ms  statement: set client_min_messages to 'LOG';
> >>> SET
> >>> postgres=# begin;
> >>> LOG:  duration: 0.345 ms  statement: begin;
> >>> BEGIN
> >>> postgres=# select 1;
> >>> LOG:  duration: 0.479 ms  statement: select 1;
> >>>    ?column?
> >>> ----------
> >>>           1
> >>> (1 row)
> >>>
> >>> postgres=# select * from missingtable;
> >>> ERROR:  relation "missingtable" does not exist
> >>> LINE 1: select * from missingtable;
> >>>                         ^
> >>> postgres=# select 1;
> >>> ERROR:  current transaction is aborted, commands ignored until end of
> >>> transaction block
> >>> postgres=# rollback;
> >>> LOG:  duration: 11390.295 ms  statement: rollback;
> >>> ROLLBACK
> >>>
> >>> If I reset xact_is_sampled (after the first error inside
> >>> AbortTransaction if I am right), "rollback" statement will not be
> >>> logged. I wonder if this "statement" should be logged?
> >>>
> >>> If the answer is no, I will reset xact_is_sampled in AbortTransaction.
> >>>
> >> FWIW, I'd prefer to log "rollback" as well so as user can recognize
> >> the end of transaction.
> >
> > Ok.
> >
> >>
> >> +       /* Determine if statements are logged in this transaction */
> >> +       xact_is_sampled = random() <= log_xact_sample_rate *
> >> MAX_RANDOM_VALUE;
> >>
> >> If log_xact_sample_rate is 1 we always log all statement in the
> >> transaction regardless of value of random(). Similarly if it's 0, we
> >> never log. I think we can avoid unnecessary random() call in both case
> >> like log_statement_sample_rate does.
> >
> > I agree, I will change that.
> >
> >>
> >>                  {"log_statement_sample_rate", PGC_SUSET, LOGGING_WHEN,
> >>                          gettext_noop("Fraction of statements over
> >> log_min_duration_statement to log."),
> >>                          gettext_noop("If you only want a sample, use a
> >> value between 0 (never "
> >> -                                                "log) and 1.0 (always
> >> log).")
> >> +                                                "log) and 1 (always
> >> log).")
> >>                  },
> >>                  &log_statement_sample_rate,
> >>                  1.0, 0.0, 1.0,
> >>                  NULL, NULL, NULL
> >>          },
> >>
> >> This change is not relevant with log_transaction_sample_rate feature
> >> but why do we need this change? In postgresql.conf.sample the
> >> description of both log_statement_sample_rate and
> >> log_transaction_sample_rate use 1.0 instead of 1, like "1.0 logs all
> >> statements from all transactions, 0 never logs". If we need this
> >> change I think it should be a separate patch.
> >
> >
> > Sorry, I changed that, someone suggest using either "0" and "1", or
> > "0.0" and "1.0" but not mixing both.

Agreed with using "0.0" and "1.0".

> > I will remove this change.
> >

--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
+#log_transaction_sample_rate = 0       # Fraction of transactions
whose statements
+                                       # are logged regardless of
their duration. 1.0 logs all
+                                       # statements from all
transactions, 0 never logs.

--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
+               {"log_transaction_sample_rate", PGC_SUSET, LOGGING_WHEN,
+                       gettext_noop("Set the fraction of transactions
to log for new transactions."),
+                       gettext_noop("Logs all statements from a
fraction of transactions. "
+                                                "Use a value between
0 (never log) and 1 (log all "
+                                                "statements for all
transactions).")

I think it would be better to use the same number in both guc.c and
postgresql.conf.sample. How about unifying them to "0.0" and "1.0" for
consistency?

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center



Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
Hello,

On 3/28/19 3:18 AM, Masahiko Sawada wrote:
>>>
>>> Sorry, I changed that, someone suggest using either "0" and "1", or
>>> "0.0" and "1.0" but not mixing both.
> 
> Agreed with using "0.0" and "1.0".
> 
>>> I will remove this change.
>>>
> 
> --- a/src/backend/utils/misc/postgresql.conf.sample
> +++ b/src/backend/utils/misc/postgresql.conf.sample
> +#log_transaction_sample_rate = 0       # Fraction of transactions
> whose statements
> +                                       # are logged regardless of
> their duration. 1.0 logs all
> +                                       # statements from all
> transactions, 0 never logs.
> 
> --- a/src/backend/utils/misc/guc.c
> +++ b/src/backend/utils/misc/guc.c
> +               {"log_transaction_sample_rate", PGC_SUSET, LOGGING_WHEN,
> +                       gettext_noop("Set the fraction of transactions
> to log for new transactions."),
> +                       gettext_noop("Logs all statements from a
> fraction of transactions. "
> +                                                "Use a value between
> 0 (never log) and 1 (log all "
> +                                                "statements for all
> transactions).")
> 
> I think it would be better to use the same number in both guc.c and
> postgresql.conf.sample. How about unifying them to "0.0" and "1.0" for
> consistency?
> 

I changed to use both 0.0 and 1.0.

Thanks!

Attachment

Re: Log a sample of transactions

From
Masahiko Sawada
Date:
On Thu, Mar 28, 2019 at 6:33 PM Adrien NAYRAT
<adrien.nayrat@anayrat.info> wrote:
>
> Hello,
>
> On 3/28/19 3:18 AM, Masahiko Sawada wrote:
> >>>
> >>> Sorry, I changed that, someone suggest using either "0" and "1", or
> >>> "0.0" and "1.0" but not mixing both.
> >
> > Agreed with using "0.0" and "1.0".
> >
> >>> I will remove this change.
> >>>
> >
> > --- a/src/backend/utils/misc/postgresql.conf.sample
> > +++ b/src/backend/utils/misc/postgresql.conf.sample
> > +#log_transaction_sample_rate = 0       # Fraction of transactions
> > whose statements
> > +                                       # are logged regardless of
> > their duration. 1.0 logs all
> > +                                       # statements from all
> > transactions, 0 never logs.
> >
> > --- a/src/backend/utils/misc/guc.c
> > +++ b/src/backend/utils/misc/guc.c
> > +               {"log_transaction_sample_rate", PGC_SUSET, LOGGING_WHEN,
> > +                       gettext_noop("Set the fraction of transactions
> > to log for new transactions."),
> > +                       gettext_noop("Logs all statements from a
> > fraction of transactions. "
> > +                                                "Use a value between
> > 0 (never log) and 1 (log all "
> > +                                                "statements for all
> > transactions).")
> >
> > I think it would be better to use the same number in both guc.c and
> > postgresql.conf.sample. How about unifying them to "0.0" and "1.0" for
> > consistency?
> >
>
> I changed to use both 0.0 and 1.0.
>

Thank you for updating the patch!

The patch looks good to me. I'll mark this patch as Ready for
Committer if other reviewer has no review comment on v7 patch.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center



Re: Log a sample of transactions

From
Christoph Berg
Date:
Re: Adrien NAYRAT 2019-03-28 <c86d676a-0b1e-f9be-3da2-63fa15070db0@anayrat.info>
> > > > Sorry, I changed that, someone suggest using either "0" and "1", or
> > > > "0.0" and "1.0" but not mixing both.
> > 
> > Agreed with using "0.0" and "1.0".
> > 
> > > > I will remove this change.

> +#log_transaction_sample_rate = 0    # Fraction of transactions whose statements
> +                    # are logged regardless of their duration. 1.0 logs all
> +                    # statements from all transactions, 0.0 never logs.

This still looks weird to me. If the default is to never log, and
that's 0.0 as per the comment, the setting should be 0.0 as well.


The same applies to log_statement_sample_rate which is already
committed, were it looks even worse:

#log_statement_sample_rate = 1  # Fraction of logged statements over
                                        # log_min_duration_statement. 1.0 logs all statements,
                                        # 0 never logs.

Is "over" even correct English? ("out of" "from"?)

Christoph



Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 3/28/19 10:45 AM, Christoph Berg wrote:
> Re: Adrien NAYRAT 2019-03-28 <c86d676a-0b1e-f9be-3da2-63fa15070db0@anayrat.info>
>>>>> Sorry, I changed that, someone suggest using either "0" and "1", or
>>>>> "0.0" and "1.0" but not mixing both.
>>>
>>> Agreed with using "0.0" and "1.0".
>>>
>>>>> I will remove this change.
> 
>> +#log_transaction_sample_rate = 0    # Fraction of transactions whose statements
>> +                    # are logged regardless of their duration. 1.0 logs all
>> +                    # statements from all transactions, 0.0 never logs.
> 
> This still looks weird to me. If the default is to never log, and
> that's 0.0 as per the comment, the setting should be 0.0 as well.

Right, fixed in patch attached

> 
> 
> The same applies to log_statement_sample_rate which is already
> committed, were it looks even worse:

Yes, I fixed in this patch, but, as it is not related to this patch, it 
should be fixed in another patch.

> 
> #log_statement_sample_rate = 1  # Fraction of logged statements over
>                                          # log_min_duration_statement. 1.0 logs all statements,
>                                          # 0 never logs.
> 
> Is "over" even correct English? ("out of" "from"?)
> 

I have no idea on it, I am not an English native speaker.

Thanks,

Attachment

RE: Log a sample of transactions

From
"Kuroda, Hayato"
Date:
Dear Adrien,

I understood the cost of randomizing is very low. Maybe it's OK..
I'll change the status to "Ready For Committer."

Finally, I apologize for having delayed review.
Thank you for your good opportunities.

Best Regards,
Hayato Kuroda
Fujitsu LIMITED



Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 3/29/19 3:06 AM, Kuroda, Hayato wrote:
> Dear Adrien,

Hello Kuroda-san,

> 
> I understood the cost of randomizing is very low. Maybe it's OK..
> I'll change the status to "Ready For Committer."

Thanks, I hope it will be commited in PG12 as the feature is closed to 
log_statement_sample_rate.

> 
> Finally, I apologize for having delayed review.
> Thank you for your good opportunities.

Don't worry, we all do what we can. Thanks for your review ;)


Best Regards,



Re: Log a sample of transactions

From
Alvaro Herrera
Date:
On 2019-Mar-29, Adrien NAYRAT wrote:

> On 3/29/19 3:06 AM, Kuroda, Hayato wrote:
> > Dear Adrien,
> 
> Hello Kuroda-san,
> 
> > 
> > I understood the cost of randomizing is very low. Maybe it's OK..
> > I'll change the status to "Ready For Committer."
> 
> Thanks, I hope it will be commited in PG12 as the feature is closed to
> log_statement_sample_rate.

Done, thanks.  I tweaked the wording of the docs somewhat; please
review that part.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services



Re: Log a sample of transactions

From
Adrien NAYRAT
Date:
On 4/3/19 11:45 PM, Alvaro Herrera wrote:
> On 2019-Mar-29, Adrien NAYRAT wrote:
> 
>> On 3/29/19 3:06 AM, Kuroda, Hayato wrote:
>>> Dear Adrien,
>>
>> Hello Kuroda-san,
>>
>>>
>>> I understood the cost of randomizing is very low. Maybe it's OK..
>>> I'll change the status to "Ready For Committer."
>>
>> Thanks, I hope it will be commited in PG12 as the feature is closed to
>> log_statement_sample_rate.
> 
> Done, thanks.  I tweaked the wording of the docs somewhat; please
> review that part.
> 

Thanks Alvaro for committing this and also thanks to all reviewers.

As I am not a native English speaker, I don't have a specific advice on 
the documentation "style".