Skip to content

Write message tracking events in order on one thread - #638

Open
JakeHuneau wants to merge 1 commit into
OpenAS2:masterfrom
JakeHuneau:fix/tracking-write-order
Open

JakeHuneau wants to merge 1 commit into
OpenAS2:masterfrom
JakeHuneau:fix/tracking-write-order

Conversation

@JakeHuneau

Copy link
Copy Markdown
Collaborator

Fixes #517.

Problem

BaseMsgTrackingModule.handle writes each tracking event on a new thread of its own, so processing a message doesn't wait on the database. DbTrackingModule.persist is synchronized. So when one write is slow, the threads behind it queue on the lock and take it in no particular order.

Under load, a message's events can be written out of order and an earlier state can overwrite a later one. That's what #517 reports: a message that has received its MDN is left with the state from "sending started".

Change

  • One writer per module: BaseMsgTrackingModule hands each event to a single-thread executor of its own. Writes stay off the processing thread and happen in the order the events were handled. The thread is a daemon, so it never keeps the JVM alive.
  • Shutdown waits for queued writes: the tracking module is an ActiveModule, so the shutdown drain from Finish files being sent before shutting down, and report the ones cut off #625 already calls its awaitIdle with the shared deadline, after the pollers have finished their sends. awaitIdle now waits until the events queued so far are written, so a message sent just before shutdown keeps its tracking record. (Previously those writes were on independent threads that nothing waited for.)
  • Stop and restart: DbTrackingModule.stop stops the writer, and start gives a restarted module a new one. An event handled after the writer has stopped is written directly instead of being dropped.

Your comment on #517 mentions moving tracking onto a queue in 5.0. This is a minimal version of that which fixes the ordering now, and it should fold into that work.

Tests

TrackingWriteOrderTest uses a recording tracker whose persist is synchronized like DbTrackingModule's:

  • Order: 200 events, with the first write slow so the rest queue behind it. With the previous thread per event, all 200 were written but out of order, in 3 runs out of 3. They're now written in order. The test counts writes rather than calling awaitIdle, so it checks only the order.
  • Handling an event doesn't wait for the write.
  • awaitIdle waits for the events already handled, and gives up at its timeout.
  • An event after the writer is stopped is written directly, not lost.
  • A restarted module writes in the background again.
  • session.drainWorkInProgress waits for queued tracking events.

Mutation checks: each of these changes fails at least one test:

  • restoring thread-per-event
  • awaitIdle not waiting
  • dropping late events
  • a restarted module keeping a stopped writer

Full suite: 253 tests pass.

Each tracking event was written on a new thread of its own so that processing
a message did not wait on the database. DbTrackingModule.persist is
synchronized, so when a write was slow the threads behind it queued on the
lock and took it in no particular order. Under load a message's events could
be written out of order and an earlier state overwrite a later one, which is
what issue OpenAS2#517 reports: a message that had received its MDN left recorded
with the state of "sending started".

BaseMsgTrackingModule now hands each event to a single-thread executor of its
own, so the writes stay off the processing thread and happen in the order the
events were handled. The thread is a daemon so it never keeps the JVM alive.

The tracking module is an ActiveModule, so the shutdown drain added in OpenAS2#625
already calls its awaitIdle with the shared deadline after the pollers have
finished their sends. awaitIdle now waits for the events queued so far to be
written, so the record of a message sent just before shutting down is not
lost. DbTrackingModule.stop stops the writer and start gives a restarted
module a new one; an event handled after the writer has stopped is written
directly rather than dropped.

The maintainer's comment on OpenAS2#517 mentions moving tracking onto a queue in 5.0;
this is the minimal form of that and should fit into it.

TrackingWriteOrderTest writes 200 events through a tracker whose synchronized
persist is slow on the first write. With the previous thread per event all
200 were written but out of order in three runs out of three; it now writes
them in order. The other tests cover not blocking the caller, awaitIdle and
its timeout, writing directly after stopping, restarting, and shutdown
waiting for queued events.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

DbTrackingModule - not synchronized well under pressure

1 participant