Reinventing Haystack

[reginafcompton]

The Councilmatic search functionality currently depends on Haystack. (It causes a lot of headaches, particularly, due its seemingly limitless hunger for memory.)

This document unravels some of the mysteries of Haystack, outlines why we might considering replacing it, and suggests how to incrementally make this happen.

@evz and I will collaborate on this project.

[jeancochrane]

I ran a quick memory profile of Haystack's update_index command, mostly cribbed from the tracemalloc docs:

import linecache
import os
import tracemalloc

from django.core.management.base import BaseCommand
from django.core.management import call_command

class Command(BaseCommand):
    help = 'Profiler'

    def display_top(self, snapshot, key_type='lineno', limit=10):
        snapshot = snapshot.filter_traces((
            tracemalloc.Filter(False, "<frozen importlib._bootstrap>"),
            tracemalloc.Filter(False, "<unknown>"),
        ))
        top_stats = snapshot.statistics(key_type)

        print("Top %s lines" % limit)
        for index, stat in enumerate(top_stats[:limit], 1):
            frame = stat.traceback[0]
            # replace "/path/to/module/file.py" with "module/file.py"
            filename = os.sep.join(frame.filename.split(os.sep)[-2:])
            print("#%s: %s:%s: %.1f KiB"
                % (index, filename, frame.lineno, stat.size / 1024))
            line = linecache.getline(frame.filename, frame.lineno).strip()
            if line:
                print('    %s' % line)

        other = top_stats[limit:]
        if other:
            size = sum(stat.size for stat in other)
            print("%s other: %.1f KiB" % (len(other), size / 1024))
        total = sum(stat.size for stat in top_stats)
        print("Total allocated size: %.1f KiB" % (total / 1024))

    def handle(self, *args, **options):

        tracemalloc.start()

        call_command('update_index')

        snapshot = tracemalloc.take_snapshot()
        self.display_top(snapshot)

Here are the results:

Indexing 15107 nyc bills
Top 10 lines
#1: <frozen importlib._bootstrap_external>:476: 213.7 KiB
#2: fields/related.py:594: 76.3 KiB
    return tuple(rhs_field for lhs_field, rhs_field in self.related_fields if rhs_field)
#3: python3.5/stringprep.py:187: 24.1 KiB
    0x1d7a8:'\u03c9', 0x1d7bb:'\u03c3', }
#4: python3.5/inspect.py:2165: 23.4 KiB
    sigcls=sigcls)
#5: fields/related.py:626: 15.2 KiB
    return tuple((lhs_field.column, rhs_field.column) for lhs_field, rhs_field in source)
#6: utils/functional.py:33: 13.2 KiB
    res = instance.__dict__[self.name] = self.func(instance)
#7: fields/related.py:590: 12.3 KiB
    return tuple(lhs_field for lhs_field, rhs_field in self.related_fields)
#8: db/utils.py:102: 11.5 KiB
    return func(*args, **kwargs)
#9: python3.5/stringprep.py:262: 10.8 KiB
    c9_set = set([917505] + list(range(917536,917632)))
#10: sql/query.py:1444: 7.7 KiB
    targets = tuple(r[0] for r in info.join_field.related_fields if r[1].column in cur_targets)
1214 other: 637.0 KiB
Total allocated size: 1045.4 KiB

That's not a lot of memory, but then again, I could be profiling this wrong. What makes us think that Haystack updating the index is causing the server to crash, again?

[reginafcompton]

Here's an example of a MemoryError that occurred while running update_index (when it was baked into import_data): https://sentry.io/datamade/nyc-council-councilmatic/issues/430697575/

[jeancochrane]

We did a little bit of memory debugging this morning to try to figure out what's going on. Some notes:

• rebuild_index uses a lot more memory than update_index on the Haystack side. During rebuild_index, the Python process continues to eat memory roughly linearly as the index grows. (We killed it after it broke 25% of server capacity, ~500MB.) This seems to indicate that rebuild_index might hold onto memory inappropriately.
• update_index doesn't actually use much memory on the Haystack side, consistent with the results I got from using tracemalloc. Solr, on the other hand, holds onto a lot of memory during the indexing process. It bumped up to around 25%, while the Python process varied between 5%-10%. Solr continues to hold onto this memory long after the indexing process has exited (currently thirty minutes and counting).
• There are three Postgres processes on the staging server, each sitting on 13-15% of memory (cumulatively 39-45% of total available resources). Indexing doesn't touch Postgres at all, but they're still throttling the server and allowing less memory to be available for indexing. Any idea why we might have three versions of Postgres running @evz?
• Profiling memory performance with top isn't great: you have to waste a lot of time watching the dashboard, and it's tough to get a sense of changes over time. Tracemalloc provides more fine-grained control, but is also a headache to use and parse. I'd like to try out mprof for generating time series with labeled function calls.

Two next steps:

1. Do some research to figure out why Solr hangs on to so much memory during and after indexing
2. Profile rebuild_index and update_index using a tool like mprof to try to get a more accurate picture of Python's contribution to the memory usage over time

[reginafcompton]

@jeancochrane - how do you feel about using the above Google doc for notes? It might be easier to consolidate and topically organize our findings into a memo-like document.

[jeancochrane]

@reginafcompton that makes sense! I missed the link for lack of reading closely 😅 Just updated the doc!