Thread: Rollback of Query Cancellation

Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 04:19:43

Dear All,

Yesterday I canceled a running query because it was taking long time (more than 12 minutes) to delete lots of records. Today when I executed the same query it hardly took few seconds to finish. It clearly explores that PostgreSQL does not perform rollback action. Is it true?

Regards,
Abdul Rehman.

Re: Rollback of Query Cancellation

From

justin

Date:

28 January 2009, 04:39:01

Abdul Rahman wrote:

Dear All,

Yesterday I canceled a running query because it was taking long time (more than 12 minutes) to delete lots of records. Today when I executed the same query it hardly took few seconds to finish. It clearly explores that PostgreSQL does not perform rollback action. Is it true?

Regards,
Abdul Rehman.

The transaction would have been rolled back. this makes me think the delete was wrapped in individual transactions for a set of records or per record. With out more information an intelligent answer is kind of hard to give.

What does the sql statement look like?
Where was the statement run?
How was the statement killed?
What do the logs show?

Re: Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 05:09:32

Thanks Justin,

Answers of your technical questions are as under:

What does the sql statement look like?

delete from ci_cif_v where req_id='0824100207';

Where was the statement run?

On SQL pan of pgAdmin-III

How was the statement killed?

By clicking the Cancel Query button ->

What do the logs show?

Message just showed the time it took to delete certain number of records.

Re: Rollback of Query Cancellation

From

Jaime Casanova

Date:

28 January 2009, 05:13:24

On Wed, Jan 28, 2009 at 12:19 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
> Dear All,
>
> PostgreSQL does not perform rollback action. Is it true?
>

no. postgresql executes all statements that are outside an explicit
transaction in its own implicit one [1] executing commit at the end,
if you cancelled the query the commit never executed and the records
were never deleted...

even more to the point, postgres never delete tuples on delete just
mark them as invalid since transaction number X. at commit time the
transaction is marked as correctly finished and all changes are WAL
logged then suddenly changes take effect... rollback never mark the
transaction as finished and doesn't save WAL records (that meaning
that changes never spread to the datafiles)

actually ROLLBACK is very cheap just don't save changes, COMMIT makes
all the work...

now, your post make me think that you think the ROLLBACK never
executed based on... reponse time? very unscientific (there are plenty
other reasons for that to happen)

[1] http://www.postgresql.org/docs/8.3/static/tutorial-transactions.html

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Jaime Casanova

Date:

28 January 2009, 05:22:52

On Wed, Jan 28, 2009 at 12:56 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
>
> What do the logs show?
>
> Message just showed the time it took to delete certain number of records.
>

can you show that message? copy 'n pasted from logs!!

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 05:29:08

Welcome Jcasanov,

Here is the output of the log files:

2009-01-27 09:24:18 FATAL: the database system is starting up
2009-01-27 09:24:19 LOG: database system was shut down at 2009-01-26 18:34:53
2009-01-27 09:24:19 LOG: checkpoint record is at 0/1B9F92C8
2009-01-27 09:24:19 LOG: redo record is at 0/1B9F92C8; undo record is at 0/0; shutdown TRUE
2009-01-27 09:24:19 LOG: next transaction ID: 0/335372; next OID: 19380
2009-01-27 09:24:19 LOG: next MultiXactId: 1; next MultiXactOffset: 0
2009-01-27 09:24:19 LOG: database system is ready
2009-01-27 18:52:43 LOG: received fast shutdown request
2009-01-27 18:52:44 LOG: shutting down
2009-01-27 18:52:44 LOG: database system is shut down
2009-01-27 18:52:44 LOG: logger shutting down

and

2009-01-28 09:42:14 FATAL: the database system is starting up
2009-01-28 09:42:14 LOG: database system was shut down at 2009-01-27 18:52:44
2009-01-28 09:42:14 LOG: checkpoint record is at 0/1B9F9368
2009-01-28 09:42:14 LOG: redo record is at 0/1B9F9368; undo record is at 0/0; shutdown TRUE
2009-01-28 09:42:14 LOG: next transaction ID: 0/336490; next OID: 19380
2009-01-28 09:42:14 LOG: next MultiXactId: 1; next MultiXactOffset: 0
2009-01-28 09:42:15 LOG: database system is ready
2009-01-28 09:42:15 FATAL: the database system is starting up

