Re: strange slow query - lost lot of time somewhere

pá 6. 5. 2022 v 1:19 odesílatel David Rowley <dgrowleyml(at)gmail(dot)com> napsal:

> On Thu, 5 May 2022 at 19:26, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
> wrote:
> >
> > čt 5. 5. 2022 v 8:51 odesílatel Jakub Wartak <Jakub(dot)Wartak(at)tomtom(dot)com>
> napsal:
> >> > Breakpoint 1, 0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
> >> > (gdb) bt
> >> > #0 0x00007f557f0c16c0 in mmap64 () from /lib64/libc.so.6
> >> > #1 0x00007f557f04dd91 in sysmalloc () from /lib64/libc.so.6
> >> > #2 0x00007f557f04eaa9 in _int_malloc () from /lib64/libc.so.6
> >> > #3 0x00007f557f04fb1e in malloc () from /lib64/libc.so.6
> >> > #4 0x0000000000932134 in AllocSetAlloc ()
> >> > #5 0x00000000009376cf in MemoryContextAllocExtended ()
> >> > #6 0x00000000006ad915 in ExecInitMemoize ()
> >>
> >> Well the PGDG repo have the debuginfos (e.g. postgresql14-debuginfo)
> rpms / dpkgs(?) so I hope you are basically 1 command away of being able to
> debug it further what happens in ExecInitMemoize()
> >> Those packages seem to be safe as they modify only /usr/lib/debug so
> should not have any impact on production workload.
> >
> > I just have to wait for admin action - I have no root rights for the
> server.
>
> Looking at ExecInitMemoize() it's hard to see what could take such a
> long time other than the build_hash_table(). Tom did mention this,
> but I can't quite see how the size given to that function could be
> larger than 91 in your case.
>
> If you get the debug symbols installed, can you use gdb to
>
> break nodeMemoize.c:268
> p size
>
> maybe there's something I'm missing following the code and maybe there
> is some way that est_entries is not set to what I thought it was.
>
> It would also be good to see the same perf report again after the
> debug symbols are installed in order to resolve those unresolved
> function names.
>

Breakpoint 1, build_hash_table (size=4369066, mstate=0xfc7f08) at
nodeMemoize.c:268
268 if (size == 0)
(gdb) p size
$1 = 4369066

This is work_mem size

+ 99,92% 0,00% postmaster postgres [.] ServerLoop
▒
+ 99,92% 0,00% postmaster postgres [.] PostgresMain
▒
+ 99,92% 0,00% postmaster postgres [.]
exec_simple_query
▒
+ 99,70% 0,00% postmaster postgres [.] PortalRun
▒
+ 99,70% 0,00% postmaster postgres [.]
FillPortalStore
▒
+ 99,70% 0,02% postmaster postgres [.]
PortalRunUtility
▒
+ 99,68% 0,00% postmaster pg_stat_statements.so [.]
0x00007f5579b599c6
▒
+ 99,68% 0,00% postmaster postgres [.]
standard_ProcessUtility
▒
+ 99,68% 0,00% postmaster postgres [.] ExplainQuery
◆
+ 99,63% 0,00% postmaster postgres [.]
ExplainOneQuery
▒
+ 99,16% 0,00% postmaster postgres [.] ExplainOnePlan
▒
+ 99,06% 0,00% postmaster pg_stat_statements.so [.]
0x00007f5579b5ad2c
▒
+ 99,06% 0,00% postmaster postgres [.]
standard_ExecutorStart
▒
+ 99,06% 0,00% postmaster postgres [.] InitPlan
(inlined) ▒
+ 99,06% 0,00% postmaster postgres [.] ExecInitNode
▒
+ 99,06% 0,00% postmaster postgres [.]
ExecInitNestLoop
▒
+ 99,00% 0,02% postmaster postgres [.]
ExecInitMemoize
▒
+ 98,87% 26,80% postmaster libc-2.28.so [.]
__memset_avx2_erms
▒
+ 98,87% 0,00% postmaster postgres [.]
build_hash_table (inlined)
▒
+ 98,87% 0,00% postmaster postgres [.] memoize_create
(inlined) ▒
+ 98,87% 0,00% postmaster postgres [.]
memoize_allocate (inlined)
▒
+ 98,87% 0,00% postmaster postgres [.]
MemoryContextAllocExtended
▒
+ 72,08% 72,08% postmaster [unknown] [k]
0xffffffffbaa010e0
0,47% 0,00% postmaster postgres [.] pg_plan_query
0,47% 0,00% postmaster pg_stat_statements.so [.]
0x00007f5579b59ba4
0,47% 0,00% postmaster postgres [.]
standard_planner
0,47% 0,00% postmaster postgres [.]
subquery_planner
0,47% 0,00% postmaster postgres [.]
grouping_planner
0,47% 0,00% postmaster postgres [.] query_planner

>
> David
>