why are printf's so slow

[Ivan Soleimanipour-4]

I use printf to do debugging of Nb modules and the output is really slow ... it comes
in spurts and during hangs it seems that some output doesn't even make it ... out.

This is when I run the IDE by itself and the output goes into a regular xterm.

[Jesse Glick]

Ivan Soleimanipour wrote:
> I use printf to do debugging of Nb modules and the output is really slow ... it comes in spurts and during hangs it seems that some output doesn't even make it ...
> out.

Are you using System.err or System.out? The latter may be buffered.

[Ivan Soleimanipour-4]

Jesse Glick wrote:
> Ivan Soleimanipour wrote:
>> I use printf to do debugging of Nb modules and the output is really
>> slow ... it comes in spurts and during hangs it seems that some output
>> doesn't even make it ...
>> out.
>
> Are you using System.err or System.out? The latter may be buffered.
>

I'm using System.out ... the buffering seems "worse" than in 6.5.1.
Who would be doing this buffering?

[Jesse Glick]

Ivan Soleimanipour wrote:
> I'm using System.out

Well then use System.err.

> Who would be doing this buffering?

Just part of Java, observable in any hello-world app.

[Gregg Wonderly-2]

Jesse Glick wrote:
> Ivan Soleimanipour wrote:
>> I'm using System.out
>
> Well then use System.err.
>
>> Who would be doing this buffering?
>
> Just part of Java, observable in any hello-world app.

There is always OutputStream.flush() to help encourage things to go out the
other end.

I think that overall, you'd find it more interesting to use the Logger class for
output from your program because then you can change where it goes to, and what
levels of information you get without having to "edit" your code.

Gregg Wonderly

[Jesse Glick]

Gregg Wonderly wrote:
> you'd find it more interesting to use the Logger
> class for output from your program because then you can change where it
> goes to, and what levels of information you get without having to "edit"
> your code.

Yes, use of Logger is encouraged for this purpose. INFO+ is logged by default. You can enable finer logging on some component when starting:

   -J-Dorg.netbeans.modules.mystuff.level=0

There is a contrib module which lets you adjust logging levels at runtime, and NbTestCase lets you do some interesting things with log messages too.

[Ivan Soleimanipour-4]

 > I think that overall, you'd find it more interesting to use the Logger class

In all my ~370 places? :-)

My logger predates the use of the logger class in NB.
I've been meaning to put an adapter in place ... I guess now is the time.

But then ...


>> Who would be doing this buffering?
>
> Just part of Java, observable in any hello-world app.
>

I debugged NB and System.out is a TopLogging$LgStream.
And the code does this:

         if (!(System.err instanceof LgStream)) {
             System.setErr(new LgStream(Logger.getLogger("stderr"))); // NOI18N
             if (DEBUG != null) DEBUG.println("initializing stderr"); // NOI18N
         }
         if (!(System.out instanceof LgStream)) {
             System.setOut(new LgStream(Logger.getLogger("stderr"))); // NOI18N
             if (DEBUG != null) DEBUG.println("initializing stdout"); // NOI18N
         }

so it's not fair to compare to Java it seems.

        Not that regular Java is that predictable in it's behaviour either.

        There is this thing called auto-flush. Apparenly the default System.out has it set to true, despite
        some web hits stating the contrary. Then the implementation of PrintStream is such that it
        sometimes even flushes with autoFlush turned off.


>> Well then use System.err.

Based on the above it looks like System.err isn't going to fare any better than System.out.

> There is always OutputStream.flush() to help encourage things to go out the other end.

And LgFlush does all kinds of funky stuff with flush():

                 flush.schedule(0);
                 flush.waitFinished(500);


So ... I'm skeptical.

The situation I'm in is that I've got a wedged EDT but it looks as if some of the logging messages
didn't make it out the door. I.e. the state I should be in according to the log doesn't
match the stack trace.
Would EDT be playing a role in flushing timers? (even though the above schedule() goes to an RP).

[Gregg Wonderly-2]

Run netbeans with the console up and use CTRL-\ in the console on *NIX or
CTRL-BREAK on windows to get the thread dump to show you where the EDT is wedged at.

Gregg Wonderly

Ivan Soleimanipour wrote:

>
>  > I think that overall, you'd find it more interesting to use the
> Logger class
>
> In all my ~370 places? :-)
>
> My logger predates the use of the logger class in NB.
> I've been meaning to put an adapter in place ... I guess now is the time.
>
> But then ...
>
>
>>> Who would be doing this buffering?
>>
>> Just part of Java, observable in any hello-world app.
>>
>
> I debugged NB and System.out is a TopLogging$LgStream.
> And the code does this:
>
>         if (!(System.err instanceof LgStream)) {
>             System.setErr(new LgStream(Logger.getLogger("stderr"))); //
> NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stderr"); //
> NOI18N
>         }
>         if (!(System.out instanceof LgStream)) {
>             System.setOut(new LgStream(Logger.getLogger("stderr"))); //
> NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stdout"); //
> NOI18N
>         }
>
> so it's not fair to compare to Java it seems.
>
>     Not that regular Java is that predictable in it's behaviour either.
>
>     There is this thing called auto-flush. Apparenly the default
> System.out has it set to true, despite
>     some web hits stating the contrary. Then the implementation of
> PrintStream is such that it
>     sometimes even flushes with autoFlush turned off.
>
>
>>> Well then use System.err.
>
> Based on the above it looks like System.err isn't going to fare any
> better than System.out.
>
>> There is always OutputStream.flush() to help encourage things to go
>> out the other end.
>
> And LgFlush does all kinds of funky stuff with flush():
>
>                 flush.schedule(0);
>                 flush.waitFinished(500);
>
>
> So ... I'm skeptical.
>
> The situation I'm in is that I've got a wedged EDT but it looks as if
> some of the logging messages
> didn't make it out the door. I.e. the state I should be in according to
> the log doesn't
> match the stack trace.
> Would EDT be playing a role in flushing timers? (even though the above
> schedule() goes to an RP).
>
>
>
>
>

[Ivan Soleimanipour-4]

On 10/14/09 14:40, Gregg Wonderly wrote:
> Run netbeans with the console up and use CTRL-\ in the console on *NIX
> or CTRL-BREAK on windows to get the thread dump to show you where the
> EDT is wedged at.
>

I know where EDT is wedged at.

I needed to know how it got there so I turned on logging ... except that logging
comes out in spurts and I can't quite trust it.

> Gregg Wonderly
>
> Ivan Soleimanipour wrote:
>>
>>  > I think that overall, you'd find it more interesting to use the
>> Logger class
>>
>> In all my ~370 places? :-)
>>
>> My logger predates the use of the logger class in NB.
>> I've been meaning to put an adapter in place ... I guess now is the time.
>>
>> But then ...
>>
>>
>>>> Who would be doing this buffering?
>>>
>>> Just part of Java, observable in any hello-world app.
>>>
>>
>> I debugged NB and System.out is a TopLogging$LgStream.
>> And the code does this:
>>
>>         if (!(System.err instanceof LgStream)) {
>>             System.setErr(new LgStream(Logger.getLogger("stderr")));
>> // NOI18N
>>             if (DEBUG != null) DEBUG.println("initializing stderr");
>> // NOI18N
>>         }
>>         if (!(System.out instanceof LgStream)) {
>>             System.setOut(new LgStream(Logger.getLogger("stderr")));
>> // NOI18N
>>             if (DEBUG != null) DEBUG.println("initializing stdout");
>> // NOI18N
>>         }
>>
>> so it's not fair to compare to Java it seems.
>>
>>     Not that regular Java is that predictable in it's behaviour either.
>>
>>     There is this thing called auto-flush. Apparenly the default
>> System.out has it set to true, despite
>>     some web hits stating the contrary. Then the implementation of
>> PrintStream is such that it
>>     sometimes even flushes with autoFlush turned off.
>>
>>
>>>> Well then use System.err.
>>
>> Based on the above it looks like System.err isn't going to fare any
>> better than System.out.
>>
>>> There is always OutputStream.flush() to help encourage things to go
>>> out the other end.
>>
>> And LgFlush does all kinds of funky stuff with flush():
>>
>>                 flush.schedule(0);
>>                 flush.waitFinished(500);
>>
>>
>> So ... I'm skeptical.
>>
>> The situation I'm in is that I've got a wedged EDT but it looks as if
>> some of the logging messages
>> didn't make it out the door. I.e. the state I should be in according
>> to the log doesn't
>> match the stack trace.
>> Would EDT be playing a role in flushing timers? (even though the above
>> schedule() goes to an RP).
>>
>>
>>
>>
>>
>

[Jesse Glick]

Ivan Soleimanipour wrote:
> LgFlush does all kinds of funky stuff with flush()

