Обсуждение: BUG #3595: Segmentation fault with a simple select query

The following bug has been logged online:

Bug reference:      3595
Logged by:          Jukka Holappa
Email address:      jukkaho@mail.student.oulu.fi
PostgreSQL version: 8.2.4
Operating system:   Gentoo Linux
Description:        Segmentation fault with a simple select query
Details:

I can't easily reproduce this problem but it happens in every few hours in
my use.

I have a web spider software implemented in Java that stores information it
finds in a PostgreSQL database. Lots of inserts, many selects, lots of
updates.

During the last few days, the database has been crashing occasionally. I
turned on all the debug information and managed to reproduce the crash after
about 6 hours of running my software. The log output near the crash
follows:

Sep  3 13:56:43 [postgres] [77737748-1] LOG:  execute <unnamed>: SELECT *
FROM hosts WHERE name = $1 LIMIT 1
Sep  3 13:56:43 [postgres] [77737748-2] DETAIL:  parameters: $1 =
'www.babewarehouse.com'
Sep  3 13:56:43 [postgres] [77737749-1] DEBUG:  CommitTransactionCommand
Sep  3 13:56:43 [postgres] [77737750-1] DEBUG:  parse <unnamed>: SELECT id
FROM urls WHERE protocol = $1 AND host = $2 AND port = $3 AND file = $4
LIMIT 1
Sep  3 13:56:43 [postgres] [77737751-1] DEBUG:  StartTransactionCommand
Sep  3 13:56:43 [postgres] [77737752-1] DEBUG:  parse tree:
Sep  3 13:56:43 [postgres] [77737752-2] DETAIL:  {QUERY :commandType 1
:querySource 0 :canSetTag true :utilityStmt <>
Sep  3 13:56:43 [postgres] [77737752-3] _:resultRelation 0 :into <>
:intoOptions <> :intoOnCommit 0 :intoTableSpaceName
Sep  3 13:56:43 [postgres] [77737752-4] _<> :hasAggs false :hasSubLinks
false :rtable ({RTE :alias <> :eref {ALIAS
Sep  3 13:56:43 [postgres] [77737752-5] _:aliasname urls :colnames ("id"
"protocol" "host" "port" "file")} :rtekind 0
Sep  3 13:56:43 [postgres] [77737752-6] _:relid 46684 :inh true :inFromCl
true :requiredPerms 2 :checkAsUser 0})
Sep  3 13:56:43 [postgres] [77737752-7] _:jointree {FROMEXPR :fromlist
({RANGETBLREF :rtindex 1}) :quals {BOOLEXPR
Sep  3 13:56:43 [postgres] [77737752-8] _:boolop and :args ({BOOLEXPR
:boolop and :args ({BOOLEXPR :boolop and :args
Sep  3 13:56:43 [postgres] [77737752-9] _({OPEXPR :opno 98 :opfuncid 0
:opresulttype 16 :opretset false :args
Sep  3 13:56:43 [postgres] [77737752-10] _({RELABELTYPE :arg {VAR :varno 1
:varattno 2 :vartype 1043 :vartypmod -1
Sep  3 13:56:43 [postgres] [77737752-11] _:varlevelsup 0 :varnoold 1
:varoattno 2} :resulttype 25 :resulttypmod -1
Sep  3 13:56:43 [postgres] [77737752-12] _:relabelformat 2} {RELABELTYPE
:arg {PARAM :paramkind 0 :paramid 1 :paramtype
Sep  3 13:56:43 [postgres] [77737752-13] _1043} :resulttype 25 :resulttypmod
-1 :relabelformat 2})} {OPEXPR :opno 15
Sep  3 13:56:43 [postgres] [77737752-14] _:opfuncid 0 :opresulttype 16
:opretset false :args ({VAR :varno 1 :varattno 3
Sep  3 13:56:43 [postgres] [77737752-15] _:vartype 23 :vartypmod -1
:varlevelsup 0 :varnoold 1 :varoattno 3} {PARAM
Sep  3 13:56:43 [postgres] [77737752-16] _:paramkind 0 :paramid 2 :paramtype
20})})} {OPEXPR :opno 96 :opfuncid 0
Sep  3 13:56:43 [postgres] [77737752-17] _:opresulttype 16 :opretset false
:args ({VAR :varno 1 :varattno 4 :vartype 23
Sep  3 13:56:43 [postgres] [77737752-18] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 4} {PARAM :paramkind 0
Sep  3 13:56:43 [postgres] [77737752-19] _:paramid 3 :paramtype 23})})}
{OPEXPR :opno 98 :opfuncid 0 :opresulttype 16
Sep  3 13:56:43 [postgres] [77737752-20] _:opretset false :args
({RELABELTYPE :arg {VAR :varno 1 :varattno 5 :vartype
Sep  3 13:56:43 [postgres] [77737752-21] _1043 :vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 5} :resulttype 25
Sep  3 13:56:43 [postgres] [77737752-22] _:resulttypmod -1 :relabelformat 2}
{RELABELTYPE :arg {PARAM :paramkind 0
Sep  3 13:56:43 [postgres] [77737752-23] _:paramid 4 :paramtype 1043}
:resulttype 25 :resulttypmod -1 :relabelformat
Sep  3 13:56:43 [postgres] [77737752-24] _2})})}} :targetList ({TARGETENTRY
:expr {VAR :varno 1 :varattno 1 :vartype 20
Sep  3 13:56:43 [postgres] [77737752-25] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 1} :resno 1 :resname id
Sep  3 13:56:43 [postgres] [77737752-26] _:ressortgroupref 0 :resorigtbl
46684 :resorigcol 1 :resjunk false})
Sep  3 13:56:43 [postgres] [77737752-27] _:returningList <> :groupClause <>
:havingQual <> :distinctClause <>
Sep  3 13:56:43 [postgres] [77737752-28] _:sortClause <> :limitOffset <>
:limitCount {FUNCEXPR :funcid 481
Sep  3 13:56:43 [postgres] [77737752-29] _:funcresulttype 20 :funcretset
false :funcformat 2 :args ({CONST :consttype 23
Sep  3 13:56:43 [postgres] [77737752-30] _:constlen 4 :constbyval true
:constisnull false :constvalue 4 [ 1 0 0 0 0 0 0
Sep  3 13:56:43 [postgres] [77737752-31] _0 ]})} :rowMarks <> :setOperations
<> :resultRelations <> :returningLists <>}
Sep  3 13:56:43 [postgres] [77737752-32] _
Sep  3 13:56:43 [postgres] [77737753-1] DEBUG:  rewritten parse tree:
Sep  3 13:56:43 [postgres] [77737753-2] DETAIL:  ({QUERY :commandType 1
:querySource 0 :canSetTag true :utilityStmt <>
Sep  3 13:56:43 [postgres] [77737753-3] _:resultRelation 0 :into <>
:intoOptions <> :intoOnCommit 0 :intoTableSpaceName
Sep  3 13:56:43 [postgres] [77737753-4] _<> :hasAggs false :hasSubLinks
false :rtable ({RTE :alias <> :eref {ALIAS
Sep  3 13:56:43 [postgres] [77737753-5] _:aliasname urls :colnames ("id"
"protocol" "host" "port" "file")} :rtekind 0
Sep  3 13:56:43 [postgres] [77737753-6] _:relid 46684 :inh true :inFromCl
true :requiredPerms 2 :checkAsUser 0})
Sep  3 13:56:43 [postgres] [77737753-7] _:jointree {FROMEXPR :fromlist
({RANGETBLREF :rtindex 1}) :quals {BOOLEXPR
Sep  3 13:56:43 [postgres] [77737753-8] _:boolop and :args ({BOOLEXPR
:boolop and :args ({BOOLEXPR :boolop and :args
Sep  3 13:56:43 [postgres] [77737753-9] _({OPEXPR :opno 98 :opfuncid 0
:opresulttype 16 :opretset false :args
Sep  3 13:56:43 [postgres] [77737753-10] _({RELABELTYPE :arg {VAR :varno 1
:varattno 2 :vartype 1043 :vartypmod -1
Sep  3 13:56:43 [postgres] [77737753-11] _:varlevelsup 0 :varnoold 1
:varoattno 2} :resulttype 25 :resulttypmod -1
Sep  3 13:56:43 [postgres] [77737753-12] _:relabelformat 2} {RELABELTYPE
:arg {PARAM :paramkind 0 :paramid 1 :paramtype
Sep  3 13:56:43 [postgres] [77737753-13] _1043} :resulttype 25 :resulttypmod
-1 :relabelformat 2})} {OPEXPR :opno 15
Sep  3 13:56:43 [postgres] [77737753-14] _:opfuncid 0 :opresulttype 16
:opretset false :args ({VAR :varno 1 :varattno 3
Sep  3 13:56:43 [postgres] [77737753-15] _:vartype 23 :vartypmod -1
:varlevelsup 0 :varnoold 1 :varoattno 3} {PARAM
Sep  3 13:56:43 [postgres] [77737753-16] _:paramkind 0 :paramid 2 :paramtype
20})})} {OPEXPR :opno 96 :opfuncid 0
Sep  3 13:56:43 [postgres] [77737753-17] _:opresulttype 16 :opretset false
:args ({VAR :varno 1 :varattno 4 :vartype 23
Sep  3 13:56:43 [postgres] [77737753-18] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 4} {PARAM :paramkind 0
Sep  3 13:56:43 [postgres] [77737753-19] _:paramid 3 :paramtype 23})})}
{OPEXPR :opno 98 :opfuncid 0 :opresulttype 16
Sep  3 13:56:43 [postgres] [77737753-20] _:opretset false :args
({RELABELTYPE :arg {VAR :varno 1 :varattno 5 :vartype
Sep  3 13:56:43 [postgres] [77737753-21] _1043 :vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 5} :resulttype 25
Sep  3 13:56:43 [postgres] [77737753-22] _:resulttypmod -1 :relabelformat 2}
{RELABELTYPE :arg {PARAM :paramkind 0
Sep  3 13:56:43 [postgres] [77737753-23] _:paramid 4 :paramtype 1043}
:resulttype 25 :resulttypmod -1 :relabelformat
Sep  3 13:56:43 [postgres] [77737753-24] _2})})}} :targetList ({TARGETENTRY
:expr {VAR :varno 1 :varattno 1 :vartype 20
Sep  3 13:56:43 [postgres] [77737753-25] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 1} :resno 1 :resname id
Sep  3 13:56:43 [postgres] [77737753-26] _:ressortgroupref 0 :resorigtbl
46684 :resorigcol 1 :resjunk false})
Sep  3 13:56:43 [postgres] [77737753-27] _:returningList <> :groupClause <>
:havingQual <> :distinctClause <>
Sep  3 13:56:43 [postgres] [77737753-28] _:sortClause <> :limitOffset <>
:limitCount {FUNCEXPR :funcid 481
Sep  3 13:56:43 [postgres] [77737753-29] _:funcresulttype 20 :funcretset
false :funcformat 2 :args ({CONST :consttype 23
Sep  3 13:56:43 [postgres] [77737753-30] _:constlen 4 :constbyval true
:constisnull false :constvalue 4 [ 1 0 0 0 0 0 0
Sep  3 13:56:43 [postgres] [77737753-31] _0 ]})} :rowMarks <> :setOperations
<> :resultRelations <> :returningLists <>})
Sep  3 13:56:43 [postgres] [77737753-32] _
Sep  3 13:56:43 [postgres] [77737754-1] DEBUG:  bind <unnamed> to <unnamed>
Sep  3 13:56:43 [postgres] [77737755-1] DEBUG:  plan:
Sep  3 13:56:43 [postgres] [77737755-2] DETAIL:  {LIMIT :startup_cost 0.00
:total_cost 61.94 :plan_rows 1 :plan_width 8
Sep  3 13:56:43 [postgres] [77737755-3] _:targetlist ({TARGETENTRY :expr
{VAR :varno 1 :varattno 1 :vartype 20
Sep  3 13:56:43 [postgres] [77737755-4] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 1} :resno 1 :resname id
Sep  3 13:56:43 [postgres] [77737755-5] _:ressortgroupref 0 :resorigtbl
46684 :resorigcol 1 :resjunk false}) :qual <>
Sep  3 13:56:43 [postgres] [77737755-6] _:lefttree {INDEXSCAN :startup_cost
0.00 :total_cost 61.94 :plan_rows 1
Sep  3 13:56:43 [postgres] [77737755-7] _:plan_width 8 :targetlist
({TARGETENTRY :expr {VAR :varno 1 :varattno 1
Sep  3 13:56:43 [postgres] [77737755-8] _:vartype 20 :vartypmod -1
:varlevelsup 0 :varnoold 1 :varoattno 1} :resno 1
Sep  3 13:56:43 [postgres] [77737755-9] _:resname id :ressortgroupref 0
:resorigtbl 46684 :resorigcol 1 :resjunk
Sep  3 13:56:43 [postgres] [77737755-10] _false}) :qual <> :lefttree <>
:righttree <> :initPlan <> :extParam (b)
Sep  3 13:56:43 [postgres] [77737755-11] _:allParam (b) :nParamExec 0
:scanrelid 1 :indexid 48972 :indexqual ({OPEXPR
Sep  3 13:56:43 [postgres] [77737755-12] _:opno 98 :opfuncid 67
:opresulttype 16 :opretset false :args ({VAR :varno 1
Sep  3 13:56:43 [postgres] [77737755-13] _:varattno 1 :vartype 1043
:vartypmod -1 :varlevelsup 0 :varnoold 1 :varoattno
Sep  3 13:56:43 [postgres] [77737755-14] _2} {CONST :consttype 25 :constlen
-1 :constbyval false :constisnull false
Sep  3 13:56:43 [postgres] [77737755-15] _:constvalue 8 [ 8 0 0 0 104 116
116 112 ]})} {OPEXPR :opno 15 :opfuncid 852
Sep  3 13:56:43 [postgres] [77737755-16] _:opresulttype 16 :opretset false
:args ({VAR :varno 1 :varattno 2 :vartype 23
Sep  3 13:56:43 [postgres] [77737755-17] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 3} {CONST :consttype 20
Sep  3 13:56:43 [postgres] [77737755-18] _:constlen 8 :constbyval false
:constisnull false :constvalue 8 [ -94 4 0 0 0 0
Sep  3 13:56:43 [postgres] [77737755-19] _0 0 ]})} {OPEXPR :opno 96
:opfuncid 65 :opresulttype 16 :opretset false :args
Sep  3 13:56:43 [postgres] [77737755-20] _({VAR :varno 1 :varattno 3
:vartype 23 :vartypmod -1 :varlevelsup 0 :varnoold
Sep  3 13:56:43 [postgres] [77737755-21] _1 :varoattno 4} {CONST :consttype
23 :constlen 4 :constbyval true :constisnull
Sep  3 13:56:43 [postgres] [77737755-22] _false :constvalue 4 [ -1 -1 -1 -1
0 0 0 0 ]})} {OPEXPR :opno 98 :opfuncid 67
Sep  3 13:56:43 [postgres] [77737755-23] _:opresulttype 16 :opretset false
:args ({VAR :varno 1 :varattno 4 :vartype
Sep  3 13:56:43 [postgres] [77737755-24] _1043 :vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 5} {CONST :consttype
Sep  3 13:56:43 [postgres] [77737755-25] _25 :constlen -1 :constbyval false
:constisnull false :constvalue 65 [ 65 0 0 0
Sep  3 13:56:43 [postgres] [77737755-26] _47 116 101 114 109 115 95 111 102
95 115 101 114 118 105 99 101 46 112 104 112
Sep  3 13:56:43 [postgres] [77737755-27] _63 109 111 100 95 105 100 61 102
53 51 48 51 54 97 53 100 50 52 52 98 50 51 50
Sep  3 13:56:43 [postgres] [77737755-28] _54 97 51 100 97 49 100 55 49 54 57
100 102 48 99 101 ]})}) :indexqualorig
Sep  3 13:56:43 [postgres] [77737755-29] _({OPEXPR :opno 98 :opfuncid 67
:opresulttype 16 :opretset false :args
Sep  3 13:56:43 [postgres] [77737755-30] _({RELABELTYPE :arg {VAR :varno 1
:varattno 2 :vartype 1043 :vartypmod -1
Sep  3 13:56:43 [postgres] [77737755-31] _:varlevelsup 0 :varnoold 1
:varoattno 2} :resulttype 25 :resulttypmod -1
Sep  3 13:56:43 [postgres] [77737755-32] _:relabelformat 2} {CONST
:consttype 25 :constlen -1 :constbyval false
Sep  3 13:56:43 [postgres] [77737755-33] _:constisnull false :constvalue 8 [
8 0 0 0 104 116 116 112 ]})} {OPEXPR :opno
Sep  3 13:56:43 [postgres] [77737755-34] _15 :opfuncid 852 :opresulttype 16
:opretset false :args ({VAR :varno 1
Sep  3 13:56:43 [postgres] [77737755-35] _:varattno 3 :vartype 23 :vartypmod
-1 :varlevelsup 0 :varnoold 1 :varoattno 3}
Sep  3 13:56:43 [postgres] [77737755-36] _{CONST :consttype 20 :constlen 8
:constbyval false :constisnull false
Sep  3 13:56:43 [postgres] [77737755-37] _:constvalue 8 [ -94 4 0 0 0 0 0 0
]})} {OPEXPR :opno 96 :opfuncid 65
Sep  3 13:56:43 [postgres] [77737755-38] _:opresulttype 16 :opretset false
:args ({VAR :varno 1 :varattno 4 :vartype 23
Sep  3 13:56:43 [postgres] [77737755-39] _:vartypmod -1 :varlevelsup 0
:varnoold 1 :varoattno 4} {CONST :consttype 23
Sep  3 13:56:43 [postgres] [77737755-40] _:constlen 4 :constbyval true
:constisnull false :constvalue 4 [ -1 -1 -1 -1 0
Sep  3 13:56:43 [postgres] [77737755-41] _0 0 0 ]})} {OPEXPR :opno 98
:opfuncid 67 :opresulttype 16 :opretset false
Sep  3 13:56:43 [postgres] [77737755-42] _:args ({RELABELTYPE :arg {VAR
:varno 1 :varattno 5 :vartype 1043 :vartypmod -1
Sep  3 13:56:43 [postgres] [77737755-43] _:varlevelsup 0 :varnoold 1
:varoattno 5} :resulttype 25 :resulttypmod -1
Sep  3 13:56:43 [postgres] [77737755-44] _:relabelformat 2} {CONST
:consttype 25 :constlen -1 :constbyval false
Sep  3 13:56:43 [postgres] [77737755-45] _:constisnull false :constvalue 65
[ 65 0 0 0 47 116 101 114 109 115 95 111 102
Sep  3 13:56:43 [postgres] [77737755-46] _95 115 101 114 118 105 99 101 46
112 104 112 63 109 111 100 95 105 100 61 102
Sep  3 13:56:43 [postgres] [77737755-47] _53 51 48 51 54 97 53 100 50 52 52
98 50 51 50 54 97 51 100 97 49 100 55 49 54
Sep  3 13:56:43 [postgres] [77737755-48] _57 100 102 48 99 101 ]})})
:indexstrategy (i 3 3 3 3) :indexsubtype (o 0 20 0
Sep  3 13:56:43 [postgres] [77737755-49] _0) :indexorderdir 1} :righttree <>
:initPlan <> :extParam (b) :allParam (b)
Sep  3 13:56:43 [postgres] [77737755-50] _:nParamExec 0 :limitOffset <>
:limitCount {CONST :consttype 20 :constlen 8
Sep  3 13:56:43 [postgres] [77737755-51] _:constbyval false :constisnull
false :constvalue 8 [ 1 0 0 0 0 0 0 0 ]}}
Sep  3 13:56:43 [postgres] [77737755-52] _
Sep  3 13:56:43 [postgres] [77737756-1] LOG:  execute <unnamed>: SELECT id
FROM urls WHERE protocol = $1 AND host = $2 AND port = $3 AND file = $4
LIMIT 1
Sep  3 13:56:43 [postgres] [77737756-2] DETAIL:  parameters: $1 = 'http', $2
= '1186', $3 = '-1', $4 =
'/terms_of_service.php?mod_id=f53036a5d244b2326a3da1d7169df0ce'
Sep  3 13:56:43 [postgres] [23131-1] DEBUG:  reaping dead processes
Sep  3 13:56:43 [postgres] [23132-1] DEBUG:  server process (PID 6033) was
terminated by signal 11
Sep  3 13:56:43 [postgres] [23133-1] LOG:  server process (PID 6033) was
terminated by signal 11
Sep  3 13:56:43 [postgres] [23134-1] LOG:  terminating any other active
server processes
Sep  3 13:56:43 [postgres] [23135-1] DEBUG:  sending SIGQUIT to process
22128
Sep  3 13:56:43 [postgres] [23136-1] DEBUG:  sending SIGQUIT to process
22129
Sep  3 13:56:43 [postgres] [23137-1] DEBUG:  reaping dead processes
Sep  3 13:56:43 [postgres] [23138-1] LOG:  all server processes terminated;
reinitializing
Sep  3 13:56:43 [postgres] [23139-1] DEBUG:  shmem_exit(0)
Sep  3 13:56:43 [postgres] [23140-1] DEBUG:  invoking
IpcMemoryCreate(size=29523968)
Sep  3 13:56:43 [postgres] [23141-1] LOG:  database system was interrupted
at 2007-09-03 13:54:45 EEST
Sep  3 13:56:43 [postgres] [23142-1] LOG:  checkpoint record is at
3C/B7A0D070
Sep  3 13:56:43 [postgres] [23143-1] LOG:  redo record is at 3C/B7A0D070;
undo record is at 0/0; shutdown FALSE
Sep  3 13:56:43 [postgres] [23144-1] LOG:  next transaction ID: 0/54598559;
next OID: 134236
Sep  3 13:56:43 [postgres] [23145-1] LOG:  next MultiXactId: 3; next
MultiXactOffset: 5
Sep  3 13:56:43 [postgres] [23146-1] LOG:  database system was not properly
shut down; automatic recovery in progress
Sep  3 13:56:43 [postgres] [23147-1] LOG:  redo starts at 3C/B7A0D0C0
Sep  3 13:56:43 [postgres] [23148-1] LOG:  unexpected pageaddr 3C/B0876000
in log file 60, segment 185, offset 8871936
Sep  3 13:56:43 [postgres] [23149-1] LOG:  redo done at 3C/B9875D48
Sep  3 13:56:56 [postgres] [23150-1] DEBUG:  recycled transaction log file
"000000010000003C000000B6"
Sep  3 13:56:56 [postgres] [23151-1] DEBUG:  recycled transaction log file
"000000010000003C000000B5"
Sep  3 13:56:56 [postgres] [23152-1] LOG:  database system is ready
Sep  3 13:56:56 [postgres] [23153-1] DEBUG:  transaction ID wrap limit is
2147484171, limited by database "postgres"
Sep  3 13:56:56 [postgres] [23154-1] DEBUG:  proc_exit(0)
Sep  3 13:56:56 [postgres] [23155-1] DEBUG:  shmem_exit(0)
Sep  3 13:56:56 [postgres] [23156-1] DEBUG:  exit(0)
Sep  3 13:56:56 [postgres] [23141-1] DEBUG:  reaping dead processes
Sep  3 13:57:56 [postgres] [23142-1] DEBUG:  proc_exit(0)
Sep  3 13:57:56 [postgres] [23143-1] DEBUG:  shmem_exit(0)
Sep  3 13:57:56 [postgres] [23144-1] DEBUG:  exit(0)

