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

log: lines are split #1302

Closed
rogpeppe opened this issue Nov 26, 2010 · 7 comments
Closed

log: lines are split #1302

rogpeppe opened this issue Nov 26, 2010 · 7 comments

Comments

@rogpeppe
Copy link
Contributor

the following program splits lines inappropriately (see attached file
containing sample output).

6g darwin 71a9509287b2+ tip

package main
import "log"
var c = make(chan bool)
func main() {
    go printer("xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx")
    go printer("yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy")
    <-c
    <-c
}

func printer(s string) {
    for i := 0; i < 10000; i++ {
        log.Print(s)
    }
    c <- true
}

Attachments:

  1. output.txt (1320004 bytes)
@alexbrainman
Copy link
Member

Comment 1:

Issue #1301 has been merged into this issue.

@robpike
Copy link
Contributor

robpike commented Nov 26, 2010

Comment 2:

Log already goes out of its way to do a single write system call per log entry.  Adding
a mutex here adds overhead for little gain.
Experiments running your program show the problem happens when the logging destination
is slow, such as writing to disk.  Fast consumers seem to alleviate the problem.   I
suspect what's going on is that with this much logging going on, buffers are filling up
and the program is being rescheduled mid-write.
If you can demonstrate the problem with modest logging volume a mutex might be the only
answer, but I would categorize this problem as a kernel issue regarding resource
exhaustion by an extreme program and not worth addressing in the library code.

Status changed to WontFix.

@rogpeppe
Copy link
Contributor Author

Comment 3:

- Log isn't calling the write system call - it's calling a Write method, which is not
thread-safe in general,
although it's common to call log.Output from different threads.
- I saw these issues when using log with a real (not extreme) program using log to
produce debug messages. Admittedly the maximum message rate was quite high, but I don't
think that's too unusual.
If log isn't reliable when writing to disk or to a tty, there's something wrong IMHO. I
agree that it's a kernel issue - writing to a pipe *should* be atomic regardless of the
speed of the reader, but it's still an issue.
- If the volume of messages is low, then a mutex will add negligible overhead; if the
volume of messages is high, then you'll need a mutex anyway.

@niemeyer
Copy link
Contributor

Comment 4:

Indeed it feels like a mutex to avoid garbled output is a good solution, and that's how
I've seen logging packages working in other languages.
As a minor note, though, if you're using a log *file*, this problem can be solved by
using O_APPEND, in which case the kernel guarantees the write atomicity.

@robpike
Copy link
Contributor

robpike commented Nov 28, 2010

Comment 5:

I'm creeped out by the idea that I need to wrap a mutex around every system call
(ignoring that it's a Write method; if the Writes aren't atomic that's their fault).  My
creep is not alleviated by the empirical result that this bug seems mac-specific.
In short, it's not the fix that bothers me, it's the precedent.

@robpike
Copy link
Contributor

robpike commented Nov 29, 2010

Comment 6:

Status changed to Thinking.

@robpike
Copy link
Contributor

robpike commented Dec 1, 2010

Comment 7:

This issue was closed by revision 1f90447.

Status changed to Fixed.

@golang golang locked and limited conversation to collaborators Jun 24, 2016
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants