Re: Missing stack frames?
Chris Angelico ros...@gmail.com writes: On Fri, Jun 6, 2014 at 12:16 PM, Nikolaus Rath nikol...@rath.org wrote: - Is there some way to make the call stack for destructors less confusing? First off, either don't have refloops, or explicitly break them. The actual code isn't as simple as the example. I wasn't even aware there were any refloops. Guess I have to start hunting them down now. That'll at least make things a bit more predictable; in CPython, you'll generally see destructors called as soon as something goes out of scope. Secondly, avoid threads when you're debugging a problem! I said this right at the beginning. If you run into problems, the first thing to do is isolate the system down to a single thread. Debugging is way easier without threads getting in each other's ways. I don't see how this would have made a difference in this case. I still would have gotten lots of apparently non-sensical backtraces. Only this time they would all come from MainThread. Best, -Nikolaus -- GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F »Time flies like an arrow, fruit flies like a Banana.« -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Nikolaus Rath nikol...@rath.org writes: ... Is there a way to produce a stacktrace without using the interactive debugger? There is the threadframe package (on PyPI). It has helped me much to analyse problems in multithreaded programs (e.g. as part of haufe.requestmonitoring). However, I doubt that it will help in your case: I also have used interactive debugging for multithreaded programs; it is true that is sometimes very difficult (especially when the debugger gets activated in several threads at once and I no longer know which debugger instance gets my input) but I never observed that stack frames have been lost: in fact, I do not see any reason why the debugger could do that: the debugger activity is part of the thread being debugged and the stack frames are thread local, i.e. they cannot be modified by other threads -- thus, the debugger should see a consitent stack, independently of what other threads do. C extensions can cause stack frames to (apparently) be missed. The Python stack is a linked list of frames the head of which is maintained in the thread description. When Python calls a Python function, it pushes a new stack frame onto this stack. However, when a C function is called, this usually does not have an associated stack frame. When the C function calls a Python function, a stack frame for it is pushed and looking at the stack frames, it appears as if the Python function has been called at the place of the C function. From the information you have provided in this discussion, I cannot see whether this can explain your observations: In your case, C extensions may be involved but they should not call back to Python functions. Someone else already mentioned that the close call can come from a destructor. Destructors can easily be called at not obvious places (e.g. s = C(); ... x = [s for s in ...]; in this example the list comprehension calls the C destructor which is not obvious when one looks only locally). The destructor calls often have intervening C code (which one does not see). However, in your case, I do not see why the cgi module should cause a destructor call of one of your server components. To summarize: I am as confused by your observations as you are and cannot give a satisfactory explanation. -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Paul Rubin no.email@nospam.invalid writes: Nikolaus Rath nikol...@rath.org writes: Still no context before the ominous close() call. I'm very confused. close() could be getting called from a destructor as the top level function of a thread exits, or something like that. Shouldn't the destructor have its own stack frame then, i.e. shouldn't the first frame be in a __del__ function? Best, -Nikolaus -- GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F »Time flies like an arrow, fruit flies like a Banana.« -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Nikolaus Rath nikol...@rath.org writes:
Chris Angelico ros...@gmail.com writes:
On Wed, Jun 4, 2014 at 12:30 PM, Nikolaus Rath nikol...@rath.org wrote:
I've instrumented one of my unit tests with a conditional
'pdb.set_trace' in some circumstances (specifically, when a function is
called by a thread other than MainThread).
I think the likelihood of this being an issue with interactive
debugging and threads is sufficiently high that you should avoid
putting the two together, at least until you can verify that the same
problem occurs without that combination.
Here's stacktrace as obtained by traceback.print_stack():
tests/t1_backends.py:563: test_extra_data[mock_s3c-zlib] PASSED
tests/t1_backends.py:563: test_extra_data[mock_s3c-bzip2] PASSED
87 tests deselected by '-kextra'
=
=== 5 passed, 1 skipped, 87 deselected in 0.65 seconds
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
853, in close
self.fh.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691,
in close
traceback.print_stack(file=sys.stdout)
something is wrong
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
853, in close
self.fh.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691,
in close
traceback.print_stack(file=sys.stdout)
something is wrong
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
1050, in close
self.fh.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691,
in close
traceback.print_stack(file=sys.stdout)
Still no context before the ominous close() call. I'm very confused.
It get's even funnier if I just repeat this exercise (without changing
code). Here are some more tracebacks that I got:
File /usr/bin/py.test-3, line 5, in module
sys.exit(load_entry_point('pytest==2.5.2', 'console_scripts', 'py.test')())
[...]
File /usr/lib/python3/dist-packages/py/_code/code.py, line 524, in
repr_traceback_entry
source = self._getentrysource(entry)
File /usr/lib/python3/dist-packages/py/_code/code.py, line 450, in
_getentrysource
source = entry.getsource(self.astcache)
File /usr/lib/python3/dist-packages/py/_code/code.py, line 199, in getsource
astnode=astnode)
File /usr/lib/python3/dist-packages/py/_code/source.py, line 367, in
getstatementrange_ast
astnode = compile(content, source, exec, 1024) # 1024 for AST
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
1050, in close
self.fh.close_real()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 702, in
close_real
traceback.print_stack(file=sys.stdout)
or also
File /usr/bin/py.test-3, line 5, in module
sys.exit(load_entry_point('pytest==2.5.2', 'console_scripts', 'py.test')())
[...]
File /usr/lib/python3.4/logging/__init__.py, line 1474, in callHandlers
hdlr.handle(record)
File /usr/lib/python3.4/logging/__init__.py, line 842, in handle
rv = self.filter(record)
File /usr/lib/python3.4/logging/__init__.py, line 699, in filter
for f in self.filters:
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 853,
in close
self.fh.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
1050, in close
self.fh.close_real()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 702, in
close_real
traceback.print_stack(file=sys.stdout)
and this one looks actually the way I would expect:
[...]
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 335,
in fetch
return self.perform_read(do_read, key)
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 58,
in wrapped
return method(*a, **kw)
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 309,
in perform_read
return fn(fh)
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 859,
in __exit__
self.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 853,
in close
self.fh.close()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line
1050, in close
self.fh.close_real()
File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 702, in
close_real
traceback.print_stack(file=sys.stdout)
I am not using any C extension modules, but I guess I nevertheless have
to assume that something seriously messed up either the stack or the
traceback printing routines?
Best,
Nikolaus
--
GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F
Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F
»Time flies like an arrow, fruit flies like a Banana.«
--
https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
dieter die...@handshake.de writes:
[...]
Someone else already mentioned that the close call
can come from a destructor. Destructors can easily be called
at not obvious places (e.g. s = C(); ... x = [s for s in ...];
in this example the list comprehension calls the C destructor
which is not obvious when one looks only locally).
The destructor calls often have intervening C code (which
one does not see). However, in your case, I do not see
why the cgi module should cause a destructor call of one
of your server components.
Paul, dieter, you are my heroes. It was indeed an issue with a
destructor. It turns out that the io.RawIOBase destructor calls
self.close(). If the instance of a derived class is part of a reference
cycle, it gets called on the next routine run of the garbage
collector -- with the stack trace originating at whatever statement was
last executed before the gc run.
The following minimal example reproduces the problem:
#!/usr/bin/env python3
import io
import traceback
import threading
class Container:
pass
class InnocentVictim(io.RawIOBase):
def close(self):
print('close called in %s by:'
% threading.current_thread().name)
traceback.print_stack()
def busywork():
numbers = []
for i in range(500):
o = Container()
o.l = numbers
numbers.append(o)
if i % 87 == 0:
numbers = []
l = [ InnocentVictim() ]
l[0].cycle = l
del l
t = threading.Thread(target=busywork)
t.start()
t.join()
If you run this, you could things like:
close called in Thread-1 by:
File /usr/lib/python3.4/threading.py, line 888, in _bootstrap
self._bootstrap_inner()
File /usr/lib/python3.4/threading.py, line 920, in _bootstrap_inner
self.run()
File /usr/lib/python3.4/threading.py, line 868, in run
self._target(*self._args, **self._kwargs)
File ./test.py, line 18, in busywork
o = Container()
File ./test.py, line 13, in close
traceback.print_stack()
Ie, a method being called by a thread that doesn't have access to the
object, and without any reference to the call in the source.
I am left wondering:
- Is there really a point in the RawIOBase destructor calling close?
- Is there some way to make the call stack for destructors less confusing?
Best,
-Nikolaus
--
GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F
Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F
»Time flies like an arrow, fruit flies like a Banana.«
--
https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
On Fri, Jun 6, 2014 at 12:16 PM, Nikolaus Rath nikol...@rath.org wrote: - Is there some way to make the call stack for destructors less confusing? First off, either don't have refloops, or explicitly break them. That'll at least make things a bit more predictable; in CPython, you'll generally see destructors called as soon as something goes out of scope. Secondly, avoid threads when you're debugging a problem! I said this right at the beginning. If you run into problems, the first thing to do is isolate the system down to a single thread. Debugging is way easier without threads getting in each other's ways. ChrisA -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Chris Angelico ros...@gmail.com writes: On Wed, Jun 4, 2014 at 12:30 PM, Nikolaus Rath nikol...@rath.org wrote: I've instrumented one of my unit tests with a conditional 'pdb.set_trace' in some circumstances (specifically, when a function is called by a thread other than MainThread). I think the likelihood of this being an issue with interactive debugging and threads is sufficiently high that you should avoid putting the two together, at least until you can verify that the same problem occurs without that combination. Is there a way to produce a stacktrace without using the interactive debugger? Best, -Nikolaus -- GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F »Time flies like an arrow, fruit flies like a Banana.« -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Nikolaus Rath nikol...@rath.org writes: Is there a way to produce a stacktrace without using the interactive debugger? Yes, use the traceback module. -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Chris Angelico ros...@gmail.com writes: On Wed, Jun 4, 2014 at 12:30 PM, Nikolaus Rath nikol...@rath.org wrote: I've instrumented one of my unit tests with a conditional 'pdb.set_trace' in some circumstances (specifically, when a function is called by a thread other than MainThread). I think the likelihood of this being an issue with interactive debugging and threads is sufficiently high that you should avoid putting the two together, at least until you can verify that the same problem occurs without that combination. Here's stacktrace as obtained by traceback.print_stack(): tests/t1_backends.py:563: test_extra_data[mock_s3c-zlib] PASSED tests/t1_backends.py:563: test_extra_data[mock_s3c-bzip2] PASSED 87 tests deselected by '-kextra' = === 5 passed, 1 skipped, 87 deselected in 0.65 seconds File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 853, in close self.fh.close() File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691, in close traceback.print_stack(file=sys.stdout) something is wrong File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 853, in close self.fh.close() File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691, in close traceback.print_stack(file=sys.stdout) something is wrong File /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py, line 1050, in close self.fh.close() File /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py, line 691, in close traceback.print_stack(file=sys.stdout) Still no context before the ominous close() call. I'm very confused. Best, -Nikolaus -- GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F »Time flies like an arrow, fruit flies like a Banana.« -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
Nikolaus Rath nikol...@rath.org writes: Still no context before the ominous close() call. I'm very confused. close() could be getting called from a destructor as the top level function of a thread exits, or something like that. -- https://mail.python.org/mailman/listinfo/python-list
Missing stack frames?
Hello, (This may or may not be related to my mail about a corrupted stack trace). I've instrumented one of my unit tests with a conditional 'pdb.set_trace' in some circumstances (specifically, when a function is called by a thread other than MainThread). However, when trying to print a back trace to figure out how this function got called, I get this: $ py.test-3 tests/t1_backends.py -k extra === test session starts === platform linux -- Python 3.3.5 -- py-1.4.20 -- pytest-2.5.2 -- /usr/bin/python3 collected 33 items tests/t1_backends.py:563: test_extra_data[mock_s3c-plain] SKIPPED tests/t1_backends.py:563: test_extra_data[mock_s3c-zlib] PASSED 31 tests deselected by '-kextra' = === 1 passed, 1 skipped, 31 deselected in 0.23 seconds /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py(693)close() - if not self.md5_checked: (Pdb) bt /home/nikratio/in-progress/s3ql/src/s3ql/backends/common.py(853)close() - self.fh.close() /home/nikratio/in-progress/s3ql/src/s3ql/backends/s3c.py(693)close() - if not self.md5_checked: (Pdb) q What does this mean? Why is there no caller above the backends/common.py code? At the very least, I would have expected some frames from threading.py...? Best, -Nikolaus -- GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F »Time flies like an arrow, fruit flies like a Banana.« -- https://mail.python.org/mailman/listinfo/python-list
Re: Missing stack frames?
On Wed, Jun 4, 2014 at 12:30 PM, Nikolaus Rath nikol...@rath.org wrote: I've instrumented one of my unit tests with a conditional 'pdb.set_trace' in some circumstances (specifically, when a function is called by a thread other than MainThread). I think the likelihood of this being an issue with interactive debugging and threads is sufficiently high that you should avoid putting the two together, at least until you can verify that the same problem occurs without that combination. ChrisA -- https://mail.python.org/mailman/listinfo/python-list
