Thread: BUG #15899: Valgrind detects errors on create gist index

The following bug has been logged on the website:

Bug reference:      15899
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 12beta2
Operating system:   Ubuntu 18.04
Description:

When executing under valgrind the following script:
create table gist_point_tbl(id int4, p point);
insert into gist_point_tbl (id, p)
select g+100000, point(g*10+1, g*10+1) from generate_series(1, 10000) g;
create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering
= on, fillfactor=50);

I get several valgrind errors:
2019-07-07 22:01:02.957 MSK|law|regression|5d22416b.5a20|LOG:  statement:
create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering
= on, fillfactor=50);
==00:00:00:12.567 23072== Conditional jump or move depends on uninitialised
value(s)
==00:00:00:12.567 23072==    at 0x1F977B: gistAddLoadedBuffer
(gistbuildbuffers.c:205)
==00:00:00:12.567 23072==    by 0x1F9E05: gistPushItupToNodeBuffer
(gistbuildbuffers.c:356)
==00:00:00:12.567 23072==    by 0x1F89F2: gistProcessItup
(gistbuild.c:645)
==00:00:00:12.567 23072==    by 0x1F8AE2: gistBufferingBuildInsert
(gistbuild.c:536)
==00:00:00:12.567 23072==    by 0x1F9257: gistBuildCallback
(gistbuild.c:481)
==00:00:00:12.567 23072==    by 0x21F0C9: heapam_index_build_range_scan
(heapam_handler.c:1664)
==00:00:00:12.567 23072==    by 0x1F9476: table_index_build_scan
(tableam.h:1509)
==00:00:00:12.567 23072==    by 0x1F9476: gistbuild (gistbuild.c:196)
==00:00:00:12.567 23072==    by 0x29C4F7: index_build (index.c:2726)
==00:00:00:12.567 23072==    by 0x29DC4B: index_create (index.c:1177)
==00:00:00:12.567 23072==    by 0x3486DF: DefineIndex (indexcmds.c:1004)
==00:00:00:12.567 23072==    by 0x529EA2: ProcessUtilitySlow
(utility.c:1366)
==00:00:00:12.567 23072==    by 0x529456: standard_ProcessUtility
(utility.c:927)
==00:00:00:12.567 23072==  Uninitialised value was created by a heap
allocation
==00:00:00:12.567 23072==    at 0x67D391: MemoryContextAlloc (mcxt.c:801)
==00:00:00:12.567 23072==    by 0x6594CE: DynaHashAlloc (dynahash.c:281)
==00:00:00:12.567 23072==    by 0x65966F: element_alloc (dynahash.c:1673)
==00:00:00:12.567 23072==    by 0x659792: get_hash_entry (dynahash.c:1282)
==00:00:00:12.567 23072==    by 0x659FF0: hash_search_with_hash_value
(dynahash.c:1055)
==00:00:00:12.567 23072==    by 0x65A1A4: hash_search (dynahash.c:911)
==00:00:00:12.567 23072==    by 0x1F9C6C: gistGetNodeBuffer
(gistbuildbuffers.c:125)
==00:00:00:12.567 23072==    by 0x1F89DF: gistProcessItup
(gistbuild.c:642)
==00:00:00:12.567 23072==    by 0x1F8AE2: gistBufferingBuildInsert
(gistbuild.c:536)
==00:00:00:12.567 23072==    by 0x1F9257: gistBuildCallback
(gistbuild.c:481)
==00:00:00:12.567 23072==    by 0x21F0C9: heapam_index_build_range_scan
(heapam_handler.c:1664)
==00:00:00:12.567 23072==    by 0x1F9476: table_index_build_scan
(tableam.h:1509)
==00:00:00:12.567 23072==    by 0x1F9476: gistbuild (gistbuild.c:196)

