Re: tsearch2 and unexpected exists

On Thu, 4 Sep 2003, Teodor Sigaev wrote:

>
>
> Nigel J. Andrews wrote:
> >
> > This will be a little vague, it was last night and I can't now do the test in
> > that db (see below) so can't give the exact wording.
> >
> > I seem to remember a report a little while ago about tsearch v2 causing
> > unexpected backend exit messages with 7.3.4 and now I'm getting similar
> > messages unpredictably and I can't find the thread in the archives either.
> >
> > What I did was install tsearch2 using share/contrib/tsearch2.sql, which placed
> > everything into public schema. Having created the tsvector column in a table
> > and populated it I tried running a pretty simple function that queried that
> > table (joined with another) using that tsvector column in the where
> > clause. This gave the unexpected exits of the backend (only the one for that
> > connection not all). The error was something like invalid MemoryContext
> > allocation 0. Other attempts gave a large number instead of 0. However, the odd
> > thing is that the query from the function that was using tsearch2 worked
> > fine when I cut it from the log and pasted it into psql directly.
> >
> > The function is in plpgsql, this is the stable tarball of tsearch v2 for 7.3.4
> > and obviously the server is 7.3.4. All running on Debian linux (woody).
> >
> > Unfortunately I can't reproduce this problem without reinstalling the db, or
> > seeing if createlang will work, since the untsearch2.sql script failed (I was
> > trying to reload tsearch2.sql jsut to see) so I foolishly dropped public schema
> > since I stupidly thought tsearch was the only thing using it. More importantly
> > I don't seem to be able to find the mailing list thread that covered pretty
> > much this exact unexpect exit fault. So, can anyone help with a fix,
> > explanation or link to the relevent thread please?
>
> Have you a core file, if yes then send gdb output, pls...



