fmt.Fprintf to os.Stderr is cached?

[antoni...@gmail.com]

Hi, 

Somehow I have an idea that output to stderr will take effect immediately without any caching, maybe that comes from another language/platform. 

But I just noticed that Go behaves differently, which makes me wonder -- what would happen to my console output, if I flip between outputting to stdout & stderr back and force? 

Thanks

[Ian Lance Taylor]

On Tue, Oct 15, 2013 at 11:13 AM, <antoni...@gmail.com> wrote:
>
> Somehow I have an idea that output to stderr will take effect immediately
> without any caching, maybe that comes from another language/platform.

In C stdout is buffered by default, stderr is not.

In Go neither os.Stdout nor os.Stderr is buffered.

If you pass os.Stderr to fmt.Fprintf, the output should appear
immediately. If you don't see this, you'll have to give us an
example.

Ian

[Tong Sun]

On Tuesday, October 15, 2013 8:01:30 PM UTC-4, Ian Lance Taylor wrote:

 

> Somehow I have an idea that output to stderr will take effect immediately
> without any caching, maybe that comes from another language/platform.

In C stdout is buffered by default, stderr is not.

In Go neither os.Stdout nor os.Stderr is buffered.

 

Then it much has been line-buffered.

If you pass os.Stderr to fmt.Fprintf, the output should appear
immediately.  If you don't see this, you'll have to give us an
example.

In a lengthy process, I output a dot every so often, and a CR at the end:

  if j%step == 0 {

fmt.Fprintf(os.Stderr, ".")

}

}

fmt.Fprintf(os.Stderr, "\n")

But it turns out that the dots all show up at once when the lengthy process finished, not one by one during it. 

Anyway to flush the os.Stderr? 

Thanks

[Péter Szilágyi]

Hi,

  Are you running SublimeText? :)

  The following code runs without buffering both on the play server as well as local console, but inside GoSublime it will buffer the dots till the line is ended: http://play.golang.org/p/ENdvg6u37m . I've not found any trivial way to disable buffering in GoSublime (alas, I've spent a maximum of 2 minutes searching for it), but I'd look for the issue there and not in Go.

Cheers,

  Peter

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

[Ian Lance Taylor]

On Wed, Oct 16, 2013 at 6:46 AM, Tong Sun <sunto...@gmail.com> wrote:
>
> In a lengthy process, I output a dot every so often, and a CR at the end:
>
> if j%step == 0 {
> fmt.Fprintf(os.Stderr, ".")
> }
> }
> fmt.Fprintf(os.Stderr, "\n")
>
> But it turns out that the dots all show up at once when the lengthy process
> finished, not one by one during it.

Show us the code. Tell us how you are running it.

Ian

[Tong Sun]

Sorry for responding late. I was having a series problems with my system. 

On Wed, Oct 16, 2013 at 10:26 AM, Ian Lance Taylor <ia...@golang.org> wrote:

> But it turns out that the dots all show up at once when the lengthy process
> finished, not one by one during it.

Show us the code.

I don't think it helps, but since you asked, 

http://sourceforge.net/p/xpt/code/ci/master/tree/lang/Go/src/db/PerfCounterExport.go

line 175~179. 

 

 Tell us how you are running it.

Run under Win7 DOS, tried both "go run" and run the compiled .exe file. The behavior is the same, dots all show up at once. 

What I can't explain is that, I tried Péter's example, also run under Win7 DOS, tried both "go run" and run the compiled .exe file, and for this case, I can see the dots progressing. I don't know if there is another file writing process in my loop is the cause of the behavior difference, and I can think of a better example to proof it. 

[Tong Sun]

On Wed, Oct 16, 2013 at 3:13 PM, Tong Sun <sunto...@gmail.com> wrote:

and I can think of a better example to proof it. 

sorry, I meant can't.

[Ian Lance Taylor]

On Wed, Oct 16, 2013 at 12:13 PM, Tong Sun <sunto...@gmail.com> wrote:
>
> On Wed, Oct 16, 2013 at 10:26 AM, Ian Lance Taylor <ia...@golang.org> wrote:
>>
>> > But it turns out that the dots all show up at once when the lengthy
>> > process
>> > finished, not one by one during it.
>>
>> Show us the code.
>
>
> I don't think it helps, but since you asked,
> http://sourceforge.net/p/xpt/code/ci/master/tree/lang/Go/src/db/PerfCounterExport.go
> line 175~179.
>
>>
>> Tell us how you are running it.
>
>
> Run under Win7 DOS, tried both "go run" and run the compiled .exe file. The
> behavior is the same, dots all show up at once.

