Date: Thu, 4 Jan 2018 12:06:47 -0800
From: Andres Freund <andres@anarazel.de>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Robert Haas <robertmhaas@gmail.com>,
	Thomas Munro <thomas.munro@enterprisedb.com>,
	"pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Subject: Re: pgsql: Add parallel-aware hash joins.
Message-ID: <20180104200647.wna6yoin7nav5qqo@alap3.anarazel.de>
References: 
 <CAEepm=2WFQrwDD4rEVKjdPBQ_di_0n=xYST1MDRsucZ=JgDPxg@mail.gmail.com>
 <18190.1514943510@sss.pgh.pa.us>
 <CAEepm=34PDuR69kfYVhmZPgMdy8pSA-MYbpesEN1SR+2oj3Y+w@mail.gmail.com>
 <5187.1515028624@sss.pgh.p!a.us>
 <CAEepm=1uuT8iJxMEsR=jL+3zEi87DB2v0+0H9o_rUXXCZPZT3A@mail.gmail.com>
 <16320.1515046173@sss.pgh.pa.us>
 <4847.1515081624@sss.pgh.pa.us>
 <CA+TgmoY7JAxRW_UQZAyxH3=JXV3WTFdwfTdyGB3TySj7c1i2yg@mail.gmail.com>
 <7839.1515085897@sss.pgh.pa.us>
 <20180104192033.irv4ppf44i2fesze@alap3.anarazel.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20180104192033.irv4ppf44i2fesze@alap3.anarazel.de>
Precedence: bulk

