Thread: [PATCH] Better logging of COPY queries if log_statement='all'

Hello.

Sometimes it's useful to log content of files used in COPY ... TO ... and
COPY ... FROM ... queries. Unfortunately PostgreSQL doesn't allow to do
it, even if log_statement='all'. Suggested patch fixes this.

Log example:

```
LOG:  statement: create table test (k int, v text);
LOG:  statement: insert into test values (111, 'aaa'), (222, 'bbb');
LOG:  statement: copy test to '/tmp/copy.txt';
LOG:  statement: 111    aaa
LOG:  statement: 222    bbb
LOG:  statement: delete from test;
LOG:  statement: copy test from '/tmp/copy.txt';
LOG:  statement: 111    aaa
LOG:  statement: 222    bbb
```
--
Best regards,
Aleksander Alekseev

On 10/17/2016 09:57 AM, Aleksander Alekseev wrote:
> Hello.
>
> Sometimes it's useful to log content of files used in COPY ... TO ... and
> COPY ... FROM ... queries. Unfortunately PostgreSQL doesn't allow to do
> it, even if log_statement='all'. Suggested patch fixes this.
>
> Log example:
>
> ```
> LOG:  statement: create table test (k int, v text);
> LOG:  statement: insert into test values (111, 'aaa'), (222, 'bbb');
> LOG:  statement: copy test to '/tmp/copy.txt';
> LOG:  statement: 111    aaa
> LOG:  statement: 222    bbb
> LOG:  statement: delete from test;
> LOG:  statement: copy test from '/tmp/copy.txt';
> LOG:  statement: 111    aaa
> LOG:  statement: 222    bbb
> ```


I'm not in favor of this, especially if it's not even optional. 
log_statement is about logging, er, statements, not logging data.

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> On 10/17/2016 09:57 AM, Aleksander Alekseev wrote:
>> Sometimes it's useful to log content of files used in COPY ... TO ... and
>> COPY ... FROM ... queries. Unfortunately PostgreSQL doesn't allow to do
>> it, even if log_statement='all'. Suggested patch fixes this.

> I'm not in favor of this, especially if it's not even optional. 

I'm not either.  It sounds good when you're looking at toy examples,
but not when it means repeating gigabytes of COPY data into the log.
        regards, tom lane

> > I'm not in favor of this, especially if it's not even optional.
>
> I'm not either.  It sounds good when you're looking at toy examples,
> but not when it means repeating gigabytes of COPY data into the log.

I understand your concern. Perhaps we could create and additional
parameter for enabling/disabling this feature or a new log_statement
value, or maybe both - i.e. rename log_statement and add a new possible
value?

According to my colleagues it would be very nice to have this feature.
For instance, if you are trying to optimize PostgreSQL for application
that uses COPY and you don't have access to or something like this.
It could also be useful in some other cases.

This feature is very simple and easy to maintain. I'm sure we could find
a solution that will make happy both developers and users.

--
Best regards,
Aleksander Alekseev

* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
> > On 10/17/2016 09:57 AM, Aleksander Alekseev wrote:
> >> Sometimes it's useful to log content of files used in COPY ... TO ... and
> >> COPY ... FROM ... queries. Unfortunately PostgreSQL doesn't allow to do
> >> it, even if log_statement='all'. Suggested patch fixes this.
>
> > I'm not in favor of this, especially if it's not even optional.
>
> I'm not either.  It sounds good when you're looking at toy examples,
> but not when it means repeating gigabytes of COPY data into the log.

This isn't new- I've seen many cases of people happily loading gigabytes
of data via INSERT with log_statement='all' on.  What I don't like is
the idea of springing this change on people.

* Aleksander Alekseev (a.alekseev@postgrespro.ru) wrote:
> I understand your concern. Perhaps we could create and additional
> parameter for enabling/disabling this feature or a new log_statement
> value, or maybe both - i.e. rename log_statement and add a new possible
> value?

Ugh.  Adding more options to log_statement is just an ugly route to go
in, in my view.  We really need a better solution here.

> According to my colleagues it would be very nice to have this feature.
> For instance, if you are trying to optimize PostgreSQL for application
> that uses COPY and you don't have access to or something like this.
> It could also be useful in some other cases.

This use-case doesn't really make much sense to me.  Can you explain it
in more detail?  Is the goal here to replicate all of the statements
that are changing data in the database?

