Re: 8.3b2 XPath-based function index server crash - Mailing list pgsql-general

> On Mon, Nov 19, 2007 at 10:02:20AM +1300, Matt Magoffin wrote:
>> Sorry if I left any relavent details out. I've been looking at this for
>> a while so many things are probably obvious only to me. Could you hint
>> at which additional details you think would be useful here?
>
> What's being asked for is a self contained example. Can you make a
> single script file that when you run it on a blank database causes the
> error?
>
> If you can't, that in itself is a useful fact. But then we need schema
> dumps and such things. EXPLAIN output for the queries that break.

I understand. I cannot make the SELECT query nor the ADD INDEX command
break on an empty database. I cannot share this database data, either.
I'll try to fill in any missing details. My table schema is this:

create table lead_test (
    id int8 not null,
    xml xml,
    processing_state varchar(20) not null,
    created timestamp with time zone not null,
    last_processed timestamp with time zone,
    processing_step int4, processing_attempts int4,
    primary key (id)
);

I have approximately 400k rows loaded in one particular database.

Back in 8.1, I have some additional indices defined using the xml2 module,
like this one:

create index assigned_area_idx ON lead (
    xpath_string(xml, '/als:auto-lead-service/als:meta[@key="AREA"][1]')
);

I was first trying to do the same sort of thing in 8.3 using the native
XML support, like this:

create index assigned_area_idx ON lead (
    xmlserialize(content(xpath('/als:auto-lead-service/als:meta[@key="AREA"][1]/text()',
xml,
        ARRAY[ARRAY['als','http://autoleadservice.com/xml/als']]))[1] as text)
);

I'm not sure if this is the correct way to do this in 8.3, but what I want
is a text-based index that I can query against like I do in 8.1. On an
empty table, this works fine. However, on my table with data in it, this
produces a crash, and the log file contains this:

DEBUG:  00000: ProcessUtility
LOCATION:  PortalRunUtility, pquery.c:1142
STATEMENT:  create index assigned_area_idx ON lead (
    xmlserialize(content(xpath('/als:auto-lead-service/als:meta[@key="AREA"][1]/text()',
xml,
    ARRAY[ARRAY['als','http://autoleadservice.com/xml/als']]))[1] as text)
    );

... time passes here with heavy CPU use...