On 2018-01-04 11:20:33 -0800, Andres Freund wrote:
> On 2018-01-04 12:11:37 -0500, Tom Lane wrote:
> > Robert Haas <robertmhaas@gmail.com> writes:
> > > On Thu, Jan 4, 2018 at 11:00 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > >> Also, what the devil is happening on skink?
> > 
> > > So, skink is apparently dying during shutdown of a user-connected
> > > backend, and specifically the one that executed the 'tablespace' test.
> > 
> > Well, yeah, valgrind is burping: the postmaster log is full of
> > 
> > ==10544== VALGRINDERROR-BEGIN
> > ==10544== Syscall param epoll_pwait(sigmask) points to unaddressable byte(s)
> > ==10544==    at 0x7011490: epoll_pwait (epoll_pwait.c:42)
> > ==10544==    by 0x4BF40B: WaitEventSetWaitBlock (latch.c:1048)
> > ==10544==    by 0x4BF40B: WaitEventSetWait (latch.c:1000)
> > ==10544==    by 0x3C0B3B: secure_read (be-secure.c:166)
> > ==10544==    by 0x3CCD9E: pq_recvbuf (pqcomm.c:963)
> > ==10544==    by 0x3CDA07: pq_getbyte (pqcomm.c:1006)
> > ==10544==    by 0x4E2A2D: SocketBackend (postgres.c:339)
> > ==10544==    by 0x4E444E: ReadCommand (postgres.c:512)
> > ==10544==    by 0x4E7588: PostgresMain (postgres.c:4085)
> > ==10544==    by 0x4641D0: BackendRun (postmaster.c:4412)
> > ==10544==    by 0x467308: BackendStartup (postmaster.c:4084)
> > ==10544==    by 0x4675F7: ServerLoop (postmaster.c:1757)
> > ==10544==    by 0x4689D4: PostmasterMain (postmaster.c:1365)
> > ==10544==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
> > ==10544== 
> > ==10544== VALGRINDERROR-END
> > 
> > But (a) this is happening in multiple branches, and (b) we've not
> > changed anything near that code in awhile.  I think something broke
> > in valgrind itself.
> 
> Some packages on skink have been upgraded. It appears that there either
> was a libc or valgrind change that made valgrind not recognize that a
> pointer of 0 might not point anywhere :(

It looks like recent glibc implements epoll_wait() as epoll_pwait() with
a NULL sigmask argument, and valgrind isn't happy with it.


> Let me check whether valgrind accept multiple suppression files, in
> which case I could add a suppression for this error to all
> branches.

Done that. I've added a valgrind-global.supp that has:

{
   null-sigmask-to-pwait-means-no-sigmask
   Memcheck:Param
   epoll_pwait(sigmask)
   fun:epoll_pwait
   fun:WaitEventSetWaitBlock
}


> Will also check whether I can reproduce locally.

Locally the above suppression allowed me to continue a bit further. But
I promptly hit other new blurbs:

assert build:
2018-01-04 12:03:45.927 PST [5716][3/189] STATEMENT:  select format('%1$s %4$s', 1, 2, 3);
==5718== Invalid write of size 8
==5718==    at 0x40E3DD: ExecInterpExpr (execExprInterp.c:1117)
==5718==    by 0x40F5E9: ExecInterpExprStillValid (execExprInterp.c:1788)
==5718==    by 0xE6B0409: ExecEvalExpr (executor.h:282)
==5718==    by 0xE6BA6EA: exec_eval_simple_expr (pl_exec.c:5602)
==5718==    by 0xE6B9DBB: exec_eval_expr (pl_exec.c:5197)
==5718==    by 0xE6B5A4B: exec_stmt_raise (pl_exec.c:3230)
==5718==    by 0xE6B2C04: exec_stmt (pl_exec.c:1632)
==5718==    by 0xE6B2956: exec_stmts (pl_exec.c:1535)
==5718==    by 0xE6B27FC: exec_stmt_block (pl_exec.c:1473)
==5718==    by 0xE6B083E: plpgsql_exec_function (pl_exec.c:474)
==5718==    by 0xE6AB13C: plpgsql_inline_handler (pl_handler.c:330)
==5718==    by 0x76C2B9: OidFunctionCall1Coll (fmgr.c:1327)
==5718==    by 0x3A28CA: ExecuteDoStmt (functioncmds.c:2234)
==5718==    by 0x5F92EB: standard_ProcessUtility (utility.c:532)
==5718==    by 0x5F8E26: ProcessUtility (utility.c:357)
==5718==    by 0x5F7D9F: PortalRunUtility (pquery.c:1178)
==5718==    by 0x5F7FC0: PortalRunMulti (pquery.c:1324)
==5718==    by 0x5F74DE: PortalRun (pquery.c:799)
==5718==    by 0x5F10BE: exec_simple_query (postgres.c:1120)
==5718==    by 0x5F5640: PostgresMain (postgres.c:4143)
==5718==  Address 0x20 is not stack'd, malloc'd or (recently) free'd
==5718== 
{
   <insert_a_suppression_name_here>
   Memcheck:Addr8
   fun:ExecInterpExpr
   fun:ExecInterpExprStillValid
   fun:ExecEvalExpr
   fun:exec_eval_simple_expr
   fun:exec_eval_expr
   fun:exec_stmt_raise
   fun:exec_stmt
   fun:exec_stmts
   fun:exec_stmt_block
   fun:plpgsql_exec_function
   fun:plpgsql_inline_handler
   fun:OidFunctionCall1Coll
   fun:ExecuteDoStmt
   fun:standard_ProcessUtility
   fun:ProcessUtility
   fun:PortalRunUtility
   fun:PortalRunMulti
   fun:PortalRun
   fun:exec_simple_query
   fun:PostgresMain
}
==5718== 
==5718== Process terminating with default action of signal 11 (SIGSEGV)
==5718==  Access not within mapped region at address 0x20
==5718==    at 0x40E3DD: ExecInterpExpr (execExprInterp.c:1117)
==5718==    by 0x40F5E9: ExecInterpExprStillValid (execExprInterp.c:1788)
==5718==    by 0xE6B0409: ExecEvalExpr (executor.h:282)
==5718==    by 0xE6BA6EA: exec_eval_simple_expr (pl_exec.c:5602)
==5718==    by 0xE6B9DBB: exec_eval_expr (pl_exec.c:5197)
==5718==    by 0xE6B5A4B: exec_stmt_raise (pl_exec.c:3230)
==5718==    by 0xE6B2C04: exec_stmt (pl_exec.c:1632)
==5718==    by 0xE6B2956: exec_stmts (pl_exec.c:1535)
==5718==    by 0xE6B27FC: exec_stmt_block (pl_exec.c:1473)
==5718==    by 0xE6B083E: plpgsql_exec_function (pl_exec.c:474)
==5718==    by 0xE6AB13C: plpgsql_inline_handler (pl_handler.c:330)
==5718==    by 0x76C2B9: OidFunctionCall1Coll (fmgr.c:1327)
==5718==    by 0x3A28CA: ExecuteDoStmt (functioncmds.c:2234)
==5718==    by 0x5F92EB: standard_ProcessUtility (utility.c:532)
==5718==    by 0x5F8E26: ProcessUtility (utility.c:357)
==5718==    by 0x5F7D9F: PortalRunUtility (pquery.c:1178)
==5718==    by 0x5F7FC0: PortalRunMulti (pquery.c:1324)
==5718==    by 0x5F74DE: PortalRun (pquery.c:799)
==5718==    by 0x5F10BE: exec_simple_query (postgres.c:1120)
==5718==    by 0x5F5640: PostgresMain (postgres.c:4143)
==5718==  If you believe this happened as a result of a stack
==5718==  overflow in your program's main thread (unlikely but
==5718==  possible), you can try to increase the size of the
==5718==  main thread stack using the --main-stacksize= flag.
==5718==  The main thread stack size used in this run was 8388608.

This looks like it might be related to recent plpgsql changes. Looks
like some pointer in:
			/* call input function (similar to InputFunctionCall) */
			if (!op->d.iocoerce.finfo_in->fn_strict || str != NULL)
