Skip to content

Speed up parse() ~7x with literal pre-filters (output unchanged) #33

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Malkiz223 wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Speed up parse() ~7x with literal pre-filters (output unchanged) #33

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
33 changes: 33 additions & 0 deletions logparser/common.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,9 @@
retry_logs=r'[ ][Rr]etrying[ ]<', # DEBUG: Retrying <GET DEBUG: Gave up retrying <GET
ignore_logs=r':[ ]Ignoring[ ]response[ ]<' # INFO: Ignoring response <404
)
LOG_CATEGORIES_FIRSTLINE_PATTERN_DICT = OrderedDict(
(k, re.compile(r'%s[ ][^\n]+?%s' % (DATETIME_PATTERN, v)))
for k, v in LOG_CATEGORIES_PATTERN_DICT.items())
for k, v in LOG_CATEGORIES_PATTERN_DICT.items():
p = re.compile(r"""\n
({time_}[ ][^\n]+?{pattern}.*?) # first line (and its details)
Expand All @@ -47,6 +50,18 @@
_odict.update({k: LOG_CATEGORIES_PATTERN_DICT[k]})
LOG_CATEGORIES_PATTERN_DICT = _odict

LOG_CATEGORIES_LITERAL_DICT = dict(
critical_logs='] CRITICAL:', # [test] CRITICAL:
error_logs='] ERROR:', # [test] ERROR:
warning_logs='] WARNING:', # [test] WARNING:
redirect_logs=': Redirecting (', # DEBUG: Redirecting (302) to <GET
retry_logs='etrying <', # DEBUG: Retrying <GET DEBUG: Gave up retrying <GET
ignore_logs=': Ignoring response <', # INFO: Ignoring response <404
)

LOG_ENTRY_NEXT_LINE_PATTERN = re.compile(
r'\r?\n%s[ ][^\n]+?(?:DEBUG|INFO|WARNING|ERROR|CRITICAL)' % DATETIME_PATTERN)

# 2019-01-01 00:00:01 [scrapy.extensions.telnet] DEBUG: Telnet console listening on 127.0.0.1:6023
# 2019-01-01 00:00:01 [scrapy.statscollectors] INFO: Dumping Scrapy stats:
# {'downloader/exception_count': 3,
Expand Down Expand Up @@ -74,6 +89,20 @@
if k not in ['telnet_username', 'telnet_password']:
LATEST_MATCHES_PATTERN_DICT[k] = r'^%s[ ].+?%s' % (DATETIME_PATTERN, v)

LATEST_MATCHES_LITERAL_DICT = dict(
scrapy_version='Scrapy ', # Scrapy 1.5.1 started (bot: demo)
telnet_console='Telnet console listening on', # Telnet console listening on 127.0.0.1:6023
# Default: 'scrapy' | Overridden settings: {'TELNETCONSOLE_USERNAME': 'usr'}
telnet_username='TELNETCONSOLE_USERNAME',
# Telnet Password: 865bba341ef25552 | Overridden settings: {'TELNETCONSOLE_PASSWORD': 'psw'}
telnet_password=None,
resuming_crawl='Resuming crawl', # Resuming crawl (675840 requests scheduled)
latest_offsite='Filtered offsite', # Filtered offsite request to 'www.baidu.com'
latest_duplicate='Filtered duplicate', # Filtered duplicate request: <GET http://httpbin.org/headers>
latest_crawl='Crawled (', # Crawled (200) <GET http://httpbin.org/headers> (referer: None)
latest_stat=' pages (at', # Crawled 3 pages (at 0 pages/min), scraped 2 items (at 0 items/min)
)

# 2019-01-01 00:00:01 [scrapy.core.scraper] DEBUG: Scraped from <200 http://httpbin.org/headers>
LATEST_SCRAPE_ITEM_PATTERN = re.compile(r"""\n
({time_}[ ][^\n]+?{pattern}[^\n]+?)\r?\n({{.*?)
Expand Down Expand Up @@ -139,7 +168,11 @@ class Common(object):
DATETIME_PATTERN = DATETIME_PATTERN
DATAS_PATTERN = DATAS_PATTERN
LOG_CATEGORIES_PATTERN_DICT = LOG_CATEGORIES_PATTERN_DICT
LOG_CATEGORIES_LITERAL_DICT = LOG_CATEGORIES_LITERAL_DICT
LOG_CATEGORIES_FIRSTLINE_PATTERN_DICT = LOG_CATEGORIES_FIRSTLINE_PATTERN_DICT
LOG_ENTRY_NEXT_LINE_PATTERN = LOG_ENTRY_NEXT_LINE_PATTERN
LATEST_MATCHES_PATTERN_DICT = LATEST_MATCHES_PATTERN_DICT
LATEST_MATCHES_LITERAL_DICT = LATEST_MATCHES_LITERAL_DICT
LATEST_SCRAPE_ITEM_PATTERN = LATEST_SCRAPE_ITEM_PATTERN

SIGTERM_PATTERN = SIGTERM_PATTERN
Expand Down
70 changes: 58 additions & 12 deletions logparser/scrapylogparser.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -48,8 +48,11 @@ def main(self):
self.data['logparser_version'] = __version__
return self.data

def re_search_final_match(self, pattern, default='', step=-1):
for line in self.lines[::step]:
def re_search_final_match(self, pattern, default='', step=-1, contains=None):
lines = self.lines if step == 1 else reversed(self.lines)
for line in lines:
if contains is not None and contains not in line:
continue
if re.search(pattern, line):
return line
return default
Expand Down Expand Up @@ -85,10 +88,16 @@ def extract_time(self):

# Extract datas for chart
def extract_datas(self):
datas = re.findall(self.DATAS_PATTERN, self.text)
# For compatibility with Python 2, str(time_) to avoid [u'2019-01-01 00:00:01', 0, 0, 0, 0] in JavaScript
self.data['datas'] = [[str(time_), int(pages), int(pages_min), int(items), int(items_min)]
for (time_, pages, pages_min, items, items_min) in datas]
datas = []
for line in self.lines:
if ' pages (at' not in line:
continue
m = self.DATAS_PATTERN.search('\n' + line)
if m:
time_, pages, pages_min, items, items_min = m.groups()
datas.append([str(time_), int(pages), int(pages_min), int(items), int(items_min)])
self.data['datas'] = datas
# TODO: Crawled (200) <GET, Scraped from <200
self.data['pages'] = None
self.data['items'] = None
Expand All @@ -103,7 +112,7 @@ def extract_latest_matches(self):
step = 1
else:
step = -1
result = self.re_search_final_match(v, step=step)
result = self.re_search_final_match(v, step=step, contains=self.LATEST_MATCHES_LITERAL_DICT.get(k))
if result:
if k == 'scrapy_version':
m = re.search(r'Scrapy[ ](\d+\.\d+\.\d+)[ ]started', result)
Expand All @@ -120,8 +129,14 @@ def extract_latest_matches(self):
result = m.group(2) if m else ''
self.data['latest_matches'][k] = result

for m in self.LATEST_SCRAPE_ITEM_PATTERN.finditer(self.text):
self.data['latest_matches']['latest_scrape'], self.data['latest_matches']['latest_item'] = m.groups()
idx = self.text.rfind(': Scraped from <')
if idx >= 0:
start = self.text.rfind('\n', 0, idx)
if start < 0:
start = 0
m = self.LATEST_SCRAPE_ITEM_PATTERN.search(self.text, start)
if m:
self.data['latest_matches']['latest_scrape'], self.data['latest_matches']['latest_item'] = m.groups()
self.data['latest_matches'].setdefault('latest_scrape', '')
self.data['latest_matches'].setdefault('latest_item', '')

Expand All @@ -143,22 +158,53 @@ def extract_latest_matches(self):

def extract_log_categories(self):
self.data['log_categories'] = OrderedDict()
for level, pattern in self.LOG_CATEGORIES_PATTERN_DICT.items():
matches = re.findall(pattern, self.text)
for level in self.LOG_CATEGORIES_PATTERN_DICT:
literal = self.LOG_CATEGORIES_LITERAL_DICT[level]
if literal not in self.text:
self.data['log_categories'][level] = dict(count=0, details=[])
continue
matches = self.find_category_entries(literal, self.LOG_CATEGORIES_FIRSTLINE_PATTERN_DICT[level])
# DEBUG: Gave up retrying <GET
if level == 'retry_logs' and matches:
count = len([i for i in matches if 'Gave up retrying <' not in i])
else:
count = len(matches)
self.data['log_categories'][level] = dict(count=count, details=matches)

def find_category_entries(self, literal, first_line_pattern):
text = self.text
entries = []
start = 0
literal_length = len(literal)
while True:
found = text.find(literal, start)
if found < 0:
break
line_start = text.rfind('\n', 0, found) + 1
first_line = first_line_pattern.match(text, line_start)
if first_line:
next_line = self.LOG_ENTRY_NEXT_LINE_PATTERN.search(text, first_line.end())
entry_end = next_line.start() if next_line else len(text)
entries.append(text[line_start:entry_end])
start = entry_end
else:
start = found + literal_length
return entries

def extract_shutdown_reason(self):
m = re.search(self.SIGTERM_PATTERN, self.re_search_final_match(self.SIGTERM_PATTERN))
m = re.search(self.SIGTERM_PATTERN,
self.re_search_final_match(self.SIGTERM_PATTERN, contains='Received SIG'))
self.data['shutdown_reason'] = m.group(1) if m else self.NA

def extract_stats_dumped(self):
self.data['finish_reason'] = self.NA # May be updated in update_data_with_crawler_stats()
m = re.search(self.PATTERN_LOG_ENDING, self.text)
dumping_index = self.text.find('Dumping Scrapy stats:')
spider_closed_index = self.text.find('INFO: Spider closed')
found_indexes = [index for index in (dumping_index, spider_closed_index) if index >= 0]
m = None
if found_indexes:
start = self.text.rfind('\n', 0, min(found_indexes)) + 1
m = self.PATTERN_LOG_ENDING.search(self.text, start)
if not (m and m.group(3)):
self.data['crawler_stats'] = {}
else:
Expand Down