You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@manifoldcf.apache.org by Roman Šitina <ro...@sitina.cz> on 2015/08/31 17:17:41 UTC
Postgres performance issue
Hello,
we can see a lot of these line in our logs when we restart a job.
ARN 2015-08-31 13:28:16,789 (Set priority thread) -
WARN 2015-08-31 13:32:43,203 (Startup thread) - Found a long-running
query (181072 ms): [UPDATE jobqueue SET
failcount=NULL,checktime=?,checkaction=?,failtime=NULL WHERE jobid=?
AND (status=? OR status=?)]
WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 0: '0'
WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 1: 'R'
WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 2: '1440693578140'
WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 3: 'G'
WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 4: 'P'
WARN 2015-08-31 13:32:43,204 (Startup thread) - Plan: Seq Scan on
jobqueue (cost=0.00..118691.83 rows=3304553 width=244)
WARN 2015-08-31 13:32:43,204 (Startup thread) - Plan: Filter:
((jobid = 1440693578140::bigint) AND ((status = 'G'::bpchar) OR
(status = 'P'::bpchar)))
WARN 2015-08-31 13:32:43,204 (Startup thread) -
WARN 2015-08-31 13:32:43,209 (Startup thread) - Stats: n_distinct=3.0
most_common_vals={P,G,C}
most_common_freqs={0.96696669,0.027633334,0.0054000001}
WARN 2015-08-31 13:32:43,209 (Startup thread) -
WARN 2015-08-31 13:40:53,834 (Set priority thread) - Found a
long-running query (74803 ms): [SELECT needpriority FROM jobqueue
WHERE id=? FOR UPDATE]
WARN 2015-08-31 13:40:53,834 (Startup thread) - Found a long-running
query (420589 ms): [UPDATE jobqueue SET
failcount=NULL,checktime=?,checkaction=?,failtime=NULL WHERE jobid=?
AND (status=? OR status=?)]
WARN 2015-08-31 13:40:53,835 (Set priority thread) - Parameter 0:
'1440696241299'
WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 0: '0'
WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 1: 'R'
WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 2: '1440693578140'
WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 3: 'G'
WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 4: 'P'
WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Index Scan
using jobqueue_pkey on jobqueue (cost=0.00..9.03 rows=1 width=8)
(actual time=0.012..0.035 rows=1 loops=1)
WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Index
Cond: (id = 1440696241299::bigint)
WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Total
runtime: 0.060 ms
WARN 2015-08-31 13:40:53,836 (Set priority thread) -
WARN 2015-08-31 13:40:53,837 (Startup thread) - Plan: Seq Scan on
jobqueue (cost=0.00..152542.58 rows=1732985 width=244)
WARN 2015-08-31 13:40:53,838 (Startup thread) - Plan: Filter:
((jobid = 1440693578140::bigint) AND ((status = 'G'::bpchar) OR
(status = 'P'::bpchar)))
WARN 2015-08-31 13:40:53,838 (Startup thread) -
WARN 2015-08-31 13:40:53,841 (Set priority thread) - Stats:
n_distinct=3.0 most_common_vals={P,G,C}
most_common_freqs={0.91589999,0.071966663,0.012133333}
WARN 2015-08-31 13:40:53,841 (Set priority thread) -
WARN 2015-08-31 13:40:53,842 (Startup thread) - Stats: n_distinct=3.0
most_common_vals={P,G,C}
most_common_freqs={0.91589999,0.071966663,0.012133333}
WARN 2015-08-31 13:40:53,842 (Startup thread) -
ERROR 2015-08-31 13:40:57,313 (Startup thread) - Exception tossed:
ERROR: deadlock detected
Detail: Process 1152 waits for ShareLock on transaction 458210;
blocked by process 7617.
Process 7617 waits for ShareLock on transaction 458208; blocked by process 1152.
Hint: See server log for query details.
org.apache.manifoldcf.core.interfaces.ManifoldCFException: ERROR:
deadlock detected
Detail: Process 1152 waits for ShareLock on transaction 458210;
blocked by process 7617.
Process 7617 waits for ShareLock on transaction 458208; blocked by process 1152.
Hint: See server log for query details.
at org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.reinterpretException(DBInterfacePostgreSQL.java:631)
at org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.performModification(DBInterfacePostgreSQL.java:663)
at org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.performUpdate(DBInterfacePostgreSQL.java:254)
- Version of Postgres: 8.4.20
- Machine: Amazon r3.xlarge - 4 CPU, 30.5 GiB Mem, 1x 80 GB storage
- Number of records in jobqueue is around 1.7 million.
- Job synchronisation is over Zookeeper.
- I set all the recommended setting found here:
https://manifoldcf.apache.org/release/trunk/en_US/how-to-build-and-deploy.html#Configuring+a+PostgreSQL+database
- Vacuum and reindex is scheduled daily.
Are these query times as expected? Is there anything we can tweak to
speed up Postgres? What about these deadlocks - is that something
which happens time to time?
Thanks for your hints
Roman
Re: Postgres performance issue
Posted by Karl Wright <da...@gmail.com>.
Hi,
When you restart a job, or restart the agents process, ManifoldCF has to
bash the states of all the jobqueue records to correct values. This is
unfortunately time consuming. But I have found no way to avoid it.
Thanks,
Karl
On Mon, Aug 31, 2015 at 11:17 AM, Roman Šitina <ro...@sitina.cz> wrote:
> Hello,
>
> we can see a lot of these line in our logs when we restart a job.
>
> ARN 2015-08-31 13:28:16,789 (Set priority thread) -
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Found a long-running
> query (181072 ms): [UPDATE jobqueue SET
> failcount=NULL,checktime=?,checkaction=?,failtime=NULL WHERE jobid=?
> AND (status=? OR status=?)]
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 0: '0'
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 1: 'R'
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 2:
> '1440693578140'
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 3: 'G'
> WARN 2015-08-31 13:32:43,203 (Startup thread) - Parameter 4: 'P'
> WARN 2015-08-31 13:32:43,204 (Startup thread) - Plan: Seq Scan on
> jobqueue (cost=0.00..118691.83 rows=3304553 width=244)
> WARN 2015-08-31 13:32:43,204 (Startup thread) - Plan: Filter:
> ((jobid = 1440693578140::bigint) AND ((status = 'G'::bpchar) OR
> (status = 'P'::bpchar)))
> WARN 2015-08-31 13:32:43,204 (Startup thread) -
> WARN 2015-08-31 13:32:43,209 (Startup thread) - Stats: n_distinct=3.0
> most_common_vals={P,G,C}
> most_common_freqs={0.96696669,0.027633334,0.0054000001}
> WARN 2015-08-31 13:32:43,209 (Startup thread) -
> WARN 2015-08-31 13:40:53,834 (Set priority thread) - Found a
> long-running query (74803 ms): [SELECT needpriority FROM jobqueue
> WHERE id=? FOR UPDATE]
> WARN 2015-08-31 13:40:53,834 (Startup thread) - Found a long-running
> query (420589 ms): [UPDATE jobqueue SET
> failcount=NULL,checktime=?,checkaction=?,failtime=NULL WHERE jobid=?
> AND (status=? OR status=?)]
> WARN 2015-08-31 13:40:53,835 (Set priority thread) - Parameter 0:
> '1440696241299'
> WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 0: '0'
> WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 1: 'R'
> WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 2:
> '1440693578140'
> WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 3: 'G'
> WARN 2015-08-31 13:40:53,835 (Startup thread) - Parameter 4: 'P'
> WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Index Scan
> using jobqueue_pkey on jobqueue (cost=0.00..9.03 rows=1 width=8)
> (actual time=0.012..0.035 rows=1 loops=1)
> WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Index
> Cond: (id = 1440696241299::bigint)
> WARN 2015-08-31 13:40:53,836 (Set priority thread) - Plan: Total
> runtime: 0.060 ms
> WARN 2015-08-31 13:40:53,836 (Set priority thread) -
> WARN 2015-08-31 13:40:53,837 (Startup thread) - Plan: Seq Scan on
> jobqueue (cost=0.00..152542.58 rows=1732985 width=244)
> WARN 2015-08-31 13:40:53,838 (Startup thread) - Plan: Filter:
> ((jobid = 1440693578140::bigint) AND ((status = 'G'::bpchar) OR
> (status = 'P'::bpchar)))
> WARN 2015-08-31 13:40:53,838 (Startup thread) -
> WARN 2015-08-31 13:40:53,841 (Set priority thread) - Stats:
> n_distinct=3.0 most_common_vals={P,G,C}
> most_common_freqs={0.91589999,0.071966663,0.012133333}
> WARN 2015-08-31 13:40:53,841 (Set priority thread) -
> WARN 2015-08-31 13:40:53,842 (Startup thread) - Stats: n_distinct=3.0
> most_common_vals={P,G,C}
> most_common_freqs={0.91589999,0.071966663,0.012133333}
> WARN 2015-08-31 13:40:53,842 (Startup thread) -
> ERROR 2015-08-31 13:40:57,313 (Startup thread) - Exception tossed:
> ERROR: deadlock detected
> Detail: Process 1152 waits for ShareLock on transaction 458210;
> blocked by process 7617.
> Process 7617 waits for ShareLock on transaction 458208; blocked by process
> 1152.
> Hint: See server log for query details.
> org.apache.manifoldcf.core.interfaces.ManifoldCFException: ERROR:
> deadlock detected
> Detail: Process 1152 waits for ShareLock on transaction 458210;
> blocked by process 7617.
> Process 7617 waits for ShareLock on transaction 458208; blocked by process
> 1152.
> Hint: See server log for query details.
> at
> org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.reinterpretException(DBInterfacePostgreSQL.java:631)
> at
> org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.performModification(DBInterfacePostgreSQL.java:663)
> at
> org.apache.manifoldcf.core.database.DBInterfacePostgreSQL.performUpdate(DBInterfacePostgreSQL.java:254)
>
>
> - Version of Postgres: 8.4.20
> - Machine: Amazon r3.xlarge - 4 CPU, 30.5 GiB Mem, 1x 80 GB storage
>
> - Number of records in jobqueue is around 1.7 million.
>
> - Job synchronisation is over Zookeeper.
>
> - I set all the recommended setting found here:
>
> https://manifoldcf.apache.org/release/trunk/en_US/how-to-build-and-deploy.html#Configuring+a+PostgreSQL+database
>
> - Vacuum and reindex is scheduled daily.
>
> Are these query times as expected? Is there anything we can tweak to
> speed up Postgres? What about these deadlocks - is that something
> which happens time to time?
>
> Thanks for your hints
>
> Roman
>