...
==00:00:00:12.662 23072== Syscall param pwrite64(buf) points to
uninitialised byte(s)
==00:00:00:12.662 23072==    at 0x5055014: pwrite (pwrite64.c:29)
==00:00:00:12.662 23072==    by 0x4F1CC0: FileWrite (fd.c:1963)
==00:00:00:12.662 23072==    by 0x4F3C83: BufFileDumpBuffer
(buffile.c:487)
==00:00:00:12.662 23072==    by 0x4F4275: BufFileWrite (buffile.c:589)
==00:00:00:12.662 23072==    by 0x1F9841: WriteTempFileBlock
(gistbuildbuffers.c:770)
==00:00:00:12.662 23072==    by 0x1F9E2E: gistPushItupToNodeBuffer
(gistbuildbuffers.c:375)
==00:00:00:12.662 23072==    by 0x1F89F2: gistProcessItup
(gistbuild.c:645)
==00:00:00:12.662 23072==    by 0x1F8AE2: gistBufferingBuildInsert
(gistbuild.c:536)
==00:00:00:12.662 23072==    by 0x1F9257: gistBuildCallback
(gistbuild.c:481)
==00:00:00:12.662 23072==    by 0x21F0C9: heapam_index_build_range_scan
(heapam_handler.c:1664)
==00:00:00:12.662 23072==    by 0x1F9476: table_index_build_scan
(tableam.h:1509)
==00:00:00:12.662 23072==    by 0x1F9476: gistbuild (gistbuild.c:196)
==00:00:00:12.662 23072==    by 0x29C4F7: index_build (index.c:2726)
==00:00:00:12.662 23072==  Address 0xf8fa420 is 80 bytes inside a block of
size 8,264 client-defined
==00:00:00:12.662 23072==    at 0x67DBD9: palloc (mcxt.c:949)
==00:00:00:12.662 23072==    by 0x4F3A63: makeBufFileCommon
(buffile.c:111)
==00:00:00:12.662 23072==    by 0x4F3AA9: makeBufFile (buffile.c:132)
==00:00:00:12.662 23072==    by 0x4F3DF0: BufFileCreateTemp
(buffile.c:203)
==00:00:00:12.662 23072==    by 0x1F9B4C: gistInitBuildBuffers
(gistbuildbuffers.c:61)
==00:00:00:12.662 23072==    by 0x1F9117: gistInitBuffering
(gistbuild.c:409)
==00:00:00:12.662 23072==    by 0x1F92A6: gistBuildCallback
(gistbuild.c:525)
==00:00:00:12.662 23072==    by 0x21F0C9: heapam_index_build_range_scan
(heapam_handler.c:1664)
==00:00:00:12.662 23072==    by 0x1F9476: table_index_build_scan
(tableam.h:1509)
==00:00:00:12.662 23072==    by 0x1F9476: gistbuild (gistbuild.c:196)
==00:00:00:12.662 23072==    by 0x29C4F7: index_build (index.c:2726)
==00:00:00:12.662 23072==    by 0x29DC4B: index_create (index.c:1177)
==00:00:00:12.662 23072==    by 0x3486DF: DefineIndex (indexcmds.c:1004)
==00:00:00:12.662 23072==  Uninitialised value was created by a heap
allocation
==00:00:00:12.662 23072==    at 0x67D391: MemoryContextAlloc (mcxt.c:801)
==00:00:00:12.662 23072==    by 0x1F992D: gistAllocateNewPageBuffer
(gistbuildbuffers.c:189)
==00:00:00:12.663 23072==    by 0x1F9DEF: gistPushItupToNodeBuffer
(gistbuildbuffers.c:354)
==00:00:00:12.663 23072==    by 0x1F89F2: gistProcessItup
(gistbuild.c:645)
==00:00:00:12.663 23072==    by 0x1F8AE2: gistBufferingBuildInsert
(gistbuild.c:536)
==00:00:00:12.663 23072==    by 0x1F9257: gistBuildCallback
(gistbuild.c:481)
==00:00:00:12.663 23072==    by 0x21F0C9: heapam_index_build_range_scan
(heapam_handler.c:1664)
==00:00:00:12.663 23072==    by 0x1F9476: table_index_build_scan
(tableam.h:1509)
==00:00:00:12.663 23072==    by 0x1F9476: gistbuild (gistbuild.c:196)
==00:00:00:12.663 23072==    by 0x29C4F7: index_build (index.c:2726)
==00:00:00:12.663 23072==    by 0x29DC4B: index_create (index.c:1177)
==00:00:00:12.663 23072==    by 0x3486DF: DefineIndex (indexcmds.c:1004)
==00:00:00:12.663 23072==    by 0x529EA2: ProcessUtilitySlow
(utility.c:1366)
...

