Logging activities in multithreaded applications

Question

I have a layered application in Java which has a multi thread data access layer which is invoked from different points. A single call to this layer is likely to spawn several threads to parallelize requests to the DB.

What I'm looking for is a logging tool that would allow me to define "activities" that are composed by various threads. Therefore, the same method in the data access layer should log different outputs depending on its caller. The ability to group different outputs to summarize the total cost of an operation is also important.

Although the application is in Java, language is not a restriction; what I need are the design guidelines so to eventually implement it. We are currently using log4j, but can't get this behaviour from it.

Answer 1

In log4j you can log the thread name with the "%t" pattern. See log4j Pattern Layout.

Answer 2

In Java5 (and later) you can call

StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();

Inspect the stack trace to whatever depth you want and log accordingly.

In Java 1.4 you can get the same info with

StackTraceElement[] stackTrace = new Exception().getStackTrace();

Answer 3

You want to associate logger objects with threads I think. A ThreadLocal variable holding a log4j logger instance for each thread might help:

http://java.sun.com/javase/6/docs/api/java/lang/ThreadLocal.html

Answer 4

You should also have a look at the nested diagnostic context feature of log4j. Pushing different contexts to the logger for different callers might do the trick for you.

Answer 5

You should be able to pass a logger around, so you create a logger based on some "common" for the task data - i.e. username, etc. Then, pass this logger as parameter to all methods you need. That way, you'll be able to set different filters and/or rules in your log4j config file. Or to scrape the output file based on the logger name.

EDIT: Also check MDC and NDC classes in log4j. You can add there context data.

Answer 6

You will need to pass some structure to the data access layer that identifies the current "activity". You might already have an "Activity"-class that makes sense, you might use a Logger-instance as Sunny suggested or you might use a third structure to keep track of the activity-context.

In any case, since your "activity" is processed across multiple threads you cannot use thread-local-storage for keeping track of the current "activity", like most of the other current answers suggest. You will need to pass it around explicitly.

I would suggest making a small facade on top of log4j that expands the interface with methods like

void debug(Activity activity, String message);

and passing the activity-context into this from the data access layer.

You will need to make some modification to the data access layer to allow you to pass the current activity to it, but how best to do that depends strongly on the current interface. If you use the Workspace-pattern, you might just need to add a setActivity() method on the Workspace-class, but other interface-pattern might require you to add an Activity parameter to all methods.

If you for some reason is unable or unwilling to change the data access layer, you might of course store the activity-context in thread-local-storage before invoking the data access layer and retrieve it just before spawning the sub-threads or enqueing the jobs in the data access layer. That is a workable solution, but is it a bit dangerous to pass information around in that way.

Answer 7

In one of my (web) applications, i use a ThreadLocal logger that captures logging information into a StringBuilder. The logger object is initialized in the HttpServlet#service method, if a trace parameter is set (if it is not set, there is a very fast null-logger). The resulting output is either dumped as a HTML comment into the requesting page, or written to a log file in one segment.