If you insist on logging all the information to the same file this is bound to
happen; it's a fact of life. It leaves you with two alternatives. One, you
synchronize the methods, which slows everything down. Two, you include in every
log message an identifier which allows you to post-filter the log file to get
just the output you want.

As a very trivial example, if you append a string including the thread id in
every message all you need do is filter for that string to see messages from
that thread:

username: john method: a()  // thread A
aaaaaaaaaaaaa               // thread A
username: peter method: b() // thread B
bbbbbbbbbbbbbbb             // thread B
aaaaaaaaaaaaa               // thread A
bbbbbbbbbbbbbbb             // thread B
end:b()                     // thread B
end:a()                     // thread A

To see the output from thread B filter the log file to just show lines which end
in the string "// thread B".

Your log file contains a time sequence of events, which is good, but you can
alter your view of that log file to suit your requirements. In the UNIX world
you could use grep, or one of its close friends. In the Windows world I'm sure
there is some equivalent.

   You need to define what the atomic logging actions are. It sounds like
you don't want the stuff between "username:" and "end:" to get interrupted,
so consider this your atomic unit of a single log entry.

   Write your own custom log handlers to receive the logging events and
buffer them. Then have the handler, upon receiving the end of an entry,
acquire a synchronization lock on the file to write to, and then empty its
buffer into the file. So the sequence of events will look like this:

yourCode.sentToHandler("john", "method: a()");
yourCode.sentToHandler("john", "aaaaaaaaaaaaa");
yourCode.sentToHandler("peter", "method: b()");
yourCode.sentToHandler("peter", "bbbbbbbbbbbbbbb");
yourCode.sentToHandler("john", "aaaaaaaaaaaaa");
yourCode.sentToHandler("peter", "bbbbbbbbbbbbbbb");
yourCode.sentToHandler("peter", "end:b()");
handler.locks(logFile);
handler.writes(logFile, "username: peter method: b()");
handler.writes(logFile, "bbbbbbbbbbbbbbb");
yourCode.sentToHandler("john", "end:a()");
handler.writes(logFile, "bbbbbbbbbbbbbbb");
handler.writes(logFile, "end:b()");
handler.releases(logFile);
handler.locks(logFile);
handler.writes(logFile, "username: john method: a()");
handler.writes(logFile, "aaaaaaaaaaaaa");
handler.writes(logFile, "aaaaaaaaaaaaa");
handler.writes(logFile, "end:a()");
handler.releases(logFile);

   - Oliver

how about doing it this way:

method: a() user: john begin
method: a() user: john sometext
method: a() user: john sometext
method: a() user: john end

this way, if the two users called the same method at the same time, you
will still be able to filter them and see what you want.
the only other option i can think of is to synchronize the methods,
which you already mentioned you wanted to avoid.
HTH

Checkout

http://logging.apache.org/log4j/docs/chainsaw.html.

It's a companion program to Log4j that handles filtering and a lot
more. It's a much more flexible option than grep and the like.

- MattC