I was hoping for a smaller example that would be easy for us to try
ourselves to see if we can replicate the behaviour.

Perhaps this has something to do with Windows. I really don't know.

For example, on my system, the following program prints one dot every
second.

Ian

package main

import (
"fmt"
"os"
"time"
)

func main() {
i := 0
for _ = range time.Tick(time.Second) {
fmt.Fprintf(os.Stderr, ".")
i++
if i > 40 {
break
}
}
fmt.Fprintf(os.Stderr, "\n")
}

[Tong Sun]

I was hoping for a smaller example that would be easy for us to try
ourselves to see if we can replicate the behaviour.

As said before, I can't think of a better example to show it.

On Wed, Oct 16, 2013 at 3:13 PM, Tong Sun <sunto...@gmail.com> wrote:

 Tell us how you are running it.

Run under Win7 DOS, tried both "go run" and run the compiled .exe file. The behavior is the same, dots all show up at once. 

What I can't explain is that, I tried Péter's example, also run under Win7 DOS, tried both "go run" and run the compiled .exe file, and for this case, I can see the dots progressing. I don't know if there is another file writing process in my loop is the cause of the behavior difference, and I can't think of a better example to proof it. 

Well, at least I can rule that one out, 

http://play.golang.org/p/rBtex6QqRf

in which another stream is being written to in the loop. 

My latest theory is that the tight loop in my code "starves" go from processing "fmt.Fprintf(os.Stderr, ".")", while time.Sleep will enable go to take a breath and do the output. 

Anyone can write a PIE Calculator in GO and do "fmt.Fprintf(os.Stderr, ".")" every so often to test the point? 

Thanks

[Dave Cheney]

env GOMAXPROCS=10 ./$YOURBIN

should be sufficient to test that hypothesis.

[Tong Sun]

On Wed, Oct 16, 2013 at 5:12 PM, Dave Cheney <da...@cheney.net> wrote:

> My latest theory is that the tight loop in my code "starves" go from
> processing "fmt.Fprintf(os.Stderr, ".")", while time.Sleep will enable go to
> take a breath and do the output.
>
> Anyone can write a PIE Calculator in GO and do "fmt.Fprintf(os.Stderr, ".")"
> every so often to test the point?
>

env GOMAXPROCS=10 ./$YOURBIN

should be sufficient to test that hypothesis.

This is under Win7 DOS, so I do

 set GOMAXPROCS=10

before running my executable. But dots all show up at once.

I've run out of ideas now. 

[Ian Lance Taylor]

On Wed, Oct 16, 2013 at 2:10 PM, Tong Sun <sunto...@gmail.com> wrote:
>
>> I was hoping for a smaller example that would be easy for us to try
>> ourselves to see if we can replicate the behaviour.
>
>
> As said before, I can't think of a better example to show it.

Well, what about my example?

I took a closer look at your program. It seems to do various database
operations. I don't know how long those would take. Then it writes
out a file, and that is where you are printing the dots. Writing the
file should be fast. It's just a local file and the printing should
be fast. The only potentially slow operation I see in that loop is
row.MustGet; I don't know what that is.

Is it possible that your program just runs so fast at the point of
printing the dots that they all appear at once?

Ian

[Tong Sun]

On Wed, Oct 16, 2013 at 5:35 PM, Ian Lance Taylor <ia...@golang.org> wrote:

On Wed, Oct 16, 2013 at 2:10 PM, Tong Sun <sunto...@gmail.com> wrote:
>
>> I was hoping for a smaller example that would be easy for us to try
>> ourselves to see if we can replicate the behaviour.
>
>
> As said before, I can't think of a better example to show it.

Well, what about my example?

Yours should be fine as well -- not much different from Péter's example that I tried. 

http://play.golang.org/p/ENdvg6u37m 

As said before, for this case, I can see the dots progressing. 

I took a closer look at your program.  It seems to do various database
operations.  I don't know how long those would take.  Then it writes
out a file, and that is where you are printing the dots.  Writing the
file should be fast.  It's just a local file and the printing should
be fast.  The only potentially slow operation I see in that loop is
row.MustGet; I don't know what that is.

Is it possible that your program just runs so fast at the point of
printing the dots that they all appear at once?

No, actually. My bad, I didn't make it clear that my program runs in minutes. I watched closely, and they were all "nothing" then "everything".

[Tong Sun]