> When executing under valgrind the following script:
> create table gist_point_tbl(id int4, p point);
> insert into gist_point_tbl (id, p)
> select g+100000, point(g*10+1, g*10+1) from generate_series(1, 10000) g;
> create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering
> = on, fillfactor=50);
>
> I get several valgrind errors:
> 2019-07-07 22:01:02.957 MSK|law|regression|5d22416b.5a20|LOG:  statement:
> create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering
> = on, fillfactor=50);
> ==00:00:00:12.567 23072== Conditional jump or move depends on uninitialised
> value(s)
> ==00:00:00:12.567 23072==    at 0x1F977B: gistAddLoadedBuffer
> (gistbuildbuffers.c:205)
> ==00:00:00:12.567 23072==    by 0x1F9E05: gistPushItupToNodeBuffer
> (gistbuildbuffers.c:356)
> ==00:00:00:12.567 23072==    by 0x1F89F2: gistProcessItup
> (gistbuild.c:645)
> ==00:00:00:12.567 23072==    by 0x1F8AE2: gistBufferingBuildInsert
> (gistbuild.c:536)
>
> ...
> ==00:00:00:12.662 23072== Syscall param pwrite64(buf) points to
> uninitialised byte(s)
> ==00:00:00:12.662 23072==    at 0x5055014: pwrite (pwrite64.c:29)
> ==00:00:00:12.662 23072==    by 0x4F1CC0: FileWrite (fd.c:1963)
> ==00:00:00:12.662 23072==    by 0x4F3C83: BufFileDumpBuffer
> (buffile.c:487)
> ==00:00:00:12.662 23072==    by 0x4F4275: BufFileWrite (buffile.c:589)
> ==00:00:00:12.662 23072==    by 0x1F9841: WriteTempFileBlock
> (gistbuildbuffers.c:770)
> ==00:00:00:12.662 23072==    by 0x1F9E2E: gistPushItupToNodeBuffer
> (gistbuildbuffers.c:375)
> ==00:00:00:12.662 23072==    by 0x1F89F2: gistProcessItup
> (gistbuild.c:645)
The attached patch eliminates these errors (but maybe
MemoryContextAllocZero is too superficial).

Best regards,
Alexander

On Sun, Jul 07, 2019 at 10:21:26PM +0300, Alexander Lakhin wrote:
>> When executing under valgrind the following script:
>> create table gist_point_tbl(id int4, p point);
>> insert into gist_point_tbl (id, p)
>> select g+100000, point(g*10+1, g*10+1) from generate_series(1, 10000) g;
>> create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering
>> = on, fillfactor=50);
>
> The attached patch eliminates these errors (but maybe
> MemoryContextAllocZero is too superficial).

Thanks for the patch and the report.

