On Tue, Mar 12, 2013 at 6:38 AM, ak0ska <akos.he...@gmail.com> wrote:
> I think my previous comment just got lost. > > So, I cut three occurrences of this error from the database log and the > corresponding part from the puppetdb log. I removed the hostnames, I hope > it's still sensible: http://pastebin.com/yvyBDWQE > The unversioned api warnings are not from the masters. They're from an > older version of the puppetdbquery library, and the puppetdb module's > puppetdb_conn_validator function. > Apart from that, there are 2 kinds of slow queries that appear in the logs: > > 2013-03-12 11:54:37,149 WARN [qtp1992135396-3384] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 452.2331 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 11:54:42,035 WARN [qtp1992135396-3391] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 452.0072 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 11:55:43,146 WARN [qtp1992135396-3392] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 441.2548 seconds; Query: >> SELECT COUNT(*) AS c FROM (SELECT DISTINCT resource FROM catalog_resources >> cr, certname_catalogs cc, certnames c WHERE cr.catalog=cc.catalog AND >> cc.certname=c.name AND c.deactivated IS NULL) r; Query Params: >> 2013-03-12 12:00:56,492 WARN [qtp1992135396-3402] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 433.4503 seconds; Query: >> SELECT COUNT(*) AS c FROM (SELECT DISTINCT resource FROM catalog_resources >> cr, certname_catalogs cc, certnames c WHERE cr.catalog=cc.catalog AND >> cc.certname=c.name AND c.deactivated IS NULL) r; Query Params: >> 2013-03-12 12:03:30,933 WARN [qtp1992135396-3392] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 467.7872 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 12:04:18,225 WARN [qtp1992135396-3396] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 472.9386 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 12:54:49,042 WARN [qtp1992135396-3463] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 464.9721 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 12:57:58,791 WARN [qtp1992135396-3482] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 460.9083 seconds; Query: >> SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, >> certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND >> c.deactivated IS NULL; Query Params: >> 2013-03-12 12:57:58,803 WARN [qtp1992135396-3490] [jdbc.internal] Query >> slower than 10s threshold: actual execution time: 460.7699 seconds; Query: >> SELECT COUNT(*) AS c FROM (SELECT DISTINCT resource FROM catalog_resources >> cr, certname_catalogs cc, certnames c WHERE cr.catalog=cc.catalog AND >> cc.certname=c.name AND c.deactivated IS NULL) r; Query Params: >> > > > Can you fire up psql, point it at your puppetdb database, and run "EXPLAIN ANALYZE SELECT COUNT(*) AS c FROM certname_catalogs cc, catalog_resources cr, certnames c WHERE cc.catalog=cr.catalog AND c.name=cc.certname AND c.deactivated IS NULL;"? That will profile the query, and we can see where the problem is. Also worth examining is the GC query (modified to be non-destructive): EXPLAIN ANALYZE SELECT * FROM resource_params WHERE NOT EXISTS (SELECT * FROM catalog_resources cr WHERE cr.resource=resource_params.resource); And the resource duplication query: EXPLAIN ANALYZE SELECT COUNT(*) AS c FROM (SELECT DISTINCT resource FROM catalog_resources cr, certname_catalogs cc, certnames c WHERE cr.catalog=cc.catalog AND cc.certname=c.name AND c.deactivated IS NULL) r; And finally, can you give us a dump of your database settings? You can do this from within psql by doing "SHOW ALL;" > I didn't see any javascript errors on the dashboard, the queries are just > slow. I ran the resource duplication query manually on the puppetdb machine: > > time curl -X GET -H 'Accept: application/json' > http://[puppetdbip]:8080/v2/metrics/mbean/com.puppetlabs.puppetdb.query.population:type=default,name=pct-resource-dupes >> -v >> * About to connect() to [puppetdbip] port 8080 (#0) >> * Trying [puppetdbip]... connected >> * Connected to [puppetdbip] ([puppetdbip]) port 8080 (#0) >> > GET >> /v2/metrics/mbean/com.puppetlabs.puppetdb.query.population:type=default,name=pct-resource-dupes >> HTTP/1.1 >> > User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/ >> 3.13.6.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2 >> > Host: [puppetdbip]:8080 >> > Accept: application/json >> > >> < HTTP/1.1 200 OK >> < Date: Tue, 12 Mar 2013 11:55:34 GMT >> < Content-Type: application/json;charset=ISO-8859-1 >> < Content-Length: 34 >> < Server: Jetty(7.x.y-SNAPSHOT) >> < >> { >> "Value" : 0.9691941482891232 >> * Connection #0 to host [puppetdbip] left intact >> * Closing connection #0 >> } >> real 16m57.604s >> user 0m0.012s >> sys 0m0.025s >> > > > On Monday, March 11, 2013 7:04:05 PM UTC+1, Ken Barber wrote: >> >> > After dropping the obsolete index, and rebuilding the others, the >> database >> > is now ~ 30 GB. We still get the constraint violation errors when >> garbage >> > collection starts. >> >> Okay - can you please send me the puppetdb.log entry that shows the >> exception? Including surrounding messages? >> >> > Also the "Resources" and "Resource duplication" values on the dashboard >> are >> > still question marks, so those queries probably time out. >> >> Again, this should have a corresponding exception in puppetdb.log or >> at least a slow query being logged, also - can you pull up the >> javascript console and see what error are produced in relation to that >> error. >> >> > Although these errors don't have a big impact on performance (at least >> for >> > now), could they be a sign of something not being quite ok? Shall we >> still >> > consider rebuilding the database? >> >> Not sure, I need more data. >> >> ken. >> > -- > You received this message because you are subscribed to the Google Groups > "Puppet Users" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to puppet-users+unsubscr...@googlegroups.com. > To post to this group, send email to puppet-users@googlegroups.com. > Visit this group at http://groups.google.com/group/puppet-users?hl=en. > For more options, visit https://groups.google.com/groups/opt_out. > > > -- You received this message because you are subscribed to the Google Groups "Puppet Users" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-users+unsubscr...@googlegroups.com. To post to this group, send email to puppet-users@googlegroups.com. Visit this group at http://groups.google.com/group/puppet-users?hl=en. For more options, visit https://groups.google.com/groups/opt_out.
