[BUG] Segmentation fault in pfree in PLy_output_tuple_funcs

Hi,

PostgreSQL 9.2.4
Linux 2.6.32

listen_addresses = '*'
max_connections = 550
shared_buffers = 35GB
work_mem = 256MB
maintenance_work_mem = 1GB
shared_preload_libraries = 'pg_stat_statements'
bgwriter_delay = 10ms
bgwriter_lru_multiplier = 10.0
effective_io_concurrency = 32
wal_level = hot_standby
synchronous_commit = off
checkpoint_segments = 1024
checkpoint_timeout = 1h
checkpoint_completion_target = 0.9
checkpoint_warning = 5min
max_wal_senders = 3
wal_keep_segments = 2048
hot_standby = on
max_standby_streaming_delay = 5min
hot_standby_feedback = on
effective_cache_size = 133GB
log_destination = 'stderr'
logging_collector = on
log_directory = '/var/log/pgsql'
log_filename = 'postgresql-%Y-%m-%d.log'
log_truncate_on_rotation = on
log_rotation_age = 1d
log_rotation_size = 0
log_checkpoints = on
log_line_prefix = '%t %p %u(at)%d from %h [vxid:%v txid:%x] [%i] '
log_lock_waits = on
log_statement = 'ddl'
log_timezone = 'W-SU'
track_activity_query_size = 4096
autovacuum_max_workers = 5
autovacuum_naptime = 5s
autovacuum_vacuum_scale_factor = 0.05
autovacuum_analyze_scale_factor = 0.05
autovacuum_vacuum_cost_delay = 5ms
datestyle = 'iso, dmy'
timezone = 'W-SU'
lc_messages = 'en_US.UTF-8'
lc_monetary = 'ru_RU.UTF-8'
lc_numeric = 'ru_RU.UTF-8'
lc_time = 'ru_RU.UTF-8'
default_text_search_config = 'pg_catalog.russian'
pg_stat_statements.track = all

Yesterday we faced a segfault on a simple PL/Python function's call:

CREATE OR REPLACE FUNCTION test_test()
RETURNS TABLE("Идентификтор" int, "Гос. номер" varchar) AS
$BODY$
import time
cars = plpy.prepare("""
select id, ident_code from cars limit 100
""")

for car in plpy.execute(cars):
return car;
$BODY$
LANGUAGE plpythonu VOLATILE
COST 100
ROWS 1000;

It has happened just once and we didn't manage to reproduce this
problem. We have a huge amount of PL/Python code in the database and
have never had this kind of problem before.

Here is the backtrace from the coredump:

