Date: Tue, 1 Oct 2019 17:02:28 -0700
From: Andres Freund <andres@anarazel.de>
To: Michael Paquier <michael@paquier.xyz>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, pgsql-committers@lists.postgresql.org
Subject: Re: pgsql: Add hooks for session start and session end, take two
Message-ID: <20191002000228.i2vcd4maxy3nl3vp@alap3.anarazel.de>
References: <E1iF8dy-0000fc-9S@gemulon.postgresql.org>
 <20191001045246.GF2781@paquier.xyz>
 <18722.1569906636@sss.pgh.pa.us>
 <20191001052543.GI2781@paquier.xyz>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20191001052543.GI2781@paquier.xyz>
Precedence: bulk

Hi,

On 2019-10-01 14:25:43 +0900, Michael Paquier wrote:
> On Tue, Oct 01, 2019 at 01:10:36AM -0400, Tom Lane wrote:
> > The idea that you can launch a query after proc_exit has started is
> > complete insanity.  I hope this is just a poorly-thought-out test
> > case, and not something that's inherent to this module.  If there
> > are not reasonable use-cases that don't need that, we should just
> > revert the feature altogether, because it's nothing but a large
> > caliber foot-gun.
>
> That was originally just part of the original test to prove the point
> of the session end hook where people wanted to be able to log some
> activity once the session is done with.

How's that countering Tom's concern?  To me it seems pretty broken to
run the session hook from within ShutdownPostgres(). What if that hook
starts another transaction, for example? Or uses any of the other
subsystems that might already have shut down at this point?

The way this is implemented right now this cannot touch *any* subsystem
that uses before_shmem_exit hooks, because they've all already been
shutdown by the time ShutdownPostgres() is called.


Case in point, this fails reliably for me if I force every query to be
JIT compiled:

PGOPTIONS='-cjit_above_cost=0' make check -C src/test/modules/test_session_hooks/

#0  __GI___pthread_mutex_lock (mutex=0x0) at ../nptl/pthread_mutex_lock.c:67
#1  0x00007f3e772a156c in __gthread_mutex_lock (__mutex=0x0) at /usr/include/x86_64-linux-gnu/c++/8/bits/gthr-default.h:748
#2  __gthread_recursive_mutex_lock (__mutex=0x0) at /usr/include/x86_64-linux-gnu/c++/8/bits/gthr-default.h:810
#3  std::recursive_mutex::lock (this=0x0) at /usr/include/c++/8/mutex:107
#4  std::lock_guard<std::recursive_mutex>::lock_guard (__m=..., this=<synthetic pointer>) at /usr/include/c++/8/bits/std_mutex.h:162
#5  llvm::orc::ExecutionSession::runSessionLocked<llvm::orc::ExecutionSession::allocateVModule()::{lambda()#1}>(llvm::orc::ExecutionSession::allocateVModule()::{lambda()#1}&&) (F=..., this=0x0) at /home/andres/src/llvm-project/llvm/include/llvm/ExecutionEngine/Orc/Core.h:786
#6  llvm::orc::ExecutionSession::allocateVModule (this=0x0) at /home/andres/src/llvm-project/llvm/include/llvm/ExecutionEngine/Orc/Core.h:808
#7  llvm::OrcCBindingsStack::addIRModule<llvm::orc::LegacyIRCompileLayer<llvm::orc::LegacyRTDyldObjectLinkingLayer, llvm::orc::SimpleCompiler> > (
    this=this@entry=0x0, Layer=..., M=std::unique_ptr<class llvm::Module> = {...}, MemMgr=std::unique_ptr<class llvm::RuntimeDyld::MemoryManager> = {...},
    ExternalResolver=ExternalResolver@entry=0x7f3e78223bd0 <llvm_resolve_symbol>, ExternalResolverCtx=0x0)
    at /home/andres/src/llvm-project/llvm/lib/ExecutionEngine/Orc/OrcCBindingsStack.h:304
#8  0x00007f3e772a1935 in llvm::OrcCBindingsStack::addIRModuleEager (ExternalResolverCtx=0x0, ExternalResolver=0x7f3e78223bd0 <llvm_resolve_symbol>, M=...,
    this=0x0) at /usr/include/c++/8/bits/move.h:74
#9  LLVMOrcAddEagerlyCompiledIR (JITStack=0x0, RetHandle=RetHandle@entry=0x7fff33127f78, Mod=0x1460fb0,
    SymbolResolver=SymbolResolver@entry=0x7f3e78223bd0 <llvm_resolve_symbol>, SymbolResolverCtx=SymbolResolverCtx@entry=0x0)
    at /home/andres/src/llvm-project/llvm/lib/ExecutionEngine/Orc/OrcCBindings.cpp:77