Trying to reproduce the crash afterwards using commandline psql client does
not work. The result is that no rows are returned and the database stays
up.

Query plan for above select:
searchdb=> explain SELECT id FROM urls WHERE protocol = 'http' AND host =
'1186' AND port = '-1' AND file =
'/terms_of_service.php?mod_id=f53036a5d244b2326a3da1d7169df0ce' LIMIT 1
;

         QUERY PLAN
----------------------------------------------------------------------------
----------------------------------------------------------------------------
------------------------------
 Limit  (cost=0.00..61.94 rows=1 width=8)
   ->  Index Scan using unique_urls on urls  (cost=0.00..61.94 rows=1
width=8)
         Index Cond: (((protocol)::text = 'http'::text) AND (host = 1186)
AND (port = -1) AND ((file)::text =
'/terms_of_service.php?mod_id=f53036a5d244b2326a3da1d7169df0ce'::text))
(3 rows)

searchdb=> select count(*) from urls;
  count
---------
 6671277
(1 row)

I'm a bit loss about what could cause this. Is there a way to check the
current database for possible corruption? Regular queries seem to work ok.

I don't have any other software crashes that would indicate hardware
problems.

Jukka Holappa wrote:
> I can't easily reproduce this problem but it happens in every few hours in
> my use.

Can you get a core dump and/or a stack trace out of it? I noted that
you're running Gentoo, so recompiling with --enable-debug, if it's not
compiled with it already, shouldn't be a problem :). --enable-cassert
could be helpful as well, though that does have an impact on performace.

