I've got a lot of performance issues related to my DBs and today finally worked out it's down to bucardo... Question is why...?
Take this as an example (the debug from some of my code): Apr 29 09:39:24 bullet reportomaticd[64485]: Parsed message: 0.00472712516784668 seconds Apr 29 09:39:24 bullet reportomaticd[64485]: Loaded SORBS hash: 0.152987003326416 seconds Apr 29 09:39:24 bullet reportomaticd[64485]: Checked spam listing in DB for 181.14.146.218 in: 0.0891940593719482 seconds [older than 12 hours] Apr 29 09:39:24 bullet reportomaticd[64485]: URLS: http://www.w3.org/tr/xhtml1/dtd/xhtml1-transitional.dtd, http://www.w3.org/1999/xhtml, http://www.x.ru/?1=1, http://www.x.ru/?2=2, http://www.x.ru/?3=3, http://www.x.ru/?4=4, http://www.x.ru/?5=5 Apr 29 09:39:24 bullet reportomaticd[64485]: Parsed embedded message: 0.0154738426208496 seconds -- Begin -- Apr 29 09:39:24 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.w3.org/tr/xhtml1/dtd/xhtml1-transitional.dtd --Rollback-- -- Begin -- Apr 29 09:47:26 bullet reportomaticd[64485]: NOTICE: URI: http://www.w3.org/1999/xhtml has ID: 54 Apr 29 09:47:26 bullet reportomaticd[64485]: NOTICE: Host: www.w3.org has ID: 28 Apr 29 09:47:26 bullet reportomaticd[64485]: NOTICE: Inserted link 28 - 54 for URL: http://www.w3.org/1999/xhtml --Commit-- -- Begin -- Apr 29 09:47:33 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.x.ru/?1=1 Apr 29 09:47:33 bullet reportomaticd[64485]: NOTICE: URI: http://www.x.ru/?1=1 has ID: 26898 Apr 29 09:47:33 bullet reportomaticd[64485]: NOTICE: Host: www.x.ru has ID: 49625032 Apr 29 09:47:33 bullet reportomaticd[64485]: NOTICE: Inserted link 49625032 - 26898 for URL: http://www.x.ru/?1=1 --Commit-- -- Begin -- Apr 29 09:47:42 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.x.ru/?2=2 Apr 29 09:47:42 bullet reportomaticd[64485]: NOTICE: URI: http://www.x.ru/?2=2 has ID: 26904 Apr 29 09:47:42 bullet reportomaticd[64485]: NOTICE: Host: www.x.ru has ID: 49625032 Apr 29 09:47:42 bullet reportomaticd[64485]: NOTICE: Inserted link 49625032 - 26904 for URL: http://www.x.ru/?2=2 --Commit-- -- Begin -- Apr 29 09:47:52 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.x.ru/?3=3 Apr 29 09:47:52 bullet reportomaticd[64485]: NOTICE: URI: http://www.x.ru/?3=3 has ID: 26914 Apr 29 09:47:52 bullet reportomaticd[64485]: NOTICE: Host: www.x.ru has ID: 49625032 Apr 29 09:47:53 bullet reportomaticd[64485]: NOTICE: Inserted link 49625032 - 26914 for URL: http://www.x.ru/?3=3 --Commit-- -- Begin -- Apr 29 09:48:04 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.x.ru/?4=4 Apr 29 09:48:04 bullet reportomaticd[64485]: NOTICE: URI: http://www.x.ru/?4=4 has ID: 26923 Apr 29 09:48:04 bullet reportomaticd[64485]: NOTICE: Host: www.x.ru has ID: 49625032 Apr 29 09:48:04 bullet reportomaticd[64485]: NOTICE: Inserted link 49625032 - 26923 for URL: http://www.x.ru/?4=4 --Commit-- -- Begin -- Apr 29 09:48:12 bullet reportomaticd[64485]: NOTICE: Starting with URI: http://www.x.ru/?5=5 Apr 29 09:48:12 bullet reportomaticd[64485]: NOTICE: URI: http://www.x.ru/?5=5 has ID: 26932 Apr 29 09:48:12 bullet reportomaticd[64485]: NOTICE: Host: www.x.ru has ID: 49625032 Apr 29 09:48:12 bullet reportomaticd[64485]: NOTICE: Inserted link 49625032 - 26932 for URL: http://www.x.ru/?5=5 --Commit-- Apr 29 09:48:22 bullet reportomaticd[64485]: Inserted 7 URLS in 66.1498029232025 seconds Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.w3.org/tr/xhtml1/dtd/xhtml1-transitional.dtd Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.w3.org/1999/xhtml Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.x.ru/?1=1 Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.x.ru/?2=2 Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.x.ru/?3=3 Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.x.ru/?4=4 Apr 29 09:48:28 bullet reportomaticd[64485]: URI: http://www.x.ru/?5=5 -- Begin -- Apr 29 09:49:10 bullet reportomaticd[64485]: Inserted message: 113.451152086258 seconds -- Commit -- Now, the NOTICE begin/commit block is in a looped call, specifically: foreach my $url (@url) { $sorbs->dbquery("SELECT inserturiandhost(?);", $url); } The function itself is very simple as well: CREATE OR REPLACE FUNCTION inserturiandhost(uri VARCHAR) RETURNS VARCHAR AS $$ DECLARE urid BIGINT; hid BIGINT; host VARCHAR; BEGIN LOOP -- First insert the URI, then get the hostname, then INSERT that -- Net result is that even if some fail on the first loop it will -- keep looping until all parts are inserted -- will return just the hostname when successful. RAISE NOTICE 'Starting with URI: %', uri; SELECT gethostfromuri(uri) INTO host; IF host IS NULL THEN RAISE EXCEPTION 'Host is null for %', uri; END IF; SELECT get_urisid(uri) INTO urid; RAISE NOTICE 'URI: % has ID: %', uri, urid; IF found THEN SELECT get_hostsid(host, 0, 0, 0) INTO hid; RAISE NOTICE 'Host: % has ID: %', host, hid; IF found THEN BEGIN INSERT INTO hosts2uris (hostsid, urisid) VALUES (hid, urid); RAISE NOTICE 'Inserted link % - % for URL: %', hid, urid, uri; EXCEPTION WHEN unique_violation THEN -- This shouldn't happen, but we catch it -- if it does as we don't want to abort the -- transaction as a whole. END; RETURN hid; END IF; END IF; -- Something went wrong, so loop back and try again.. END LOOP; END; $$ LANGUAGE plpgsql; You can see that after each operation the is a RAISE NOTICE and at the start you can see the 'Starting' message.. everything happens in a few milliseconds.. until it gets to the end of the function, which is when the transaction is committed and therefore the replication triggers are processed... Why does it take 8-10 seconds per commit? How can I go through debugging bucardo to find out what the heck is causing it? Steps taken so far: Removed replication triggers from the tables: commits take: 35 ms per URL Added triggers, and ran "validate all", truncated tables used.. commit takes: 8-10s per URL VACUUM ANALYSEd bucardo.bucardo_delta and bucardo.bucardo_track tables.... commit takes: 8-10s per URL REINDEX TABLEd bucardo.bucardo_delta and bucardo.bucardo_track tables.... commit takes: 8-10s per URL Any other suggestions (especially as it's affecting lots of other tables as well) I suspect this is locking as my lock counts seem to go higher and higher... -- Michelle Sullivan http://www.mhix.org/ _______________________________________________ Bucardo-general mailing list [email protected] https://mail.endcrypt.com/mailman/listinfo/bucardo-general
