Issue Details (XML | Word | Printable)

Key: PYFB-58
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Blocker Blocker
Assignee: Pavel Cisar
Reporter: Dominik Psenner
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Firebird driver for Python

Severe performance loss and minor memory leak

Created: 30/Sep/15 12:51 PM   Updated: 15/Feb/17 12:02 PM
Component/s: None
Affects Version/s: 1.4.10
Fix Version/s: 1.4.11

Environment: Any


 Description  « Hide
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.

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Dominik Psenner added a comment - 30/Sep/15 01:13 PM
# -*- 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))
        

Dominik Psenner added a comment - 02/Oct/15 09:25 AM - edited
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 PYFB-58

_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?

Dominik Psenner added a comment - 05/Nov/15 07:27 AM
Are there any updates on this issue?

Pavel Cisar added a comment - 11/Nov/15 01:40 PM
Suggested fix was not good and introduced another problems. Proper fix was to make weakref callback work as expected.