I can see that most of the complaints from valgrind go away, and I am
still bumping into these two ones.
==14943== Conditional jump or move depends on uninitialised value(s)
==14943==    at 0x1FD7A5: gistchoose (gistutil.c:535)
==14943==    by 0x20B5BA: gistProcessItup (gistbuild.c:597)
==14943==    by 0x20C367: gistProcessEmptyingQueue (gistbuild.c:973)
==14943==    by 0x20C476: gistEmptyAllBuffers (gistbuild.c:1036)
==14943==    by 0x20ACD9: gistbuild (gistbuild.c:207)
==14943==    by 0x2DCDF9: index_build (index.c:2726)
==14943==    by 0x2DA4CA: index_create (index.c:1177)
==14943==    by 0x3C52BB: DefineIndex (indexcmds.c:1005)
==14943==    by 0x653A27: ProcessUtilitySlow (utility.c:1373)
==14943==    by 0x652AE0: standard_ProcessUtility (utility.c:927)
==14943==    by 0x651B78: ProcessUtility (utility.c:360)
==14943==    by 0x650AD7: PortalRunUtility (pquery.c:1175)
==14943==  Uninitialised value was created by a stack allocation
==14943==    at 0x4C6F3B0: ??? (in
/usr/lib/x86_64-linux-gnu/libcrypto.so.1.1)
==14943==
==14943== Conditional jump or move depends on uninitialised value(s)
==14943==    at 0x1FD770: gistchoose (gistutil.c:513)
==14943==    by 0x20B5BA: gistProcessItup (gistbuild.c:597)
==14943==    by 0x20C367: gistProcessEmptyingQueue (gistbuild.c:973)
==14943==    by 0x20C476: gistEmptyAllBuffers (gistbuild.c:1036)
==14943==    by 0x20ACD9: gistbuild (gistbuild.c:207)
==14943==    by 0x2DCDF9: index_build (index.c:2726)
==14943==    by 0x2DA4CA: index_create (index.c:1177)
==14943==    by 0x3C52BB: DefineIndex (indexcmds.c:1005)
==14943==    by 0x653A27: ProcessUtilitySlow (utility.c:1373)
==14943==    by 0x652AE0: standard_ProcessUtility (utility.c:927)
==14943==    by 0x651B78: ProcessUtility (utility.c:360)
==14943==    by 0x650AD7: PortalRunUtility (pquery.c:1175)
==14943==  Uninitialised value was created by a stack allocation
==14943==    at 0x4C6F3B0: ??? (in /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1)

Still they don't make much sense, because these point to complaints
that keep_current_best may have an uninitialized value, and this
variable is initialized before scanning the tuples on the page.  I
would not have expected that an uninitialized thing from libcrypto
stack would have an effect here, and we have the project policy to
not silence stuff fro outside the tree as far as I know.

Regarding the patch, I have been reviewing it and the two changes are
fine by me.  I would have just reordered the fields in
gistGetNodeBuffer to match the structure, but that's mainly nanny-ism
from my side.

Regarding the zero-allocation, we have gistLoadNodeBuffer() loading
directly the block's contents from a temporary file after allocating a
page, but gistPushItupToNodeBuffer() justifies that as a cheap
insurance.  So that's good for me.  Do others have objections or extra
thoughts?  This comes from 1d27dcf, so this should go all the way down.
--
Michael

Hi,

