Log a sample of transactions

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

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 statements of 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.

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

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,

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 all 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?

Regards,

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

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

Thanks,

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

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

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!

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 find all 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

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!

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

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?

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 almost same as check_log_duration.

Best Regards,
Hayato Kuroda
Fujitsu LIMITED

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

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 almost same as check_log_duration.

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

Here is 4th patch.

Thanks!

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 almost same 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

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.

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