Edgewall Software
Modify

Opened 7 months ago

Closed 6 months ago

Last modified 5 months ago

#13356 closed defect (fixed)

Subversion pool is destroyed more than once while testing trac/versioncontrol/tests/functional.py

Reported by: Jun Omae Owned by: Jun Omae
Priority: normal Milestone: 1.5.3
Component: version control Version:
Severity: normal Keywords: svn114
Cc: Branch:
Release Notes:

Fix double-destroying memory pool error from tracd server on functional-test

API Changes:
Internal Changes:

Description

The trac/versioncontrol/tests/functional.py passes but AssertionError: This pool has already been destroyed is logged in testenv/testing.log.

$ make python=39 clean Trac.egg-info trac/versioncontrol/tests/functional.py
find . -name \*.py[co] -exec rm {} \;
coverage erase
rm -fr build/doc

Python: /home/jun66j5/venv/py39/bin/python

  Package        Version
  ------------------------------------------------------
  Python       : 3.9.2 (default, Feb 20 2021, 20:59:40)
               : [GCC 5.4.0 20160609]
  Setuptools   : 53.1.0
  Pip          : 21.0.1
  Wheel        : not installed
  Jinja2       : 2.11.3
  Babel        : 2.9.0
  sqlite3      : 2.6.0 (3.11.0)
  PySqlite     : not installed
  PyMySQL      : 1.0.2
  Psycopg2     : 2.8.6 (dt dec pq3 ext lo64)
  SVN bindings : 1.14.0 (r1876290)
  Mercurial    : 5.7
  Pygments     : 2.8.0
  Textile      : 4.0.1
  Pytz         : 2021.1
  Docutils     : 0.16
  Selenium     : 3.141.0
  PyTidyLib    : 0.3.2
  LXML         : 4.6.2
  coverage     : 5.4

Variables:
  PATH=/home/jun66j5/venv/py39/bin:/home/jun66j5/bin:/home/jun66j5/.gem/ruby/2.0.0/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin
  PYTHONPATH=.
  TRAC_TEST_DB_URI=
  server-options= -p 3000 -a '*,/home/jun66j5/src/trac-htdigest.txt,auth'  -e

External dependencies:
  Git version: git version 2.29.0
  Subversion version: 1.14.0

python  setup.py egg_info
running egg_info
writing Trac.egg-info/PKG-INFO
writing dependency_links to Trac.egg-info/dependency_links.txt
writing entry points to Trac.egg-info/entry_points.txt
writing requirements to Trac.egg-info/requires.txt
writing top-level names to Trac.egg-info/top_level.txt
reading manifest file 'Trac.egg-info/SOURCES.txt'
writing manifest file 'Trac.egg-info/SOURCES.txt'
python  -m unittest  trac.versioncontrol.tests.functional.test_suite
.................
----------------------------------------------------------------------
Ran 17 tests in 25.887s

OK
127.0.0.1 - - [05/Mar/2021 21:17:37] "GET /admin/versioncontrol/repository HTTP/1.1" 200 -
127.0.0.1 - - [05/Mar/2021 21:17:38] "GET /admin/versioncontrol/repository/award_1 HTTP/1.1" 200 -
Exception ignored in: <function SubversionRepository.__del__ at 0x7efebbb88040>
Traceback (most recent call last):
  File "/home/jun66j5/src/tracdev/git/tracopt/versioncontrol/svn/svn_fs.py", line 412, in __del__
    self.close()
  File "/home/jun66j5/src/tracdev/git/tracopt/versioncontrol/svn/svn_fs.py", line 455, in close
    self.pool.destroy()
  File "/home/jun66j5/src/tracdev/git/tracopt/versioncontrol/svn/svn_fs.py", line 211, in destroy
    self.apr_pool_destroy(self._pool)
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/svn/core.py", line 300, in svn_pool_destroy
    pool.destroy()
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/libsvn/core.py", line 9907, in destroy
    self.assert_valid()
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/libsvn/core.py", line 9893, in assert_valid
    assert self.valid(), "This pool has already been destroyed"
AssertionError: This pool has already been destroyed
Exception ignored in: <function Pool.__del__ at 0x7efebbb86940>
Traceback (most recent call last):
  File "/home/jun66j5/src/tracdev/git/tracopt/versioncontrol/svn/svn_fs.py", line 222, in __del__
    self.destroy()
  File "/home/jun66j5/src/tracdev/git/tracopt/versioncontrol/svn/svn_fs.py", line 211, in destroy
    self.apr_pool_destroy(self._pool)
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/svn/core.py", line 300, in svn_pool_destroy
    pool.destroy()
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/libsvn/core.py", line 9907, in destroy
    self.assert_valid()
  File "/home/jun66j5/venv/py39/lib/python3.9/site-packages/libsvn/core.py", line 9893, in assert_valid
    assert self.valid(), "This pool has already been destroyed"
