CC @dvyukov

Difference between go build and go run looks strange. Do we have any known precedent of differences?

@adilbaig can you provide a step-by-step repro instructions?

It is there in the code comments I believe -

// This program demonstrates a memory leak in Go's built-in race detector.
// You will need RabbitMQ and Postgres installed on your machine.

// First, run the program like this:
// > 	go build -o race experimental/rabbitmqmemoryleak.go && ./race
// Observe the 'RES' memory in `top`. It should level after a bit
//
// Then, run the program like this:
// > 	go build -race -o race experimental/rabbitmqmemoryleak.go && ./race
// Watch as RAM usage counts unchecked

Did you want anything specific ?

Something that I can copy-paste into my console.

@dvyukov How about this.

# Have RabbitMQ and Postgres setup (tested with version 9.6), on Ubuntu
sudo apt install rabbitmq-server postgresql-9.6
go get "github.com/streadway/amqp"
go build -o race rabbitmqmemoryleak.go && ./race
# Open `top` in another shell and see that memory usage (RES) is flat for this process. CTRL+C ./race.
go build -race -o race rabbitmqmemoryleak.go && ./race
# Now, open `top` in another shell and see the memory leak

You don't actually need to create Postgres tables. I see the leaks when the SQL errors out (for example due to bad login credentials).

Can reproduce it now.
The problem is that the program grows infinite stack with infinite recursion:

...
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
  main.someErroneousSQLTransaction()
      /tmp/rabbitmqmemoryleak.go:107 +0x5b
  main.handler()
      /tmp/rabbitmqmemoryleak.go:96 +0x22b
  database/sql.(*DB).Begin()
      database/sql/sql.go:1637 +0x6d
...

So it will crash without race detector sooner or later too, makes GC slow, crash messages unreadable, etc.
It's just that race detector is more sensitive to thousands of unique stacks as it memorizes tons of contextual information about the program as it runs. In this case it memorizes several variations of the stack per recursion frame, which is quadratic memory consumption.

@dvnagorny

So it will crash without race detector sooner or later too

I haven't seen that happen, as I ran it without the race detector over the weekend. Can you confirm that it's stable without -race?

I'm a novice at Go, but, given your explanation, am i right to think this will be an issue for any evented system (that errors out on events).?

Can you confirm that it's stable without -race?

no.

I'm a novice at Go, but, given your explanation, am i right to think this will be an issue for any evented system (that errors out on events).?

I don't know about these libraries, but what first comes to my mind is that there is a way to use them without infinite recursion. You both have an infinite loop in handler and call it recursively. I would expect that you need to do only 1 of these things, but not both. Have you looked at other usage examples of these libraries? Do all of them use it in the same way?

I don't know about these libraries, but what first comes to my mind is that there is a way to use them without infinite recursion. You both have an infinite loop in handler and call it recursively. I would expect that you need to do only 1 of these things, but not both.

I guess it only looks recursive in the dump, but it isn't, it's just running in a loop one message after another erroring out at every message. So I'm guessing with the race detector on, a reference to something in the sql package is still being bandied around. I tried replacing the sql error with a plain fmt.Errorf, memory usage remained flat. So it isn't any error that causes the leak, but something specific to the sql library. That's my guess.

for {
		message, ok, err := channel.Get(queue, false)
		if err != nil {
			log.Fatal(err)
		}
		if !ok {
			continue
		}

		log.Printf("%+v", message)

		// err = someErroneousSQLTransaction(pgb)
		err = fmt.Errorf("FAKE ERROR!") //Didn't leak
		if err != nil {
			log.Printf("ERROR: %s", err)
			message.Nack(false, true)
		} else {
			message.Ack(false)
		}
	}
...

Have you looked at other usage examples of these libraries? Do all of them use it in the same way?

Yep, it's largely just fetching and processing a message in a loop. Here's a canonical example from the site: https://www.rabbitmq.com/tutorials/tutorial-one-go.html (Code is at https://github.com/rabbitmq/rabbitmq-tutorials/blob/master/go/receive.go)

@dvnagorny