Output to var/log/messages may be delayed. But output to console should be immediate, at least so long as you are using System.err. It has always worked for me. If you
can reproduce otherwise, please file a bug.

[Stefano Gargiulo]

>
> > I think that overall, you'd find it more interesting to use the
> Logger class
>
> In all my ~370 places? :-)
NB has an awesome find/replace (in project) funciton :) then it's easy
to refactor...

>
> I debugged NB and System.out is a TopLogging$LgStream.
> And the code does this:
>
>         if (!(System.err instanceof LgStream)) {
>             System.setErr(new LgStream(Logger.getLogger("stderr")));
> // NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stderr");
> // NOI18N
>         }
>         if (!(System.out instanceof LgStream)) {
>             System.setOut(new LgStream(Logger.getLogger("stderr")));
> // NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stdout");
> // NOI18N
>         }
>
> so it's not fair to compare to Java it seems.

I think this is the code that NB use for log messages in the graphical
log console, you are in an IDE, it is active by default!

>
> I needed to know how it got there so I turned on logging ... except
> that logging
> comes out in spurts and I can't quite trust it.
if you want to debug your application into an IDE you can use directly
the IDE debugger instead of the printfs.... or the awesome NB profiler
to detect your hang,  or JMX,  Jconsole etc..

but if you prefer real-time logs for debbugging then is better to debug
manually into a separate jvm, without the IDE overhead...
"you cannot have your cake and eat it"

the old fashioned java -jar command can help...

Best regards,
Stefano.





Ivan Soleimanipour ha scritto:

>
> > I think that overall, you'd find it more interesting to use the
> Logger class
>
> In all my ~370 places? :-)
>
> My logger predates the use of the logger class in NB.
> I've been meaning to put an adapter in place ... I guess now is the time.
>
> But then ...
>
>
>>> Who would be doing this buffering?
>>
>> Just part of Java, observable in any hello-world app.
>>
>
> I debugged NB and System.out is a TopLogging$LgStream.
> And the code does this:
>
>         if (!(System.err instanceof LgStream)) {
>             System.setErr(new LgStream(Logger.getLogger("stderr")));
> // NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stderr");
> // NOI18N
>         }
>         if (!(System.out instanceof LgStream)) {
>             System.setOut(new LgStream(Logger.getLogger("stderr")));
> // NOI18N
>             if (DEBUG != null) DEBUG.println("initializing stdout");
> // NOI18N
>         }
>
> so it's not fair to compare to Java it seems.
>
>     Not that regular Java is that predictable in it's behaviour either.
>
>     There is this thing called auto-flush. Apparenly the default
> System.out has it set to true, despite
>     some web hits stating the contrary. Then the implementation of
> PrintStream is such that it
>     sometimes even flushes with autoFlush turned off.
>
>
>>> Well then use System.err.
>
> Based on the above it looks like System.err isn't going to fare any
> better than System.out.
>
>> There is always OutputStream.flush() to help encourage things to go
>> out the other end.
>
> And LgFlush does all kinds of funky stuff with flush():
>
>                 flush.schedule(0);
>                 flush.waitFinished(500);
>
>
> So ... I'm skeptical.
>
> The situation I'm in is that I've got a wedged EDT but it looks as if
> some of the logging messages
> didn't make it out the door. I.e. the state I should be in according
> to the log doesn't
> match the stack trace.
> Would EDT be playing a role in flushing timers? (even though the above
> schedule() goes to an RP).
>
>
>

[Ivan Soleimanipour-4]

On 10/14/09 17:42, Jesse Glick wrote:
> Ivan Soleimanipour wrote:
>> LgFlush does all kinds of funky stuff with flush()
>
> Output to var/log/messages may be delayed. But output to console should
> be immediate, at least so long as you are using System.err. It has
> always worked for me. If you can reproduce otherwise, please file a bug.
>

Well output via System.err also comes in spurts via TopLogging$LgStream.

Before I file a bug, do you know off-hand if output from a wrapped external
library would be treated differently?

[Jesse Glick]

Ivan Soleimanipour wrote:
> [would] output from a wrapped external library [] be treated differently?

Should not matter - all System.err output should appear on console immediately.

One thing to check - if you are omitting the newline at the end of a message, the text might be buffered up until the next complete line arrives. Always use
System.err.println, end strings for printf with "\n", or otherwise ensure that you terminate messages with a newline.