Let me know if you need help compiling or getting a core dump or stack
trace with gdb.

> I'm a bit loss about what could cause this. Is there a way to check the
> current database for possible corruption? Regular queries seem to work ok.

Not really. If the query that crashed works when ran after restart, it's
not likely that corruption caused the crash. You could take a backup
with pg_dump; that at least scans through all data, so if something is
corrupted in a table it will complain.

--
  Heikki Linnakangas
  EnterpriseDB   http://www.enterprisedb.com

-----BEGIN PGP SIGNED MESSAGE-----
Hash: RIPEMD160

Heikki Linnakangas kirjoitti:
> Jukka Holappa wrote:
>> I can't easily reproduce this problem but it happens in every few hours in
>> my use.
>
> Can you get a core dump and/or a stack trace out of it? I noted that
> you're running Gentoo, so recompiling with --enable-debug, if it's not
> compiled with it already, shouldn't be a problem :). --enable-cassert
> could be helpful as well, though that does have an impact on performace.
>
> Let me know if you need help compiling or getting a core dump or stack
> trace with gdb.
>
>> I'm a bit loss about what could cause this. Is there a way to check the
>> current database for possible corruption? Regular queries seem to work ok.
>
> Not really. If the query that crashed works when ran after restart, it's
> not likely that corruption caused the crash. You could take a backup
> with pg_dump; that at least scans through all data, so if something is
> corrupted in a table it will complain.
>

