BUG #14322: Possible inconsistent behavior with timestamp_to_str()
The following bug has been logged on the website:
Bug reference: 14322
Logged by: Keith Fiske
Email address: keith@keithf4.com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:
It seems when I call timestamp_to_str() on a non-null value then call it on
a null value in the same statement, it returns the previous non-null value.
I've included the code and debug lines from where I encountered this when
testing my app.
I use SPI to retrieve the values:
appendStringInfo(&buf, "SELECT sub_min::timestamptz, sub_max::timestamptz
FROM %s.check_subpartition_limits('%s.%s', 'time')", partman_schema,
parent_schemaname, parent_tablename);
ret = SPI_execute(buf.data, true, 1);
sub_timestamp_min = DatumGetTimestampTz(SPI_getbinval(SPI_tuptable->vals[0],
SPI_tuptable->tupdesc, 1, &sub_timestamp_min_isnull));
sub_timestamp_max = DatumGetTimestampTz(SPI_getbinval(SPI_tuptable->vals[0],
SPI_tuptable->tupdesc, 2, &sub_timestamp_max_isnull));
Querying the table normally, can see it returns nulls:
keith@keith=# select * from
partman.check_subpartition_limits('partman_test.time_taptest_table',
'time');
sub_min | sub_max
---------+---------
«NULL» | «NULL»
(1 row)
elog(DEBUG1, "sub_timestamp_min: %s, sub_timestamp_min_isnull: %d,
sub_timestamp_max: %ld, sub_timestamp_max_isnull: %d"
, timestamptz_to_str(sub_timestamp_min), sub_timestamp_min_isnull,
sub_timestamp_max, sub_timestamp_max_isnull);
elog(DEBUG1, "run_maint before loop: current_partition_timestamp: %s,
premade_count: %d, sub_timestamp_min: %s, sub_timestamp_max: %s"
, timestamptz_to_str(current_partition_timestamp), premade_count,
timestamptz_to_str(sub_timestamp_min),
timestamptz_to_str(sub_timestamp_max));
elog(DEBUG1, "run_maint before loop2: premade_count: %d, sub_timestamp_min:
%s, sub_timestamp_max: %s"
, premade_count, timestamptz_to_str(sub_timestamp_min),
timestamptz_to_str(sub_timestamp_max));
Can see the initial debug line, things are normal. Next line
current_partition_timestamp is returned along with the sub values which are
then equal to current_partition_timestamp. Removing
current_partition_timestamp from the same statement in the following line
things return as expected.
2016-09-09 17:38:15 EDT [] [9828]: [29-1] user=,db=,e=00000 DEBUG:
sub_timestamp_min: 1999-12-31 19:00:00-05, sub_timestamp_min_isnull: 1,
sub_timestamp_max: 0, sub_timestamp_max_isnull: 1
2016-09-09 17:38:15 EDT [] [9828]: [30-1] user=,db=,e=00000 DEBUG:
run_maint before loop: current_partition_timestamp: 2016-09-11 00:00:00-04,
premade_count: 0, sub_timestamp_min: 2016-09-11 00:00:00-04,
sub_timestamp_max: 2016-09-11 00:00:00-04
2016-09-09 17:38:15 EDT [] [9828]: [31-1] user=,db=,e=00000 DEBUG:
run_maint before loop2: premade_count: 0, sub_timestamp_min: 1999-12-31
19:00:00-05, sub_timestamp_max: 1999-12-31 19:00:00-05
I know I should always check for a null return from SPI before operating on
a value, and I do before I actually use those values. But I had them in my
debug lines where checking for whether they're null before outputting to
debug didn't seem to matter and it was really confusing me why the values
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behavior when
dealing with nulls or it's an actual problem, so figured I'd report it.
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
On 2016-09-09 23:54:48 +0000, keith@keithf4.com wrote:
The following bug has been logged on the website:
Bug reference: 14322
Logged by: Keith Fiske
Email address: keith@keithf4.com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:It seems when I call timestamp_to_str() on a non-null value then call it on
a null value in the same statement, it returns the previous non-null value.
I've included the code and debug lines from where I encountered this when
testing my app.
Uh. You can't just call timestamptz_to_str() on a NULL value. The datum
doesn't have to have any meaningful value if it's null.
I know I should always check for a null return from SPI before operating on
a value, and I do before I actually use those values. But I had them in my
debug lines where checking for whether they're null before outputting to
debug didn't seem to matter and it was really confusing me why the values
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behavior when
dealing with nulls or it's an actual problem, so figured I'd report it.
I don't think there's an issue here. The datum value isn't guaranteed
to be initialized if the value is null, and I think that's what you're
seeing here.
Greetings,
Andres Freund
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
On Fri, Sep 9, 2016 at 8:02 PM, Andres Freund <andres@anarazel.de> wrote:
On 2016-09-09 23:54:48 +0000, keith@keithf4.com wrote:
The following bug has been logged on the website:
Bug reference: 14322
Logged by: Keith Fiske
Email address: keith@keithf4.com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:It seems when I call timestamp_to_str() on a non-null value then call it
on
a null value in the same statement, it returns the previous non-null
value.
I've included the code and debug lines from where I encountered this when
testing my app.Uh. You can't just call timestamptz_to_str() on a NULL value. The datum
doesn't have to have any meaningful value if it's null.I know I should always check for a null return from SPI before operating
on
a value, and I do before I actually use those values. But I had them in
my
debug lines where checking for whether they're null before outputting to
debug didn't seem to matter and it was really confusing me why the values
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behavior when
dealing with nulls or it's an actual problem, so figured I'd report it.I don't think there's an issue here. The datum value isn't guaranteed
to be initialized if the value is null, and I think that's what you're
seeing here.Greetings,
Andres Freund
Understood. Just confused me for a while and wanted to make sure it wasn't
a real issue. Thanks!
Keith
On Fri, Sep 9, 2016 at 8:02 PM, Keith <keith@keithf4.com> wrote:
On Fri, Sep 9, 2016 at 8:02 PM, Andres Freund <andres@anarazel.de> wrote:
On 2016-09-09 23:54:48 +0000, keith@keithf4.com wrote:
The following bug has been logged on the website:
Bug reference: 14322
Logged by: Keith Fiske
Email address: keith@keithf4.com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:It seems when I call timestamp_to_str() on a non-null value then call
it on
a null value in the same statement, it returns the previous non-null
value.
I've included the code and debug lines from where I encountered this
when
testing my app.
Uh. You can't just call timestamptz_to_str() on a NULL value. The datum
doesn't have to have any meaningful value if it's null.I know I should always check for a null return from SPI before
operating on
a value, and I do before I actually use those values. But I had them in
my
debug lines where checking for whether they're null before outputting to
debug didn't seem to matter and it was really confusing me why thevalues
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behavior when
dealing with nulls or it's an actual problem, so figured I'd report it.I don't think there's an issue here. The datum value isn't guaranteed
to be initialized if the value is null, and I think that's what you're
seeing here.Greetings,
Andres Freund
Understood. Just confused me for a while and wanted to make sure it wasn't
a real issue. Thanks!Keith
Ok, this may be more of an actual issue than I thought. It seems that, even
if all variables to the timestamptz_to_str() function have a valid value
set, if it is called multiple times in the same statement, it keeps the
first value for all following occurrences. Belows is an example. I kept
getting zero for the difference between these two timestamps and it was
confusing the hell out of me until I did a debug output of the actual query
being run. You can see if I swap the two values around, it keeps the same
timestamp value of the first occurrence each time. I also output the
variable values to ensure they're valid.
My code:
resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(last_partition_timestamp),
timestamptz_to_str(current_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);
resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(current_partition_timestamp),
timestamptz_to_str(last_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);
Log output:
2016-09-13 16:01:02 EDT [] [16417]: [24-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-23
00:00:00-04', '2016-09-23 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000
2016-09-13 16:01:02 EDT [] [16417]: [25-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-15
00:00:00-04', '2016-09-15 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000
Keith
On Tue, Sep 13, 2016 at 4:16 PM, Keith Fiske <keith@omniti.com> wrote:
On Fri, Sep 9, 2016 at 8:02 PM, Keith <keith@keithf4.com> wrote:
On Fri, Sep 9, 2016 at 8:02 PM, Andres Freund <andres@anarazel.de> wrote:
On 2016-09-09 23:54:48 +0000, keith@keithf4.com wrote:
The following bug has been logged on the website:
Bug reference: 14322
Logged by: Keith Fiske
Email address: keith@keithf4.com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:It seems when I call timestamp_to_str() on a non-null value then call
it on
a null value in the same statement, it returns the previous non-null
value.
I've included the code and debug lines from where I encountered this
when
testing my app.
Uh. You can't just call timestamptz_to_str() on a NULL value. The datum
doesn't have to have any meaningful value if it's null.I know I should always check for a null return from SPI before
operating on
a value, and I do before I actually use those values. But I had them
in my
debug lines where checking for whether they're null before outputting
to
debug didn't seem to matter and it was really confusing me why the
values
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behaviorwhen
dealing with nulls or it's an actual problem, so figured I'd report it.
I don't think there's an issue here. The datum value isn't guaranteed
to be initialized if the value is null, and I think that's what you're
seeing here.Greetings,
Andres Freund
Understood. Just confused me for a while and wanted to make sure it
wasn't a real issue. Thanks!Keith
Ok, this may be more of an actual issue than I thought. It seems that,
even if all variables to the timestamptz_to_str() function have a valid
value set, if it is called multiple times in the same statement, it keeps
the first value for all following occurrences. Belows is an example. I kept
getting zero for the difference between these two timestamps and it was
confusing the hell out of me until I did a debug output of the actual query
being run. You can see if I swap the two values around, it keeps the same
timestamp value of the first occurrence each time. I also output the
variable values to ensure they're valid.My code:
resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(last_partition_timestamp),
timestamptz_to_str(current_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(current_partition_timestamp),
timestamptz_to_str(last_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);Log output:
2016-09-13 16:01:02 EDT [] [16417]: [24-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-23
00:00:00-04', '2016-09-23 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000
2016-09-13 16:01:02 EDT [] [16417]: [25-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-15
00:00:00-04', '2016-09-15 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000Keith
So think I found a fix for it for now using timestamp_out() instead (saw it
referenced in the timestamptz_to_str() source). Just makes the string
building more complicated
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, DatumGetCString(DirectFunctionCall1(timestamp_out,
TimestampTzGetDatum(last_partition_timestamp)))
, DatumGetCString(DirectFunctionCall1(timestamp_out,
TimestampTzGetDatum(current_partition_timestamp)))
, partition_interval);
Looking through the code it seems all calls to timestamp_to_str() only
reference it once per statement. I don't see any reason why you shouldn't
be able to call this function more than once at a time, though. Makes cases
where you need text output of timestamps a lot easier to build.
Keith Fiske <keith@omniti.com> writes:
Ok, this may be more of an actual issue than I thought. It seems that, even
if all variables to the timestamptz_to_str() function have a valid value
set, if it is called multiple times in the same statement, it keeps the
first value for all following occurrences.
What is current_partition_timestamp? Is it coming from the transaction
timestamp? That doesn't change intra-statement ...
regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
On Tue, Sep 13, 2016 at 4:52 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Keith Fiske <keith@omniti.com> writes:
Ok, this may be more of an actual issue than I thought. It seems that,
even
if all variables to the timestamptz_to_str() function have a valid value
set, if it is called multiple times in the same statement, it keeps the
first value for all following occurrences.What is current_partition_timestamp? Is it coming from the transaction
timestamp? That doesn't change intra-statement ...regards, tom lane
No, it's obtained elsewhere by querying the current max timestamp value
from the partition set.
Shouldn't matter if it was, though. You can see that all it takes to change
the string output of the timestamp is swapping the values around. The
values of the variables are the same in either case.
On 2016-09-13 22:58, Keith Fiske wrote:
No, it's obtained elsewhere by querying the current max timestamp value
from the partition set.
Shouldn't matter if it was, though. You can see that all it takes to change
the string output of the timestamp is swapping the values around. The
values of the variables are the same in either case.
Did you miss this part?
/* [ ... ] Note
* also that the result is in a static buffer, not pstrdup'd.
*/
.m
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
On Tue, Sep 13, 2016 at 5:03 PM, Marko Tiikkaja <marko@joh.to> wrote:
On 2016-09-13 22:58, Keith Fiske wrote:
No, it's obtained elsewhere by querying the current max timestamp value
from the partition set.
Shouldn't matter if it was, though. You can see that all it takes to
change
the string output of the timestamp is swapping the values around. The
values of the variables are the same in either case.Did you miss this part?
/* [ ... ] Note
* also that the result is in a static buffer, not pstrdup'd.
*/.m
Yeah I did see that when i went to look at its source and wondered if that
may be why, but I'm still fairly new to C and wasn't sure that was the
reason.
Still think it would be nice to use it in a more flexible manner.
Keith Fiske <keith@omniti.com> writes:
On Tue, Sep 13, 2016 at 5:03 PM, Marko Tiikkaja <marko@joh.to> wrote:
Did you miss this part?
/* [ ... ] Note
* also that the result is in a static buffer, not pstrdup'd.
Oh, duh.
Yeah I did see that when i went to look at its source and wondered if that
may be why, but I'm still fairly new to C and wasn't sure that was the
reason.
Still think it would be nice to use it in a more flexible manner.
You can pstrdup its result if you want. If it did that internally
it would result in some memory leaks we didn't want, IIRC.
regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs