Log4j - dealing with multithreaded invocations?

[Piper707]

Hi,

I have a class with 4 methods. I want to use Log4j to log messages for
each of these methods to a common log file.

Ideally I would like the log messages for each method to be seperated
from the others. But if multiple users were to invoke the methods at
the same time, then the messages in my log file would be jumbled up
with the others.

I can probably try making the methods synchronized so i dont get into
this sort of trouble, but logging by itself doesn't seem to be a good
enough reason to be making methods synchronized.

What approach can I use to deal with this?

Thank you,
Rohit.

 

[hilz]

Hi,

I have a class with 4 methods. I want to use Log4j to log messages for
each of these methods to a common log file.

Ideally I would like the log messages for each method to be seperated
from the others. But if multiple users were to invoke the methods at
the same time, then the messages in my log file would be jumbled up
with the others.

I can probably try making the methods synchronized so i dont get into
this sort of trouble, but logging by itself doesn't seem to be a good
enough reason to be making methods synchronized.

What approach can I use to deal with this?

Thank you,
Rohit.

How about having the username and the method name as part of the log
message, and then filter the log file by user or by method name or by
anything else... you can even write a small program that reads the log
file and filter it to your liking.

HTH

 

[Piper707]

Hi,

I do have the username and method name as part of the log message, but
then imagine within each method call, the log looks like this:

username: john method: a()
aaaaaaaaaaaaa
aaaaaaaaaaaaa
end:a()

if someone else invokes b() it should look like this:

username: peter method: b()
bbbbbbbbbbbbbbb
bbbbbbbbbbbbbbb
end:b()

This still doesnt solve my problem, because if I'm writing to a single
file it may come out like this:

username: john method: a()
aaaaaaaaaaaaa
username: peter method: b()
bbbbbbbbbbbbbbb
aaaaaaaaaaaaa
bbbbbbbbbbbbbbb
end:b()
end:a()

 

[Piper707]

Hi,

I dont think that would solve my problem. Imagine the logging within my
methods looked like this:

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

if at the same time, someone else invoked a method b(), since they both
end up writing to a common log file - my log may end up looking like
this:

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

Then i wont be able to differentiate if "sometext" comes from the call
to a() or that to b()..

 

[Piper707]

Sorry for the multiple posts. IE's giving me trouble.

----------------------------------------------------------------------------

Hi,

I dont think that would solve my problem. Imagine the logging within my
methods looked like this:

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

if at the same time, someone else invoked a method b(), since they both
end up writing to a common log file - my log may end up looking like
this:

method: a() user: john
sometext
sometext
method: b() user: peter
sometext
sometext
end: b()
end: a()

Then i wont be able to differentiate if "sometext" comes from the call
to a() or that to b()..

 

[hilz]

Sorry for the multiple posts. IE's giving me trouble.

----------------------------------------------------------------------------

Hi,

I dont think that would solve my problem. Imagine the logging within my
methods looked like this:

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

if at the same time, someone else invoked a method b(), since they both
end up writing to a common log file - my log may end up looking like
this:

method: a() user: john
sometext
sometext
method: b() user: peter
sometext
sometext
end: b()
end: a()

Then i wont be able to differentiate if "sometext" comes from the call
to a() or that to b()..

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

 

[Nigel Wade]

Hi,

I do have the username and method name as part of the log message, but
then imagine within each method call, the log looks like this:

username: john method: a()
aaaaaaaaaaaaa
aaaaaaaaaaaaa
end:a()

if someone else invokes b() it should look like this:

username: peter method: b()
bbbbbbbbbbbbbbb
bbbbbbbbbbbbbbb
end:b()

This still doesnt solve my problem, because if I'm writing to a single
file it may come out like this:

username: john method: a()
aaaaaaaaaaaaa
username: peter method: b()
bbbbbbbbbbbbbbb
aaaaaaaaaaaaa
bbbbbbbbbbbbbbb
end:b()
end:a()

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.

 

[Raymond DeCampo]

Hi,

I have a class with 4 methods. I want to use Log4j to log messages for
each of these methods to a common log file.

Ideally I would like the log messages for each method to be seperated
from the others. But if multiple users were to invoke the methods at
the same time, then the messages in my log file would be jumbled up
with the others.

I can probably try making the methods synchronized so i dont get into
this sort of trouble, but logging by itself doesn't seem to be a good
enough reason to be making methods synchronized.

What approach can I use to deal with this?

Rohit,

FYI, almost all of the suggestions I've seen in this thread (add
timestamp to log, add thread id to log, add method name to log) are
achievable via log4j configuration. I.e., you do not need to change
your code. For the username thing, you may want to use NDC (nested
diagnostic context), which requires minimal code changes.

If you need to know more, I suggest you contact the log4j users list.
(I think it is (e-mail address removed) and you should subscribe
first. Check on http://logging.apache.org to be sure.)

HTH,
Ray

 

[Piper707]

Thanks for the replies. Looks like adding some sort of an identifier to
the log might be the way to go. This will eventually run on unix, so
i'll probably have awk/grep to sort the file for me.

Ray, thanks for the tip. I'll dig in a little more into log4j to see
what it can do and check out the log4j users list too.

- Rohit.

 

[MattC]

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

 

[Oliver Wong]

Hi,

I do have the username and method name as part of the log message, but
then imagine within each method call, the log looks like this:

username: john method: a()
aaaaaaaaaaaaa
aaaaaaaaaaaaa
end:a()

if someone else invokes b() it should look like this:

username: peter method: b()
bbbbbbbbbbbbbbb
bbbbbbbbbbbbbbb
end:b()

This still doesnt solve my problem, because if I'm writing to a single
file it may come out like this:

username: john method: a()
aaaaaaaaaaaaa
username: peter method: b()
bbbbbbbbbbbbbbb
aaaaaaaaaaaaa
bbbbbbbbbbbbbbb
end:b()
end:a()

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

 

[Piper707]

Oliver,

I never thought of that approach. That sounds really good. Let me see
how i can put it together.

Thanks
Rohit.