On 25/07/14 03:26, Gustavo Niemeyer wrote:
> Hey Ian,
>
> On Thu, Jul 24, 2014 at 4:03 AM, Ian Booth <ian.bo...@canonical.com> wrote:
>> However, doing a session.Copy() each time the transaction log collection is
>> queried (every 5 seconds) causes a number of test failures when the host
>> machine
>> is heavily loaded. Either extra events are received or events are missed.
>>
>> Can anyone explain what's going on here? Why does copying a session affect
>> what's read from the txn log collection?
>
> Would be good to have more details about the failure scenario, but I
> can provide a few general hints that have a chance of being helpful.
>
> What session.Copy does when a session is in Strong mode (the default
> one) is to take a new socket out of the pool, or to establish a new
> connection if that's required. So whatever side-effect you're
> observing is a direct consequence of that.
>
> One way this might be causing trouble, considering that we're talking
> about test cases that involve timing somehow, and that the scenario
> you describe is also of a heavily loaded system, is by skewing the
> clock. It's much more expensive to establish a new connection than to
> send data via a socket at hand.
>
> Another way it changes the situation is by increasing concurrency. If
> there are two tasks being concurrently done in Go but reaching out to
> the database via the same Strong session, they'll be serialized on
> their way out. With multiple Strong sessions, each has its own
> connection related to its own server thread, and can carry out the
> requests concurrently for longer.
>
> Please let me know if that helps or whether you have more details.
>
>
We've transitioned to using Session.Copy() to address the situation whereby Juju
would create a mongo collection instance and then continue to make db calls
against that collection without realising the underlying socket may have become
disconnected. This resulted in Juju components failing, logging "i/o timeout"
errors talking to mongo, even though mongo itself was still up and running.
Using the pattern:
s := session.Copy()
defer s.Close()
<do stuff with s>
seems to be the accepted pattern to ensure a fresh underlying socket is selected
from the socket pool maintained by the driver if needed. eg this is used
throughout the charm store.
As an aside - I'm wondering whether the mgo driver shouldn't transparently catch
an i/o error associated with a dead socket and retry using a fresh connection
rather than imposing that responsibility on the caller?
The watcher itself is a go routine managed using a tomb. It has a loop which is
run every 5 seconds to poll a transaction collection. The watcher will initially
grab the _id (lastId) of the most recent transaction record, then every 5
seconds:
iter := log.Find(nil).Batch(10).Sort("-$natural").Iter()
where log is session.DB.C("txns.log")
The code iterates over the log entries until the last known _id is reached. Any
newly added entries are turned into events. The application code which may add
new events to the log occurs using a different session.
The symptoms of the test failures are that extra events are sent, or not enough
events are sent. The lastId is calculated once when the watcher is started. From
that point, the log entries to process come from iterating over the collection
back to the last processed id, updating the last Id along the way so that the
next poll goes back to the right place etc.
The tests simply create and start a watcher, make a db change, and wait for the
watcher to emit events. If the expected events don't arrive in a given time, the
tests fail. So there's 2 go routines, one for the watcher polling loop and one
in which the test is run.
So it seems the socket copy causes the view of the underlying collection to
become "incorrect" somehow. eg newer added records are not seen, therefore they
are not processed and the expected events don't get sent out. I've tried adding
an extra delay to the test to allow the watcher to wake up one more time to poll
the log collection in case any new records would become visible then, but that
didn't help.
If session.Copy() doesn't work here, what's the approach to use to ensure the
watcher just doesn't become dead because the underlying socket dies? Or how can
we make the session.Copy() approach work always even when the host machine is
under high load? Or maybe watcher code is fine and the tests are wrong?
The tests are quite simple:
func (s *FastPeriodSuite) TestWatchAfterKnown(c *gc.C) {
// insert a new record to cause a new log entry to be created
revno := s.insert(c, "test", "a")
// start the watcher
s.w.StartSync()
// listen for changes
s.w.Watch("test", "a", -1, s.ch)
// this next line fails........
assertChange(c, s.ch, watcher.Change{"test", "a", revno})
assertNoChange(c, s.ch)
assertOrder(c, -1, revno)
}
func assertChange(c *gc.C, watch <-chan watcher.Change, want watcher.Change) {
select {
case got := <-watch:
if got != want {
c.Fatalf("watch reported %v, want %v", got, want)
}
case <-time.After(worstCase):
c.Fatalf("watch reported nothing, want %v", want)
}
}
--
Juju-dev mailing list
Juju-dev@lists.ubuntu.com
Modify settings or unsubscribe at:
https://lists.ubuntu.com/mailman/listinfo/juju-dev