You're right. Dumping out works just fine and it doesn't complain
anything. With my problem case I didn't actually have the data there
that I was querying for.. so the problem could have been with the index
used.

I have been trying to repeat this problem with all the debugging
information on.. and with gdb ready.. but I have been unable to
reproduce the problem.

Because of my mistakes with debugging the postmaster process and perhaps
not always shutting it down properly, I might have caused some problems
myself.. so the results may not be so reliable any more. I'll restore
from my database dump and let it run again without fiddling around too much.

Currently it has some problem with another index for sure as it says:
'ERROR: could not find left sibling in "next_indexing_key"' and when
trying to recreate the url table index that was used in the problematic
query I reported about, I had some errors like:

NOTICE:  ALTER TABLE / ADD UNIQUE will create implicit index
"unique_urls" for table "urls"
ERROR:  xlog flush request 3F/1868BB20 is not satisfied --- flushed only
to 3F/833AF28
CONTEXT:  writing block 4018 of relation 1663/46508/79461

I'll keep trying to produce a clean crash report if at all possible.

- - Jukka
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.7 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFG3Y+mYYWM2XTSwX0RAztjAJ9idxeXULMNUycfpFjN3+oPyJ9VqgCcCZvn
zL1ARtPynJz6NGUuzmQJyyE=
=r/ey
-----END PGP SIGNATURE-----