Re: Rollback of Query Cancellation

From

Jaime Casanova

Date:

28 January 2009, 05:39:05

On Wed, Jan 28, 2009 at 1:29 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
> Welcome Jcasanov,
>
> Here is the output of the log files:
>
> 2009-01-27 09:24:18 FATAL:  the database system is starting up
> 2009-01-27 09:24:19 LOG:  database system was shut down at 2009-01-26
> 18:34:53
> 2009-01-27 09:24:19 LOG:  checkpoint record is at 0/1B9F92C8
> 2009-01-27 09:24:19 LOG:  redo record is at 0/1B9F92C8; undo record is at
> 0/0; shutdown TRUE
> 2009-01-27 09:24:19 LOG:  next transaction ID: 0/335372; next OID: 19380
> 2009-01-27 09:24:19 LOG:  next MultiXactId: 1; next MultiXactOffset: 0
> 2009-01-27 09:24:19 LOG:  database system is ready

all these messages are 'cause the database is starting up

> 2009-01-27 18:52:43 LOG:  received fast shutdown request
> 2009-01-27 18:52:44 LOG:  shutting down
> 2009-01-27 18:52:44 LOG:  database system is shut down
> 2009-01-27 18:52:44 LOG:  logger shutting down
>

the database was shutting down

> and
>
> 2009-01-28 09:42:14 FATAL:  the database system is starting up
> 2009-01-28 09:42:14 LOG:  database system was shut down at 2009-01-27
> 18:52:44
> 2009-01-28 09:42:14 LOG:  checkpoint record is at 0/1B9F9368
> 2009-01-28 09:42:14 LOG:  redo record is at 0/1B9F9368; undo record is at
> 0/0; shutdown TRUE
> 2009-01-28 09:42:14 LOG:  next transaction ID: 0/336490; next OID: 19380
> 2009-01-28 09:42:14 LOG:  next MultiXactId: 1; next MultiXactOffset: 0
> 2009-01-28 09:42:15 LOG:  database system is ready
> 2009-01-28 09:42:15 FATAL:  the database system is starting up
>

starting up again


none of these are saying the time for some records being deleted, read
my prior post about why is not possible that message (commit never
executed)


--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 06:10:55

Thanks Jaime,
Plz consider the actual log files to explore the issue in detail. Because I have pasted the log files of client machine, I am using (sorry).

2009-01-27 18:29:25 STATEMENT: delete from ci_cin_type_v where req_id='0824100207'
    delete from ci_cust_type_v where req_id='0824100207'
    delete from ci_dependents_v where req_id='0824100207'
    delete from ci_employer_v where req_id='0824100207'
    delete from ci_cor_sig_v where req_id='0824100207'
    delete from ci_corporate_v where req_id='0824100207'
    delete from ci_individual_v where req_id='0824100207'
    delete from ci_cif_v where req_id='0824100207'
2009-01-27 18:29:41 ERROR: relation "ci_cust_type_v" does not exist
2009-01-27 18:29:41 STATEMENT: delete from ci_cust_type_v where req_id='0824100207'
2009-01-27 18:52:08 LOG: could not receive data from client: No connection could be made because the target machine actively refused it.
2009-01-27 18:52:08 LOG: unexpected EOF on client connection
2009-01-27 18:52:08 LOG: could not receive data from client: No connection could be made because the target machine actively refused it.
2009-01-27 18:52:08 LOG: unexpected EOF on client connection

Here, I am talking about the last query (Bold_Italic). Now my question is still stands. Kindly continue to up your valuable text.

From: Jaime Casanova <jcasanov@systemguards.com.ec>
To: Abdul Rahman <abr_ora@yahoo.com>
Cc: pgsql-general@postgresql.org
Sent: Wednesday, January 28, 2009 11:38:59 AM
Subject: Re: Rollback of Query Cancellation

