[Bucardo-general] Performance issues... (4.5.x)
Michelle Sullivan
michelle at sorbs.net
Mon Apr 29 15:39:22 UTC 2013
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/
More information about the Bucardo-general
mailing list