[Twisted-Python] Second try at reporting gtk reactor problem

[David E. Konerding]

exarkun at divmod.com wrote:

>On Fri, 27 Feb 2004 08:17:31 -0800, "David E. Konerding" <dekonerding at 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 at 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