I guess it only looks recursive in the dump, but it isn't, it's just running in a loop one message after another erroring out at every message.

No, it calls someErroneousSQLTransaction which calls sql.(*DB).Begin which calls handler again.

Maybe I am missing something, but I fail to see how a sql.(*DB).Begin() call can call into user level code.

Also, @adilbaig, you are creating a transaction but are not using the tx to make your queries but instead, you are using the main db handle itself to make the QueryRow call. Any reason for that ? If you want your queries to happen through the transaction, you should use the tx handle itself to make the queries.

Also, we already have options to transaction types - https://golang.org/pkg/database/sql/#IsolationLevel. You can set them directly while creating a tx object.

My suspicion is that creating multiple transactions from mulitple goroutines is somehow causing this behavior in the race detector. Can you try with pgb.BeginTx() by setting opts to repeatable read, and use the tx to make the query and see if it makes any difference ?

@agnivade That was a mistake. Thanks for pointing it out!

Also, we already have options to transaction types ..

Nice! I will use that in my code.

The change doesn't make a difference though. I also think the bug resides somewhere in sql creating connections (not necessarily transactions) inside goroutines. Here's the code:

func someErroneousSQLTransaction(pgb *sql.DB) error {
	ctx := context.Background()
	refTx, err := pgb.BeginTx(ctx, &sql.TxOptions{Isolation: sql.LevelRepeatableRead})
	if err != nil {
		return err
	}
	defer func() {
		if err != nil {
			refTx.Rollback()
		} else {
			refTx.Commit()
		}
	}()

	var referenceID int64
	switch err = refTx.QueryRow(`SELECT "ID" FROM public.blah LIMIT 1`).Scan(&referenceID); err {
	case sql.ErrNoRows:
		break
	case nil:
		break
	default:
		return err
	}

	return nil
}

If that is the case, then I think we can take out rabbitMQ from the equation. Perhaps you can shorten the test by just spawning 10 goroutines which share a (*sql.DB) connection and perform the same query. And run that with race detector and see what happens.

Also, we are still unclear as to why the behavior does not show with go run -race, but only with go build -race. @dvyukov - do you have any clues on that ?

@agnivade - Well no, it only leaks when you're processing RMQ messages. Just plain channels throwing sql errors doesn't leak. The combination of the two libraries is playing a part.

Right. It seems that the trace is indeed broken.
First thing that comes to mind is broken panic/defer/recover support. On recover we should unwind race stack accordingly calling the necessary amount of racefuncexit, but I don't see this code at all. Did we ever do this? Does this program recover from panics? Defer should work out-of-the-box, at least that was the intention, but I wonder if it somehow leads to unmatched racefuncenter/racefuncexit.
I am travelling for next 3 weeks and most likely won't be be able to look closer.

Here is minimized reproducer:

package main

var x uint64

func main() {
	go func() {
		x++
	}()
	for i := 0; i < 10; i++ {
		baz()
	}
	x++
}

func baz() {
	defer func() {
		recover()
	}()
	foo()
}

func foo() {
	panic(0)
}

$ go version
go version devel +c9cc20bd3a Sat Sep 1 15:43:42 2018 +0000 linux/amd64

$ go run -race -gcflags=-l /tmp/test.go
==================
WARNING: DATA RACE
Read at 0x0000005253e8 by main goroutine:
  main.main()
      /tmp/test.go:12 +0x72
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54
  main.main()
      /tmp/test.go:10 +0x54

Previous write at 0x0000005253e8 by goroutine 5:
  main.main.func1()
      /tmp/test.go:7 +0x56

Goroutine 5 (finished) created at:
  main.main()
      /tmp/test.go:6 +0x46
==================

The repeated frames must not be present in the trace.
The root cause is that we don't unwind tsan stack on panic, i.e. not calling racefuncexit for each unwound frame. The bug is more visible with recover, but strictly saying affects just defer too. Consider that a race happens in a deferred func, or that main application loop runs in a deferred function.
This is not a regression, panics were never properly supported.