On Wed, Jan 28, 2009 at 1:29 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
> Welcome Jcasanov,
>
> Here is the output of the log files:
>
> 2009-01-27 09:24:18 FATAL: the database system is starting up
> 2009-01-27 09:24:19 LOG: database system was shut down at 2009-01-26
> 18:34:53
> 2009-01-27 09:24:19 LOG: checkpoint record is at 0/1B9F92C8
> 2009-01-27 09:24:19 LOG: redo record is at 0/1B9F92C8; undo record is at
> 0/0; shutdown TRUE
> 2009-01-27 09:24:19 LOG: next transaction ID: 0/335372; next OID: 19380
> 2009-01-27 09:24:19 LOG: next MultiXactId: 1; next MultiXactOffset: 0
> 2009-01-27 09:24:19 LOG: database system is ready

all these messages are 'cause the database is starting up

> 2009-01-27 18:52:43 LOG: received fast shutdown request
> 2009-01-27 18:52:44 LOG: shutting down
> 2009-01-27 18:52:44 LOG: database system is shut down
> 2009-01-27 18:52:44 LOG: logger shutting down
>

the database was shutting down

> and
>
> 2009-01-28 09:42:14 FATAL: the database system is starting up
> 2009-01-28 09:42:14 LOG: database system was shut down at 2009-01-27
> 18:52:44
> 2009-01-28 09:42:14 LOG: checkpoint record is at 0/1B9F9368
> 2009-01-28 09:42:14 LOG: redo record is at 0/1B9F9368; undo record is at
> 0/0; shutdown TRUE
> 2009-01-28 09:42:14 LOG: next transaction ID: 0/336490; next OID: 19380
> 2009-01-28 09:42:14 LOG: next MultiXactId: 1; next MultiXactOffset: 0
> 2009-01-28 09:42:15 LOG: database system is ready
> 2009-01-28 09:42:15 FATAL: the database system is starting up
>

starting up again

none of these are saying the time for some records being deleted, read
my prior post about why is not possible that message (commit never
executed)

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 06:15:56

Very nice!
Most probably it was waiting for something else. This is the reason the query executed today and clearly showed certain number of rows deleted. But what ELSE?

From: Sim Zacks <sim@compulab.co.il>
To: Abdul Rahman <abr_ora@yahoo.com>
Sent: Wednesday, January 28, 2009 12:08:28 PM
Subject: Re: [GENERAL] Rollback of Query Cancellation

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Its very possible that the reason that the query was because there was a
lock on the table. If you run select * from pg_stat_activity while the
query is running there is a waiting flag that indicates whether your
query is actually being executed or if it is waiting for something else.

Sim

Abdul Rahman wrote:
> Dear All,
>
> Yesterday I canceled a running query because it was taking long time
> (more than 12 minutes) to delete lots of records. Today when I executed
> the same query it hardly took few seconds to finish. It clearly explores
> that PostgreSQL does not perform rollback action. Is it true?
>
> Regards,
> Abdul Rehman.
>

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmABGwACgkQjDX6szCBa+oOzwCguiRslM90EAKY/wo34htqtXUH
hWIAoLkALRcBYEJ7jW5ordKRX73jqyR9
=TqIi
-----END PGP SIGNATURE-----

Re: Rollback of Query Cancellation

From

Jaime Casanova

Date:

28 January 2009, 06:20:58

On Wed, Jan 28, 2009 at 2:10 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
> Thanks Jaime,
> Plz consider the actual log files to explore the issue in detail. Because I
> have pasted the log files of client machine, I am using (sorry).
>
>
> 2009-01-27 18:29:25 STATEMENT:  delete from ci_cin_type_v where
> req_id='0824100207'
>     delete from ci_cust_type_v where req_id='0824100207'
>     delete from ci_dependents_v where req_id='0824100207'
>     delete from ci_employer_v where req_id='0824100207'
>     delete from ci_cor_sig_v where req_id='0824100207'
>     delete from ci_corporate_v where req_id='0824100207'
>     delete from ci_individual_v where req_id='0824100207'
>     delete from ci_cif_v where req_id='0824100207'

then you have a lot of deletes, are there executing inside a
transaction? are you calling a trigger?

> 2009-01-27 18:29:41 ERROR:  relation "ci_cust_type_v" does not exist

this table does not exist

> 2009-01-27 18:29:41 STATEMENT:  delete from ci_cust_type_v where
> req_id='0824100207'
> 2009-01-27 18:52:08 LOG:  could not receive data from client: No connection
> could be made because the target machine actively refused it.
> 2009-01-27 18:52:08 LOG:  unexpected EOF on client connection
> 2009-01-27 18:52:08 LOG:  could not receive data from client: No connection
> could be made because the target machine actively refused it.
> 2009-01-27 18:52:08 LOG:  unexpected EOF on client connection
>

