Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
mrwiora opened this issue Oct 30, 2019 · 4 comments
Open

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

mrwiora opened this issue Oct 30, 2019 · 4 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@mrwiora
Copy link

mrwiora commented Oct 30, 2019

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
Copy link
Contributor

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.

@ianlancetaylor ianlancetaylor added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 30, 2019
@mrwiora
Copy link
Author

mrwiora commented Oct 31, 2019

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
Copy link
Contributor

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.

@agnivade agnivade added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Nov 3, 2019
@mrwiora
Copy link
Author

mrwiora commented Nov 4, 2019

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

@ALTree ALTree added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jan 7, 2020
@ALTree ALTree added this to the Unplanned milestone Jan 7, 2020
@seankhliao seankhliao changed the title output buffer seems to be blocked by first come, first serve os: output buffer seems to be blocked by first come, first serve Jun 18, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

4 participants