On Wed, Oct 16, 2013 at 5:35 PM, Ian Lance Taylor <ia...@golang.org> wrote:

I took a closer look at your program.  It seems to do various database
operations.  I don't know how long those would take.  Then it writes
out a file, and that is where you are printing the dots.  Writing the
file should be fast.  It's just a local file and the printing should
be fast.  The only potentially slow operation I see in that loop is
row.MustGet; I don't know what that is.

I've stripped out the core functionality of the code:

http://play.golang.org/p/HX0G79dvV9

The next step would be find/generate a super monster table to slow down the process...

[brainman]

On Thursday, 17 October 2013 10:21:13 UTC+11, Tong Sun wrote:

I've stripped out the core functionality of the code:

http://play.golang.org/p/HX0G79dvV9

This is what your program outputs:

...............................

Finished correctly

Is this wrong?

Alex

[Tong Sun]

On Wed, Oct 16, 2013 at 10:02 PM, brainman <alex.b...@gmail.com> wrote:

I've stripped out the core functionality of the code:

http://play.golang.org/p/HX0G79dvV9

This is what your program outputs:

...............................

Finished correctly

Is this wrong?

That's correct, but seems you don't know what we were testing since you just jump into the middle of the discussion. I'll repost over here:

But it turns out that the dots all show up at once when the lengthy process finished, not one by one during it.... I run under Win7 DOS, tried both "go run" and run the compiled .exe file. The behavior is the same, dots all show up at once. My program runs in minutes. I watched closely, and they were all "nothing" then all-of-sudden "everything".

 

I also tried Péter's example, http://play.golang.org/p/ENdvg6u37m, also run under Win7 DOS, tried both "go run" and run the compiled .exe file, and for this case, I can see the dots progressing.

However, I'm very glad that my code is now short enough for someone to run it correctly. 

Now the next step. Please refer to http://pastebin.com/YxCij3Cs

There are two SQL statements there. Please run the first SQL statement first, in tempdb on local machine, then run the second SQL statement 10~20 times, as instructed in the code. And then run

  go run OdbcTableOut.go "" BigTable

supply the first parameter as the connection string if you are not running the above in tempdb on local machine. 

In Go neither os.Stdout nor os.Stderr is buffered. 

Then we should see the dots progressing. However, you will find, in this simple example,  the dots all show up at once after the lengthy process finished, not one by one during it. I.e., "nothing" then all-of-sudden "everything".

Please verify. 

Thanks

[brainman]

> Then we should see the dots progressing. ...

I don't see why the should behave as you've described.

Alex

[Tong Sun]

On Fri, Oct 18, 2013 at 2:39 AM, brainman <alex.b...@gmail.com> wrote:

> Then we should see the dots progressing. ...

I don't see why the should behave as you've described.

Interesting. 

- Do you agree that "In Go neither os.Stdout nor os.Stderr is buffered"?

- Have you  tried Péter's example, http://play.golang.org/p/ENdvg6u37m?

What's your justification that Go Stderr should be buffered for this case? 

[Tamás Gulácsi]

What about Flush ing after each dot?

[Tong Sun]

On Fri, Oct 18, 2013 at 2:08 PM, Tamás Gulácsi <tgula...@gmail.com> wrote:

What about Flush ing after each dot?

That should work, but I don't know how (only attempted os.Stderr.Flush()), and my OP was

Anyway to flush the os.Stderr? 

but no one answered. 

[Gulácsi Tamás]

2013/10/19 Tong Sun <sunto...@gmail.com>:

Try this: http://play.golang.org/p/EGR0SqsX9_

TL;DR: use *os.File 's Sync() method or *bufio.Buffer 's Flush() method.

GThomas

[Alex Skinner]

Why?  Ian just said that neither is buffered,.

The two run identically in your example.  I think Ian's theory that it's completing quickly is probably right, else Windows behaves differently.

Thanks,

Alex

[Tong Sun]

On Sat, Oct 19, 2013 at 7:31 PM, Alex Skinner <als...@gmail.com> wrote:

Why?  Ian just said that neither is buffered,.

The two run identically in your example.  

Agree. The example is not for flushing Stderr, but to flush file write. I.e., there is no os.Stderr.Flush() because by design it should not be necessary. 

 

I think Ian's theory that it's completing quickly is probably right, else Windows behaves differently.

Nope, 

1. Windows does not behave differently because Péter's example, http://play.golang.org/p/ENdvg6u37m, works on Windows as well. 

2. My program runs in minutes. The dots all show up at once after the lengthy process finished, not one by one during it. 

I believe Alex Brainman has confirmed the above behavior on his side too. 

[Volker Dobler]

What happens if you do not print single dots, but some "very long" string

which includes newlines too?

V.

[brainman]

On Saturday, 19 October 2013 04:37:19 UTC+11, Tong Sun wrote:

> - Do you agree that "In Go neither os.Stdout nor os.Stderr is buffered"?

I'am not sure. But I would say yes.

> - Have you  tried Péter's example, http://play.golang.org/p/ENdvg6u37m?

I did now. It prints:

C:\>go run a.go

..........

What is your point?

Alex

[brainman]

On Friday, 18 October 2013 05:10:08 UTC+11, Tong Sun wrote:

> ... Please run the first SQL statement first, in tempdb on local machine, then run the second SQL statement 10~20 times, as instructed in the code. And then run ...

I did. I run your http://play.golang.org/p/HX0G79dvV9 program against BigTable, instead of sys.databases.

> ... Then we should see the dots progressing. However, you will find, in this simple example, the dots all show up at once after the lengthy process finished, not one by one during it. I.e., "nothing" then all-of-sudden "everything". ...

Yes, I see all dots are printed at once. But why shouldn't they? Please explain. And whatever reason it happens, it is not because of "os.Stderr is buffered". I think that "os.Stderr is buffered" is red herring here. I would look for a different explanation instead. I would insert fmt.Printf statements to measure execution times for each step you're interested. These will show where your execution time goes.

If you want to see dots printed one by one with nice equal interval, you can use time.Sleep to pause in between your print statements. :-)

Alex

[Chris Hines]

This code (http://play.golang.org/p/Wtkoi5GZv8) seems more parallel to yours by writing a lot of data to a file between each write to os.Stderr. Running it from a Win 7 command prompt I see the periods appear evenly throughout the run.

This code (http://play.golang.org/p/UM7FBMAIdh) tests the idea of a CPU bound computation causing problems. Running it from a Win 7 command prompt I see the periods appear evenly throughout the run.

Considering these two results and the code you originally posted, I wonder if perhaps your program is spending all of it's time waiting for the database to return the first row. Perhaps you could log the time before and after this code:

sql := fmt.Sprintf("exec TSL_prc_PerfCounterCollectionInCsvFormat"+

" @RunId = %d, @InstanceName=N'\\\\%s\\%%'", _runId, machine)

table, err := table.Get(conn, sql)

[Tong Sun]

The point is not what it prints but how it prints. It clearly shows that mt.Fprintf(os.Stderr, ".") should take effect immediately, not sometime later.

I did. I run your http://play.golang.org/p/HX0G79dvV9 program against BigTable, instead of sys.databases.

Thanks!

> ... Then we should see the dots progressing. However, you will find, in this simple example, the dots all show up at once after the lengthy process finished, not one by one during it. I.e., "nothing" then all-of-sudden "everything". ...

Yes, I see all dots are printed at once. But why shouldn't they? Please explain.

As said before, the mt.Fprintf(os.Stderr, ".") should take effect immediately, not sometime later. 

My above program prints a dot for every it record outputs. So if it takes 10 seconds to run for 10 records, then dots should be printed about 1 second at time, not all at once at the end, right? If it happens too fast to you, please run the second SQL statement 10~20 times more to make it obvious. 

 

And whatever reason it happens, it is not because of "os.Stderr is buffered". I think that "os.Stderr is buffered" is red herring here. I would look for a different explanation instead.

Agree. but the above result, observing from an end user prospective, shows the symptom of Stderr being buffered to the end, which was my initial guess. And if you have following the entire thread, you would know that I was trying to come up with all different explanations and have written small code to test whether they are correct or not. Just so far all my other guessings have been proving wrong. 

That's so much I can do from an end user prospective, trying to guess what's happening in the black box. 

[Volker Dobler]

Am Montag, 21. Oktober 2013 16:03:55 UTC+2 schrieb Tong Sun:

Agree. but the above result, observing from an end user prospective, shows the symptom of Stderr being buffered to the end, which was my initial guess. And if you have following the entire thread, you would know that I was trying to come up with all different explanations and have written small code to test whether they are correct or not. Just so far all my other guessings have been proving wrong. 

That's so much I can do from an end user prospective, trying to guess what's happening in the black box. 

There is no need for guessing.

Please replace your code which prints a single dot by

fmt.Fprintf(os.Stderr, "Now: %s\n\n\n\n\", time.Now().Format(time.RFC3339Nano)) 

and post the output.

V.