os: output buffer seems to be blocked by first come, first serve

[mrwiora]

What version of Go are you using (go version)?

1.13.3

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/user/sdk/go1.13.3"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/user/sdk/go1.13.3/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build069569925=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I have a very heavy load application, where I use the standard program output as logging output. This logging output is then redirected by docker towards a logserver. So far so nice.
This works perfectly, but sometimes I am missing some log lines - while the code after the print has been executed. It looks like there is an issue when two concurrent threads access the output of the application - is this intended or cannot be resolved? Maybe I am using the wrong way to output my data? I could not find anything related to that.
I've written a short example code, which seems to reproduce the problem - the same issue occurs when using fmt.println()

package main

func main() {
        x := 0
        for x < 1000 {
                //println(x)
                go myPrintFunc(x)
                x++
        }
        println(x)
}

func myPrintFunc(i int) {
        println(i)
}

What did you expect to see?

The same result as I would get with the println(i) commented in and the go-call commented out, which in my case always produces all outputs.

What did you see instead?

each time other values (which are part of the output) - I guess the first comming output blocks the other outputs.

[ianlancetaylor]

Your program does not wait for all the goroutines to complete. If I add a sync.WaitGroup to make sure that all goroutines complete, I see all the expected output lines.

[mrwiora]

nice! Seems to solve the issue for now for the sample program. Thanks! My issue here was apparently, that the program was clased before the goroutines finished.

However this will not solve the issue with my normal program - as the programm runs infinitely, but my logs dissappear too. Is there a smoother way to access the standard output than just using fmt.Println() or println()? Or a way of debugging this behaviour?

btw: For anyone who is interested in the sync solution:

package main

import (
	"fmt"
	"sync"
)

func main() {
	var wg sync.WaitGroup
	x := 0
	for x < 1000 {
		//println(x)
		wg.Add(1)
		go myPrintFunc(x, &wg)
		x++
	}
	fmt.Println(x)
	wg.Wait()
}

func myPrintFunc(i int, wg *sync.WaitGroup) {
	fmt.Println(i)
	wg.Done()
}

[ianlancetaylor]

Where are your logs going? If they are going to a file that is not opened in append mode, then I think that multiple concurrent writes can overlap. This should not happen if they are going to the ordinary standard output/standard error, nor if they are going to a file opened in append mode.

[mrwiora]

achtually they are indeed going to either println() or fmt.Println() as I've configured my docker host to redirect the logfiles to a central search server.

But I am seeing the issues while performing jmeter load-tests even without the docker-environment (round about 700 requests per second) - so only println to the standard output... :D that is why I thought one output would oust the other