Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1obPZd-0002dl-8w for pgsql-bugs@arkaria.postgresql.org; Thu, 22 Sep 2022 17:01:17 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1obPZZ-00083J-1s for pgsql-bugs@arkaria.postgresql.org; Thu, 22 Sep 2022 17:01:13 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1obPDP-0007cW-RP for pgsql-bugs@lists.postgresql.org; Thu, 22 Sep 2022 16:38:19 +0000 Received: from mail-lj1-x232.google.com ([2a00:1450:4864:20::232]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1obPDL-0003EP-DT for pgsql-bugs@lists.postgresql.org; Thu, 22 Sep 2022 16:38:19 +0000 Received: by mail-lj1-x232.google.com with SMTP id c7so11639999ljm.12 for ; Thu, 22 Sep 2022 09:38:15 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date; bh=YSQGq2ibWFLVut31yLaYL4Szsad2aRrbXc+t3gNyzlk=; b=YdPOQGGrMPipb+T0wndpjWZccSvO5lEGbX3xgbz74t6eJBB5M3dIzpg+5xxL3U++S2 A+cdksBabo8U1qWcTzg9HsQoFxIFkGu4G7jo9ukvL5dDS94r0s1aUfi0PZIrrMg55Nwh 4uNHDsHpz4U2g+oSJ+d8xEcu2YKq48jJ70hlhrQkUghGcUzOTWtZOC5NSPFFPY/XKe/f Rf7aOwpmnyLzG1EYjieFxS1wP/UvAXkqSLpEYPIOwb8oLhCNixnQX/Lqe6AS1CsdiULT XAKZRUZjNusHx3DDrLSPZ+NSm5F7y2aTK4a0KWRy8bNQtpidHUq2SCGMRh3FIPbhLaZ3 NrjA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date; bh=YSQGq2ibWFLVut31yLaYL4Szsad2aRrbXc+t3gNyzlk=; b=TGK2MauzLMNcQajoIBPUyx44NmHPIboDRZyVFxW6yonCCguaJa0bHcnl1ihD0E9JFX vVi7cW3khm52U0rjA1pQ6/jlU+kGwUqFrHqWdmkqtDtXfAtIJsKeA16r7UkioFHAh85c YgRSg66wjwqBI8gtsV6Z+hy6M8GQ3VpV1PQ48kSuJdTYdXBp648xJdl2jgqKHh4tOZBq MWHC88MpJm4DIAOy9spxf7QNqHxox0cIIUi72MAKyXCDfCUzv06lv5BCAGE2T2Gs+4uh cIU6wei4CynlTFI3Q8mUJrMIPPo32vhDW+E8/V2KsNQUwZw0Exf4+9n4uY68/mCeas4l Veuw== X-Gm-Message-State: ACrzQf1K1HcuWfCu1FFGZX1696n9kYUb6PujreNCnGPZwcpmoDwrbbMX OfEd7x41Dsz4AP/4w+UgBNmd2YwOzLTQ5mmUEx3CpywC X-Google-Smtp-Source: AMsMyM4CzS4aH1v3Rp8czzuBVC7zT5dzTDZ1xUnt9AEAJT7p8AUcKGTVTfpy2FpsQuB28Qpa46snrP/ObBKETlB9VO0= X-Received: by 2002:a05:651c:504:b0:26c:6760:b9d6 with SMTP id o4-20020a05651c050400b0026c6760b9d6mr1459969ljp.278.1663864693937; Thu, 22 Sep 2022 09:38:13 -0700 (PDT) MIME-Version: 1.0 References: <17619-0de62ceda812b8b5@postgresql.org> In-Reply-To: From: Dmitry Astapov Date: Thu, 22 Sep 2022 17:38:00 +0100 Message-ID: Subject: Re: BUG #17619: AllocSizeIsValid violation in parallel hash join To: Thomas Munro Cc: pgsql-bugs@lists.postgresql.org Content-Type: multipart/alternative; boundary="000000000000095c7e05e946b023" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000095c7e05e946b023 Content-Type: text/plain; charset="UTF-8" And I think that if on line 322 should be ">" and not ">=" as well. On Thu, 22 Sep 2022, 17:11 Dmitry Astapov, wrote: > Thomas, I think I know what is going on, and it is happening in > sts_puttuple when it needs to write 32760 bytes exacly. All references > below a taken in the tag REL_13_8. > > Lets say that we enter sts_puttuple and on line 321 we compute a size > > of 32760 bytes. Lets say that buffer is currently partially filled so a > write of this size would not fit. > > We proceed to flush chunk on line 338, which resets the write pointer to 8 > bytes past the start of SharedTuplestoreChunk, leaving exactly 32760 bytes > free. > > We take the if on line 342 > (the > one with the comment "It still might not be enough space", and then proceed > to write whole 32760 bytes and reach the line 373 with size == 0. > > It looks like this codepath is written with assumption that size >0 here > and sts_flush_chunk would be called immediately after inside the loop on > line 375. But because size == 0, loop will not execute, sts_flush_chunk > will not be called, and since we haven't updated write pointer so far, it > will stay at the beginning of the chunk. At this point we exit > sts_puttuple, and next call of sts_putttuple would overwrite the tuple we > just memcopied into the chank. If this new tuple is shorter, then remaining > part of the chunk would be garbage from the overwritten tuple. > > I think >= on line 342 should be just > . I tried this change locally, and > it fixed the issue for me. > > Do you agree with my analysis? > > On Thu, Sep 22, 2022 at 1:51 PM Dmitry Astapov wrote: > >> >> >> On Thu, Sep 22, 2022 at 9:44 AM Thomas Munro >> wrote: >> >>> On Thu, Sep 22, 2022 at 7:46 PM PG Bug reporting form >>> wrote: >>> > (gdb) p size >>> > $2 = 1702125924 >>> >>> Thanks for the detailed report. Hmm. That size, on a little-endian >>> system, is equivalent to the byte sequence "date\0\0\0\0", which looks >>> pretty suspiciously like the inside of a tuple, and not its size. We >>> must have got out of sync somehow. >>> >> >> Great catch! I added some debugging output to the BufFileRead and >> sts_read_tuple and it looks to me that the sequence of events immediately >> before the problem happens is like this: >> >> >> 1. sts_read_tuple is called multiple times to read from a particular >> file, and a bunch of tuples are read this way >> 2. sts_read_tuple is called once more. In my experiments, I always >> had read_ntuples_available - 2 == read_ntuples at this point, but maybe >> this is just a coincidence. >> 1. inside this sts_read_tuple_call, BufFileRead is called to read >> metadata, and succeeds (and this chunk of the file looks -- to my naive eye >> -- exactly like any other tuple start) >> 2. Second BufFileRead call happens to get the size, and reads the >> correct size (I see what's in the file, I could find corresponding values >> in the database tables, and it all lines up). >> 3. Third BufFileRead happens to read the actual tuple. So far so >> good, and sts_read_tuple finishes. >> 3. At this point, the position in the file (buf_file -> currOffset + >> post) points right after the last tuple read, but what's there does not >> look like the start of the next tuple to me. It seems like there was >> another, longer tuple written there before (with quite long rhs.payload >> value) and somehow the tuple that was just read was written over it, so we >> have "> like leftovers from another tuple>" >> 4. So another sts_read_tuple call happens, and it reads 4 bytes of >> this garbage as metadata, and the next 4 bytes as length, and this is when >> everything derails... >> >> I also double-checked at the logs of the (test) database where this issue >> was first spotted (and where a lot of queries similar to the one I am using >> to trigger this issue are happening) and found out that along with "invalid >> memory alloc request size" we also got a couple of occasions of "Unexpected >> chunk in shared tuplestore temporary file. Expected overflow chunk", which >> looks like another error that could be potentially explained by >> BufFileRead's inside sts_read_tuple reading "garbage". >> >> I'm happy to build a patched version of 13.8 (or another revision if you >> want me to) to collect more debug information for you if this could help. >> >> -- >> D. Astapov >> > > > -- > D. Astapov > --000000000000095c7e05e946b023 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
And I think that if on line 322 should be ">"= ; and not ">=3D" as well.=C2=A0

On Thu, 22 Sep 2022, 17:11 Dmit= ry Astapov, <dastapov@gmail.com> wrote:
Thoma= s, I think I know what is going on, and it is happening in sts_puttuple whe= n it needs to write 32760 bytes exacly. All references below a taken in the= tag REL_13_8.

Lets say that we enter sts_puttuple and o= n line 321 we compute a size of 32760 byte= s. Lets say that buffer is currently partially filled so a write of this si= ze would not fit.

We proceed to flush chunk on lin= e 338, which resets the write pointer to 8 bytes past the start of SharedTu= plestoreChunk, leaving exactly 32760 bytes free.

W= e take the if on line 342=C2=A0(the one wi= th the comment "It still might not be enough space", and then pro= ceed to write whole 32760 bytes and reach the line 373 with size =3D=3D 0.= =C2=A0

It looks like this codepath is written with= assumption that size >0 here and sts_flush_chunk would be called immedi= ately after inside the loop on line 375. But because size =3D=3D 0, loop wi= ll not execute, sts_flush_chunk will not be called, and since we haven'= t updated write pointer so far, it will stay at the beginning of the chunk.= At this point we exit sts_puttuple, and next call of sts_putttuple would o= verwrite the tuple we just memcopied into the chank. If this new tuple is s= horter, then remaining part of the chunk would be garbage from the overwrit= ten tuple.

I think >=3D on line=C2=A0342 should= be just > . I tried this change locally, and it fixed the issue for me.=

Do you agree with my analysis?

On Thu, Sep 2= 2, 2022 at 1:51 PM Dmitry Astapov <dastapov@gmail.com> wrote:
=


On Thu, Sep 22, 2022 at 9:44 AM Thomas Munro <tho= mas.munro@gmail.com> wrote:
On Thu, Sep 22, 2022 at 7:46 PM PG Bug reporting form <noreply@postgresql.org> wrote:
> (gdb) p size
> $2 =3D 1702125924

Thanks for the detailed report.=C2=A0 Hmm.=C2=A0 That size, on a little-end= ian
system, is equivalent to the byte sequence "date\0\0\0\0", which = looks
pretty suspiciously like the inside of a tuple, and not its size.=C2=A0 We<= br> must have got out of sync somehow.

Grea= t catch! I added some debugging output to the BufFileRead and sts_read_tupl= e and it looks to me that the sequence of events immediately before the pro= blem happens is like this:

  1. sts_read_tuple = is called multiple times to read from a particular file, and a bunch of tup= les are read this way
  2. sts_read_tuple is called once more. In my exp= eriments, I always had read_ntuples_available - 2 =3D=3D read_ntuples at th= is point, but maybe this is just a coincidence.
    1. =C2=A0inside th= is sts_read_tuple_call, BufFileRead is called to read metadata, and succeed= s (and this chunk of the file looks -- to my naive eye -- exactly like any = other tuple start)
    2. Second BufFileRead call happens to get the size,= and reads the correct size (I see what's in the file, I could find cor= responding values in the database tables, and it all lines up).=C2=A0
      3. <= li>Third BufFileRead happens to read the actual tuple. So far so good, and = sts_read_tuple finishes.
  3. At this point, the=C2=A0position in t= he file (buf_file -> currOffset=C2=A0+ post) points right after the last= tuple read, but what's there does not look like the start of the next = tuple to me. It seems like there was another, longer tuple written there be= fore (with quite long rhs.payload value) and somehow the tuple that was jus= t read was written over it, so we have "<tuple read on step 2 above= ><current read position here><what looks like leftovers from an= other tuple><a bunch of zeroes><new tuple start>"
    4. <= li>So another sts_read_tuple call happens, and it reads 4 bytes of this gar= bage as metadata, and the next 4 bytes as length, and this is when everythi= ng derails...
I also double-checked at the logs of the (test)= database where this issue was first spotted (and where a lot of queries si= milar to the one I am using to trigger this issue are happening) and found = out that along with "invalid memory alloc request size" we also g= ot a couple of occasions of "Unexpected chunk in shared tuplestore tem= porary file. Expected overflow chunk", which looks like another error = that could be potentially explained by BufFileRead's inside sts_read_tu= ple reading "garbage".

I'm hap= py to build a patched version of 13.8 (or another revision if you want me t= o) to collect more debug information for you if this could help.
=
--
D. Astapov


--
D. Astapov
--000000000000095c7e05e946b023--