[freeside-users] Error with 1.9cvs continues

[Timothy Butkiewicz]

Update on the Error with 1.9cvs continues

Still battling with this issue. I started logging queries that take
longer than 100ms. The logs fill pretty quickly with items such as the
following:

I see indexes on the following in the database, but appears that
postgres really grinds on these. I let the browser sit on day on pulling
up a single customer and it completed about 4 hours later and displayed
the customer info. Any help is surely appreciated! I've tuned and
retuned apache and postgres but finger seems to be pointing to the
queries in the db.  


Jan 16 01:10:01 srvr postgres[21980]: [116-1] LOG:  duration: 200.204 ms
bind dbdpg_p21837_394087: SELECT * FROM cust_bill_pay WHERE paynum = $1
Jan 16 01:10:01 srvr postgres[21980]: [116-2] DETAIL:  parameters: $1 =
'1187'
Jan 16 01:10:02 srvr postgres[21980]: [117-1] LOG:  duration: 200.522 ms
parse dbdpg_p21837_394237: SELECT * FROM cust_pay_refund WHERE paynum =
$1
Jan 16 01:10:02 srvr postgres[21980]: [118-1] LOG:  duration: 200.425 ms
parse dbdpg_p21837_394363: SELECT * FROM cust_bill_pay WHERE paynum = $1
Jan 16 01:10:03 srvr postgres[21980]: [119-1] LOG:  duration: 200.574 ms
parse dbdpg_p21837_394486: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:03 srvr postgres[21980]: [120-1] LOG:  duration: 260.554 ms
parse dbdpg_p21837_394604: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:04 srvr postgres[21980]: [121-1] LOG:  duration: 200.518 ms
parse dbdpg_p21837_394747: SELECT * FROM cust_credit_bill WHERE invnum =
$1
Jan 16 01:10:04 srvr postgres[21980]: [122-1] LOG:  duration: 187.049 ms
parse dbdpg_p21837_394913: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:05 srvr postgres[21980]: [123-1] LOG:  duration: 216.543 ms
parse dbdpg_p21837_395060: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:06 srvr postgres[21980]: [124-1] LOG:  duration: 200.522 ms
parse dbdpg_p21837_395401: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:07 srvr postgres[21980]: [125-1] LOG:  duration: 200.167 ms
bind dbdpg_p21837_395565: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:07 srvr postgres[21980]: [125-2] DETAIL:  parameters: $1 =
'31295'
Jan 16 01:10:08 srvr postgres[21980]: [126-1] LOG:  duration: 431.371 ms
execute dbdpg_p21837_395830: SELECT * FROM conf WHERE ( agentnum IS NULL
) AND name = $1
Jan 16 01:10:08 srvr postgres[21980]: [126-2] DETAIL:  parameters: $1 =
'encryption'
Jan 16 01:10:08 srvr postgres[21980]: [127-1] LOG:  duration: 100.434 ms
parse dbdpg_p21837_395979: SELECT * FROM cust_bill_pay WHERE paynum = $1
Jan 16 01:10:09 srvr postgres[21980]: [128-1] LOG:  duration: 100.443 ms
parse dbdpg_p21837_396090: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:09 srvr postgres[21980]: [129-1] LOG:  duration: 100.190 ms
statement: DEALLOCATE dbdpg_p21837_396238
Jan 16 01:10:10 srvr postgres[21980]: [130-1] LOG:  duration: 100.537 ms
parse dbdpg_p21837_396377: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:10 srvr postgres[21980]: [131-1] LOG:  duration: 100.516 ms
parse dbdpg_p21837_396510: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:11 srvr postgres[21980]: [132-1] LOG:  duration: 100.471 ms
parse dbdpg_p21837_396825: SELECT * FROM cust_pay_refund WHERE paynum =
$1
Jan 16 01:10:11 srvr postgres[21980]: [133-1] LOG:  duration: 100.243 ms
bind dbdpg_p21837_396988: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:11 srvr postgres[21980]: [133-2] DETAIL:  parameters: $1 =
'encryption'
Jan 16 01:10:12 srvr postgres[21980]: [134-1] LOG:  duration: 100.486 ms
parse dbdpg_p21837_397125: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:12 srvr postgres[21980]: [135-1] LOG:  duration: 100.506 ms
parse dbdpg_p21837_397264: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:14 srvr postgres[21980]: [136-1] LOG:  duration: 168.270 ms
statement: DEALLOCATE dbdpg_p21837_397612
Jan 16 01:10:14 srvr postgres[21980]: [137-1] LOG:  duration: 124.467 ms
parse dbdpg_p21837_397754: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:14 srvr postgres[21980]: [138-1] LOG:  duration: 104.135 ms
execute dbdpg_p21837_397899: SELECT * FROM cust_bill_pay WHERE paynum =
$1
Jan 16 01:10:14 srvr postgres[21980]: [138-2] DETAIL:  parameters: $1 =
'32558'
Jan 16 01:10:15 srvr postgres[21980]: [139-1] LOG:  duration: 100.184 ms
statement: DEALLOCATE dbdpg_p21837_397982
Jan 16 01:10:15 srvr postgres[21980]: [140-1] LOG:  duration: 120.415 ms
parse dbdpg_p21837_398130: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:16 srvr postgres[21980]: [141-1] LOG:  duration: 156.392 ms
parse dbdpg_p21837_398407: SELECT * FROM cust_bill_pay WHERE paynum = $1
Jan 16 01:10:17 srvr postgres[21980]: [142-1] LOG:  duration: 136.166 ms
execute dbdpg_p21837_398568: SELECT * FROM conf WHERE ( agentnum IS NULL
) AND name = $1
Jan 16 01:10:17 srvr postgres[21980]: [142-2] DETAIL:  parameters: $1 =
'encryption'
Jan 16 01:10:18 srvr postgres[21980]: [143-1] LOG:  duration: 164.417 ms
parse dbdpg_p21837_398865: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:18 srvr postgres[21980]: [144-1] LOG:  duration: 164.296 ms
parse dbdpg_p21837_398993: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:19 srvr postgres[21980]: [145-1] LOG:  duration: 156.368 ms
parse dbdpg_p21837_399143: SELECT * FROM cust_credit_bill WHERE invnum =
$1
Jan 16 01:10:19 srvr postgres[21980]: [146-1] LOG:  duration: 148.425 ms
parse dbdpg_p21837_399275: SELECT * FROM cust_bill_pay WHERE paynum = $1
Jan 16 01:10:20 srvr postgres[21980]: [147-1] LOG:  duration: 144.437 ms
parse dbdpg_p21837_399450: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:20 srvr postgres[21980]: [148-1] LOG:  duration: 156.423 ms
parse dbdpg_p21837_399608: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:21 srvr postgres[21980]: [149-1] LOG:  duration: 132.164 ms
execute dbdpg_p21837_399746: SELECT * FROM conf WHERE ( agentnum IS NULL
) AND name = $1
Jan 16 01:10:21 srvr postgres[21980]: [149-2] DETAIL:  parameters: $1 =
'encryption'
Jan 16 01:10:21 srvr postgres[21980]: [150-1] LOG:  duration: 152.189 ms
statement: DEALLOCATE dbdpg_p21837_399906
Jan 16 01:10:21 srvr postgres[21980]: [151-1] LOG:  duration: 132.098 ms
bind dbdpg_p21837_400025: SELECT * FROM cust_bill_pay WHERE invnum = $1
Jan 16 01:10:21 srvr postgres[21980]: [151-2] DETAIL:  parameters: $1 =
'42967'
Jan 16 01:10:22 srvr postgres[21980]: [152-1] LOG:  duration: 160.267 ms
parse dbdpg_p21837_400157: SELECT * FROM cust_pay_refund WHERE paynum =
$1
Jan 16 01:10:23 srvr postgres[21980]: [153-1] LOG:  duration: 316.385 ms
parse dbdpg_p21837_400458: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:24 srvr postgres[21980]: [154-1] LOG:  duration: 140.186 ms
statement: DEALLOCATE dbdpg_p21837_400574
Jan 16 01:10:24 srvr postgres[21980]: [155-1] LOG:  duration: 136.427 ms
parse dbdpg_p21837_400715: SELECT * FROM cust_credit_bill WHERE invnum =
$1
Jan 16 01:10:25 srvr postgres[21980]: [156-1] LOG:  duration: 132.203 ms
bind dbdpg_p21837_401024: SELECT * FROM conf WHERE ( agentnum IS NULL )
AND name = $1
Jan 16 01:10:25 srvr postgres[21980]: [156-2] DETAIL:  parameters: $1 =
'encryption'
Jan 16 01:10:26 srvr postgres[21980]: [157-1] LOG:  duration: 172.397 ms
parse dbdpg_p21837_401213: SELECT * FROM cust_pay_refund WHERE paynum =
$1
Jan 16 01:10:26 srvr postgres[21980]: [158-1] LOG:  duration: 136.186 ms
statement: DEALLOCATE dbdpg_p21837_401344