Re: refreshRow is slow

From: "John T(dot) Dow" <john(at)johntdow(dot)com>
To: "Oliver Jowett" <oliver(at)opencloud(dot)com>
Cc: "pgsql-jdbc(at)postgresql(dot)org" <pgsql-jdbc(at)postgresql(dot)org>
Subject: Re: refreshRow is slow
Date: 2010-01-15 23:06:49
Message-ID: 201001152307.o0FN7Aw2027525@web2.nidhog.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-jdbc

I observe the following in the jdbc log.

There's the original read only query, with 722 rows. The actual query was "SELECT * FROM doctor WHERE 1 = 1". Yes, I know it could just be "SELECT * FROM doctor" but the query is generated based on user input, and that's my version of a null where clause.

After the first row of the result set was displayed, I changed a field and updated the table. The log shows the query "for update" and later a commit.

Following that, where my program would do the refreshRow on the original resultset, I find a 21 instances of this block (some lines omitted):

17:25:50.812 (1) simple execute, handler=org(dot)postgresql(dot)jdbc2(dot)AbstractJdbc2Statement$StatementResultHandler(at)1142196, maxRows=0, fetchSize=0, flags=17
17:25:50.812 (1) FE=> Parse(stmt=null,query="SELECT attname FROM pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2",oids={23,23})
17:25:50.812 (1) FE=> Bind(stmt=null,portal=null,$1=<16404>,$2=<1>)
17:25:50.812 (1) FE=> Describe(portal=null)
17:25:50.812 (1) FE=> Execute(portal=null,limit=0)
17:25:50.812 (1) FE=> Sync
17:25:50.812 (1) <=BE ParseComplete [null]
17:25:50.812 (1) <=BE BindComplete [null]
17:25:50.812 (1) <=BE RowDescription(1)
17:25:50.812 (1) <=BE DataRow
17:25:50.812 (1) <=BE CommandStatus(SELECT)
17:25:50.812 (1) <=BE ReadyForQuery(I)

The only difference between the 21 blocks is that the $2 parameter goes 1, 2, 3, 4, ... 21

After the 21st block comes this, and that ends the log.

17:38:47.031 (1) selecting select id, address, citystatezip, combined, degree, email, fax, firstname, groupname, lastname, nfiid, pabsid, practicetype, ssn, telephone, insertby, insertdate, inserttime, updateby, updatedate, updatetime from doctor where id= ?
17:38:47.046 (1) simple execute, handler=org(dot)postgresql(dot)jdbc2(dot)AbstractJdbc2Statement$StatementResultHandler(at)d3c6a3, maxRows=0, fetchSize=0, flags=17
17:38:47.046 (1) FE=> Parse(stmt=null,query="select id, address, citystatezip, combined, degree, email, fax, firstname, groupname, lastname, nfiid, pabsid, practicetype, ssn, telephone, insertby, insertdate, inserttime, updateby, updatedate, updatetime from doctor where id= $1",oids={1043})
17:38:47.046 (1) FE=> Bind(stmt=null,portal=null,$1=<0984>)
17:38:47.046 (1) FE=> Describe(portal=null)
17:38:47.046 (1) FE=> Execute(portal=null,limit=0)
17:38:47.046 (1) FE=> Sync
17:38:47.046 (1) <=BE ParseComplete [null]
17:38:47.046 (1) <=BE BindComplete [null]
17:38:47.046 (1) <=BE RowDescription(21)
17:38:47.046 (1) <=BE DataRow
17:38:47.046 (1) <=BE CommandStatus(SELECT)
17:38:47.046 (1) <=BE ReadyForQuery(I)
17:38:47.046 (1) done updates
17:38:49.765 (1) FE=> Terminate

The value 0984 is the primary key value for the row I changed. I repeated this with the same original resultset, but moved to the 25th row before making a change. Again it did 21 instances of this block (the primary key value was of course different).

To me, who knows nothing, the mystery is why 21 repetitions?

I repeated this with another table. The original query had 792 rows. I went to the last row and made a change. This time there were 408 repetitions. Again, it used the primary key for the $1 parameter shown above.

So why 408 repetitions this time?

John

Responses

Browse pgsql-jdbc by date

  From Date Subject
Next Message Oliver Jowett 2010-01-15 23:24:29 Re: refreshRow is slow
Previous Message Maciek Sakrejda 2010-01-15 16:42:28 Re: COPY using Hibernate