> 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.
---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster
