Skip to content
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.

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

Severe performance loss and minor memory leak [PYFB58] #75

Closed
firebird-automations opened this issue Sep 30, 2015 · 6 comments
Closed

Comments

@firebird-automations
Copy link

Submitted by: Dominik Psenner (dpsenner)

We implemented a connection pool and due to heavy load connections are practically never freed. We soon noticed significant performance loss when executing millions of queries on a single connection. In our test we observed that executing a random query (select first 1 * from rdb$database) got us these timings:

first 10000 queries: 17 seconds
next 10000 queries: 30 seconds
next 10000 queries: 42 seconds
next 10000 queries: 53 seconds

The transaction is committed after every query. Soon we found out that the transaction class holds references to all its cursors with a weakref:

class Transaction(object):
def __init__:
self._cursors = [] #⁠ Weak references to cursors

When creating a cursor the weakref to that cursor is stored in this list and should be freed as soon as the cursor is no longer in use. But unfortunately this is not the case. Only when the transaction is closed also the cursors are freed up. We were able to narrow down the issue to this line:

class Transaction(object):
def cursor(self,connection = None):
[...]
self._cursors.append(weakref.ref(c, _weakref_callback(self.__remove_cursor)))
[...]

This line adds a weakref to the cursor with a weakref callback, but that weakref callback is immediately freed and thus self.__remove_cursor is never invoked. This has the effect that when def __close_cursors(self) is called it has to cycle over millions of weakrefs that point to nowhere. Changing this to:

self._cursors.append(weakref.ref(c, self.__remove_cursor))

solved the performance issue but we do not know if this results in other issues. You might know a better way to solve this. Generally we do not understand why there is the need to keep weakrefs to cursors that have been created. Anyway, this is a blocker for us, please try to work out a fix as soon as you can.

Commits: a7daea5 FirebirdSQL/fbt-repository@b08b0dc

@firebird-automations
Copy link
Author

Commented by: Dominik Psenner (dpsenner)

#⁠ -*- coding: utf-8 -*-
#⁠ This is a test showing the issue

import sys
import time
import datetime
import fdb

#⁠ Auxiliary method
def timing(action, showEnterLog=True):
class controlled_execution:
def __init__(self, a, el):
self.tic = None
self.action = a
self.showEnterLog = el
self.checkpoints = []

    def \_\_enter\_\_\(self\):
        self\.tic = time\.clock\(\)
        if self\.showEnterLog:
            print u"\{1\} \- \{0\}"\.format\(self\.action, datetime\.datetime\.now\(\)\.strftime\("%Y\-%m\-%d %H:%M:%S\.%f"\)\[:\-3\]\)
        return self

    def \_\_exit\_\_\(self, exc\_type, exc\_val, exc\_tb\):
        total = self\.elapsedTotal\(\)
        if self\.checkpoints:
            minDiff = min\(\[diff for ts, diff, msg in self\.checkpoints\]\)
            maxDiff = max\(\[diff for ts, diff, msg in self\.checkpoints\]\)
            avgDiff = total / len\(self\.checkpoints\)
            print u"\{1\} \- \{0\}; Gesamtdauer: \{2:0\.3f\}s; min/max/avg: \{3:0\.3f\}s/\{4:0\.3f\}s/\{5:0\.3f\}s"\.format\(
                self\.action, datetime\.datetime\.now\(\)\.strftime\("%Y\-%m\-%d %H:%M:%S\.%f"\)\[:\-3\], total, minDiff, maxDiff,
                avgDiff\)
        else:
            print u"\{1\} \- \{0\}; Gesamtdauer: \{2:0\.3f\}s"\.format\(self\.action, datetime\.datetime\.now\(\)\.strftime\(
                "%Y\-%m\-%d %H:%M:%S\.%f"\)\[:\-3\], total\)
        if exc\_val is not None:
            return False

    def checkpoint\(self, message=None\):
        toc = time\.clock\(\)
        diff = toc \- self\.tic
        self\.tic = toc
        ts = datetime\.datetime\.now\(\)
        if message is not None:
            print u"\{0\} \- \{1\}; Dauer: \{2:0\.3f\}s"\.format\(ts\.strftime\("%Y\-%m\-%d %H:%M:%S\.%f"\)\[:\-3\], message, diff\)
        self\.checkpoints \+= \[\(ts, diff, message\)\]

    def elapsedTotal\(self\):
        total = self\.elapsedSinceLastCheckpoint\(\)
        for ts, diff, msg in self\.checkpoints:
            total \+= diff
        return total

    def elapsedSinceLastCheckpoint\(self\):
        last = time\.clock\(\) \- self\.tic
        return last

return controlled\_execution\(action, showEnterLog\)

def test(connection):
try:
cur = connection.cursor()
cur.execute('select * from rdb$database')
cur.fetchall()
finally:
connection.commit()

if __name__ == '__main__':
connection = fdb.connect(host='127.0.0.1', database=r'foo', user='SYSDBA',
password='masterke', sql_dialect=3, charset='UTF-8',
role='SYSDBA')
executions = 100
for h in xrange(1, executions+1):
with timing('test') as t:
for i in xrange(1, executions+1):
for j in xrange(1, 100+1):
test(connection)
t.checkpoint()
sys.stdout.write("\r{2}:{0} / {1}".format(i, executions, h))
print "; {0} checkpoints".format(len(t.checkpoints))

@firebird-automations
Copy link
Author

Commented by: Dominik Psenner (dpsenner)

We found an alternative that could fix the issue without removing the weakrefs. This is the patch:

#⁠ HG changeset patch
#⁠ User dpsenner
#⁠ Date 1443769991 -7200
#⁠ Fri Oct 02 09:13:11 2015 +0200
#⁠ Node ID c71fa20acbc90c55f5c73e4dd061ee4b26653c3c
#⁠ Parent d36d56a6ad66a4e4b7e36853e6570ac0107f4145
Probable fix for PYFB58

_weakref_callback was never called and thus never cleaned up the weakref in the
list and therefore the execution of queries became slower and slower the longer
a connection or transaction was kept open.

diff -r d36d56a6ad66 -r c71fa20acbc9 fdb/fbcore.py
--- a/fdb/fbcore.py Mon Aug 31 13:11:51 2015 +0000
+++ b/fdb/fbcore.py Fri Oct 02 09:13:11 2015 +0200
@@ -3676,10 +3676,15 @@
if not self.active:
raise ProgrammingError("Transaction object is not active")
def __close_cursors(self):
+ remove_cursors = []
for cursor in self._cursors:
c = cursor()
if c:
c.close()
+ else:
+ remove_cursors += [cursor]
+ for cursor in remove_cursors:
+ self.__remove_cursor(cursor)
def __con_in_list(self,connection):
for con in self._connections:
if con() == connection:

For now we apply this patch to ship a bugfix release. Would you please check and feed back if this fix is safe?

@firebird-automations
Copy link
Author

Commented by: Dominik Psenner (dpsenner)

Are there any updates on this issue?

@firebird-automations
Copy link
Author

Commented by: @pcisar

Suggested fix was not good and introduced another problems. Proper fix was to make weakref callback work as expected.

@firebird-automations
Copy link
Author

Modified by: @pcisar

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 1.4.11 [ 10741 ]

@firebird-automations
Copy link
Author

Modified by: @pcisar

status: Resolved [ 5 ] => Closed [ 6 ]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants