Friday, August 23, 2013

Logging in parallel environment: identification of tasks without rewriting existing code

While working on parallel plugin support in a proprietary java execution framework
I was looking for a solution of having log messages produced by
tasks and other threads spawned by tasks have meaningful IDs that would
help one quickly identify groups of threads corresponding to a task.

So: single log file, multiple plugins, plugin may have multiple tasks,
task may create an unknown number of threads.  This is because while
we provide the parallel API to facilitate task creation, plugins
have their own freedom to create threads.

Ideally, we want the log file to have plugin id, and task id.
The problem is, when logging, how do we know what is the plugin id and task id.
When logger.log() is called, we have the stack frame, class loader, and
thread itself.  Looking further at these options:
1) Inspecting the entire stack frame and finding relevant objects on the stack
is too expensive
2) Classloader: we would have to have a classloader per task,
which we don't want to do since it interferes with other aspects of
the framework
3) Thread info: we have no control over thread creation, thread name, thread local.
E.g. we can't ensure that each time thread is created something is assigned
automatically to it, like a special name, thread local value, etc.
Except we can ensure it's put in the thread group of our choice if we
use security manager.

This turned out to be the most optimal solution.  Framework already had
security manager in place, and we could use it to assign each newly created
thread the group of its parent, and assign newly executed plugins and
plugin tasks a special groups.  In this way, once plugin task is started
in its own thread group, all threads it creates are placed in the same group.

[In practice, because no plugin code was ever using thread groups, it wasn't even
necessary to modify the security manager, because the default group is thread's group].

Alternative solution would be using something like logging context, like MDC in log4j
(we actually were using java logging).  It sets fields in ThreadLocal.  But that
would require modifications to existing code and ensuring all new code sets
that information correctly.  The MDC approach doesn't work well with thread pools:
the context needs to be transferred to the threads in the pool.

The disadvantage of ThreadGroup-based solution is that you cannot reuse threads.
E.g. you cannot have a thread pool for plugin tasks, because once thread is created
its group cannot be changed.  So it's impossible to reuse the thread for another task.
That was a small inconvenience, because java.util.concurrent Executors use thread
pools.  However it wasn't a performance inconvenience, because plugin tasks are
created where things are truly slow, so thread creation isn't an issue.

No comments: