Strange pattern in slowdown of queries from a session over bolt

[connorwake]

We recently started noticing that a lot of our queries are running slowly over bolt from the python driver when they open up new sessions. At first we thought that it was because we were setting up the sessions wrong and so they weren't correctly pulling from the connection pool and it would keep having to start up new connections with each request. However during our debugging and testing we ran into this strange case:

def tf(f):
     start = time()
     f()
     end = time()
     return (end - start)*1000

This function is just here to time how long each query takes.

with driver.new_session() as session:
    for i in range(0, 500):
        val = tf(lambda: session.run("match (n) return count(n)"))
        if val > 2:
            print i, ":", val

Then this creates one session and uses it to run the same query over and over. Usually the queries take under a ms, but this prints out the ones that didn't and this is what we got:

0 : 3.43799591064
2 : 2.49195098877
6 : 2.96497344971
14 : 4.04977798462
30 : 6.24489784241
62 : 12.0089054108
132 : 23.7801074982
266 : 17.529964447
432 : 41.0959720612

(This was running on my local graph, we see the same thing in our prod environment but with 10x larger slowdowns)
There's a pattern where the one's that take ~10x time is roughly following f(0) = 0, f(n) = f(n-1)+ 2^n. I've run this a few times and its always the same ones that are slow.

Any ideas what could be going on here and why these specific queries are so slow?

[zhenlineo]

Hi,

A quick look at your code tells me it might because you did not consume the result or close the session.

If you did not consume any result in this session, then all result will be buffered into memory before next run.

And if you do not close any session after you use you will not "reuse" any connection as the connection is always hold by this session. The connection will never go back to the pool and no connection timeout is actually checked ever on this connection.

So if you move the 'with driver.session() as session' into for loop, you might see no increase in the time. But your timing function actually is not really timing correctly if you do not consume result as it only times send without receiving.

Let us know if this solves your problem.

Cheers,
Zhen

[connorwake]

I don't think it has anything to do with not closing the session. Just to double check I ran this code

for i in range(0, 50):
    session = driver.session()
    val = tf(lambda: session.run("match (n) return count(n)"))
    if val > 2:
        print i, ":", val
    session.close()

This time every single request took ~60ms on our production environment (so the equivalent of the ~10ms results on local). When