guess this messages are received after the CANCEL QUERY

if the series of deletes are all executed inside a transaction then
they all were rollback if not only the last one (the one that
generates the error) was rolledback

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Abdul Rahman

Date:

28 January 2009, 07:06:32

Well Jaime,

I executed all the delete queries one by one. Now I am unable to understand that why it took sufficient time to run the last query before cancellation.

i.e. delete from ci_cif_v where req_id='0824100207';

This morning it performed the delete operation and deleted certain number of rows within few seconds. Then what it was doing yesterday. Here it seems that it was performing something else (as guessed by Sim Zacks) before the execution of delete query. And when I canceled, the query was not executed till that time. Then why it didn't take sufficient amount of time to perform something else before the execution of same query today.

From: Jaime Casanova <jcasanov@systemguards.com.ec>
To: Abdul Rahman <abr_ora@yahoo.com>
Cc: pgsql-general@postgresql.org
Sent: Wednesday, January 28, 2009 12:20:41 PM
Subject: Re: Rollback of Query Cancellation

On Wed, Jan 28, 2009 at 2:10 AM, Abdul Rahman <abr_ora@yahoo.com> wrote:
> Thanks Jaime,
> Plz consider the actual log files to explore the issue in detail. Because I
> have pasted the log files of client machine, I am using (sorry).
>
>
> 2009-01-27 18:29:25 STATEMENT: delete from ci_cin_type_v where
> req_id='0824100207'
> delete from ci_cust_type_v where req_id='0824100207'
> delete from ci_dependents_v where req_id='0824100207'
> delete from ci_employer_v where req_id='0824100207'
> delete from ci_cor_sig_v where req_id='0824100207'
> delete from ci_corporate_v where req_id='0824100207'
> delete from ci_individual_v where req_id='0824100207'
> delete from ci_cif_v where req_id='0824100207'

then you have a lot of deletes, are there executing inside a
transaction? are you calling a trigger?

> 2009-01-27 18:29:41 ERROR: relation "ci_cust_type_v" does not exist

this table does not exist

> 2009-01-27 18:29:41 STATEMENT: delete from ci_cust_type_v where
> req_id='0824100207'
> 2009-01-27 18:52:08 LOG: could not receive data from client: No connection
> could be made because the target machine actively refused it.
> 2009-01-27 18:52:08 LOG: unexpected EOF on client connection
> 2009-01-27 18:52:08 LOG: could not receive data from client: No connection
> could be made because the target machine actively refused it.
> 2009-01-27 18:52:08 LOG: unexpected EOF on client connection
>

guess this messages are received after the CANCEL QUERY

if the series of deletes are all executed inside a transaction then
they all were rollback if not only the last one (the one that
generates the error) was rolledback

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Re: Rollback of Query Cancellation

From

Sim Zacks

Date:

28 January 2009, 07:28:52

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Abdul Rahman wrote:
> Very nice!
> Most probably it was waiting for something else. This is the reason the
> query executed today and clearly showed certain number of rows deleted.
> But what ELSE?
>
It could be a ton of things, but as an example, if you have a cursor
open on a row that your query wants to delete.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmADtsACgkQjDX6szCBa+onTQCgoEKG1CsZXfmmYLBW29gvHoOb
kv8AoNzW1MHOUuPM0bOISTn/ppnuuyXM
=CFb7
-----END PGP SIGNATURE-----

Re: Rollback of Query Cancellation

From

Jasen Betts

Date:

01 February 2009, 01:38:25

On 2009-01-28, Abdul Rahman <abr_ora@yahoo.com> wrote:
> --0-2110834523-1233119974=:72728
> Content-Type: text/plain; charset=us-ascii
>
> Dear All,
>
> Yesterday I canceled a running query because it was taking long time
> (more than 12 minutes) to delete lots of records. Today when I
> executed the same query it hardly took few seconds to finish. It
> clearly explores that PostgreSQL does not perform rollback action.
> Is it true?

it's true, but that's not proof. (the delete could have got held up by
a lock yesterday)