Hi ak0ska, So I've been spending the last 2 days trying all kinds of things to replicate your constraint violation problem and I still am getting nowhere with it. I've been speaking to all kinds of smart people and we believe its some sort of lock and/or transactional mode problem but none of my testing can replicate it.
My latest test was something like: https://gist.github.com/kbarber/5157836 But with all that preparation and load simulation I still couldn't replicate it :-(. I think I need more data from you ... in this case, a statement log. Now a statement log can be pretty heavy, so if we can get the data surrounding a GC only that should be enough - however I anticipate it might reduce some performance so if you're apprehensive about doing it in production I fully understand. I'm just running out of ideas, and without more data I may have trouble coming to a conclusion. Anyway, if at all possible the instructions for enabling this are as follows: * Go to your postgresql.conf file (On RHEL 6 this is usually located in /var/lib/pgsql/data) * Add/modify the entries: log_statement = 'all' log_line_prefix = '%m PID[%p] SID[%c] VTID[%v] TID[%x] ' * Restart postgresql * Logs should go to: /var/lib/pgsql/data/pg_log The closer you can do this to being set _just before_ a GC run the better, as it will reduce the amount of time this setting needs to be on. Once you have a GC run and a subsequent constraint logged you should be able to turn it off. Don't worry about PuppetDB during these cases, it retries the database so if you can take the small hit with queries the outage should be quick while you switch off/on the setting (and be mindful that catalogs/facts/reports submissions will get queued, queries of course will fail during that short time during DB restart). Now the data itself is going to obviously contain private items, so if you prefer to send it to me privately thats fine (contact me off this list if so). Otherwise, it might need some scrubbing. So the concern I have with your issue, even though it doesn't stop a catalog from being submitted - is that you're seeing a 'block' when those two catalogs get submitted which makes me fear that data doesn't get populated until _after_ the GC is complete. This is a concern because we don't want data to be delayed like this. If this wasn't the case we could happily let it fail and retry, ultimately the data isn't lost, but we should be able to process data within reasonable time limits without you have to worry about database GC slowing things down. Now in regards to your performance, we are going to keep looking into the results you gave us. Looking at your settings Deepak and I think you probably need to increase at least work_mem to 16MB and maintenance_work_mem to 32MB (this is used during vacuum) the main item being work_mem here really. These are reasonable changes we've seen other users apply with success, but alone they probably won't solve your issue - it would be good to just get you working using higher values for these. I'm very curious to understand the disk IO for your systems also. What are the nature of the disks where your database is located? Are they SCSI/SATA/FC or otherwise? What filesystem type are you using? Can you give me any other details you might find interesting? What are the results of the command: iostat -k 5 A few samples of the run would be useful to see, so we can understand the average disk IO going on here. FYI To give you an idea of what we _should_ be seeing for say, just one of your queries, here is a query on a Centos 5.8 box (running just postgresql 8.1 actually): puppetdb=# 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; QUERY PLAN ------------------------------------------------------------------------------------------------- --------------------------------------------------- Aggregate (cost=91792.54..91792.55 rows=1 width=0) (actual time=2611.872..2611.872 rows=1 loops =1) -> HashAggregate (cost=91737.14..91761.76 rows=2462 width=41) (actual time=2606.507..2609.48 9 rows=5478 loops=1) -> Hash Join (cost=184.36..90322.32 rows=565926 width=41) (actual time=7.060..2072.000 rows=867847 loops=1) Hash Cond: ((cr.catalog)::text = (cc.catalog)::text) -> Seq Scan on catalog_resources cr (cost=0.00..80139.47 rows=867847 width=82) ( actual time=0.021..1119.260 rows=867847 loops=1) -> Hash (cost=159.17..159.17 rows=2015 width=41) (actual time=7.032..7.032 rows= 2195 loops=1) -> Hash Join (cost=62.34..159.17 rows=2015 width=41) (actual time=2.438..5 .830 rows=2195 loops=1) Hash Cond: (cc.certname = c.name) -> Seq Scan on certname_catalogs cc (cost=0.00..65.79 rows=2179 widt h=50) (actual time=0.005..0.908 rows=2195 loops=1) -> Hash (cost=37.15..37.15 rows=2015 width=9) (actual time=2.427..2. 427 rows=2195 loops=1) -> Seq Scan on certnames c (cost=0.00..37.15 rows=2015 width=9 ) (actual time=0.008..1.088 rows=2195 loops=1) Filter: (deactivated IS NULL) Total runtime: 2611.935 ms (13 rows) As you can see, 2 seconds on my box and 475 seconds on yours - the difference is just too large to be considered a normal discrepancy :-). Be mindful, this is on data that represents 2000 nodes ... so its not like my tables are smaller then yours (at least not drastically), however I do notice the number of resources is much higher so I'm going to try and replicate that. For now, I'm going to ponder more on your performance as I believe that affects you the most - so let us get back to you with more updates. If you can give me any details as I've requested for now that would be appreciated. ken. On Wed, Mar 13, 2013 at 2:00 AM, ak0ska <akos.he...@gmail.com> wrote: > Hello Deepak, > > Here are the queries you asked for: > > >> >> 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. >> > > QUERY > PLAN > ------------------------------------------------------------------------------------------------------------------------------------------------------- > Aggregate (cost=3132186.09..3132186.10 rows=1 width=0) (actual > time=348426.375..348426.376 rows=1 loops=1) > -> Hash Join (cost=247.37..3096532.80 rows=14261314 width=0) (actual > time=24059.151..348255.933 rows=1604253 loops=1) > Hash Cond: ((cr.catalog)::text = (cc.catalog)::text) > -> Seq Scan on catalog_resources cr (cost=0.00..2871450.86 > rows=16444286 width=41) (actual time=24053.542..347250.967 rows=2107982 > loops=1) > -> Hash (cost=216.42..216.42 rows=2476 width=41) (actual > time=5.555..5.555 rows=2476 loops=1) > -> Hash Join (cost=94.84..216.42 rows=2476 width=41) > (actual time=1.850..4.555 rows=2476 loops=1) > Hash Cond: (cc.certname = c.name) > -> Seq Scan on certname_catalogs cc (cost=0.00..82.55 > rows=2855 width=62) (actual time=0.010..0.941 rows=2855 loops=1) > -> Hash (cost=63.71..63.71 rows=2490 width=21) > (actual time=1.818..1.818 rows=2490 loops=1) > -> Seq Scan on certnames c (cost=0.00..63.71 > rows=2490 width=21) (actual time=0.013..0.823 rows=2490 loops=1) > Filter: (deactivated IS NULL) > Total runtime: 348446.364 ms > (12 rows) > > > > >> 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); >> > > > QUERY PLAN > ------------------------------------------------------------------------------------------------------------------------------------------------------------------------ > Nested Loop Anti Join (cost=0.00..1710681.18 rows=360492 width=126) > (actual time=1967.182..1967.182 rows=0 loops=1) > -> Seq Scan on resource_params (cost=0.00..13249.23 rows=389623 > width=126) (actual time=0.013..76.403 rows=389693 loops=1) > -> Index Scan using idx_catalog_resources_resource on catalog_resources > cr (cost=0.00..21429.14 rows=5291 width=41) (actual time=0.004..0.004 > rows=1 loops=389693) > Index Cond: ((cr.resource)::text = > (resource_params.resource)::text) > Total runtime: 1967.253 ms > (5 rows) > > > >> 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; >> > > QUERY PLAN > ------------------------------------------------------------------------------------------------------------------------------------------------------------- > Aggregate (cost=3129997.71..3129997.72 rows=1 width=0) (actual > time=474369.420..474369.420 rows=1 loops=1) > -> HashAggregate (cost=3129927.78..3129958.86 rows=3108 width=41) > (actual time=474351.730..474365.144 rows=49466 loops=1) > -> Hash Join (cost=248.48..3094726.38 rows=14080561 width=41) > (actual time=21536.467..473678.479 rows=1604237 loops=1) > Hash Cond: ((cr.catalog)::text = (cc.catalog)::text) > -> Seq Scan on catalog_resources cr (cost=0.00..2871450.86 > rows=16444286 width=82) (actual time=21531.355..472692.303 rows=1934212 > loops=1) > -> Hash (cost=217.36..217.36 rows=2490 width=41) (actual > time=5.071..5.071 rows=2476 loops=1) > -> Hash Join (cost=94.84..217.36 rows=2490 width=41) > (actual time=1.700..4.048 rows=2476 loops=1) > Hash Cond: (cc.certname = c.name) > -> Seq Scan on certname_catalogs cc > (cost=0.00..83.08 rows=2908 width=62) (actual time=0.010..0.603 rows=2855 > loops=1) > -> Hash (cost=63.71..63.71 rows=2490 width=21) > (actual time=1.670..1.670 rows=2490 loops=1) > -> Seq Scan on certnames c > (cost=0.00..63.71 rows=2490 width=21) (actual time=0.014..0.785 rows=2490 > loops=1) > Filter: (deactivated IS NULL) > Total runtime: 474370.129 ms > (13 rows) > > >> >> And finally, can you give us a dump of your database settings? You can do >> this from within psql by doing "SHOW ALL;" > > > http://pastebin.com/raw.php?i=HfhqfVa4 > > Thank you for your help! > > Cheers, > > ak0ska > > > -- > 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.