Thanks!

Stephen

    Aleksander Alekseev wrote:

> According to my colleagues it would be very nice to have this feature.
> For instance, if you are trying to optimize PostgreSQL for application
> that uses COPY and you don't have access to or something like this.
> It could also be useful in some other cases.

Outside of the app, what can be already set up is an AFTER INSERT
FOR EACH ROW trigger that essentially does:
 raise LOG, '%', NEW;

The main drawback of this approach is that, for each line of data
emitted to the log, there's another STATEMENT: copy... line added.
But that might be not too bad for certain uses.

Ideally we should be able to access the new rowset as a whole through
a statement-level trigger. In that case, the data could be logged in
a one-shot operation by that trigger.
There's a related item in the TODO list: "Allow statement-level triggers to access modified rows"
and an old thread on -hackers here:
https://www.postgresql.org/message-id/20060522150647.GE24404@svana.org
that discussed this topic in relation to MSSQL having this functionality.


Best regards,
--
Daniel Vérité
PostgreSQL-powered mailer: http://www.manitou-mail.org
Twitter: @DanielVerite

> > According to my colleagues it would be very nice to have this feature.
> > For instance, if you are trying to optimize PostgreSQL for application
> > that uses COPY and you don't have access to or something like this.
> > It could also be useful in some other cases.
>
> This use-case doesn't really make much sense to me.  Can you explain it
> in more detail?  Is the goal here to replicate all of the statements
> that are changing data in the database?

The idea is to record application workload in real environment and write
a benchmark based on this record. Then using this benchmark we could try
different OS/DBMS configuration (or maybe hardware), find an extremum,
then change configuration in production environment.

It's not always possible to change an application or even database (e.g.
to use triggers) for this purpose. For instance, if DBMS is provided as
a service.

Currently PostgreSQL allows to record all workload _except_ COPY
queries. Considering how easily it could be done I think it's wrong.
Basically the only real question here is how it should look like in
postgresql.conf.

--
Best regards,
Aleksander Alekseev

> > > According to my colleagues it would be very nice to have this feature.
> > > For instance, if you are trying to optimize PostgreSQL for application
> > > that uses COPY and you don't have access to or something like this.
> > > It could also be useful in some other cases.
> >
> > This use-case doesn't really make much sense to me.  Can you explain it
> > in more detail?  Is the goal here to replicate all of the statements
> > that are changing data in the database?
>
> The idea is to record application workload in real environment and write
> a benchmark based on this record. Then using this benchmark we could try
> different OS/DBMS configuration (or maybe hardware), find an extremum,
> then change configuration in production environment.
>
> It's not always possible to change an application or even database (e.g.
> to use triggers) for this purpose. For instance, if DBMS is provided as
> a service.
>
> Currently PostgreSQL allows to record all workload _except_ COPY
> queries. Considering how easily it could be done I think it's wrong.
> Basically the only real question here is how it should look like in
> postgresql.conf.

OK, how about introducing a new boolean parameter named log_copy?
Corresponding patch is attached.

--
Best regards,
Aleksander Alekseev

Aleksander,

* Aleksander Alekseev (a.alekseev@postgrespro.ru) wrote:
> > The idea is to record application workload in real environment and write
> > a benchmark based on this record. Then using this benchmark we could try
> > different OS/DBMS configuration (or maybe hardware), find an extremum,
> > then change configuration in production environment.
> >
> > It's not always possible to change an application or even database (e.g.
> > to use triggers) for this purpose. For instance, if DBMS is provided as
> > a service.
> >
> > Currently PostgreSQL allows to record all workload _except_ COPY
> > queries. Considering how easily it could be done I think it's wrong.
> > Basically the only real question here is how it should look like in
> > postgresql.conf.
>
> OK, how about introducing a new boolean parameter named log_copy?
> Corresponding patch is attached.

The parameter would be better as 'log_copy_data', I believe.  The actual
COPY command is already logged with just 'log_statement = all', of
course.

Also..

> diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
> index 8c25b45..84a7542 100644
> --- a/doc/src/sgml/config.sgml
> +++ b/doc/src/sgml/config.sgml
> @@ -5205,6 +5205,20 @@ FROM pg_stat_activity;
>        </listitem>
>       </varlistentry>
>
> +     <varlistentry id="guc-log-copy" xreflabel="log_copy">
> +      <term><varname>log_copy</varname> (<type>boolean</type>)
> +      <indexterm>
> +       <primary><varname>log_copy</> configuration parameter</primary>
> +      </indexterm>
> +      </term>
> +      <listitem>
> +       <para>
> +        Controls whether file content is logged during execution of
> +        COPY queries.  The default is <literal>off</>.
> +       </para>
> +      </listitem>
> +     </varlistentry>

"file" isn't accurate here and I don't know that it actually makes sense
to log "COPY TO" data- we don't log the results of SELECT statements,
after all, and the use-case you outlined above (which I generally agree
is one we should consider) doesn't have any need for the data of "COPY
TO" statements to be in the log, it seems to me.

Can you elaborate on why we would want to log the data sent to the
client with a COPY TO command.  If there is a reason, why wouldn't we
want to support that for SELECT and ... RETURNING commands too?

Thanks!

Stephen

<p><br /><br /><div class="moz-cite-prefix">On 10/20/2016 12:36 PM, Aleksander Alekseev wrote:<br /></div><blockquote
cite="mid:20161020093652.GB24208@e733.localdomain"type="cite"><blockquote type="cite"><blockquote
type="cite"><blockquotetype="cite"><pre wrap="">According to my colleagues it would be very nice to have this feature.
 
For instance, if you are trying to optimize PostgreSQL for application
that uses COPY and you don't have access to or something like this. 
It could also be useful in some other cases.
</pre></blockquote><pre wrap="">
This use-case doesn't really make much sense to me.  Can you explain it
in more detail?  Is the goal here to replicate all of the statements
that are changing data in the database?
</pre></blockquote><pre wrap="">
The idea is to record application workload in real environment and write
a benchmark based on this record. Then using this benchmark we could try
different OS/DBMS configuration (or maybe hardware), find an extremum,
then change configuration in production environment.

It's not always possible to change an application or even database (e.g.
to use triggers) for this purpose. For instance, if DBMS is provided as
a service.

Currently PostgreSQL allows to record all workload _except_ COPY
queries. Considering how easily it could be done I think it's wrong.
Basically the only real question here is how it should look like in
postgresql.conf.
</pre></blockquote><pre wrap="">
OK, how about introducing a new boolean parameter named log_copy?
Corresponding patch is attached.

</pre></blockquote> This is a useful feature I was waiting for some time.<br /> If some application which workload you
wantto collect is using COPY statement, then recording network traffic was your only option.<br /><pre
class="moz-signature"cols="72">-- 
 
Grigory Smolkin
Postgres Professional: <a class="moz-txt-link-freetext"
href="http://www.postgrespro.com">http://www.postgrespro.com</a>
The Russian Postgres Company</pre>

Grigory,

* Grigory Smolkin (g.smolkin@postgrespro.ru) wrote:
> On 10/20/2016 12:36 PM, Aleksander Alekseev wrote:
> >>>>According to my colleagues it would be very nice to have this feature.
> >>>>For instance, if you are trying to optimize PostgreSQL for application
> >>>>that uses COPY and you don't have access to or something like this.
> >>>>It could also be useful in some other cases.
> >>>This use-case doesn't really make much sense to me.  Can you explain it
> >>>in more detail?  Is the goal here to replicate all of the statements
> >>>that are changing data in the database?
> >>The idea is to record application workload in real environment and write
> >>a benchmark based on this record. Then using this benchmark we could try
> >>different OS/DBMS configuration (or maybe hardware), find an extremum,
> >>then change configuration in production environment.
> >>
> >>It's not always possible to change an application or even database (e.g.
> >>to use triggers) for this purpose. For instance, if DBMS is provided as
> >>a service.
> >>
> >>Currently PostgreSQL allows to record all workload _except_ COPY
> >>queries. Considering how easily it could be done I think it's wrong.
> >>Basically the only real question here is how it should look like in
> >>postgresql.conf.
> >OK, how about introducing a new boolean parameter named log_copy?
> >Corresponding patch is attached.
>
> This is a useful feature I was waiting for some time.
> If some application which workload you want to collect is using COPY
> statement, then recording network traffic was your only option.

As I pointed out to Aleksander, you would still need to record network
traffic to see all of the data going to and from the database since we
do not include SELECT or ... RETURNING results in the log files.  If
that is needed then that's a whole different discussion.

Thanks!

Stephen