On Sat, 3 Oct 2020 at 08:15, James Coleman <[email protected]> wrote:
>
> Jaime: was the backtrace in the original report by any chance record
> from breakpointing in the first call to get_sortgroupref_tle() (and
> one that successfully returned a sort group ref) rather than a call
> that hit the elog error on line 379?
>
I remember the first backtrace a made for this was on the line of the
elog but then a second backtrace was with the function, now that
repeat it with line of the function for the elog (and the original
query) i see again create_incrementalsort_plan() which made me try
with enable_incremental_sort disabled...
sorry for that, attached a better backtrace
--
Jaime Casanova www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
#0 get_sortgroupref_tle (sortref=5, targetList=0x556dc23ec8d0) at tlist.c:379
__errno_location = <optimized out>
l = 0x0
__func__ = "get_sortgroupref_tle"
#1 0x0000556dc0a5168c in prepare_sort_from_pathkeys (lefttree=0x556dc23ecb38,
pathkeys=0x556dc23a0380, relids=0x0, reqColIdx=0x0,
adjust_tlist_in_place=false, p_numsortkeys=0x7fffc84b343c,
p_sortColIdx=0x7fffc84b3430, p_sortOperators=0x7fffc84b3428,
p_collations=0x7fffc84b3420, p_nullsFirst=0x7fffc84b3418) at createplan.c:5897
ec = 0x556dc23a0b58
em = 0x556dc23a0878
tle = 0x0
pathkey = 0x556dc23a1018
pk_datatype = 0
sortop = 1754
j = 0x556dc23ec8f8
i__state = {l = 0x556dc23a0380, i = 3}
tlist = 0x556dc23ec8d0
i = 0x556dc23a03b0
numsortkeys = 3
sortColIdx = 0x556dc23a1618
sortOperators = 0x556dc23ec7c0
collations = 0x556dc23ecc50
nullsFirst = 0x556dc23ecc78
__func__ = "prepare_sort_from_pathkeys"
#2 0x0000556dc0a51ed2 in make_incrementalsort_from_pathkeys
(lefttree=0x556dc23ecb38, pathkeys=0x556dc23a0380, relids=0x0,
nPresortedCols=1) at createplan.c:6173
numsortkeys = 21869
sortColIdx = 0x556dc23ec6b8
sortOperators = 0x556dc22e14a0
collations = 0x556dc23a1f48
nullsFirst = 0x3c23ec850
#3 0x0000556dc0a49b16 in create_incrementalsort_plan (root=0x556dc22e14a0,
best_path=0x556dc23a3058, flags=1) at createplan.c:2025
plan = 0x7fffc84b3480
subplan = 0x556dc23ecb38
#4 0x0000556dc0a47184 in create_plan_recurse (root=0x556dc22e14a0,
best_path=0x556dc23a3058, flags=1) at createplan.c:472
plan = 0x556dc23ec6b8
__func__ = "create_plan_recurse"
#5 0x0000556dc0a49549 in create_gather_merge_plan (root=0x556dc22e14a0,
best_path=0x556dc23a32d8) at createplan.c:1770
gm_plan = 0x556dc23ec500
subplan = 0x556dc0b8162b <check_stack_depth+9>
pathkeys = 0x556dc23a0380
tlist = 0x556dc23ec6b8
#6 0x0000556dc0a472d8 in create_plan_recurse (root=0x556dc22e14a0,
best_path=0x556dc23a32d8, flags=0) at createplan.c:519
plan = 0x556dc23ec500
__func__ = "create_plan_recurse"
#7 0x0000556dc0a4de9b in create_nestloop_plan (root=0x556dc22e14a0,
best_path=0x556dc23eaf80) at createplan.c:4087
join_plan = 0x7fffc84b35b0
outer_plan = 0x7fffc84b35c0
inner_plan = 0x556dc23ec450
tlist = 0x556dc23ec500
joinrestrictclauses = 0x556dc23eab80
joinclauses = 0x556dc09ea053 <new_list+103>
otherclauses = 0x7fffc84b35a0
outerrelids = 0x556dc23ec450
nestParams = 0xe200000001
saveOuterRels = 0x0
#8 0x0000556dc0a47d75 in create_join_plan (root=0x556dc22e14a0,
best_path=0x556dc23eaf80) at createplan.c:1033
plan = 0x556dc0b8162b <check_stack_depth+9>
gating_clauses = 0x7fffc84b35f0
__func__ = "create_join_plan"
#9 0x0000556dc0a46f71 in create_plan_recurse (root=0x556dc22e14a0,
best_path=0x556dc23eaf80, flags=8) at createplan.c:401
plan = 0x556dc23eaf80
__func__ = "create_plan_recurse"
#10 0x0000556dc0a4978d in create_projection_plan (root=0x556dc22e14a0,
best_path=0x556dc23eb7d8, flags=5) at createplan.c:1862
plan = 0x556dc0b8162b <check_stack_depth+9>
subplan = 0x7fffc84b3680
tlist = 0xaf0
needs_result_node = false
#11 0x0000556dc0a46fdb in create_plan_recurse (root=0x556dc22e14a0,
best_path=0x556dc23eb7d8, flags=5) at createplan.c:417
plan = 0x7fff00000000
__func__ = "create_plan_recurse"
#12 0x0000556dc0a49c77 in create_upper_unique_plan (root=0x556dc22e14a0,
best_path=0x556dc23ebeb8, flags=1) at createplan.c:2091
plan = 0x7fffc84b3700
subplan = 0x556dc0b8162b <check_stack_depth+9>
#13 0x0000556dc0a470df in create_plan_recurse (root=0x556dc22e14a0,
best_path=0x556dc23ebeb8, flags=1) at createplan.c:450
plan = 0x556dc23ec130
__func__ = "create_plan_recurse"
#14 0x0000556dc0a46e4f in create_plan (root=0x556dc22e14a0,
best_path=0x556dc23ebeb8) at createplan.c:333
plan = 0x556dc23ebeb8
__func__ = "create_plan"
#15 0x0000556dc0a59603 in standard_planner (parse=0x556dc23acf28,
query_string=0x556dc22bb380 "explain \nselect distinct\n subq_0.c1 as
c0,\n ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as
c2,\n subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >=
"..., cursorOptions=256, boundParams=0x0) at planner.c:412
result = 0x556dc0d306a0 <check_enable_rls+158>
glob = 0x556dc22e1388
tuple_fraction = 0
root = 0x556dc22e14a0
final_rel = 0x556dc23ec130
best_path = 0x556dc23ebeb8
top_plan = 0x7fffc84b3870
lp = 0x7f42fec41bc8
lr = 0xac22feba8
#16 0x0000556dc0a59368 in planner (parse=0x556dc23acf28,
query_string=0x556dc22bb380 "explain \nselect distinct\n subq_0.c1 as
c0,\n ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as
c2,\n subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >=
"..., cursorOptions=256, boundParams=0x0) at planner.c:275
result = 0xfec41bc8
#17 0x0000556dc0b7dfdd in pg_plan_query (querytree=0x556dc23acf28,
query_string=0x556dc22bb380 "explain \nselect distinct\n subq_0.c1 as
c0,\n ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as
c2,\n subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >=
"..., cursorOptions=256, boundParams=0x0) at postgres.c:875
plan = 0x0
#18 0x0000556dc08b42e0 in ExplainOneQuery (query=0x556dc23acf28,
cursorOptions=256, into=0x0, es=0x556dc22e3fc0, queryString=0x556dc22bb380
"explain \nselect distinct\n subq_0.c1 as c0,\n
ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as c2,\n
subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >= "...,
params=0x0, queryEnv=0x0) at explain.c:391
planstart = {tv_sec = 313312, tv_nsec = 35909370}
bufusage = {shared_blks_hit = 140736553761216, shared_blks_read =
93929871418525, shared_blks_dirtied = 93929898430248, shared_blks_written =
93929897595696, local_blks_hit = 140736553761360, local_blks_read =
93929872713447, local_blks_dirtied = 93929898429200, local_blks_written =
93929898430248, temp_blks_read = 93929897595696, temp_blks_written =
93926639796225, blk_read_time = {tv_sec = 93929897595608, tv_nsec =
93926639796225}, blk_write_time = {tv_sec = 93929897607256, tv_nsec =
93929898430248}}
plan = 0x100556dc237a9b0
planduration = {tv_sec = 7553601320, tv_nsec = 93929898430248}
bufusage_start = {shared_blks_hit = 0, shared_blks_read =
93929897594672, shared_blks_dirtied = 140736553761136, shared_blks_written =
93929874909467, local_blks_hit = 140736553761152, local_blks_read = 64,
local_blks_dirtied = 93929897595696, local_blks_written = 93929897606000,
temp_blks_read = 140736553761184, temp_blks_written = 93929871417427,
blk_read_time = {tv_sec = 139925718834120, tv_nsec = 970662608897},
blk_write_time = {tv_sec = 93929897595696, tv_nsec = 93929897595696}}
#19 0x0000556dc08b3e2f in ExplainQuery (pstate=0x556dc22e3e60,
stmt=0x556dc23e2810, params=0x0, dest=0x556dc22e3dc8) at explain.c:275
l__state = {l = 0x556dc22e1330, i = 0}
l = 0x556dc22e1348
es = 0x556dc22e3fc0
tstate = 0x80
rewritten = 0x556dc22e1330
lc = 0x0
timing_set = false
summary_set = false
__func__ = "ExplainQuery"
#20 0x0000556dc0b86bd5 in standard_ProcessUtility (pstmt=0x556dc23e28d8,
queryString=0x556dc22bb380 "explain \nselect distinct\n subq_0.c1 as
c0,\n ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as
c2,\n subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >=
"..., context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
dest=0x556dc22e3dc8, qc=0x7fffc84b3cf0) at utility.c:829
parsetree = 0x556dc23e2810
isTopLevel = true
isAtomicContext = false
pstate = 0x556dc22e3e60
readonly_flags = 7
__func__ = "standard_ProcessUtility"
#21 0x0000556dc0b86397 in ProcessUtility (pstmt=0x556dc23e28d8,
queryString=0x556dc22bb380 "explain \nselect distinct\n subq_0.c1 as
c0,\n ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as
c2,\n subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >=
"..., context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
dest=0x556dc22e3dc8, qc=0x7fffc84b3cf0) at utility.c:524
No locals.
#22 0x0000556dc0b85149 in PortalRunUtility (portal=0x556dc231eb60,
pstmt=0x556dc23e28d8, isTopLevel=true, setHoldSnapshot=true,
dest=0x556dc22e3dc8, qc=0x7fffc84b3cf0) at pquery.c:1157
utilityStmt = 0x556dc23e2810
snapshot = 0x556dc2378ab8
#23 0x0000556dc0b84e3b in FillPortalStore (portal=0x556dc231eb60,
isTopLevel=true) at pquery.c:1017
treceiver = 0x556dc22e3dc8
qc = {commandTag = CMDTAG_UNKNOWN, nprocessed = 0}
__func__ = "FillPortalStore"
#24 0x0000556dc0b847ac in PortalRun (portal=0x556dc231eb60,
count=9223372036854775807, isTopLevel=true, run_once=true, dest=0x556dc23976a0,
altdest=0x556dc23976a0, qc=0x7fffc84b3ec0) at pquery.c:751
_save_exception_stack = 0x7fffc84b3fd0
_save_context_stack = 0x0
_local_sigjmp_buf = {{__jmpbuf = {0, -2648403899227423917,
93929868042176, 140736553764096, 0, 0, -2648403899246298285,
-8206988669814031533}, __mask_was_saved = 0, __saved_mask = {__val =
{20437679530, 93929898342024, 128, 93929897439840, 93929897606000,
140736553762336, 29592, 93929897606544, 93929898338848, 140736553762368,
93929874909888, 13, 112, 93929898342160, 112, 3360374352}}}}
_do_rethrow = false
result = false
nprocessed = 93929898342048
saveTopTransactionResourceOwner = 0x556dc22e86b0
saveTopTransactionContext = 0x556dc2378960
saveActivePortal = 0x0
saveResourceOwner = 0x556dc22e86b0
savePortalContext = 0x0
saveMemoryContext = 0x556dc2378960
__func__ = "PortalRun"
#25 0x0000556dc0b7e5f7 in exec_simple_query (query_string=0x556dc22bb380
"explain \nselect distinct\n subq_0.c1 as c0,\n
ref_0.radi_usua_radi as c1,\n ref_0.radi_nume_asoc as c2,\n
subq_0.c1 as c3,\n case when (cast(null as pg_lsn) >= "...) at
postgres.c:1239
snapshot_set = true
per_parsetree_context = 0x0
plantree_list = 0x556dc2397648
parsetree = 0x556dc23e2848
commandTag = CMDTAG_EXPLAIN
qc = {commandTag = CMDTAG_UNKNOWN, nprocessed = 0}
querytree_list = 0x556dc23975f0
portal = 0x556dc231eb60
receiver = 0x556dc23976a0
format = 0
parsetree_item__state = {l = 0x556dc23e2880, i = 0}
dest = DestRemote
oldcontext = 0x556dc2378960
parsetree_list = 0x556dc23e2880
parsetree_item = 0x556dc23e2898
save_log_statement_stats = false
was_logged = false
use_implicit_block = false
msec_str =
"L\000\000\000\002\000\000\000\274\003\000\000\000\000\000\000\200\263+\302mU\000\000\266\003\000\000\006\000\000"
__func__ = "exec_simple_query"
#26 0x0000556dc0b82950 in PostgresMain (argc=1, argv=0x556dc22e6c28,
dbname=0x556dc22e6b40 "postgres", username=0x556dc22b7dc8 "jcasanov") at
postgres.c:4315
query_string = 0x556dc22bb380 "explain \nselect distinct\n
subq_0.c1 as c0,\n ref_0.radi_usua_radi as c1,\n
ref_0.radi_nume_asoc as c2,\n subq_0.c1 as c3,\n case when
(cast(null as pg_lsn) >= "...
firstchar = 81
input_message = {data = 0x556dc22bb380 "explain \nselect distinct\n
subq_0.c1 as c0,\n ref_0.radi_usua_radi as c1,\n
ref_0.radi_nume_asoc as c2,\n subq_0.c1 as c3,\n case when
(cast(null as pg_lsn) >= "..., len = 951, maxlen = 1024, cursor = 951}
local_sigjmp_buf = {{__jmpbuf = {0, -2648403899112080557,
93929868042176, 140736553764096, 0, 0, -2648403899191772333,
-8206988670912545965}, __mask_was_saved = 1, __saved_mask = {__val = {0, 0,
30064771072, 93929897444952, 0, 93929897439840, 93929874861492, 1024,
93929897444976, 140736553762976, 93929874865965, 93929897444976,
93929897439840, 34359672832, 93929897444976, 93929897444952}}}}
send_ready_for_query = false
disable_idle_in_transaction_timeout = false
__func__ = "PostgresMain"
#27 0x0000556dc0acc95b in BackendRun (port=0x556dc22dff10) at postmaster.c:4536
av = 0x556dc22e6c28
maxac = 2
ac = 1
i = 1
__func__ = "BackendRun"
#28 0x0000556dc0acc0d3 in BackendStartup (port=0x556dc22dff10) at
postmaster.c:4220
bn = 0x556dc22df620
pid = 0
__func__ = "BackendStartup"
#29 0x0000556dc0ac8526 in ServerLoop () at postmaster.c:1739
port = 0x556dc22dff10
i = 2
rmask = {fds_bits = {256, 0 <repeats 15 times>}}
selres = 1
now = 1601736265
readmask = {fds_bits = {448, 0 <repeats 15 times>}}
nSockets = 9
last_lockfile_recheck_time = 1601736254
last_touch_time = 1601734993
__func__ = "ServerLoop"
#30 0x0000556dc0ac7d75 in PostmasterMain (argc=3, argv=0x556dc22b5d40) at
postmaster.c:1412
opt = -1
status = 0
userDoption = 0x556dc22d81d0 "data"
listen_addr_saved = true
i = 64
output_config_variable = 0x0
__func__ = "PostmasterMain"
#31 0x0000556dc09ca9ac in main (argc=3, argv=0x556dc22b5d40) at main.c:210
do_check_root = true
Detaching from program: /opt/var/pgdg/13/stable/bin/postgres, process 32025
[Inferior 1 (process 32025) detached]