DEBUG:  00000: StartTransaction
LOCATION:  ShowTransactionState, xact.c:3995
DEBUG:  00000: name: unnamed; blockState:       DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children: <>
LOCATION:  ShowTransactionStateRec, xact.c:4020
DEBUG:  00000: CommitTransaction
LOCATION:  ShowTransactionState, xact.c:3995
DEBUG:  00000: name: unnamed; blockState:       STARTED; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children: <>
LOCATION:  ShowTransactionStateRec, xact.c:4020
DEBUG:  00000: autovacuum: processing database "lms_infiniti"
LOCATION:  AutoVacWorkerMain, autovacuum.c:1600
DEBUG:  00000: StartTransaction
LOCATION:  ShowTransactionState, xact.c:3995
DEBUG:  00000: name: unnamed; blockState:       DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children: <>
LOCATION:  ShowTransactionStateRec, xact.c:4020
DEBUG:  00000: pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_attribute: vac: 0 (threshold 543), anl: 0 (threshold 296)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_class: vac: 0 (threshold 111), anl: 0 (threshold 81)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_index: vac: 0 (threshold 81), anl: 0 (threshold 65)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_opclass: vac: 0 (threshold 72), anl: 0 (threshold 61)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_amop: vac: 0 (threshold 119), anl: 0 (threshold 85)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_amproc: vac: 0 (threshold 99), anl: 0 (threshold 74)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: pg_trigger: vac: 0 (threshold 63), anl: 0 (threshold 56)
LOCATION:  relation_needs_vacanalyze, autovacuum.c:2566
DEBUG:  00000: CommitTransaction
LOCATION:  ShowTransactionState, xact.c:3995
DEBUG:  00000: name: unnamed; blockState:       STARTED; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children: <>
LOCATION:  ShowTransactionStateRec, xact.c:4020
DEBUG:  00000: proc_exit(0)
LOCATION:  proc_exit, ipc.c:95
DEBUG:  00000: shmem_exit(0)
LOCATION:  shmem_exit, ipc.c:156
DEBUG:  00000: exit(0)
LOCATION:  proc_exit, ipc.c:113
DEBUG:  00000: reaping dead processes
LOCATION:  reaper, postmaster.c:2081
DEBUG:  00000: server process (PID 966) exited with exit code 0
LOCATION:  LogChildExit, postmaster.c:2485
DEBUG:  00000: reaping dead processes
LOCATION:  reaper, postmaster.c:2081
DEBUG:  00000: server process (PID 965) was terminated by signal 11:
Segmentation fault
LOCATION:  LogChildExit, postmaster.c:2505
LOG:  00000: server process (PID 965) was terminated by signal 11:
Segmentation fault
LOCATION:  LogChildExit, postmaster.c:2505
LOG:  00000: terminating any other active server processes
LOCATION:  HandleChildCrash, postmaster.c:2350
DEBUG:  00000: sending SIGQUIT to process 959
LOCATION:  HandleChildCrash, postmaster.c:2405
DEBUG:  00000: sending SIGQUIT to process 960
LOCATION:  HandleChildCrash, postmaster.c:2417
DEBUG:  00000: sending SIGQUIT to process 961
LOCATION:  HandleChildCrash, postmaster.c:2429
DEBUG:  00000: sending SIGQUIT to process 962
LOCATION:  HandleChildCrash, postmaster.c:2459
DEBUG:  00000: forked new backend, pid=968 socket=7
LOCATION:  BackendStartup, postmaster.c:2818
LOG:  00000: connection received: host=[local]
LOCATION:  BackendInitialize, postmaster.c:2995
FATAL:  57P03: the database system is in recovery mode
LOCATION:  ProcessStartupPacket, postmaster.c:1649
DEBUG:  00000: proc_exit(1)
LOCATION:  proc_exit, ipc.c:95
DEBUG:  00000: shmem_exit(1)
LOCATION:  shmem_exit, ipc.c:156
DEBUG:  00000: exit(1)
LOCATION:  proc_exit, ipc.c:113
DEBUG:  00000: reaping dead processes
LOCATION:  reaper, postmaster.c:2081
DEBUG:  00000: server process (PID 968) exited with exit code 1
LOCATION:  LogChildExit, postmaster.c:2485
DEBUG:  00000: reaping dead processes
LOCATION:  reaper, postmaster.c:2081
LOG:  00000: all server processes terminated; reinitializing
LOCATION:  PostmasterStateMachine, postmaster.c:2658
DEBUG:  00000: shmem_exit(0)
LOCATION:  shmem_exit, ipc.c:156
DEBUG:  00000: invoking IpcMemoryCreate(size=38330368)
LOCATION:  CreateSharedMemoryAndSemaphores, ipci.c:128
LOG:  00000: database system was interrupted; last known up at 2007-11-19
11:02:35 NZDT
LOCATION:  StartupXLOG, xlog.c:4787
DEBUG:  00000: checkpoint record is at 1/1513CA4C
LOCATION:  StartupXLOG, xlog.c:4857
DEBUG:  00000: redo record is at 1/1513CA4C; shutdown TRUE
LOCATION:  StartupXLOG, xlog.c:4883
DEBUG:  00000: next transaction ID: 0/562; next OID: 802816
LOCATION:  StartupXLOG, xlog.c:4887
DEBUG:  00000: next MultiXactId: 1; next MultiXactOffset: 0
LOCATION:  StartupXLOG, xlog.c:4890
LOG:  00000: database system was not properly shut down; automatic
recovery in progress
LOCATION:  StartupXLOG, xlog.c:4954
LOG:  00000: redo starts at 1/1513CA8C
LOCATION:  StartupXLOG, xlog.c:5016
LOG:  00000: record with zero length at 1/151498E0
LOCATION:  ReadRecord, xlog.c:3099
LOG:  00000: redo done at 1/1514805C
LOCATION:  StartupXLOG, xlog.c:5086
DEBUG:  00000: transaction ID wrap limit is 2147484026, limited by
database "template1"
LOCATION:  SetTransactionIdLimit, varsup.c:283
DEBUG:  00000: proc_exit(0)
LOCATION:  proc_exit, ipc.c:95
DEBUG:  00000: shmem_exit(0)
LOCATION:  shmem_exit, ipc.c:156
DEBUG:  00000: exit(0)
LOCATION:  proc_exit, ipc.c:113
DEBUG:  00000: reaping dead processes
LOCATION:  reaper, postmaster.c:2081
LOG:  00000: autovacuum launcher started
LOCATION:  AutoVacLauncherMain, autovacuum.c:519
LOG:  00000: database system is ready to accept connections
LOCATION:  reaper, postmaster.c:2155

That is my original problem, and primary task. To try to investigate
further, I originally thought perhaps there was some specific XML document
that would cause this crash, and tried to narrow it down by using a SELECT
statement to see if I could find where it crashed. So I used SELECT
statements with OFFSET to narrow it down, until I found the server would
consistently crash on a specific offset, for example

select
id,xmlserialize(content(xpath('/als:auto-lead-service/als:meta[@key="AREA"][1]/text()',
xml,  ARRAY[ARRAY['als','http://autoleadservice.com/xml/als']]))[1] as
text) from lead order by id limit 1 offset 100000;

However, if I alter the SQL to lookup that same row by its primary key, like

select
id,xmlserialize(content(xpath('/als:auto-lead-service/als:meta[@key="AREA"][1]/text()',
xml,  ARRAY[ARRAY['als','http://autoleadservice.com/xml/als']]))[1] as
text) from lead where id = 38373893;

it runs fine without any error. So it then seemed like the crash only
occurs after processing the XML on many rows over time.

The EXPLAIN output isn't very much, I get only:

                                QUERY PLAN
--------------------------------------------------------------------------
 Limit  (cost=103905.81..103905.82 rows=1 width=40)
   ->  Sort  (cost=103655.81..104622.53 rows=386688 width=40)
         Sort Key: id
         ->  Seq Scan on lead  (cost=0.00..46622.60 rows=386688 width=40)
(4 rows)

Hope this helps, please let me know any more details that would be helpful.