Re: [Twisted-Python] Second try at reporting gtk reactor problem
On Fri, 27 Feb 2004 08:17:31 -0800, "David E. Konerding" <dekonerding@lbl.gov> wrote:
Hello, since nobody actually responding with a useful message regarding my report, I'm reposting an extremely simple (1 page) example which exhibits the behavior. My example creates a gtkreactor and runs it. A small reporter class is run from a second thread. Under the gtk reactor, the log messages from the second thread are not reported in a timely fashion (only once per second or so). From my understanding the messages should be printed more frequently (about once every 1/10th second). This does work under the wx and plain reactors, so I suspect there is a defect in the gtk reactor. I would simply like to get a confirmation that my example is a valid one, that the results I expect are valid, and that other people can reproduce my experience. If that is the case then I will submit a formal bug report. All of this should be reproducible using Twisted 1.2.0. Things get even weirder if you remove the logging support and replace it with all print statements.
When I run this program, here is the output: exarkun@boson:~$ python p.py 2004/02/27 12:36 EST [-] Log opened. 2004/02/27 12:36 EST [-] 'ticker: 1077903388' 2004/02/27 12:36 EST [-] 'ticker: 1077903389' 2004/02/27 12:36 EST [-] 'ticker: 1077903390' 2004/02/27 12:36 EST [-] 'ThingyManager submitting' 2004/02/27 12:36 EST [-] TestThingy created 2004/02/27 12:36 EST [-] 'ThingyManager created' 2004/02/27 12:36 EST [-] 'ThingyManager calledInThread' 2004/02/27 12:36 EST [-] 'ticker: 1077903391' 2004/02/27 12:36 EST [-] 'ticker: 1077903392' 2004/02/27 12:36 EST [-] 'ticker: 1077903393' 2004/02/27 12:36 EST [-] 'ticker: 1077903394' 2004/02/27 12:36 EST [-] TestThingy run 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] 'ticker: 1077903395' 2004/02/27 12:36 EST [-] 'ticker: 1077903396' 2004/02/27 12:36 EST [-] 'ticker: 1077903397' 2004/02/27 12:36 EST [-] 'ticker: 1077903398' 2004/02/27 12:36 EST [-] 'ticker: 1077903399' 2004/02/27 12:36 EST [-] 'ticker: 1077903400' 2004/02/27 12:36 EST [-] 'ticker: 1077903401' 2004/02/27 12:36 EST [-] 'ticker: 1077903402' <- I hit ^C here 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy done 2004/02/27 12:36 EST [-] 'Reactor done' Jp
exarkun@divmod.com wrote:
On Fri, 27 Feb 2004 08:17:31 -0800, "David E. Konerding" <dekonerding@lbl.gov> wrote:
Hello, since nobody actually responding with a useful message regarding my report, I'm reposting an extremely simple (1 page) example which exhibits the behavior. My example creates a gtkreactor and runs it. A small reporter class is run from a second thread. Under the gtk reactor, the log messages from the second thread are not reported in a timely fashion (only once per second or so). From my understanding the messages should be printed more frequently (about once every 1/10th second). This does work under the wx and plain reactors, so I suspect there is a defect in the gtk reactor. I would simply like to get a confirmation that my example is a valid one, that the results I expect are valid, and that other people can reproduce my experience. If that is the case then I will submit a formal bug report. All of this should be reproducible using Twisted 1.2.0. Things get even weirder if you remove the logging support and replace it with all print statements.
When I run this program, here is the output:
exarkun@boson:~$ python p.py 2004/02/27 12:36 EST [-] Log opened. 2004/02/27 12:36 EST [-] 'ticker: 1077903388' 2004/02/27 12:36 EST [-] 'ticker: 1077903389' 2004/02/27 12:36 EST [-] 'ticker: 1077903390' 2004/02/27 12:36 EST [-] 'ThingyManager submitting' 2004/02/27 12:36 EST [-] TestThingy created 2004/02/27 12:36 EST [-] 'ThingyManager created' 2004/02/27 12:36 EST [-] 'ThingyManager calledInThread' 2004/02/27 12:36 EST [-] 'ticker: 1077903391' 2004/02/27 12:36 EST [-] 'ticker: 1077903392' 2004/02/27 12:36 EST [-] 'ticker: 1077903393' 2004/02/27 12:36 EST [-] 'ticker: 1077903394' 2004/02/27 12:36 EST [-] TestThingy run 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] 'ticker: 1077903395' 2004/02/27 12:36 EST [-] 'ticker: 1077903396' 2004/02/27 12:36 EST [-] 'ticker: 1077903397' 2004/02/27 12:36 EST [-] 'ticker: 1077903398' 2004/02/27 12:36 EST [-] 'ticker: 1077903399' 2004/02/27 12:36 EST [-] 'ticker: 1077903400' 2004/02/27 12:36 EST [-] 'ticker: 1077903401' 2004/02/27 12:36 EST [-] 'ticker: 1077903402' <- I hit ^C here 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy message 2004/02/27 12:36 EST [-] TestThingy done 2004/02/27 12:36 EST [-] 'Reactor done'
OK, precisely: you're not seeing TestThingy messages as frequently as they are should be generated, and when you hit ^C they start coming frequently (after the gtk mainloop is exited, I believe). Now the only thing is to determine whether there is any real problem with the example. The only remaining criticism I anticipate is the use of log. calls in the second thread, but removing them doesn't substantially change the problem (actually, it just exhibits a *different* kind of unexpected behavior). Dave
participants (2)
-
David E. Konerding -
exarkun＠divmod.com