Thread: Transactional issue that begs for explanation
I am having problems explaining the following course of events:
I created table test_keys(key int,val varchar(10)); No PK, no indexes.
I populated the table using the following SQL:
insert into test_keys values(1,'Key1');
insert into test_keys values(2,'Key2');
insert into test_keys values(3,'Key3');
insert into test_keys values(4,'Key4');
insert into test_keys values(5,'Key5');
insert into test_keys values(6,'Key6');
insert into test_keys values(7,'Key7');
insert into test_keys values(8,'Key8');
insert into test_keys values(9,'Key9');
insert into test_keys values(10,'Key10');
insert into test_keys values(11,'Key11');
insert into test_keys values(12,'Key12');
insert into test_keys values(13,'Key13');
insert into test_keys values(14,'Key14');
insert into test_keys values(15,'Key15');
insert into test_keys values(16,'Key16');
insert into test_keys values(17,'Key17');
insert into test_keys values(18,'Key18');
insert into test_keys values(19,'Key19');
insert into test_keys values(20,'Key20');
To make the story more interesting, I added the following:
CREATE or REPLACE FUNCTION logtrg() RETURNS trigger AS $$
open(STDOUT,">>/tmp/logfile") or die("Cannot open log:$!\n");
$key=$_TD->{old}{key};
$val=$_TD->{old}{val};
print "Firing on: $key $val\n";
return;
$$ LANGUAGE plperlu;
CREATE TRIGGER log_upd BEFORE UPDATE on test_keys
FOR EACH ROW EXECUTE PROCEDURE logtrg();
Essentially, I added trigger that records the values that the trigger
fires upon and puts those values into /tmp/logfile
Next, opened 2 sessions and executed the following:
Session 1: Session 2:
----------------
----------------
begin; begin;
update test_keys update test_keys
set val='EVEN' set val='DIV5'
where key%2=0; where key%5=0;
rollback; commit;
Here is the content of my logfile:
root@ubuntu:~# tail -f /tmp/logfile
Firing on: 2 Key2
Firing on: 4 Key4
Firing on: 6 Key6
Firing on: 8 Key8
Firing on: 10 Key10
Firing on: 12 Key12
Firing on: 14 Key14
Firing on: 16 Key16
Firing on: 18 Key18
Firing on: 20 EVEN
Firing on: 5 Key5
Firing on: 10 Key10
Firing on: 15 Key15
Question: where did "EVEN" on the key 20 come from? The first
transaction was rolled back, the 2nd transaction shouldn't have seen any
changes made by the first transaction. I am using PgSQL 8.4.4 on Ubuntu
10, 32bit version (laptop).
I repeated the experiment several times, and this happens rather
consistently.
--
Mladen Gogala
Sr. Oracle DBA
1500 Broadway
New York, NY 10036
(212) 329-5251
www.vmsinfo.com
The Leader in integrated Media Intelligence Solutions
On 10 September 2010 09:49, Mladen Gogala <mladen.gogala@vmsinfo.com> wrote:
> I am having problems explaining the following course of events:
>
> I created table test_keys(key int,val varchar(10)); No PK, no indexes.
> I populated the table using the following SQL:
> insert into test_keys values(1,'Key1');
> insert into test_keys values(2,'Key2');
> insert into test_keys values(3,'Key3');
> insert into test_keys values(4,'Key4');
> insert into test_keys values(5,'Key5');
> insert into test_keys values(6,'Key6');
> insert into test_keys values(7,'Key7');
> insert into test_keys values(8,'Key8');
> insert into test_keys values(9,'Key9');
> insert into test_keys values(10,'Key10');
> insert into test_keys values(11,'Key11');
> insert into test_keys values(12,'Key12');
> insert into test_keys values(13,'Key13');
> insert into test_keys values(14,'Key14');
> insert into test_keys values(15,'Key15');
> insert into test_keys values(16,'Key16');
> insert into test_keys values(17,'Key17');
> insert into test_keys values(18,'Key18');
> insert into test_keys values(19,'Key19');
> insert into test_keys values(20,'Key20');
>
> To make the story more interesting, I added the following:
> CREATE or REPLACE FUNCTION logtrg() RETURNS trigger AS $$
> open(STDOUT,">>/tmp/logfile") or die("Cannot open log:$!\n");
> $key=$_TD->{old}{key};
> $val=$_TD->{old}{val};
> print "Firing on: $key $val\n";
> return;
> $$ LANGUAGE plperlu;
>
> CREATE TRIGGER log_upd BEFORE UPDATE on test_keys
> FOR EACH ROW EXECUTE PROCEDURE logtrg();
>
> Essentially, I added trigger that records the values that the trigger fires
> upon and puts those values into /tmp/logfile
>
> Next, opened 2 sessions and executed the following:
> Session 1: Session 2:
> ----------------
> ----------------
> begin; begin;
> update test_keys update test_keys
> set val='EVEN' set val='DIV5'
> where key%2=0; where key%5=0;
> rollback; commit;
>
> Here is the content of my logfile:
>
>
> root@ubuntu:~# tail -f /tmp/logfile
> Firing on: 2 Key2
> Firing on: 4 Key4
> Firing on: 6 Key6
> Firing on: 8 Key8
> Firing on: 10 Key10
> Firing on: 12 Key12
> Firing on: 14 Key14
> Firing on: 16 Key16
> Firing on: 18 Key18
> Firing on: 20 EVEN
> Firing on: 5 Key5
> Firing on: 10 Key10
> Firing on: 15 Key15
>
> Question: where did "EVEN" on the key 20 come from? The first transaction
> was rolled back, the 2nd transaction shouldn't have seen any changes made by
> the first transaction. I am using PgSQL 8.4.4 on Ubuntu 10, 32bit version
> (laptop).
>
> I repeated the experiment several times, and this happens rather
> consistently.
This is quite odd. I've done exactly the same thing on 8.4.4 Gentoo
x64 and it returns the expected result so I haven't been able to
recreate it. What does the table contain after that series of events?
--
Thom Brown
Twitter: @darkixion
IRC (freenode): dark_ixion
Registered Linux user: #516935
On 10 September 2010 11:27, Mladen Gogala <mladen.gogala@vmsinfo.com> wrote: > Thom Brown wrote: >> >> This is quite odd. I've done exactly the same thing on 8.4.4 Gentoo >> x64 and it returns the expected result so I haven't been able to >> recreate it. What does the table contain after that series of events? >> >> > > Oh, the content is correct, 4 records are modified, 5,10,15 and 20 have all > value 'DIV5'. I've been bitten by triggers before so I am testing the > trigger behavior. The good news is that "before update" trigger doesn't fire > twice, as is the case with Oracle. BTW, is there any simpler method to > simulate DBMS_OUTPUT, other than using plperlu the way I did? Please reply to all so everyone else can see your response. :) (list copied in again for this message) But I personally don't know of the best way to produce the logging you're after. -- Thom Brown Twitter: @darkixion IRC (freenode): dark_ixion Registered Linux user: #516935
Mladen Gogala <mladen.gogala@vmsinfo.com> writes:
> To make the story more interesting, I added the following:
> CREATE or REPLACE FUNCTION logtrg() RETURNS trigger AS $$
> open(STDOUT,">>/tmp/logfile") or die("Cannot open log:$!\n");
> $key=$_TD->{old}{key};
> $val=$_TD->{old}{val};
> print "Firing on: $key $val\n";
> return;
> $$ LANGUAGE plperlu;
I suspect you're shooting yourself in the foot by repeatedly re-opening
the backend's stdout and not fflush'ing anywhere along the line: somehow
the data going to the log file is getting mangled. I don't see any
strange behavior here when using a less dangerous logging technique,
such as
CREATE or REPLACE FUNCTION logtrg() RETURNS trigger AS $$
$key=$_TD->{old}{key};
$val=$_TD->{old}{val};
elog(NOTICE, "Firing on: $key $val\n");
return;
$$ LANGUAGE plperlu;
(Actually, I don't see anything funny when using your original version
of the function, either; but it's probably dependent on a lot of
platform-specific libc details exactly how you got that result.)
regards, tom lane
Tom Lane wrote:
> I suspect you're shooting yourself in the foot by repeatedly re-opening
> the backend's stdout and not fflush'ing anywhere along the line: somehow
> the data going to the log file is getting mangled. I don't see any
> strange behavior here when using a less dangerous logging technique,
> such as
>
> CREATE or REPLACE FUNCTION logtrg() RETURNS trigger AS $$
> $key=$_TD->{old}{key};
> $val=$_TD->{old}{val};
> elog(NOTICE, "Firing on: $key $val\n");
> return;
> $$ LANGUAGE plperlu;
>
> (Actually, I don't see anything funny when using your original version
> of the function, either; but it's probably dependent on a lot of
> platform-specific libc details exactly how you got that result.)
>
> regards, tom lane
>
Tom, you are a great guy. I didn't know about the elog function, I've
just tried to re-invent the wheel. Thanks for the pointer, I will try
with elog. Actually, I was trying to check what from the following
article is applicable to Postgres:
http://tkyte.blogspot.com/2005/08/something-different-part-i-of-iii.html
http://tkyte.blogspot.com/2005/08/part-ii-seeing-restart.html
http://tkyte.blogspot.com/2005/09/part-iii-why-is-restart-important-to.html
What I did figure out is
a) Postgres doesn't restart the transaction the same way that Oracle
does or the trigger would fire twice.
b) There is no DBMS_OUTPUT, so I tried to re-invent the wheel.
I still don't know what does Postgres do when the data in a block
needed by current transaction changes the value? Oracle simply restarts
the transaction, in order to have a clean slate.
--
Mladen Gogala
Sr. Oracle DBA
1500 Broadway
New York, NY 10036
(212) 329-5251
www.vmsinfo.com
Mladen Gogala wrote on 11.09.2010 05:32: > b) There is no DBMS_OUTPUT, so I tried to re-invent the wheel. RAISE NOTICE is the Postgres equivalent to DBMS_OUTPUT http://www.postgresql.org/docs/current/static/plpgsql-errors-and-messages.html