pgsql: Avoid valgrind complaint about write() of uninitalized bytes.

On 2018-02-06 19:25:04 +0000, Robert Haas wrote:

Avoid valgrind complaint about write() of uninitalized bytes.

LogicalTapeFreeze() may write out its first block when it is dirty but
not full, and then immediately read the first block back in from its
BufFile as a BLCKSZ-width block. This can only occur in rare cases
where very few tuples were written out, which is currently only
possible with parallel external tuplesorts. To avoid valgrind
complaints, tell it to treat the tail of logtape.c's buffer as
defined.

Commit 9da0cc35284bdbe8d442d732963303ff0e0a40bc exposed this problem
but did not create it. LogicalTapeFreeze() has always tended to write
out some amount of garbage bytes, but previously never wrote less than
one block of data in total, so the problem was masked.

Per buildfarm members lousyjack and skink.

Peter Geoghegan, based on a suggestion from Tom Lane and me. Some
comment revisions by me.

Doesn't appear to have fixed the problem entirely:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2018-02-20%2017%3A10%3A01

relevant excerpt:
==12452== Syscall param write(buf) points to uninitialised byte(s)
==12452== at 0x4E49C64: write (write.c:26)
==12452== by 0x4BF8BF: FileWrite (fd.c:2017)
==12452== by 0x4C1B69: BufFileDumpBuffer (buffile.c:513)
==12452== by 0x4C1C61: BufFileFlush (buffile.c:657)
==12452== by 0x4C21D6: BufFileRead (buffile.c:561)
==12452== by 0x63ADA8: ltsReadBlock (logtape.c:274)
==12452== by 0x63AEF6: ltsReadFillBuffer (logtape.c:304)
==12452== by 0x63B560: LogicalTapeRewindForRead (logtape.c:771)
==12452== by 0x640567: mergeruns (tuplesort.c:2671)
==12452== by 0x645122: tuplesort_performsort (tuplesort.c:1866)
==12452== by 0x23357D: _bt_parallel_scan_and_sort (nbtsort.c:1626)
==12452== by 0x234F71: _bt_parallel_build_main (nbtsort.c:1527)
==12452== Address 0xc3cd368 is 744 bytes inside a block of size 8,272 client-defined
==12452== at 0x6362D1: palloc (mcxt.c:858)
==12452== by 0x4C1DA6: BufFileCreateShared (buffile.c:249)
==12452== by 0x63B062: LogicalTapeSetCreate (logtape.c:571)
==12452== by 0x64489A: inittapes (tuplesort.c:2419)
==12452== by 0x644B1C: puttuple_common (tuplesort.c:1695)
==12452== by 0x644E01: tuplesort_putindextuplevalues (tuplesort.c:1545)
==12452== by 0x233391: _bt_spool (nbtsort.c:514)
==12452== by 0x2333CA: _bt_build_callback (nbtsort.c:574)
==12452== by 0x286004: IndexBuildHeapRangeScan (index.c:2879)
==12452== by 0x286366: IndexBuildHeapScan (index.c:2419)
==12452== by 0x23356F: _bt_parallel_scan_and_sort (nbtsort.c:1615)
==12452== by 0x234F71: _bt_parallel_build_main (nbtsort.c:1527)
==12452== Uninitialised value was created by a heap allocation
==12452== at 0x6362D1: palloc (mcxt.c:858)
==12452== by 0x63B20E: LogicalTapeWrite (logtape.c:634)
==12452== by 0x63EA46: writetup_index (tuplesort.c:4206)
==12452== by 0x643769: dumptuples (tuplesort.c:2994)
==12452== by 0x64511A: tuplesort_performsort (tuplesort.c:1865)
==12452== by 0x23357D: _bt_parallel_scan_and_sort (nbtsort.c:1626)
==12452== by 0x234F71: _bt_parallel_build_main (nbtsort.c:1527)
==12452== by 0x252E2A: ParallelWorkerMain (parallel.c:1397)
==12452== by 0x4614DF: StartBackgroundWorker (bgworker.c:841)
==12452== by 0x46F400: do_start_bgworker (postmaster.c:5741)
==12452== by 0x46F541: maybe_start_bgworkers (postmaster.c:5954)
==12452== by 0x4700A6: sigusr1_handler (postmaster.c:5134)
==12452==
==12452== VALGRINDERROR-END

Note that the above path doesn't appear to go through
LogicalTapeFreeze(), therfore not hitting the VALGRIND_MAKE_MEM_DEFINED
added in the above commit.

Greetings,

Andres Freund

On Tue, Feb 20, 2018 at 9:34 PM, Andres Freund <andres@anarazel.de> wrote:

Doesn't appear to have fixed the problem entirely:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&amp;dt=2018-02-20%2017%3A10%3A01

relevant excerpt:
==12452== Syscall param write(buf) points to uninitialised byte(s)
==12452== at 0x4E49C64: write (write.c:26)
==12452== by 0x4BF8BF: FileWrite (fd.c:2017)
==12452== by 0x4C1B69: BufFileDumpBuffer (buffile.c:513)
==12452== by 0x4C1C61: BufFileFlush (buffile.c:657)
==12452== by 0x4C21D6: BufFileRead (buffile.c:561)
==12452== by 0x63ADA8: ltsReadBlock (logtape.c:274)
==12452== by 0x63AEF6: ltsReadFillBuffer (logtape.c:304)
==12452== by 0x63B560: LogicalTapeRewindForRead (logtape.c:771)
==12452== by 0x640567: mergeruns (tuplesort.c:2671)
==12452== by 0x645122: tuplesort_performsort (tuplesort.c:1866)
==12452== by 0x23357D: _bt_parallel_scan_and_sort (nbtsort.c:1626)
==12452== by 0x234F71: _bt_parallel_build_main (nbtsort.c:1527)

Note that the above path doesn't appear to go through
LogicalTapeFreeze(), therfore not hitting the VALGRIND_MAKE_MEM_DEFINED
added in the above commit.

Sure, but it looks like it has the exact same underlying cause to the
LogicalTapeFreeze() issue. It shouldn't be very hard to write an
equivalent patch for LogicalTapeRewindForRead() -- I pointed out that
this could happen there instead before the first patch went in, in
fact. My mistake was to imagine that that could never happen during
the regression tests.

I think I see why this happened, and why it happens inconsistently on
skink. Because memtuples is generally much smaller during merging than
it is during initial run generation, you can have enough tuples to
have to spill a run to disk, and yet not enough to fully fill even a
small buffer during the subsequent merge (logtape.c buffers also don't
have per-tuple palloc() header overhead, which is a huge proportion of
total memory used for an int4 primary key CREATE INDEX). This failure
is sensitive to the scheduling of worker processes, which is why we
only see it occasionally on skink.

The multiple-row-versions isolation test, which is where we see the
failure, seems to want to use multiple parallel workers for its ALTER
TABLE ... ADD PRIMARY KEY, in part because the table fillfactor is
rather low -- you end up with a case that gets a parallel sort, and
yet still has very few tuples to sort, a bit like the
LogicalTapeFreeze() issue already fixed.

Should we even be doing a parallel external sort here? It's hardly
part of an intentional effort to test the code. I had to push to get
us to give external sorts test coverage at one point about 18 months
ago, because of concerns about the overhead/duration of external
sorts. Not that I feel strongly about this myself.

--
Peter Geoghegan

On Wed, Feb 21, 2018 at 10:55 AM, Peter Geoghegan <pg@bowt.ie> wrote:

Sure, but it looks like it has the exact same underlying cause to the
LogicalTapeFreeze() issue. It shouldn't be very hard to write an
equivalent patch for LogicalTapeRewindForRead() -- I pointed out that
this could happen there instead before the first patch went in, in
fact. My mistake was to imagine that that could never happen during
the regression tests.

Attached patch does this. I cannot recreate this issue locally, but
this should still fix it on skink.

Should we even be doing a parallel external sort here? It's hardly
part of an intentional effort to test the code. I had to push to get
us to give external sorts test coverage at one point about 18 months
ago, because of concerns about the overhead/duration of external
sorts. Not that I feel strongly about this myself.

I suppose that we should commit this patch, even if we subsequently
suppress parallel CREATE INDEX in the multiple-row-versions isolation
test.

--
Peter Geoghegan

On Wed, Feb 21, 2018 at 3:18 PM, Peter Geoghegan <pg@bowt.ie> wrote:

On Wed, Feb 21, 2018 at 10:55 AM, Peter Geoghegan <pg@bowt.ie> wrote:

Sure, but it looks like it has the exact same underlying cause to the
LogicalTapeFreeze() issue. It shouldn't be very hard to write an
equivalent patch for LogicalTapeRewindForRead() -- I pointed out that
this could happen there instead before the first patch went in, in
fact. My mistake was to imagine that that could never happen during
the regression tests.

Attached patch does this. I cannot recreate this issue locally, but
this should still fix it on skink.

Committed.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Thu, Feb 22, 2018 at 6:32 AM, Robert Haas <robertmhaas@gmail.com> wrote:

Attached patch does this. I cannot recreate this issue locally, but
this should still fix it on skink.

Committed.

Looks like it worked.

--
Peter Geoghegan