Thread: Problem with background worker

Problem with background worker

From
Marc Cousin
Date:
Hi,

I'm trying to write a background writer, and I'm facing a problem with
timestamps. The following code is where I'm having a problem (it's just a demo for
the problem):

BackgroundWorkerInitializeConnection("test", NULL);
while (!got_sigterm)
{int ret;/* Wait 1s */ret = WaitLatch(&MyProc->procLatch,WL_LATCH_SET | WL_TIMEOUT |
WL_POSTMASTER_DEATH,1000L);ResetLatch(&MyProc->procLatch);/*Insert dummy for now
*/StartTransactionCommand();SPI_connect();PushActiveSnapshot(GetTransactionSnapshot());ret= SPI_execute("INSERT INTO
logVALUES (now(),statement_timestamp(),clock_timestamp())", false,
0);SPI_finish();PopActiveSnapshot();CommitTransactionCommand();
}

\d log
      Column        |           Type           | Modifiers
---------------------+--------------------------+---------------now                 | timestamp with time zone |
statement_timestamp| timestamp with time zone | clock_timestamp     | timestamp with time zone |
 

Here is its content. Only the clock_timestamp is right. There are missing records at the
beginning because i truncated the table for this example.
             now              |      statement_timestamp      |        clock_timestamp        
-------------------------------+-------------------------------+-------------------------------2013-03-20
15:01:44.618623+01| 2013-03-20 15:01:44.618623+01 | 2013-03-20 15:01:52.77683+012013-03-20 15:01:44.618623+01 |
2013-03-2015:01:44.618623+01 | 2013-03-20 15:01:53.784301+012013-03-20 15:01:44.618623+01 | 2013-03-20
15:01:44.618623+01| 2013-03-20 15:01:54.834212+012013-03-20 15:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 |
2013-03-2015:01:55.848497+012013-03-20 15:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:01:56.872671+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:01:57.888461+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:01:58.912448+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:01:59.936335+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:02:00.951247+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20
15:02:01.967937+012013-03-2015:01:44.618623+01 | 2013-03-20 15:01:44.618623+01 | 2013-03-20 15:02:02.983613+01
 


Most of the code is copy/paste from worker_spi (I don't really understand the 
PushActiveSnapshot(GetTransactionSnapshot()) and PopActiveSnapshot() but the 
behaviour is the same with or without them, and they were in worker_spi).

I guess I'm doing something wrong, but I really dont't know what it is.

Should I attach the whole code ?

Regards,

Marc



Re: Problem with background worker

From
Alvaro Herrera
Date:
Marc Cousin escribió:
> Hi,
>
> I'm trying to write a background writer, and I'm facing a problem with
> timestamps. The following code is where I'm having a problem (it's just a demo for
> the problem):
>
> BackgroundWorkerInitializeConnection("test", NULL);
> while (!got_sigterm)
> {
>     int ret;
>     /* Wait 1s */
>     ret = WaitLatch(&MyProc->procLatch,
>     WL_LATCH_SET | WL_TIMEOUT | WL_POSTMASTER_DEATH,
>     1000L);
>     ResetLatch(&MyProc->procLatch);
>     /* Insert dummy for now */
>     StartTransactionCommand();
>     SPI_connect();
>     PushActiveSnapshot(GetTransactionSnapshot());
>     ret = SPI_execute("INSERT INTO log VALUES (now(),statement_timestamp(),clock_timestamp())", false, 0);
>     SPI_finish();
>     PopActiveSnapshot();
>     CommitTransactionCommand();
> }

Ah.  The reason for this problem is that the statement start time (which
also sets the transaction start time, when it's the first statement) is
set by postgres.c, not the transaction-control functions in xact.c.  So
you'd need to add a SetCurrentStatementStartTimestamp() call somewhere
in your loop.

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services



Re: Problem with background worker

From
Marc Cousin
Date:
On 20/03/2013 16:33, Alvaro Herrera wrote:
> Marc Cousin escribió:
>> Hi,
>>
>> I'm trying to write a background writer, and I'm facing a problem with
>> timestamps. The following code is where I'm having a problem (it's just a demo for
>> the problem):
>>
>> BackgroundWorkerInitializeConnection("test", NULL);
>> while (!got_sigterm)
>> {
>>     int ret;
>>     /* Wait 1s */
>>     ret = WaitLatch(&MyProc->procLatch,
>>     WL_LATCH_SET | WL_TIMEOUT | WL_POSTMASTER_DEATH,
>>     1000L);
>>     ResetLatch(&MyProc->procLatch);
>>     /* Insert dummy for now */
>>     StartTransactionCommand();
>>     SPI_connect();
>>     PushActiveSnapshot(GetTransactionSnapshot());
>>     ret = SPI_execute("INSERT INTO log VALUES (now(),statement_timestamp(),clock_timestamp())", false, 0);
>>     SPI_finish();
>>     PopActiveSnapshot();
>>     CommitTransactionCommand();
>> }
>
> Ah.  The reason for this problem is that the statement start time (which
> also sets the transaction start time, when it's the first statement) is
> set by postgres.c, not the transaction-control functions in xact.c.  So
> you'd need to add a SetCurrentStatementStartTimestamp() call somewhere
> in your loop.
>

Yes, that works. Thanks a lot !

Maybe this should be added to the worker_spi example ?

Regards



Re: Problem with background worker

From
Alvaro Herrera
Date:
Marc Cousin escribió:
> On 20/03/2013 16:33, Alvaro Herrera wrote:

> >Ah.  The reason for this problem is that the statement start time (which
> >also sets the transaction start time, when it's the first statement) is
> >set by postgres.c, not the transaction-control functions in xact.c.  So
> >you'd need to add a SetCurrentStatementStartTimestamp() call somewhere
> >in your loop.
>
> Yes, that works. Thanks a lot !
>
> Maybe this should be added to the worker_spi example ?

Yeah, I think I need to go over the postgres.c code and figure out what
else needs to be called.  I have a pending patch from Guillaume to
improve worker_spi some more; I'll add this bit too.

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services



Re: Problem with background worker

From
Guillaume Lelarge
Date:
On Wed, 2013-03-20 at 13:13 -0300, Alvaro Herrera wrote:
> Marc Cousin escribió:
> > On 20/03/2013 16:33, Alvaro Herrera wrote:
>
> > >Ah.  The reason for this problem is that the statement start time (which
> > >also sets the transaction start time, when it's the first statement) is
> > >set by postgres.c, not the transaction-control functions in xact.c.  So
> > >you'd need to add a SetCurrentStatementStartTimestamp() call somewhere
> > >in your loop.
> >
> > Yes, that works. Thanks a lot !
> >
> > Maybe this should be added to the worker_spi example ?
>
> Yeah, I think I need to go over the postgres.c code and figure out what
> else needs to be called.  I have a pending patch from Guillaume to
> improve worker_spi some more; I'll add this bit too.
>

Happy to know that you still remember it :) Thanks.


--
Guillaume
http://blog.guillaume.lelarge.info
http://www.dalibo.com




Re: Problem with background worker

From
Alvaro Herrera
Date:
Marc Cousin escribió:
> On 20/03/2013 16:33, Alvaro Herrera wrote:

> >Ah.  The reason for this problem is that the statement start time (which
> >also sets the transaction start time, when it's the first statement) is
> >set by postgres.c, not the transaction-control functions in xact.c.  So
> >you'd need to add a SetCurrentStatementStartTimestamp() call somewhere
> >in your loop.
> >
>
> Yes, that works. Thanks a lot !
>
> Maybe this should be added to the worker_spi example ?

Done in
http://git.postgresql.org/pg/commitdiff/e543631f3c162ab5f6020b1d0209e0353ca2229a

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services