Обсуждение: Negative result with (now()-previously_inserted_timestamp)
I have an IRC logger storing its data in a Postgres 8.3.3. The table in question has the interesting column declared as: time timestamp with time zone default now() The logger uses a prepared statement to insert data, and does not mention this column in the INSERT statement, hence the assumption that default clause is being used. I ran the following query, and got an unexpected negative value. Does this imply that SELECT-transaction was able to see a row created by INSERT-transaction which started after the SELECT-transaction? postgres=> select channel, min( now()-time ) from irclog group by channel order by 2 asc; channel | min --------------+------------------------- #archlinux | -00:00:00.11686 ##C | 00:00:00.09718 #debian | 00:00:00.482193 ##linux | 00:00:01.172365 ... # | 36 days 14:01:17.395093 (21 rows) (Note: the '#' row can serve as a diagnosis starting point since that channel group has never been inserted into since the incident) I scoured the release notes 8.3.4 to 8.3.11 for any relevant fixes and found only this one: http://www.postgresql.org/docs/8.3/static/release-8-3-5.html Fix improper display of fractional seconds in interval values when using a non-ISO datestyle in an --enable-integer-datetimes build (Ron Mayer) But I don't think this applies to this bug report as I am using ISO datestyle. postgres=> show DateStyle; DateStyle ----------- ISO, MDY (1 row) Regards, -- gurjeet.singh @ EnterpriseDB - The Enterprise Postgres Company http://www.EnterpriseDB.com singh.gurjeet@{ gmail | yahoo }.com Twitter/Skype: singh_gurjeet Mail sent from my BlackLaptop device
Gurjeet Singh <singh.gurjeet@gmail.com> writes:
> I ran the following query, and got an unexpected negative value. Does this
> imply that SELECT-transaction was able to see a row created by
> INSERT-transaction which started after the SELECT-transaction?
Was the SELECT inside a BEGIN block?
regards, tom lane
On Wed, Jul 7, 2010 at 12:18 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Gurjeet Singh <singh.gurjeet@gmail.com> writes: > > I ran the following query, and got an unexpected negative value. Does > this > > imply that SELECT-transaction was able to see a row created by > > INSERT-transaction which started after the SELECT-transaction? > > Was the SELECT inside a BEGIN block? > No. I have the psql session still open so can confirm that with absolute confidence. If you must know, this instance is on a low-cost, hosted, Xen virtual machine. By any chance, can we suspect the timer accuracy here? Or possibly an NTP server foul-play! Regards, -- gurjeet.singh @ EnterpriseDB - The Enterprise Postgres Company http://www.EnterpriseDB.com singh.gurjeet@{ gmail | yahoo }.com Twitter/Skype: singh_gurjeet Mail sent from my BlackLaptop device
On Wed, Jul 7, 2010 at 12:18 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Gurjeet Singh <singh.gurjeet@gmail.com> writes: > > I ran the following query, and got an unexpected negative value. Does > this > > imply that SELECT-transaction was able to see a row created by > > INSERT-transaction which started after the SELECT-transaction? > > Was the SELECT inside a BEGIN block? Oh, I get it. You mean read-committed transaction mode's side-effect inside a transaction block! No, that's not the case. Just confirmed that by issuing a syntactically wrong statement in that session (resulting in ERROR), and then doing 'select 1'; it did not raise the error 'Current transaction is aborted...'. And scrolling back the session does not show any BEGIN/COMMIT/ROLLBACK commands that I would have issued. Regards, -- gurjeet.singh @ EnterpriseDB - The Enterprise Postgres Company http://www.EnterpriseDB.com singh.gurjeet@{ gmail | yahoo }.com Twitter/Skype: singh_gurjeet Mail sent from my BlackLaptop device
Excerpts from Gurjeet Singh's message of mié jul 07 00:43:32 -0400 2010: > If you must know, this instance is on a low-cost, hosted, Xen virtual > machine. I think Tom diagnosed an issue affecting pgstats as being out of sync gettimeofday() results on different processes. IIRC this was on a virtualized machine of some kind.
Gurjeet Singh <singh.gurjeet@gmail.com> writes: > On Wed, Jul 7, 2010 at 12:18 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: >> Gurjeet Singh <singh.gurjeet@gmail.com> writes: >>> I ran the following query, and got an unexpected negative value. Does >>> this imply that SELECT-transaction was able to see a row created by >>> INSERT-transaction which started after the SELECT-transaction? >> >> Was the SELECT inside a BEGIN block? > Oh, I get it. You mean read-committed transaction mode's side-effect inside > a transaction block! > No, that's not the case. Just confirmed that by issuing a syntactically > wrong statement in that session (resulting in ERROR), and then doing 'select > 1'; it did not raise the error 'Current transaction is aborted...'. Well, now() would be the time of receipt of the command message from the client. The transaction snapshot would be taken a bit later than that. It's theoretically possible for another transaction to start and commit in between. That'd be more likely if now() had been set by a separate transaction-starting command, but if your server was loaded enough then maybe it could happen anyway. We have seen at least one case where it appeared that the value of gettimeofday() was significantly different on different CPUs of a multiprocessor machine: http://archives.postgresql.org/pgsql-hackers/2010-03/msg00985.php It's possible you're dealing with something like that, too. regards, tom lane