Multiple threads using System.out.println in Java

Question

I have a multi-threaded Java application that will output information about a message it receives to the console for debugging purposes. Each time the application receives a message, it will call a System.out.println(String) on the message.

The problem that I am having is that if the application gets flooded with messages, System.out.println() prints erroneous information (like old buffer information). This is leading me to wonder if there is a threading issue where multiple threads are calling the println function at one time, and not properly flushing the buffer.

In my main program (thread), I have something to the effect of:

while(iterator.hasNext())
{
    SelectionKey key = iterator.next();

    channel.receive(buffer);     // The buffer is a ByteBuffer.
    buffer.flip();

    new Thread(new ThreadToPrintTheMessage(buffer)).start();

    buffer.clear();

    iterator.remove();
}

In my thread, I have something to the effect of:

@Override
public void run()
{
    System.out.println(message);
    System.out.flush();   // I have better results with this.  But, it doesn't
                          // fully resolve the issue.
}

Is there a simple way for me to have multiple threads print out to the console at one time without the buffers containing old information?

Thanks

EDIT: updated the code in the main thread to be more representative of what my program is doing.

Ferrotype

Can you show some of the "old buffer information". System.out.println is synchronized so you shouldn't get "old" information. – Luminal

multiple threads print out to the console at one time? you mean each thread at a time? – Aguilera

For example, if I am getting XML messages, you would have something like: </tag>>/tag> – Ferrotype

I think the problem lies outside of println issue. You need to check that your app is not reading/generating old messages. – Blitz

@thinksteep Each spawned thread is calling the println method. – Ferrotype

@SamGoldberg If I send messages one at a time, there is no problem. It's only a problem when I send many at a time, which is why I'm wondering if there conflict between the println and flush. – Ferrotype

@Phanto: this looks like you have 2 threads writing to the same variable/field somewhere, and they are overwriting each other. – Blitz

@SamGoldberg I am going to update my main post with more of the actual code. – Ferrotype

@Phanto: it looks like you are sharing the buffer object with multiple threads. That won't work. Each thread needs its own separate buffer object, or the main thread needs to convert the buffer to a local string variable, and then pass the string to the thread. – Blitz

@Phanto: so, you are trying to asynchronously handle a buffer that is cleared immediately after the asynchronous call has been made (or even written to)? That's not going to work, you should pass a copy of buffer into the ThreadToPrintTheMessage() ctor (unless you make a copy inside the constructor yourself.) – Graduation

@AlexanderPavlov in my thread's constructor, I have a private ByteBuffer object declared, and the constructor does a: this.buffer = buffer. I assumed that Java does pass by value and therefore makes a copy (unless this is wrong). – Ferrotype

This is wrong. Objects in Java are always passed by reference. The accepted answer does exactly what is necessary to avoid improper used of a buffer shared among multiple threads. – Graduation

Answer 1

Here might be some sample code to fix the problem:

while(iterator.hasNext())
{
    SelectionKey key = iterator.next();

    channel.receive(buffer);     // The buffer is a ByteBuffer.
    buffer.flip();
    byte[] bytes = new byte[buffer.limit()];  // copy buffer contents to an array
    buffer.get(bytes);
    // thread will convert byte array to String
    new Thread(new ThreadToPrintTheMessage(bytes)).start();

    buffer.clear();

    iterator.remove();
}

Blitz

This did it! You and Alexander Pavlov identified what the problem was... I was trying to print a buffer that was being shared and modified by a different resource. – Ferrotype

Answer 2

synchronized (System.out) {
    System.out.println(message);
    System.out.flush();
}

Graduation

@Luminal right, just thought it could have been a race between println() and flush() but obviously this is not the case. @Phanto, what kind of output are you getting? – Graduation

@AlexanderPavlov please see comment in the main post. – Ferrotype

@AlexanderPavlov if you don't use synchronized block then really there could be race condition between println() and flush() if yes then why/how? if no then also why/how? – Temporary

Yes there can be one. Why not? – Graduation

Answer 3

You should be using Java.util.logging or some other logging framework for this purpose.

http://docs.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html

import java.util.logging.Logger;
....
Logger log = Logger.getLogger("com.something.something");
....
log.log(Level.Info, "Message");

Rocketeer

Could you provide a small example? – Ferrotype

Answer 4

I haven't got time to check println source be be sure it's thread safe always (you could, if you wanted to), but are you sure that your println is wrong? It may well be that code is running at a very different times than you think. Threads often get hung up on locks or just get forgotten by the scheduler, so what you think should run A, B, C, D can run B, C, D, A. Then you wonder why println is messed up, printing last what you think ran first. And this is a really simple example. The difference between what you expect to happen with multi-threading and what does happen can be truly astounding. Generally, the higher the thread-to-core ratio, the worse it is. Single core machines always do everything the opposite of what you would expect.

And you don't even need multiple threads to have this problem. My first jolts came with event queues (on Windows 3.1), which did not share my views on when things should run. It took me a while to figure out that the messages were scrambled because the OS had a much different idea of how they should run than I did.

There may well be some subtleties with System.out.println and flush that I don't know about, but even when you get all that working, be aware that those threads have rather contrary minds of their own. Even Logger won't solve all your problems.

Celery

According to multiple people, println is thread safe, so it really could be messed up schedules. – Coon