I also made this test without consuming the results as I was just trying to look at the overhead that each request has when we create a new session. Since each of our requests seems to have a ~60ms overhead on production without even consuming the results we are running into big performance issues. (I also tested this out with the query RETURN 1+1 to make sure it wasn't the time it took to run the actual query)

So to clarify, the main issue we are running into is it should take less than 1ms for the ConnectionPool to give back a not in_use Connection, however we always see a ~60ms overhead to get this new connection/session when a new session is made.

Another situation we ran into this is with the following commands we ran (I'm back on local here)

>>> s1 = driver.session()
>>> tf(lambda: s1.run(“match (n) return count(n)“))
29.2189121246
>>> tf(lambda: s1.run(“match (n) return count(n)“))
0.646114349365
>>> tf(lambda: s1.run(“match (n) return count(n)“))
0.288963317871
>>> tf(lambda: s1.run(“return 1+1”))
0.328063964844
>>> s2 = driver.session()
>>> tf(lambda: s2.run(“match (n) return count(n)“))
29.837846756
>>> tf(lambda: s2.run(“match (n) return count(n)“))
0.320911407471
>>> tf(lambda: s2.run(“return 1+1”))
0.29182434082
>>> s1.close()
>>> s3 = driver.session()
>>> tf(lambda: s3.run(“match (n) return count(n)“))
6.22081756592

As you can see, using a connection already attached to the session was very fast. Getting a new connection was pretty slow (as expected). However having a session grab a connection from the pool of available sessions seemed to happen at a medium speed in between using an existing session and creating an entirely new connection.

Thanks for the help!

[connorwake]

I've investigated some more using the cProfile library and found that the slowdown comes from {method 'read' of '_ssl._SSLSocket' objects}. The subset of functions and their results that had a slowdown (in what I guessed was roughly the correct order) is:

n  tottime  percall  cumtime  percall filename:lineno(function)
1    0.000    0.000    0.067    0.067 api.py:268(run)
1    0.000    0.000    0.063    0.063 connection.py:243(fetch)
1    0.000    0.000    0.063    0.063 connection.py:282(_receive)
1    0.000    0.000    0.063    0.063 {method 'receive_message' of 'neo4j.bolt._io.ChunkedInputBuffer' objects}
1    0.000    0.000    0.063    0.063 ssl.py:760(recv_into)
1    0.000    0.000    0.063    0.063 ssl.py:632(read)
1    0.063    0.063    0.063    0.063 {method 'read' of '_ssl._SSLSocket' objects}

From this, the entire slowdown is coming from reading the ssl. I'm not sure what is going wrong with it though.

[zhenlineo]

That's Odd. Could you also try to turn off ssl in your test to see if it will make any difference to the numbers?

You could turn ssl off by by using the following code on driver creation:
driver = GraphDatabase.driver(uri, auth=(user, password), encrypted=False)

Thanks.

[connorwake]

I ran it again without ssl. I got the same slowdown, but now the culprit has changed just {method 'receive_message' of 'neo4j.bolt._io.ChunkedInputBuffer' objects}

n  tottime  percall  cumtime  percall filename:lineno(function)
1    0.000    0.000    0.063    0.063 api.py:268(run)
1    0.000    0.000    0.062    0.062 connection.py:243(fetch)
1    0.000    0.000    0.062    0.062 connection.py:282(_receive)
1    0.062    0.062    0.062    0.062 {method 'receive_message' of 'neo4j.bolt._io.ChunkedInputBuffer' objects}

This is what I ran to get this:

driver = GraphDatabase.driver(uri, auth=(user, password), encrypted=False)
>>> s1 = driver.session()
>>> tf(lambda: s1.run("match (n) return count(n)"))
251.62601470947266
>>> tf(lambda: s1.run("match (n) return count(n)"))
0.30517578125
>>> tf(lambda: s1.run("match (n) return count(n)"))
0.25081634521484375
>>> s1.close()
>>> s2 = driver.session()
>>> tf(lambda: s2.run("match (n) return count(n)"))
67.10577011108398
>>> s2.close()
>>> s3 = driver.session()
>>> cProfile.runctx("s3.run(\"match (n) return count(n)\")", globals(), locals())

[connorwake]

We also found that when we added a 2ms delay into the loop as below we didn't see any slowdowns.

with driver.new_session() as session:
    for i in range(0, 500):
        sleep(0.002)
        val = tf(lambda: session.run("match (n) return count(n)"))
        if val > 2:
            print i, ":", val

[zhenlineo]

Will investigate more on this.

Thanks to provide us detailed explanation. We will investigate more to decide if it is caused by a bug or some things else there.

Cheers,
Zhen

[connorwake]

Of course. Thanks for looking into it! Let me know if there's any other info I can provide.

[connorwake]

I ran the same test with the javascript driver and it behaves as expected. So when a session is closed and a new one is opened, the next query run with the new session takes as long as the old session with the existing connection did, rather than taking an extra bit of overhead with the new session. I just wanted to confirm that it was something with the python code itself rather than the graph/network setup.

[connorwake]

We've investigated more and discovered that the pattern only happens when we don't consume the results. However when we consume the results we consistently get this slowdown. This means that the python driver is too slow for us to use realistically as it consistently adds a 60ms overhead to our queries. To verify this we ran RETURN 1+1 and it took 60ms through the python driver while the database says it takes ~1ms.
Unless this is not a common slowdown that people see? We are still trying to find if there are any other things that could be causing it, but since the javascript driver seems to be working fine under the same setup, we are thinking its something with the python driver.

[technige]

Are you using the C module or the pure Python module?

[connorwake]

We've tried both with the same results.

[technige]

The Python driver is certainly slower than the other drivers but there should be a noticeable difference between the C and pure Python variants.

[connorwake]

We've definitely tried both of them and we didn't see any difference between the two. Is there something else that could be going on?

[connorwake]

Turns out the biggest part of the slowdown was coming from some hidden network latency and the rest of it was from how the driver doesn't always seem to receive results unless the buffer is consumed. Now that its resolved, I'm going to close this issue.