AssertionError: This pool has already been destroyed
127.0.0.1 - - [05/Mar/2021 21:17:38] "GET /chrome/site/your_project_logo.png HTTP/1.1" 304 -
127.0.0.1 - - [05/Mar/2021 21:17:38] "POST /admin/versioncontrol/repository/award_1 HTTP/1.1" 303 -

Similar issue occurs on 1.4-stable with Subversion 1.14.

$ make python=27-svn114 trac/versioncontrol/tests/functional.py

Python: /home/jun66j5/venv/py27-svn114/bin/python

  Package        Version
  -------------------------------------------------------
  Python       : 2.7.12 (default, Feb 25 2021, 14:00:40)
               : [GCC 5.4.0 20160609]
  Setuptools   : 42.0.2
  Pip          : 19.3.1
  Wheel        : 0.33.6
  Jinja2       : 2.11.3
  Genshi       : 0.7.5 (with speedups)
  Babel        : 2.9.0
  sqlite3      : 2.6.0 (3.11.0)
  PySqlite     : 2.8.3 (3.31.1)
  PyMySQL      : 0.10.1
  Psycopg2     : 2.8.6 (dt dec pq3 ext lo64)
  SVN bindings : 1.14.1 (r1886195)
  Mercurial    : 5.7
  Pygments     : 2.5.2
  Textile      : 3.0.4
  Pytz         : 2021.1
  Docutils     : 0.16
  Twill        : 0.9
  LXML         : 4.6.2
  coverage     : 5.5

Variables:
  PATH=/home/jun66j5/venv/py27-svn114/bin:/home/jun66j5/bin:/home/jun66j5/.gem/ruby/2.0.0/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin
  PYTHONPATH=.
  TRAC_TEST_DB_URI=
  server-options= -p 3000 -a '*,/home/jun66j5/src/trac-htdigest.txt,auth'  -e

External dependencies:
  Git version: git version 2.29.0
  Subversion version: 1.14.1

python  -m unittest  trac.versioncontrol.tests.functional.test_suite
.................
----------------------------------------------------------------------
Ran 17 tests in 14.365s

OK
Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method apr_pool_t.__del__ of <libsvn.core.apr_pool_t; proxy of <Swig Object of type 'apr_pool_t *' at 0x7f52aeb14de0> >> ignored

Attachments (0)

Change History (8)

comment:1 by Ryan J Ollos, 7 months ago

The exception

Exception TypeError: TypeError("'NoneType' object is not callable",) in <bound method apr_pool_t.__del__ of <libsvn.core.apr_pool_t; proxy of <Swig Object of type 'apr_pool_t *' at 0x7f52aeb14de0> >> ignored

was also reported in #13261.

comment:2 by Jun Omae, 7 months ago

Owner: set to Jun Omae
Status: newassigned

Proposed changes in [5f8aa2dff/jomae.git].

In the changes, our Pool class changes simple wrapper of svn.core.apr_pool_t object because the apr_pool_t class has the same logic of our Pool class.

$ make python=39 unit-test functional-test
SKIP_FUNCTIONAL_TESTS=1 python  -m unittest  trac.test.test_suite
...
----------------------------------------------------------------------
Ran 2742 tests in 40.573s

OK (skipped=5)
python  -m unittest  trac.tests.functional.test_suite
...
----------------------------------------------------------------------
Ran 221 tests in 460.105s

OK
$ wc -l testenv/testing.log
2577 testenv/testing.log
$ grep -c 'destroyed' testenv/testing.log
0

comment:3 by Ryan J Ollos, 6 months ago

The changes look good. Just curious, what is the reason for wrapping core.Pool from bindings/ctypes-python/csvn/core/__init__.py rather than using core.Pool directly?

comment:4 by Jun Omae, 6 months ago

Trac passes the pool object to Subversion API via Pool.__call__. I thought avoiding to change calls of the method by keeping Pool.__call__ method.

-        root_path_utf8 = repos.svn_repos_find_root_path(path_utf8, self.pool())
+        root_path_utf8 = repos.svn_repos_find_root_path(path_utf8, self.pool)

Though, I tried to remove our Pool class, jomae.git@t13356-remove-pool-class. However, after the changes, the memory pool is not released. I'm not sure why.

Memory profiles of sync with local mirror of Genshi Subversion repository

Trac Subversion Increment on repos.sync()
1.4-stable 1.9 27.9 MiB
1.4-stable 1.10 31.0 MiB
1.4-stable 1.14 31.4 MiB
trunk 1.14 21.9 MiB
t13356 1.14 23.8 MiB
t13356-remove-pool-class 1.14 102.3 MiB

memprof.py script

# -*- coding: utf-8 -*-

import sys
import memory_profiler
import tempfile
from trac.env import Environment
from trac.test import rmtree
from trac.versioncontrol.api import RepositoryManager