is NULL.


==4286== Conditional jump or move depends on uninitialised value(s)
==4286==    at 0x6BA8A17: __wcsnlen_avx2 (strlen-avx2.S:261)
==4286==    by 0x6AF2FF1: wcsrtombs (wcsrtombs.c:104)
==4286==    by 0x6A88A40: wcstombs (wcstombs.c:34)
==4286==    by 0x514772: lowerstr_with_len.part.1 (ts_locale.c:284)
==4286==    by 0x523A63: readstoplist (ts_utils.c:119)
==4286==    by 0xEAB2839: dsnowball_init (dict_snowball.c:201)
==4286==    by 0x684975: OidFunctionCall1Coll (fmgr.c:1327)
==4286==    by 0x679277: lookup_ts_dictionary_cache (ts_cache.c:337)
==4286==    by 0x514E02: LexizeExec (ts_parse.c:203)
==4286==    by 0x5153ED: parsetext (ts_parse.c:405)
==4286==    by 0x521DD2: to_tsvector_byid (to_tsany.c:249)
==4286==    by 0x380261: ExecInterpExpr (execExprInterp.c:664)
==4286==    by 0x456069: ExecEvalExprSwitchContext (executor.h:301)
==4286==    by 0x456069: evaluate_expr (clauses.c:4873)
==4286==    by 0x4588B5: evaluate_function (clauses.c:4424)
==4286==    by 0x4588B5: simplify_function (clauses.c:4064)
==4286==    by 0x457519: eval_const_expressions_mutator (clauses.c:2676)
==4286==    by 0x3D615A: expression_tree_mutator (nodeFuncs.c:2903)
==4286==    by 0x458E43: simplify_function (clauses.c:4055)
==4286==    by 0x457519: eval_const_expressions_mutator (clauses.c:2676)
==4286==    by 0x3D5C02: expression_tree_mutator (nodeFuncs.c:2614)
==4286==    by 0x4572C1: eval_const_expressions_mutator (clauses.c:3671)
==4286==  Uninitialised value was created by a heap allocation
==4286==    at 0x4C2BB76: malloc (vg_replace_malloc.c:299)
==4286==    by 0x6A9667: AllocSetAlloc (aset.c:945)
==4286==    by 0x6B5AC7: palloc (mcxt.c:848)
==4286==    by 0x5238EA: get_tsearch_config_filename (ts_utils.c:55)
==4286==    by 0x5239AF: readstoplist (ts_utils.c:75)
==4286==    by 0xEAB2839: dsnowball_init (dict_snowball.c:201)
==4286==    by 0x684975: OidFunctionCall1Coll (fmgr.c:1327)
==4286==    by 0x679277: lookup_ts_dictionary_cache (ts_cache.c:337)
==4286==    by 0x514E02: LexizeExec (ts_parse.c:203)
==4286==    by 0x5153ED: parsetext (ts_parse.c:405)
==4286==    by 0x521DD2: to_tsvector_byid (to_tsany.c:249)
==4286==    by 0x380261: ExecInterpExpr (execExprInterp.c:664)
==4286==    by 0x456069: ExecEvalExprSwitchContext (executor.h:301)
==4286==    by 0x456069: evaluate_expr (clauses.c:4873)
==4286==    by 0x4588B5: evaluate_function (clauses.c:4424)
==4286==    by 0x4588B5: simplify_function (clauses.c:4064)
==4286==    by 0x457519: eval_const_expressions_mutator (clauses.c:2676)
==4286==    by 0x3D615A: expression_tree_mutator (nodeFuncs.c:2903)
==4286==    by 0x458E43: simplify_function (clauses.c:4055)
==4286==    by 0x457519: eval_const_expressions_mutator (clauses.c:2676)
==4286==    by 0x3D5C02: expression_tree_mutator (nodeFuncs.c:2614)
==4286==    by 0x4572C1: eval_const_expressions_mutator (clauses.c:3671)
==4286== 
{
   <insert_a_suppression_name_here>
   Memcheck:Cond
   fun:__wcsnlen_avx2
   fun:wcsrtombs
   fun:wcstombs
   fun:lowerstr_with_len.part.1
   fun:readstoplist
   fun:dsnowball_init
   fun:OidFunctionCall1Coll
   fun:lookup_ts_dictionary_cache
   fun:LexizeExec
   fun:parsetext
   fun:to_tsvector_byid
   fun:ExecInterpExpr
   fun:ExecEvalExprSwitchContext
   fun:evaluate_expr
   fun:evaluate_function
   fun:simplify_function
   fun:eval_const_expressions_mutator
   fun:expression_tree_mutator
   fun:simplify_function
   fun:eval_const_expressions_mutator
   fun:expression_tree_mutator
   fun:eval_const_expressions_mutator
}

I don't recall any recent changes in the area, so this might be a glibc
internal issue.

Greetings,

Andres Freund