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

Search Discussions

  • Thom Brown at Sep 10, 2010 at 9:49 am

    On 10 September 2010 09:49, Mladen Gogala 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
  • Thom Brown at Sep 10, 2010 at 10:34 am

    On 10 September 2010 11:27, Mladen Gogala 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
  • Tom Lane at Sep 11, 2010 at 2:23 am

    Mladen Gogala 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
  • Mladen Gogala at Sep 11, 2010 at 3:32 am

    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
  • Thomas Kellerer at Sep 11, 2010 at 6:54 am

    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

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-novice @
categoriespostgresql
postedSep 10, '10 at 8:49a
activeSep 11, '10 at 6:54a
posts6
users4
websitepostgresql.org
irc#postgresql

People

Translate

site design / logo © 2022 Grokbase