quetz-mod_python-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nicolas Lehuen <nicolas.leh...@gmail.com>
Subject Re: session handling - the next generation
Date Sun, 12 Jun 2005 14:41:18 GMT
Hi Jim,

How where you creating the session object in requestobject.c ? If you
were using PythonObject_New, then this may explain the memory leak.
Objects that must be managed by the garbage collector have to be
created with PyObject_GC_New.

Regards,

Nicolas

2005/6/12, Jim Gallacher <jg.lists@sympatico.ca>:
> Replying to my own email,
> 
> It looks like there was problem with a circular reference in
> req->session->req. This resulted in a memory leak which I had
> mis-interpreted as a reference count problem in req_get_session.
> 
> As a result, I was not doing a Py_INCREF(self->session) in
> req_get_session(). This resulted in the intermittent segfault. (I  just
> *knew* I was going to screw up the reference counting. :) )
> 
> Refactoring TestSession to remove saved reference to the request object
> fixed the memory leak problem. Adding Py_INCREF(self->session) in
> req_get_session() fixed the segfault problem.
> 
> I still don't understand why the memory lead only occurs when the
> session object is created in requestobject.c and not when created
> directly in a python script, but there you go.
> 
> Jim
> 
> Jim Gallacher wrote:
> > Hi All,
> >
> > Sorry for the long post, but I think I have a nice contribution to the
> > session handling mechanism, but I've got a bug I just can't track down.
> > Make yourself a cup of coffee, sit down and have a read.
> >
> > In an effort to make session handling more transparent and less error
> > prone, I've added a new method called get_session to the request object.
> >
> > (As an aside, I've also created a new apache config directive
> > PythonSessionOptions, a req.get_session_options() to read the directive,
> > and a small internal change to req.internal_redirect() to pass a session
> > to a redirected request).
> >
> > req.get_session() returns the session instance if it exists or creates a
> > new one. Internally it calls some python code,
> > mod_python.Session.create_session(), which does the actual work. The
> > user will only use get_session() to access their session, and so all our
> > deadlocking issues are gone forever.
> >
> > It mostly works, but I've found that approx 1 in 10000 requests will
> > segfault. Calling mod_python.Session.create_session directly does not
> > segfault (tested for 2000000 requests) so that is not the issue.
> >
> > I really hope someone can spot where the problem is. I've reduced
> > everything to the simplest possible case. The unlock method in
> > TestSession very rarely segfault or raise an exception and then
> > segfault, but very rarely. It only fails 0.004% of the time based on
> > 500000 requests. I suspect some kind of garbage collection issue, maybe
> > a circular reference caused by req->session->_req, but I don't
> > understand why it works 99.996 % of the time.
> >
> > I've included the full error.log for 5000000 requests at the end of this
> > message, but the ones that caught my eye as unusual are:
> >
> > [Tue Jun 07 17:52:02 2005] [notice] child pid 15066 exit signal
> > Segmentation fault (11)
> > Fatal Python error: deletion of interned string failed
> >
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: Traceback (most recent call last):
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
> > line 299, in HandlerDispatch\n    result = object(req)
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/var/www/mp/mptest.py", line 19, in handler\n    sess =
> > req.get_session()
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File
> > "/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 46,
> > in create_session\n    return TestSession(req,sid)
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File
> > "/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 40,
> > in unlock\n    if self._lock and self._locked:
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: AttributeError: 'TestSession' object has no attribute '_lock'
> >
> > [Tue Jun 07 18:04:03 2005] [notice] child pid 16170 exit signal
> > Segmentation fault (11)
> > Fatal Python error: GC object already tracked
> >
> >
> > I hope someone can give me some insight to the problem. Note that I'm
> > using mpm-worker.
> >
> > Regards,
> > Jim
> >
> > ------------------------------------------------------------------------
> > mptest.py
> > # the test handler
> >
> > from mod_python import apache
> > from mod_python import TestSession
> >
> > def handler(req):
> >     req.content_type = 'text/plain'
> >     req.write('mptest.py')
> >
> >     if req.path_info:
> >         test_case = req.path_info[1:]
> >     else:
> >         test_case = '1'
> >
> >     if test_case == '1':
> >         # the good case - always works
> >         sess = TestSession.create_session(req,None)
> >     elif test_case == '2':
> >         # the bad case - sometimes segfaults
> >         sess = req.get_session()
> >     else:
> >         req.write('no test specified')
> >
> >     return apache.OK
> >
> > ---------------------------------------------------------------------------------------------------
> >
> > mod_python/TestSession.py
> > # emulate a simple test session
> > import _apache
> > from Session import _new_sid
> >
> > class TestSession(object):
> >
> >     def __init__(self, req, sid=0, secret=None, timeout=0, lock=1):
> >         req.log_error("TestSession.__init__")
> 
>            ### CIRCULAR REFERENCE  self._req = req
>            ### causes memory leak
> >         self._req = req
>            ###
> 
> >         self._lock = 1
> >         self._locked = 0
> >         self._sid = _new_sid(req)
> >         self.lock()
> >         self.unlock()
> >
> >     def lock(self):
> >         if self._lock:
> >             _apache._global_lock(self._req.server, self._sid)
> >             self._locked = 1
> >
> >     def unlock(self):
> >         # unlock will ocassionally segfault
> >         if self._lock and self._locked:
> >             _apache._global_unlock(self._req.server, self._sid)
> >             self._locked = 0
> >
> > def create_session(req,sid):
> >     return TestSession(req,sid)
> >
> > -------------------------------------------------------------------------------------------------
> >
> > src/requestobject.c
> > In the following code session is a PyObject* defined in the the
> > requestobject struct.
> >
> > static PyObject *req_get_session(requestobject *self, PyObject *args)
> > {
> >     PyObject *m;
> >     PyObject *sid;
> >
> >     if (!self->session) {
> >         m = PyImport_ImportModule("mod_python.TestSession");
> >         /* is this redirected request with an existing session? */
> >         sid = PyObject_CallMethod(self->subprocess_env, "get",
> > "(ss)","REDIRECT_PYSID", "");
> >
> >         self->session = PyObject_CallMethod(m, "create_session", "(OO)",
> > self, sid);
> >         Py_DECREF(m);
> >         Py_DECREF(sid);
> >         if (self->session == NULL)
> >             return NULL;
> >     }
> 
>        // increase ref count to fix segfault problem
>        Py_INCREF(self->session);
> 
> >     return self->session;
> > }
> >
> > --------------------------------------------------------------------------------------------------------
> >
> > /var/log/apache2/error.log
> >
> > The full error log for approx 500000 requests (generated using grep -v
> > "TestSession.__init" error.log).
> >
> > [Tue Jun 07 16:35:32 2005] [notice] mod_python: Creating 32 session
> > mutexes based on 6 max processes and 25 max threads.
> > [Tue Jun 07 16:35:32 2005] [notice] Apache/2.0.54 (Debian GNU/Linux)
> > mod_python/3.2.0-dev-20050519 Python/2.3.5 configured -- resuming normal
> > operations
> > [Tue Jun 07 16:35:49 2005] [notice] child pid 11540 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 16:35:49 2005] [notice] child pid 11545 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 16:36:05 2005] [notice] child pid 11601 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 16:46:21 2005] [notice] child pid 11629 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 16:46:35 2005] [notice] child pid 11949 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:04:07 2005] [notice] child pid 12454 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:11:47 2005] [notice] child pid 12351 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:18:08 2005] [notice] child pid 12342 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:18:20 2005] [notice] child pid 13057 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:34:48 2005] [notice] child pid 12859 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:36:35 2005] [notice] child pid 13599 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:38:10 2005] [notice] child pid 13698 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:39:02 2005] [notice] child pid 13764 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:39:13 2005] [notice] child pid 13819 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:39:15 2005] [notice] child pid 13810 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:40:02 2005] [notice] child pid 13917 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:41:03 2005] [notice] child pid 13048 exit signal
> > Segmentation fault (11)
> > Fatal Python error: GC object already tracked
> > [Tue Jun 07 17:42:41 2005] [notice] child pid 14016 exit signal Aborted (6)
> > Fatal Python error: GC object already tracked
> > [Tue Jun 07 17:45:10 2005] [notice] child pid 14321 exit signal Aborted (6)
> > [Tue Jun 07 17:48:01 2005] [notice] child pid 14439 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:48:49 2005] [notice] child pid 14508 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:50:03 2005] [notice] child pid 14615 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:50:03 2005] [notice] child pid 14672 exit signal
> > Segmentation fault (11)
> > Fatal Python error: GC object already tracked
> > [Tue Jun 07 17:50:53 2005] [notice] child pid 14665 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:50:53 2005] [notice] child pid 14758 exit signal Aborted (6)
> > [Tue Jun 07 17:51:18 2005] [notice] child pid 14800 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:18 2005] [notice] child pid 14832 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:18 2005] [notice] child pid 14864 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:20 2005] [notice] child pid 14893 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:21 2005] [notice] child pid 14921 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:21 2005] [notice] child pid 14928 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:23 2005] [notice] child pid 14977 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:51:24 2005] [notice] child pid 15006 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:52:02 2005] [notice] child pid 15066 exit signal
> > Segmentation fault (11)
> > Fatal Python error: deletion of interned string failed
> > [Tue Jun 07 17:53:06 2005] [notice] child pid 15109 exit signal Aborted (6)
> > Fatal Python error: deletion of interned string failed
> > [Tue Jun 07 17:53:55 2005] [notice] child pid 15210 exit signal Aborted (6)
> > [Tue Jun 07 17:54:03 2005] [notice] child pid 15104 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:54:05 2005] [notice] child pid 15312 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:54:17 2005] [notice] child pid 15405 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:55:04 2005] [notice] child pid 15437 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:55:04 2005] [notice] child pid 15483 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:55:17 2005] [notice] child pid 15563 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: Traceback (most recent call last):
> > [Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
> > line 287, in HandlerDispatch\n    log=debug)
> > [Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
> > line 422, in import_module\n    module = sys.modules[module_name]
> > [Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: KeyError: 'mptest'
> > [Tue Jun 07 17:55:58 2005] [notice] child pid 15474 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:56:08 2005] [notice] child pid 15600 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:56:08 2005] [notice] child pid 15644 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:57:08 2005] [notice] child pid 15730 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:57:10 2005] [notice] child pid 15778 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:57:44 2005] [notice] child pid 15772 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:58:11 2005] [notice] child pid 15902 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:58:21 2005] [notice] child pid 15945 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: Traceback (most recent call last):
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
> > line 299, in HandlerDispatch\n    result = object(req)
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File "/var/www/mp/mptest.py", line 19, in handler\n    sess =
> > req.get_session()
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File
> > "/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 46,
> > in create_session\n    return TestSession(req,sid)
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest:   File
> > "/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 40,
> > in unlock\n    if self._lock and self._locked:
> > [Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
> > mptest: AttributeError: 'TestSession' object has no attribute '_lock'
> > [Tue Jun 07 17:59:38 2005] [notice] child pid 15939 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:02:59 2005] [notice] child pid 15865 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:02:59 2005] [notice] child pid 16051 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:03:02 2005] [notice] child pid 16142 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:04:03 2005] [notice] child pid 16170 exit signal
> > Segmentation fault (11)
> > Fatal Python error: GC object already tracked
> > [Tue Jun 07 18:04:16 2005] [notice] child pid 16248 exit signal Aborted (6)
> > [Tue Jun 07 18:04:40 2005] [notice] child pid 16285 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:05:15 2005] [notice] child pid 16318 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:16:49 2005] [notice] child pid 16573 exit signal
> > Segmentation fault (11)
> > [Tue Jun 07 18:17:50 2005] [notice] child pid 16924 exit signal
> > Segmentation fault (11)
> >
> 
>

Mime
View raw message