Unfortunately it was only after getting this core file that I noticed I don't
have it built with debugging symbols. However, as a starting point, here's the
psql session that kicks the core dump, the entire log for the server (although
it's not got much debug logging enabled) and the back trace. Oh, and the psql
session showing the successful completion of the tsearch2 query logged from the
function body.

When I have data for the query to find there are actually results for
'inviting'. However, at the moment there are a thousand or so tuples in the
main table but the tsvector column is null for all of them. I noticed this
problem when I had valid data in the tsvector column used in the query, and
indeed got tuples returned for the search word used in the following logs, so
it doesn't appear to be a problem with nulls.

In the query below the pertinent details of the main table are:

    id, article_id integer type,
    name, summary text type
    and search1 of type tsvector.

No dropped columns, in fact this is a completely new install of the db from
release scripts. The only anomoly is that tsearch2.sql was run such that SET
search_path at the top was replaced with a: set search_path tsearch2; command
and any other lines matching /SET search_path/ just deleted. However, this is
because having installed into public things got a little messy forcing me to do
this new install from release scripts and I first saw this problem with the
installation in public so it's not to do with installation schema.

I'll have to see if I can get everything rebuilt with -g :( If this is
sufficient could you let me know please, it'd save me some work and my wife is
already annoyed at how much I work.

Thanks, apart from this instability it looks good, I'm running the old tsearch
on a 7.2.x db and the version just seems nicer.


--
Nigel J. Andrews




$ psql -U cms cms_1
Welcome to psql 7.3.4, the PostgreSQL interactive terminal.

Type:  \copyright for distribution terms
       \h for help with SQL commands
       \? for help on internal slash commands
       \g or terminate with semicolon to execute query
       \q to quit

cms_1=> \c - cda
You are now connected as new user cda.
cms_1=> select basic_search('inviting');
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
!>



A fresh start of the server (to enable core dumping) so the entire log is:


2003-09-06 00:24:56 LOG:  database system was shut down at 2003-09-06 00:24:54 BST
2003-09-06 00:24:56 LOG:  checkpoint record is at 9/D625BBE0
2003-09-06 00:24:56 LOG:  redo record is at 9/D625BBE0; undo record is at 0/0; shutdown TRUE
2003-09-06 00:24:56 LOG:  next transaction id: 1408188; next oid: 2819206
2003-09-06 00:24:56 LOG:  database system is ready
2003-09-06 00:25:51 LOG:  connection received: host=[local]
2003-09-06 00:25:51 LOG:  connection authorized: user=cms database=cms_1
2003-09-06 00:25:51 LOG:  query: begin; select getdatabaseencoding(); commit
2003-09-06 00:25:51 LOG:  duration: 0.002865 sec
2003-09-06 00:25:51 LOG:  query: BEGIN; SELECT usesuper FROM pg_catalog.pg_user WHERE usename = 'cms'; COMMIT
2003-09-06 00:25:51 LOG:  duration: 0.009513 sec
2003-09-06 00:25:54 LOG:  connection received: host=[local]
2003-09-06 00:25:54 LOG:  connection authorized: user=cda database=cms_1
2003-09-06 00:25:54 LOG:  query: begin; select getdatabaseencoding(); commit
2003-09-06 00:25:54 LOG:  duration: 0.001072 sec
2003-09-06 00:25:54 LOG:  query: BEGIN; SELECT usesuper FROM pg_catalog.pg_user WHERE usename = 'cda'; COMMIT
2003-09-06 00:25:54 LOG:  duration: 0.004303 sec
2003-09-06 00:25:59 LOG:  query: select basic_search('inviting');
2003-09-06 00:25:59 LOG:  query: SELECT  ac.id ,ac.article_id ,ac.name ,ac.summary FROM article_content ac
,article_statuss  
WHERE ac.status_id = s.id AND s.name = 'Live' AND ac.search1 @@ to_tsquery('default',  $1 )
2003-09-06 00:25:59 LOG:  query: select oid from pg_ts_cfg where ts_name = $1
2003-09-06 00:25:59 LOG:  query: select prs_name from pg_ts_cfg where oid = $1
2003-09-06 00:25:59 LOG:  query: select lt.tokid, pg_ts_cfgmap.dict_name from pg_ts_cfgmap, pg_ts_cfg, token_type( $1 )
aslt 
 where lt.alias = pg_ts_cfgmap.tok_alias and pg_ts_cfgmap.ts_name = pg_ts_cfg.ts_name and pg_ts_cfg.oid= $2 order by
lt.tokid
 desc;
2003-09-06 00:25:59 LOG:  query: select oid from pg_ts_parser where prs_name = $1
2003-09-06 00:25:59 LOG:  query: select prs_start, prs_nexttoken, prs_end, prs_lextype, prs_headline from pg_ts_parser
where 
oid = $1
2003-09-06 00:25:59 LOG:  query: select oid from pg_ts_dict where dict_name = $1
2003-09-06 00:25:59 LOG:  query: select dict_init, dict_initoption, dict_lexize from pg_ts_dict where oid = $1
2003-09-06 00:25:59 LOG:  server process (pid 11145) was terminated by signal 11
2003-09-06 00:25:59 LOG:  terminating any other active server processes
2003-09-06 00:25:59 LOG:  all server processes terminated; reinitializing shared memory and semaphores
2003-09-06 00:25:59 LOG:  database system was interrupted at 2003-09-06 00:24:56 BST
2003-09-06 00:25:59 LOG:  checkpoint record is at 9/D625BBE0
2003-09-06 00:25:59 LOG:  redo record is at 9/D625BBE0; undo record is at 0/0; shutdown TRUE
2003-09-06 00:25:59 LOG:  next transaction id: 1408188; next oid: 2819206
2003-09-06 00:25:59 LOG:  database system was not properly shut down; automatic recovery in progress
2003-09-06 00:25:59 LOG:  connection received: host=[local]
2003-09-06 00:25:59 FATAL:  The database system is starting up
2003-09-06 00:26:01 LOG:  ReadRecord: record with zero length at 9/D625BC20
2003-09-06 00:26:01 LOG:  redo is not required
2003-09-06 00:26:03 LOG:  database system is ready




(gdb) bt
#0  0x08173aa7 in pfree ()
#1  0x40a4f90c in to_tsquery_name () from /usr/local/stow/postgresql-7.3.4/lib/tsearch2.so
#2  0x080d53e6 in ExecMakeFunctionResult ()
#3  0x080d58de in ExecEvalFunc ()
#4  0x080d5f60 in ExecEvalExpr ()
#5  0x080d5111 in ExecEvalFuncArgs ()
#6  0x080d51ca in ExecMakeFunctionResult ()
#7  0x080d5886 in ExecEvalOper ()
#8  0x080d5f50 in ExecEvalExpr ()
#9  0x080d60c6 in ExecQual ()
#10 0x080d65b3 in ExecScan ()
#11 0x080dc76e in ExecSeqScan ()
#12 0x080d4379 in ExecProcNode ()
#13 0x080dbe27 in ExecNestLoop ()
#14 0x080d43c9 in ExecProcNode ()
#15 0x080d32de in ExecutePlan ()
#16 0x080d29b0 in ExecutorRun ()
#17 0x080e0a95 in _SPI_cursor_operation ()
#18 0x080e00d4 in SPI_cursor_fetch ()
#19 0x40a272a8 in exec_stmt_fors () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#20 0x40a26bd1 in exec_stmt () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#21 0x40a26a65 in exec_stmts () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#22 0x40a269bb in exec_stmt_block () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#23 0x40a25f8a in plpgsql_exec_function () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#24 0x40a239ed in plpgsql_call_handler () from /usr/local/stow/postgresql-7.3.4/lib/plpgsql.so
#25 0x080d5301 in ExecMakeFunctionResult ()
#26 0x080d58de in ExecEvalFunc ()
#27 0x080d5f60 in ExecEvalExpr ()
#28 0x080d6259 in ExecTargetList ()
#29 0x080d64eb in ExecProject ()
#30 0x080dc573 in ExecResult ()
#31 0x080d4359 in ExecProcNode ()
#32 0x080d32de in ExecutePlan ()
#33 0x080d29b0 in ExecutorRun ()
#34 0x0812394b in ProcessQuery ()
#35 0x08121e1d in pg_exec_query_string ()
#36 0x08122f30 in PostgresMain ()
#37 0x0810a8fa in DoBackend ()
#38 0x0810a1ef in BackendStartup ()
#39 0x0810936c in ServerLoop ()
#40 0x08108ec3 in PostmasterMain ()
#41 0x080e60df in main ()
#42 0x401d814f in __libc_start_main () from /lib/libc.so.6
(gdb)



The query issued directly in psql:


You are now connected as new user cda.
cms_1=> SELECT  ac.id ,ac.article_id ,ac.name ,ac.summary FROM article_content ac ,article_status s WHERE ac.status_id
=s.id AND s.name = 'Live' AND ac.search1 @@ to_tsquery('default',  'inviting' ); 
 id | article_id | name | summary
----+------------+------+---------
(0 rows)

cms_1=>