Jukka Holappa wrote:
> Currently it has some problem with another index for sure as it says:
> 'ERROR: could not find left sibling in "next_indexing_key"' and when
> trying to recreate the url table index that was used in the problematic
> query I reported about, I had some errors like:
>
> NOTICE:  ALTER TABLE / ADD UNIQUE will create implicit index
> "unique_urls" for table "urls"
> ERROR:  xlog flush request 3F/1868BB20 is not satisfied --- flushed only
> to 3F/833AF28
> CONTEXT:  writing block 4018 of relation 1663/46508/79461

The likely cause for that is that the LSN on a data page is corrupted.
It tried to flush the WAL up to location 3F/1868BB20, but there wasn't
that much WAL generated.

It starts to sound more and more like a hardware problem to me. You
mentioned that you have no other software crashes, but I wonder if
you're running anything else on the server that stresses it in any
significant way. I'd suggest checking/replacing the RAM for starters,
that's the most common component to fail, and would cause random
corruption like that. Or if you have spare hardware, switch to another
server and see if the problem goes reappears.

--
  Heikki Linnakangas
  EnterpriseDB   http://www.enterprisedb.com

-----BEGIN PGP SIGNED MESSAGE-----
Hash: RIPEMD160

Heikki Linnakangas kirjoitti:
> Jukka Holappa wrote:
>> Currently it has some problem with another index for sure as it says:
>> 'ERROR: could not find left sibling in "next_indexing_key"' and when
>> trying to recreate the url table index that was used in the problematic
>> query I reported about, I had some errors like:
>>
>> NOTICE:  ALTER TABLE / ADD UNIQUE will create implicit index
>> "unique_urls" for table "urls"
>> ERROR:  xlog flush request 3F/1868BB20 is not satisfied --- flushed only
>> to 3F/833AF28
>> CONTEXT:  writing block 4018 of relation 1663/46508/79461
>
> The likely cause for that is that the LSN on a data page is corrupted.
> It tried to flush the WAL up to location 3F/1868BB20, but there wasn't
> that much WAL generated.
>

Like I said above quoted parts, the likely cause for this problem was my
own mistake by closing down postgresql the wrong way.

> It starts to sound more and more like a hardware problem to me. You
> mentioned that you have no other software crashes, but I wonder if
> you're running anything else on the server that stresses it in any
> significant way. I'd suggest checking/replacing the RAM for starters,
> that's the most common component to fail, and would cause random
> corruption like that. Or if you have spare hardware, switch to another
> server and see if the problem goes reappears.
>

Of course it can be a hardware problem, but I still don't think so.
However, I can't replicate the original problem at this time and
original broken files (with the original problem from the time before my
feeble debugging attempts) are gone at this point anyway.

I think you can close this bug report down as a bogus one and I'll get
back to you if I have something solid to show later on.

- - Jukka
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.7 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFG5l+zYYWM2XTSwX0RA4G0AJ4zjTEd8szpOeZJWuh05vPTg4BYiACfV8gk
HoxfbB/GDMvl7JbaHux6X+Y=
=mVVe
-----END PGP SIGNATURE-----