[tor-bugs] #17488 [ExoneraTor]: ExoneraTor hangs forever on old known-positive test
Tor Bug Tracker & Wiki
blackhole at torproject.org
Thu Nov 5 12:31:25 UTC 2015
#17488: ExoneraTor hangs forever on old known-positive test
------------------------+--------------------------
Reporter: starlight | Owner: karsten
Type: defect | Status: accepted
Priority: Very High | Milestone:
Component: ExoneraTor | Version:
Severity: Major | Resolution:
Keywords: | Actual Points:
Parent ID: | Points:
Sponsor: |
------------------------+--------------------------
Comment (by karsten):
I'm stuck, but I'll post my findings here in the hope that somebody else
can resolve this mystery.
The bottleneck seems to be the second select in function
`search_statusentries_by_address_date`, that ''"finds status entries of
relays having an exit list entry with the provided IP address as the exit
address."'' That select can be really slow depending on whether the
provided IP address is found in an exit list or not. Consider date
`2011-04-29` and IP addresses `98.113.149.36` (the address mentioned in
this ticket) and `86.59.21.38` (tor26, not an exit):
{{{
EXPLAIN ANALYZE
SELECT statusentry.rawstatusentry,
statusentry.descriptor,
statusentry.validafter,
statusentry.fingerprint,
HOST(statusentry.oraddress),
HOST(exitlistentry.exitaddress),
-- Pick only the last scan result that took place in the 24 hours
-- before the valid-after time.
MAX(exitlistentry.scanned)
FROM statusentry
JOIN exitlistentry
ON statusentry.fingerprint = exitlistentry.fingerprint
WHERE exitlistentry.exitaddress = '98.113.149.36'::INET
-- Focus on a time period from 1 day before and 1 day after the
-- given date. Also include a second day before the given date
-- for exit lists, because it can take up to 24 hours to scan a
-- relay again. We shouldn't miss exit list entries here.
AND DATE(exitlistentry.scanned) >= '2011-04-27'
AND DATE(exitlistentry.scanned) <= '2011-04-30'
AND DATE(statusentry.validafter) >= '2011-04-28'
AND DATE(statusentry.validafter) <= '2011-04-30'
-- Consider only exit list scans that took place in the 24 hours
-- before the relay was listed in a consensus.
AND statusentry.validafter >= exitlistentry.scanned
AND statusentry.validafter - exitlistentry.scanned <=
'1 day'::INTERVAL
GROUP BY 1, 2, 3, 4, 5, 6;
}}}
Query results are:
{{{
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=11062.95..11062.97 rows=1 width=342) (actual
time=100644.027..100644.202 rows=57 loops=1)
-> Nested Loop (cost=0.01..11062.94 rows=1 width=342) (actual
time=122.074..100643.033 rows=84 loops=1)
Join Filter: ((statusentry.validafter - exitlistentry.scanned) <=
'1 day'::interval)
-> Index Scan using exitlistentry_exitaddress_scanneddate on
exitlistentry (cost=0.01..8.82 rows=1 width=56) (actual
time=23.242..68.592 rows=4 loops=1)
Index Cond: ((exitaddress = '98.113.149.36'::inet) AND
(date(scanned) >= '2011-04-27'::date) AND (date(scanned) <=
'2011-04-30'::date))
-> Index Scan using statusentry_fingerprint_validafter on
statusentry (cost=0.00..11054.09 rows=1 width=327) (actual
time=26.442..25142.994 rows=60 loops=4)
Index Cond: ((fingerprint = exitlistentry.fingerprint) AND
(validafter >= exitlistentry.scanned))
Filter: ((date(validafter) >= '2011-04-28'::date) AND
(date(validafter) <= '2011-04-30'::date))
Total runtime: 100644.583 ms
(9 rows)
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=11062.95..11062.97 rows=1 width=342) (actual
time=11.782..11.782 rows=0 loops=1)
-> Nested Loop (cost=0.01..11062.94 rows=1 width=342) (actual
time=11.773..11.773 rows=0 loops=1)
Join Filter: ((statusentry.validafter - exitlistentry.scanned) <=
'1 day'::interval)
-> Index Scan using exitlistentry_exitaddress_scanneddate on
exitlistentry (cost=0.01..8.82 rows=1 width=56) (actual
time=11.766..11.766 rows=0 loops=1)
Index Cond: ((exitaddress = '86.59.21.38'::inet) AND
(date(scanned) >= '2011-04-27'::date) AND (date(scanned) <=
'2011-04-30'::date))
-> Index Scan using statusentry_fingerprint_validafter on
statusentry (cost=0.00..11054.09 rows=1 width=327) (never executed)
Index Cond: ((fingerprint = exitlistentry.fingerprint) AND
(validafter >= exitlistentry.scanned))
Filter: ((date(validafter) >= '2011-04-28'::date) AND
(date(validafter) <= '2011-04-30'::date))
Total runtime: 11.953 ms
(9 rows)
}}}
Note that I saw much worse total runtimes for the first query which took
about 10 times as long.
Also note that I created two new indexes that aren't yet contained in
[https://gitweb.torproject.org/exonerator.git/tree/db/exonerator.sql
ExoneraTor's database schema] yet:
{{{
CREATE INDEX statusentry_validafter_fingerprint
ON statusentry (validafter, fingerprint);
CREATE INDEX statusentry_fingerprint_validafter
ON statusentry (fingerprint, validafter);
}}}
Before having these indexes, the above query would use statusentry_pkey,
but overall runtimes were comparable. And 1.5 minutes or even 15 minutes
is obviously unacceptable for this query. 1.5 seconds would be
acceptable.
Hmm. What's the index that we're obviously missing? (I'd rather not want
to change the table structure, but if that's really, really the only way
to fix this, let's talk about it.)
Feedback much appreciated!
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/17488#comment:3>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list