On 2019-07-09 13:43:41 +0900, Michael Paquier wrote:
> On Sun, Jul 07, 2019 at 10:21:26PM +0300, Alexander Lakhin wrote:
> I can see that most of the complaints from valgrind go away, and I am
> still bumping into these two ones.
> ==14943== Conditional jump or move depends on uninitialised value(s)
> ==14943==    at 0x1FD7A5: gistchoose (gistutil.c:535)
> ==14943==    by 0x20B5BA: gistProcessItup (gistbuild.c:597)
> ==14943==    by 0x20C367: gistProcessEmptyingQueue (gistbuild.c:973)
> ==14943==    by 0x20C476: gistEmptyAllBuffers (gistbuild.c:1036)
> ==14943==    by 0x20ACD9: gistbuild (gistbuild.c:207)
> ==14943==    by 0x2DCDF9: index_build (index.c:2726)
> ==14943==    by 0x2DA4CA: index_create (index.c:1177)
> ==14943==    by 0x3C52BB: DefineIndex (indexcmds.c:1005)
> ==14943==    by 0x653A27: ProcessUtilitySlow (utility.c:1373)
> ==14943==    by 0x652AE0: standard_ProcessUtility (utility.c:927)
> ==14943==    by 0x651B78: ProcessUtility (utility.c:360)
> ==14943==    by 0x650AD7: PortalRunUtility (pquery.c:1175)
> ==14943==  Uninitialised value was created by a stack allocation
> ==14943==    at 0x4C6F3B0: ??? (in
> /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1)
> ==14943==
> ==14943== Conditional jump or move depends on uninitialised value(s)
> ==14943==    at 0x1FD770: gistchoose (gistutil.c:513)
> ==14943==    by 0x20B5BA: gistProcessItup (gistbuild.c:597)
> ==14943==    by 0x20C367: gistProcessEmptyingQueue (gistbuild.c:973)
> ==14943==    by 0x20C476: gistEmptyAllBuffers (gistbuild.c:1036)
> ==14943==    by 0x20ACD9: gistbuild (gistbuild.c:207)
> ==14943==    by 0x2DCDF9: index_build (index.c:2726)
> ==14943==    by 0x2DA4CA: index_create (index.c:1177)
> ==14943==    by 0x3C52BB: DefineIndex (indexcmds.c:1005)
> ==14943==    by 0x653A27: ProcessUtilitySlow (utility.c:1373)
> ==14943==    by 0x652AE0: standard_ProcessUtility (utility.c:927)
> ==14943==    by 0x651B78: ProcessUtility (utility.c:360)
> ==14943==    by 0x650AD7: PortalRunUtility (pquery.c:1175)
> ==14943==  Uninitialised value was created by a stack allocation
> ==14943==    at 0x4C6F3B0: ??? (in /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1)
> 
> Still they don't make much sense, because these point to complaints
> that keep_current_best may have an uninitialized value, and this
> variable is initialized before scanning the tuples on the page.  I
> would not have expected that an uninitialized thing from libcrypto
> stack would have an effect here, and we have the project policy to
> not silence stuff fro outside the tree as far as I know.

I think this is just that openssl bug we've been talking about a while
ago. keep_current_best is initialized via random(), which is in turn
initialized with openssl's randomness (cf InitProcessGlobals()). As
valgrind - legitimately - thinks that the openssl' random value is
tainted by uninitialized data, it thinks that keep_current_best is
uninitialized. And the branches above are the first values where a jump
is made based on that uninitialized data.

Greetings,

Andres Freund

On Tue, Jul 09, 2019 at 01:43:41PM +0900, Michael Paquier wrote:
> Regarding the zero-allocation, we have gistLoadNodeBuffer() loading
> directly the block's contents from a temporary file after allocating a
> page, but gistPushItupToNodeBuffer() justifies that as a cheap
> insurance.  So that's good for me.  Do others have objections or extra
> thoughts?  This comes from 1d27dcf, so this should go all the way down.

Tested and committed down to 9.4.
--
Michael

On Tue, Jul 09, 2019 at 01:59:25PM -0700, Andres Freund wrote:
> I think this is just that openssl bug we've been talking about a while
> ago. keep_current_best is initialized via random(), which is in turn
> initialized with openssl's randomness (cf InitProcessGlobals()). As
> valgrind - legitimately - thinks that the openssl' random value is
> tainted by uninitialized data, it thinks that keep_current_best is
> uninitialized. And the branches above are the first values where a jump
> is made based on that uninitialized data.

Yes, thanks for reminding of that issue:
https://www.postgresql.org/message-id/20190611205131.e5trufqahzpiwut6@alap3.anarazel.de
I completely forgot about it, and I am now on 1.1.1c on my dev
machine, so this explains that.
--
Michael