[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

Re: Thoughts on bug 969327 - possible threading problem



Just for posterity, having (I think) solved this problem, I'd like to
explain what I did.

> Notice that in both sets of anaconda logs the "spoke is ready: ..." and
> "setting <object> status to: ..." come in batches, right next to each
> other. They are nowhere near the threads that send the messages, most
> are happening after their associated threads are actually done.
> 
> This could be a logging artifact, maybe they just aren't being logged
> until later for some reason. But since the reporters are seeing actual
> problems I am suspicious that something is holding up hubQ and it is
> processing them all at about the same time.

What's going on here is that the logging messages are generated at the
end of some branch of the case in _update_spokes.  This was only getting
run once per second (I bumped it to 100ms in my patch), which
necessarily means the messages are going to get logged a long ways off
from where the messages get enqueued.

Long story short, we can't actually trust our logging of this kind of
stuff.  We could, perhaps, do the logging when the messages are enqueued
instead of when they are processed.  That'd make our logging make more
sense, but would mean the log would be less coupled to the actual state
of the UI.

> Anyone have any ideas for debugging this?

Our hunch was that the problem was the storage execute thread was
running multiple times.  Thus I worked backwards from it - figure out
exactly where an execute method can be run.  There's three places in
hubs/__init__.py where that happens.  Given that our logging is
unreliable, I just added print statements that showed what spoke was
executing and what method in __init__.py was calling execute.

Sure enough, a couple were getting called multiple times - from
_createBox and from _update_spokes.  This is because certain spokes have
a changed method that always returns True.  I couldn't change that
without breaking other things (git log on spokes/storage.py for
explanation), so I just introduced another attribute that prevents
execute from running if the spoke hasn't actually been visited since
execute last ran.

- Chris


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]