We could either defer racefuncexit instead of calling it, or manually call racefuncexit necessary amount of times before calling deferred functions (can we figure out how many frames we skip?). In both cases we need to be careful handling runtime functions because runtime is not instrumented, so we can potentially call racefuncexit too many times, or rely on racefuncexit being deferred when it's actually not.

Thank you for filing this issue @adilbaig and thanks @agnivade and @dvyukov for chasing down the bug and for the minimal repro!

@dvyukov perhaps do you think that we should punt this feature request to Go1.14 as it is this late in the Go1.13 cycle?

I think this is unstaffed, so we can move this right to Unplanned.

Roger that @dvyukov! I might be interested in this so will kindly page you sometime for CL reviews on it. I'll move it over.

Hi @dvyukov @odeke-em, can you describe a little bit more about the current behavior of these types of programs?

I have a program which uses lib/pq to connect to a Postgres database. lib/pq uses panics extensively, as a way of short-circuiting the call stack. I was using it with the race detector on. I also observe large and growing memory usage when I keep the program running, on both Mac and Linux, with Go 1.13 and tip.

Is it possible that panics are somehow not being garbage collected properly when the race detector is on?

I would expect the memory leak to be minimal (8 bytes per frame). That is tied to goroutine, so if the goroutine exits, the memory should be released.

That actually fits the profile perfectly. I had a long-running program that was reading rows out of a database in a for loop, then sending them to a downstream server, all in one blocking thread. The database library (github.com/lib/pq) uses panic and recover while sending and reading data, and I was using defer cancel() with context.WithTimeout throughout the program.

It also makes sense why I didn't see this on HTTP servers that are also long running. Those also use defer and recover() but inside of the spawned goroutine for an incoming connection so the recover will get cleaned up.

See #37233 for more information.

Change https://golang.org/cl/220586 mentions this issue: doc/articles: mention memory leak in race detector docs

Change https://golang.org/cl/221019 mentions this issue: [release-branch.go1.14] doc/articles/race_detector: mention memory leak potential

We just realized we were hitting this for many months in our dev and qa environments where we are running a server compiled with the race defector enabled. Ultimately disabling it kept the resident memory stable and not leaking to the point of being OOM killed over the course of the day. We however were not seeing 8 bytes of leakage at a time as opposed to many MB. When I core dumped the process and ran strings on it, I saw many duplicates of a record we pull from the database although we cache that value in a go map internally.

I eventually ran strace -k filtering for mmap calls since malloc can call mmap if the size requested is over a threshold. Doing this showed a lot of calls into tsan/sanitizer library shadow methods. I’m wondering if the shadow variables maintained end up making wholesale copies of certain values or regions of memory?

Either way, the detector is too useful and we will keep it on, but getting it to not leak memory would excise a lot of noise from our development and testing processes.

I’m wondering if the shadow variables maintained end up making wholesale copies of certain values or regions of memory?

No, the additional regions allocated by the race runtime should only hold internal metadata and never user data, or copies of user data.

I see. So around 7/15 02:00 is when we turned off the detector and as soon as we turned it back on today we started leaking again.

We've had that type of trend for at least 3 months now and not running it for a 12 hour period showed no kind of abnormal leakage of memory. So maybe something else is going on that is causing a ton of 8 byte leakages?

Keeping in mind that this is mostly HTTP traffic load that stays consistent day over day.

I've had users report this when using https://github.com/anacrolix/stm with the race detector enabled. Per other comments above, there is a lot of defer/recover, and very long call stacks that don't look correct.

Change https://go.dev/cl/458218 mentions this issue: runtime: implement traceback iterator

Once this is fixed, we should unwind the documentation change in CL 221019

FYI, @dvyukov 's test case no longer reproduces for me.

I also tried forcing baz to use stack-allocated defers (by adding a named result parameter) and heap-allocated defers (by adding a for { ...; break } wrapper around the defer statement).

I also tried adding a runtime.Gosched() call after the go func() { x++ }() statement, to ensure the "Read at" and "Previous write at" match the same goroutines as in @dvyukov 's output.

Could something have changed in recent versions is Go (I presume 1.21 @mdempsky ?) that could have fixed this issue?