#10 0x00007f3e78222d84 in llvm_compile_module (context=0x13aaea8) at /home/andres/src/postgresql/src/backend/jit/llvm/llvmjit.c:553
#11 llvm_get_function (context=0x13aaea8, funcname=0x14a2370 "evalexpr_1_0") at /home/andres/src/postgresql/src/backend/jit/llvm/llvmjit.c:262
#12 0x00007f3e7822be2e in ExecRunCompiledExpr (state=0x14a1d98, econtext=0x14a19c0, isNull=0x0)
    at /home/andres/src/postgresql/src/backend/jit/llvm/llvmjit_expr.c:2434
#13 0x00000000006b2529 in ExecEvalExprNoReturn (econtext=0x14a19c0, state=0x14a1d98) at /home/andres/src/postgresql/src/include/executor/executor.h:356
#14 ExecEvalExprNoReturnSwitchContext (econtext=0x14a19c0, state=0x14a1d98) at /home/andres/src/postgresql/src/include/executor/executor.h:356
#15 ExecProject (projInfo=0x14a1d90) at /home/andres/src/postgresql/src/include/executor/executor.h:388
#16 ExecResult (pstate=<optimized out>) at /home/andres/src/postgresql/src/backend/executor/nodeResult.c:136
#17 0x00000000006afe04 in ExecProcNode (node=0x14a18b0) at /home/andres/src/postgresql/src/include/executor/executor.h:240
#18 ExecModifyTable (pstate=0x14a1638) at /home/andres/src/postgresql/src/backend/executor/nodeModifyTable.c:2072
#19 0x0000000000687eec in ExecProcNode (node=0x14a1638) at /home/andres/src/postgresql/src/include/executor/executor.h:240
#20 ExecutePlan (execute_once=<optimized out>, dest=0xb1a9e0 <spi_printtupDR>, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>,
    operation=CMD_INSERT, use_parallel_mode=<optimized out>, planstate=0x14a1638, estate=0x14a12c8)
    at /home/andres/src/postgresql/src/backend/executor/execMain.c:1646
#21 standard_ExecutorRun (queryDesc=0x1432db0, direction=<optimized out>, count=0, execute_once=<optimized out>)
    at /home/andres/src/postgresql/src/backend/executor/execMain.c:364
#22 0x00000000006bfe2e in _SPI_pquery (tcount=0, fire_triggers=true, queryDesc=<optimized out>) at /home/andres/src/postgresql/src/backend/executor/spi.c:2521
#23 _SPI_execute_plan (plan=<optimized out>, paramLI=<optimized out>, snapshot=<optimized out>, crosscheck_snapshot=<optimized out>,
    read_only=<optimized out>, fire_triggers=<optimized out>, tcount=<optimized out>) at /home/andres/src/postgresql/src/backend/executor/spi.c:2297
#24 0x00000000006c1ee6 in SPI_execute (tcount=tcount@entry=0, read_only=false,
    src=0x1433648 "INSERT INTO session_hook_log (dbname, username, hook_at) VALUES ('contrib_regression', 'regress_sess_hook_usr2', 'END');")
    at /home/andres/src/postgresql/src/backend/executor/spi.c:514
#25 SPI_exec (src=0x1433648 "INSERT INTO session_hook_log (dbname, username, hook_at) VALUES ('contrib_regression', 'regress_sess_hook_usr2', 'END');",
    tcount=tcount@entry=0) at /home/andres/src/postgresql/src/backend/executor/spi.c:526
#26 0x00007f3e843cdf6f in register_session_hook (hook_at=<optimized out>)
    at /home/andres/src/postgresql/src/test/modules/test_session_hooks/test_session_hooks.c:68
#27 0x00000000007e5d65 in shmem_exit (code=code@entry=0) at /home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:239
#28 0x00000000007e5e6f in proc_exit_prepare (code=code@entry=0) at /home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:194
#29 0x00000000007e5f02 in proc_exit (code=code@entry=0) at /home/andres/src/postgresql/src/backend/storage/ipc/ipc.c:107
#30 0x000000000080bb35 in PostgresMain (argc=<optimized out>, argv=argv@entry=0x13a3fb0, dbname=<optimized out>, username=<optimized out>)
    at /home/andres/src/postgresql/src/backend/tcop/postgres.c:4470
#31 0x0000000000785436 in BackendRun (port=0x139d360, port=0x139d360) at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4459
#32 BackendStartup (port=0x139d360) at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4150
#33 ServerLoop () at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1718
#34 0x0000000000788307 in PostmasterMain (argc=argc@entry=8, argv=argv@entry=0x1372ed0)
    at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1391
#35 0x00000000004e6a54 in main (argc=8, argv=0x1372ed0) at /home/andres/src/postgresql/src/backend/main/main.c:210

The reason for that is simply that at that point llvmjit.c's own
shutdown hook has already shutdown parts of the JIT subsystem (which
needs to flush profiling information to disk, for profiling to be
useful).

Greetings,

Andres Freund