rqt_console: Filters get sloooow when there are many messages

[jonbinney]

When there are lots of messages (~20,000), adding a filter brings rqt_console to a screeching halt. The gui becomes unresponsive for a while.

import rospy, time
rospy.init_node('spam')

d = 0
r = rospy.Rate(1000)
while not rospy.is_shutdown():
    rospy.loginfo('sppppaaaam %d' % d)
    d += 1
    r.sleep()

[jonbinney]

I tried running just string search and regular expressions on 20,000 lines of text and it is fast in python:

import time
import re
import random

strings = []
for i in range(20000):
    strings.append(''.join([chr(random.randint(0,255)) for ii in range(100)]))


t0 = time.time()
num = 0
search_str = 'ion'
for s in strings:
    if search_str in s:
        num += 1
t1 = time.time()

print t1-t0


t2 = time.time()
num = 0
search_re = re.compile('k*ej.ion')
for s in strings:
    if search_re.search(s):
        num += 1
t3 = time.time()

print t3 - t2

So not sure why the qt filter is slow

[jonbinney]

(it took 3ms for the string search and 36ms for the regex search on my i7)

[ablasdel]

This is most likely an issue with either the implementation of QSortFilterProxy or how it is bing used.

[jonbinney]

bing??

[jonbinney]

rqt_console uses bing for searcH?

[ablasdel]

Yes that is the slow down!

[ablasdel]

Seriously though this is issue was created collaboratively (Binney + Me) and I have known of this issue for some time. I thought it was us running into the limits of Qt on Python QTableViews with QSortFilterProxyModels but the proof of concept showing how fast python should be able to regex strings makes me want to revisit and research what is actually slowing us down here and hopefully squeeze out a bit more speed. This won't be done by Hydro Release but I will keep an eye on it.

[ablasdel]

Talked with Jon about this and ran rqt_console with 20k msgs through profiler. It looks like we can save a considerable portion of the time if we streamline our data handling during the AcceptFilterRow function. We should not be swaping things around so much.

[dirk-thomas]

Please point me to specific things and how you think they should be changed. I already have a working copy with a significant refactoring of rqt_console. So please don't patch the current version in the repo.

[ablasdel]

I am not going to be actively working on this anymore today so we can let the other pull requests move in front of this.

[ablasdel]

Just so you have an idea starting at this line:
https://github.com/ros-visualization/rqt_common_plugins/blob/hydro-devel/rqt_console/src/rqt_console/message_proxy_model.py#L63

We get the data and put it in a list and then later convert it to an object and do a couple of other things. From the profile it seems like we can save a rather significant amount by reworking the storage to be exactly what we need at filter time.

[dirk-thomas]

Ok, that part is already refactored in my workspace. The proxy model accesses the message from the source model directly without calling data():

def filterAcceptsRow(self, sourcerow, sourceparent):
    msg = self.sourceModel()._messages[sourcerow]
    if self._exclude_filters.test_message(msg):
        # hide excluded message
        return False
    if self._highlight_filters.count_enabled_filters() == 0:
        # no need to check and update message status without filters
        return True
    highlighted = self._highlight_filters.test_message(msg)
    # update message state
    msg.highlighted = highlighted
    return highlighted

[ablasdel]

Ok good that is the first step down. The next step is to walk all the way through test_message(msg) and make sure I don't do any conversion or other stupid stuff that would slow it down.

After that once the dust settles I think I would want to run it back through a profiler and filter 20k msgs at once and see where our bottleneck is after fixing this one.

[ablasdel]

@dirk-thomas has the working version of this at the moment. I am assigning this to him for his upcoming pull request to close this.

[dirk-thomas]

Addressed in #186.