(gdb) bt f
#0 0x00000000007381d7 in pfree (pointer=0x7eff56a141a0) at mcxt.c:659
header = 0x7eff56a14190
#1 0x00007eff56a14927 in PLy_output_tuple_funcs (arg=0x1ad6960,
desc=0x19d9520) at plpy_typeio.c:199
i = <value optimized out>
__func__ = "PLy_output_tuple_funcs"
#2 0x00007eff56a0f155 in PLy_function_build_args
(fcinfo=0x7fffa59cb6b0, proc=0x1ad6940) at plpy_exec.c:416
desc = 0x19d9520
save_exception_stack = 0x7fffa59cb420
save_context_stack = 0x7fffa59cb630
local_sigjmp_buf = {{
__jmpbuf = {28236528, 5106765649720773924, 1, 28238888,
140735971899056, 140735971900064, -5106611986378781404,
-4962882071449170652},
__mask_was_saved = 0,
__saved_mask = {
__val = {0 <repeats 16 times>}
}
}}
arg = 0x0
args = 0x7eff62979ef0
i = <value optimized out>
__func__ = "PLy_function_build_args"
#3 0x00007eff56a0f437 in PLy_exec_function (fcinfo=0x7fffa59cb6b0,
proc=0x1ad6940) at plpy_exec.c:59
save_exception_stack = 0x7fffa59cb560
save_context_stack = 0x7fffa59cb630
local_sigjmp_buf = {{
__jmpbuf = {28236528, 5106765649720773924, 1, 28238888,
140735971899056, 140735971900064, -5106611986395558620,
-4962882071897174748},
__mask_was_saved = 0,
__saved_mask = {
__val = {13483862011252313380, 0, 0, 0, 192, 11739232,
601, 26726112, 139635135180228, 139635135180228, 7570912, 0, 26987960,
0, 8192, 8388608}
}
}}
rv = <value optimized out>
plargs = 0x0
plrv = 0x0
plerrcontext = {
previous = 0x7fffa59cbaa0,
callback = 0x7375b6 <AllocSetContextCreate+54>,
arg = 0x1ad6940
}
__func__ = "PLy_exec_function"
#4 0x00007eff56a0ff04 in plpython_call_handler (fcinfo=0x7fffa59cb6b0)
at plpy_main.c:236
funcoid = <value optimized out>
proc = <value optimized out>
save_exception_stack = 0x7fffa59cbc70
save_context_stack = <value optimized out>
local_sigjmp_buf = {{
__jmpbuf = {28236528, 5106765649720773924, 1, 28238888,
140735971899056, 140735971900064, -5106611986208912092,
-4962882072010945244},
__mask_was_saved = 0,
__saved_mask = {
__val = {0, 0, 281474976710656, 1043, 28238888,
3324408277, 28238888, 3324408277, 26985416, 0, 0, 28238920, 5790802, 0,
0, 0}
}
}}
---Type <return> to continue, or q <return> to quit---
retval = <value optimized out>
exec_ctx = 0x19bcdb8
plerrcontext = {
previous = 0x0,
callback = 0x7eff56a0ffb0 <plpython_error_callback>,
arg = 0x1aee428
}
__func__ = "plpython_call_handler"
#5 0x0000000000587fd5 in ExecMakeTableFunctionResult
(funcexpr=0x1aee428, econtext=0x1aedaf0, expectedDesc=0x1aee1e0,
randomAccess=0 '\000') at execQual.c:2156
result = 5967294
tupstore = 0x0
tupdesc = 0x0
funcrettype = 2249
returnsTuple = 1 '\001'
returnsSet = 1 '\001'
fcinfo = {
flinfo = 0x1aee448,
context = 0x0,
resultinfo = 0x7fffa59cba60,
fncollation = 0,
isnull = 0 '\000',
nargs = 0,
arg = {25859072, 0, 1043, 0 <repeats 20 times>, 7489698, 0,
0, 0, 64, 140735971899536, 4586382, 1, 2, 139635337082480, 7471000, 0,
0, 0, 420013441810432, 3324408277, 0,
4294967295, 7433724, 25962000, 2, 8, 7482628, 0,
140735971899532, 0, 25962288, 8589934592, 25962040, 25962200, 25962176,
25962144, 8589934592, 4479650889751, 40, 25856768,
1043, 4294967295, 100, 0, 7570165, 0, 25962928, 25952256,
25962288, 0, 140735971899960, 25962456, 5991898, 0, 26567760,
140735971852288, 7372282, 8589934594, 26567760, 1043,
26567760, 140735971899792, 26567760, 140735971899856,
7372282, 26786736, 26567760, 1043, 26567760, 140735971899856, 7378619,
6981568, 140735971899856, 2, 0, 139635337081568,
287762808832, 1125891316908032, 0, 6981568, 281483566645432},
argnull = "\002", '\000' <repeats 16 times>"\224, \212\001",
'\000' <repeats 12 times>, "\023\004", '\000' <repeats 65 times>
}
fcusage = {
fs = 0x0,
save_f_total_time = {
tv_sec = 0,
tv_usec = 0
},
save_total = {
tv_sec = 0,
tv_usec = 0
},
f_start = {
tv_sec = 0,
tv_usec = 0
}
}
rsinfo = {
type = T_ReturnSetInfo,
econtext = 0x1aedaf0,
expectedDesc = 0x1aee1e0,
allowedModes = 11,
returnMode = SFRM_ValuePerCall,
isDone = ExprSingleResult,
---Type <return> to continue, or q <return> to quit---
setResult = 0x0,
setDesc = 0x0
}
tmptup = {
t_len = 0,
t_self = {
ip_blkid = {
bi_hi = 0,
bi_lo = 0
},
ip_posid = 0
},
t_tableOid = 0,
t_data = 0x18d4b35
}
callerContext = 0x19bc3c8
oldcontext = <value optimized out>
direct_function_call = 1 '\001'
first_time = 1 '\001'
__func__ = "ExecMakeTableFunctionResult"
#6 0x0000000000599151 in FunctionNext (node=0x1aed9e0) at
nodeFunctionscan.c:65
slot = <value optimized out>
estate = <value optimized out>
direction = ForwardScanDirection
tuplestorestate = <value optimized out>
#7 0x0000000000588c3e in ExecScanFetch (node=0x1aed9e0,
accessMtd=0x5990e0 <FunctionNext>, recheckMtd=0x598e50
<FunctionRecheck>) at execScan.c:82
estate = <value optimized out>
#8 ExecScan (node=0x1aed9e0, accessMtd=0x5990e0 <FunctionNext>,
recheckMtd=0x598e50 <FunctionRecheck>) at execScan.c:132
econtext = 0x1aedaf0
qual = 0x0
projInfo = 0x0
isDone = <value optimized out>
resultSlot = <value optimized out>
#9 0x00000000005817f8 in ExecProcNode (node=0x1aed9e0) at
execProcnode.c:425
result = <value optimized out>
__func__ = "ExecProcNode"
#10 0x0000000000580722 in ExecutePlan (queryDesc=0x18d3990,
direction=<value optimized out>, count=0) at execMain.c:1395
slot = <value optimized out>
current_tuple_count = 0
#11 standard_ExecutorRun (queryDesc=0x18d3990, direction=<value
optimized out>, count=0) at execMain.c:303
estate = 0x1aed8d0
operation = CMD_SELECT
dest = 0x18c2f20
sendTuples = <value optimized out>
oldcontext = 0x19bc2b8
#12 0x00007eff57fb2a4b in pgss_ExecutorRun (queryDesc=0x18d3990,
direction=ForwardScanDirection, count=0) at pg_stat_statements.c:719
save_exception_stack = 0x7fffa59cbe00
save_context_stack = 0x0
local_sigjmp_buf = {{
__jmpbuf = {25985856, 5106765649720642852, 25964320,
26032528, 1, 25964272, -5106611986443793116, -4962879123083490012},
__mask_was_saved = 0,
---Type <return> to continue, or q <return> to quit---
__saved_mask = {
__val = {5773925, 26032528, 28235984, 0, 25985856,
25964096, 5770657, 0, 28162928, 0, 25964320, 26032528, 1, 25964272,
7625096, 26782512}
}
}}
#13 0x00000000006568f7 in PortalRunSelect (portal=0x18c8340,
forward=<value optimized out>, count=0, dest=0x18c2f20) at pquery.c:944
queryDesc = 0x18d3990
direction = ForwardScanDirection
nprocessed = <value optimized out>
__func__ = "PortalRunSelect"
#14 0x0000000000657b98 in PortalRun (portal=0x18c8340,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x18c2f20,
altdest=0x18c2f20, completionTag=0x7fffa59cbf10 "") at pquery.c:788
save_exception_stack = 0x7fffa59cc050
save_context_stack = 0x0
local_sigjmp_buf = {{
__jmpbuf = {25964320, 5106769150708288804, 25985856,
26785952, 2, 25964272, -5106611986450084572, 5106765901172706596},
__mask_was_saved = 0,
__saved_mask = {
__val = {7493551, 25964272, 26715728, 9017635, 25985856,
9017635, 80, 25856832, 25985856, 26785952, 2, 25964272, 7570597,
8762301, 2, 26785680}
}
}}
result = <value optimized out>
nprocessed = <value optimized out>
saveTopTransactionResourceOwner = 0x197cff0
saveTopTransactionContext = 0x197cee0
saveActivePortal = 0x0
saveResourceOwner = 0x197cff0
savePortalContext = 0x0
saveMemoryContext = 0x197cee0
__func__ = "PortalRun"
#15 0x000000000065425b in exec_simple_query (query_string=0x198ab30 "
select * from test_test();") at postgres.c:1046
parsetree = 0x198b790
portal = 0x18c8340
snapshot_set = <value optimized out>
commandTag = <value optimized out>
completionTag =
"\000\000\000\000\377\177\000\000\024\370\237\245\377\177\000\000p\277\234\245\377\177\000\000\060K\215\001\000\000\000\000P\277\234\245\377\177\000\000\024\370\237\245\377\177\000\000\220\277\234\245\377\177\000\000\200\301\234\245\377\177\000"
querytree_list = <value optimized out>
plantree_list = 0x18c2ef0
receiver = 0x18c2f20
format = 0
dest = DestRemote
oldcontext = 0x197cee0
parsetree_list = 0x198b8c0
parsetree_item = 0x198b8a0
save_log_statement_stats = 0 '\000'
was_logged = <value optimized out>
isTopLevel = <value optimized out>
msec_str =
"\034\000\000\000\000\000\000\000\060\253\230\001\000\000\000\000\001\000\000\000\000\000\000\000\201\200\200\200\200\200\200\200"
__func__ = "exec_simple_query"
#16 0x00000000006550b0 in PostgresMain (argc=<value optimized out>,
argv=<value optimized out>, dbname=0x18aa4d0 "transport",
username=<value optimized out>) at postgres.c:3959
query_string = 0x198ab30 " select * from test_test();"
firstchar = <value optimized out>
---Type <return> to continue, or q <return> to quit---
input_message = {
data = 0x198ab30 " select * from test_test();",
len = 29,
maxlen = 1024,
cursor = 29
}
local_sigjmp_buf = {{
__jmpbuf = {140735971901792, 5106768996678765860, 1, 1,
-9187201950435737471, 0, -5106611986527679196, 5106765900793253156},
__mask_was_saved = 1,
__saved_mask = {
__val = {0, 0, 0, 0, 0, 139635321201376, 139635337349552,
0, 4294967295, 0, 1, 11688832, 0, 9259542123273814145, 13970, 0}
}
}}
send_ready_for_query = 0 '\000'
__func__ = "PostgresMain"
#17 0x0000000000611991 in BackendRun () at postmaster.c:3614
ac = 1
secs = 439980748
usecs = 431501
i = <value optimized out>
av = 0x18aa5e0
maxac = <value optimized out>
#18 BackendStartup () at postmaster.c:3304
bn = 0x18cf0a0
pid = 0
#19 ServerLoop () at postmaster.c:1367
rmask = {
fds_bits = {8, 0 <repeats 15 times>}
}
selres = <value optimized out>
readmask = {
fds_bits = {56, 0 <repeats 15 times>}
}
nSockets = 6
now = <value optimized out>
last_touch_time = 1386663421
__func__ = "ServerLoop"
#20 0x00000000006145a1 in PostmasterMain (argc=<value optimized out>,
argv=<value optimized out>) at postmaster.c:1127
opt = <value optimized out>
status = <value optimized out>
userDoption = <value optimized out>
listen_addr_saved = 1 '\001'
i = <value optimized out>
__func__ = "PostmasterMain"
#21 0x00000000005b3540 in main (argc=5, argv=0x18a7680) at main.c:199

Any thoughts?

--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (901) 903-0499, +7 (988) 888-1979
gray(dot)ru(at)gmail(dot)com