@memory_profiler.profile
def main(envpath, svnrepos):
    options = [
        ('project', 'name', 'Memory profile'),
        ('trac', 'database', 'sqlite:db/trac.db'),
        ('components', 'tracopt.versioncontrol.svn', 'enabled'),
    ]
    env = Environment(envpath, create=True, options=options)
    env.config.set('repositories', '.type', 'svn')
    env.config.set('repositories', '.dir', svnrepos)
    env.config.save()
    env.shutdown()
    env = None
    env = Environment(envpath)
    rm = RepositoryManager(env)
    repos = rm.get_repository('')
    repos.sync()


try:
    tmpdir = tempfile.mkdtemp(prefix='trac-')
    main(tmpdir, sys.argv[1])
finally:
    rmtree(tmpdir)

t13356-remove-pool-class with Subversion 1.14

Filename: /home/jun66j5/src/tracdev/git/memprof.py

Line #    Mem usage    Increment  Occurences   Line Contents
============================================================
    11     33.9 MiB     33.9 MiB           1   @memory_profiler.profile
    12                                         def main(envpath, svnrepos):
    13     33.9 MiB      0.0 MiB           1       options = [
    14                                                 ('project', 'name', 'Memory profile'),
    15                                                 ('trac', 'database', 'sqlite:db/trac.db'),
    16                                                 ('components', 'tracopt.versioncontrol.svn', 'enabled'),
    17                                             ]
    18     50.6 MiB     16.7 MiB           1       env = Environment(envpath, create=True, options=options)
    19     50.6 MiB      0.0 MiB           1       env.config.set('repositories', '.type', 'svn')
    20     50.6 MiB      0.0 MiB           1       env.config.set('repositories', '.dir', svnrepos)
    21     50.6 MiB      0.0 MiB           1       env.config.save()
    22     50.6 MiB      0.0 MiB           1       env.shutdown()
    23     50.6 MiB      0.0 MiB           1       env = None
    24     51.4 MiB      0.8 MiB           1       env = Environment(envpath)
    25     51.4 MiB      0.0 MiB           1       rm = RepositoryManager(env)
    26     57.2 MiB      5.8 MiB           1       repos = rm.get_repository('')
    27    159.5 MiB    102.3 MiB           1       repos.sync()

comment:5 by Ryan J Ollos, 6 months ago

Thanks for sharing the profiling script. Seems best to go ahead with the proposed changes for 1.5.3.

comment:6 by Jun Omae, 6 months ago

I noticed root cause of that memory pool is not released during repository sync with Subversion repository. repos.ChangeCollector() instance is not finalized after it is passed to svn.delta.make_editor(). The class and the method are used in SubversionChangeset.get_changes().

Workaround is to clear editor.__dict__ for ref-count leak due to delta.make_editor().

Test script

# -*- coding: utf-8 -*-

from svn import core, delta, fs, repos
import sys
import weakref


def main(*args):
    pool = core.Pool(core.application_pool)
    repos_ptr = repos.open(args[0].encode('utf-8'), pool)
    fs_ptr = repos.fs(repos_ptr)
    do_replay(fs_ptr, 1, pool)


def do_replay(fs_ptr, rev, pool):
    root_ptr = fs.revision_root(fs_ptr, rev, pool)
    editor = repos.ChangeCollector(fs_ptr, root_ptr, pool)
    editor_ref = weakref.ref(editor)
    e_ptr, e_baton = delta.make_editor(editor, pool)
    # repos.replay(root_ptr, e_ptr, e_baton, pool)
    del root_ptr, editor, e_ptr, e_baton
    assert editor_ref() is None

if __name__ == '__main__':
    main(*sys.argv[1:])

Result

$ ~/venv/py39/bin/python fs-root.py ~/var/svn/genshi.edgewall.org
Traceback (most recent call last):
  File "/home/jun66j5/src/tracdev/git/fs-root.py", line 70, in <module>
    main(*sys.argv[1:])
  File "/home/jun66j5/src/tracdev/git/fs-root.py", line 12, in main
    do_replay(fs_ptr, 1, pool)
  File "/home/jun66j5/src/tracdev/git/fs-root.py", line 22, in do_replay
    assert editor_ref() is None
AssertionError

New proposed changes in log:jomae.git@t13356-remove-pool-class.v2 (diff).

Trac Subversion Increment on repos.sync()
trunk 1.14 21.9 MiB
t13356-remove-pool-class.v2 1.14 17.3 MiB

comment:7 by Ryan J Ollos, 6 months ago

Nice, that looks difficult to have tracked down. I ran the tests on macOS and they pass.

comment:8 by Jun Omae, 6 months ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

Committed in [17519].

The memory leak on repository sync has been reported in #13112,​13129.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Jun Omae.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Jun Omae to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.