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.

Sign up for GitHub

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

Jump to bottom

runtime/race: false positive in reflect during net/rpc test #7460

Closed
rsc opened this issue Mar 4, 2014 · 8 comments
Closed

runtime/race: false positive in reflect during net/rpc test #7460

rsc opened this issue Mar 4, 2014 · 8 comments
Labels
FrozenDueToAge RaceDetector
Milestone
Go1.3

Comments

@rsc
Copy link
Contributor

rsc commented Mar 4, 2014 

See http://build.golang.org/log/b2cd252bfeae7df4a89e41af488bffd8104f3228 for an example.

It says that the race is on the writes to e.word, but e.word is writing to the local
variable i, which is on the stack. 'go build -gcflags -m reflect' confirms this:

./value.go:128: packEface &i does not escape

Here is the race report:

WARNING: DATA RACE
Write by goroutine 16:
  reflect.packEface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:153 +0x27d
  reflect.valueInterface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:1081 +0x28c
  reflect.Value.Interface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:1051 +0x7b
  net/rpc.(*service).call()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/net/rpc/server.go:389 +0x3dc

Previous write by goroutine 62:
  reflect.packEface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:153 +0x27d
  reflect.valueInterface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:1081 +0x28c
  reflect.Value.Interface()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/reflect/value.go:1051 +0x7b
  net/rpc.(*service).call()
      /Users/builder/workspace/darwin-amd64-race-cheney-2b66d388d1af/go/src/pkg/net/rpc/server.go:389 +0x3dc

This seems like a bug in the race detector. Why is it reporting a race on a stack
variable?
Is it that the two goroutines ran one after the other and wrote to the same location?
That's a little surprising to show up as a false positive.
@rsc
Copy link
Contributor Author

rsc commented Mar 4, 2014

Comment 1:

The linux failure appears to be the same problem.
http://build.golang.org/log/beb9b0bce42d560d2cb9e139f861b2f150cb1b8e
This is creating the closure and then deferring it.
    0x0072 00114 (/Users/rsc/g/go/src/pkg/net/http/server.go:1097)  MOVQ    24(CX),BP
    0x0076 00118 (/Users/rsc/g/go/src/pkg/net/http/server.go:1097)  MOVQ    BP,"".origConn+288(SP)
    0x007e 00126 (/Users/rsc/g/go/src/pkg/net/http/server.go:1097)  MOVQ    32(CX),BP
    0x0082 00130 (/Users/rsc/g/go/src/pkg/net/http/server.go:1097)  MOVQ    BP,"".origConn+296(SP)
    0x008a 00138 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    $0,"".autotmp_1292+416(SP)
    0x0096 00150 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    $0,"".autotmp_1292+424(SP)
    0x00a2 00162 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    $0,"".autotmp_1292+432(SP)
    0x00ae 00174 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  LEAQ    "".autotmp_1292+416(SP),CX
    0x00b6 00182 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    CX,"".autotmp_1291+248(SP)
    0x00be 00190 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    CX,(SP)
    0x00c2 00194 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$8
    0x00c2 00194 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $1,$3
    0x00c2 00194 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  CALL    ,runtime.racewrite(SB)
    0x00c7 00199 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    "".autotmp_1291+248(SP),CX
    0x00cf 00207 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$-1
    0x00cf 00207 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  NOP ,
    0x00cf 00207 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    $"".func·011+0(SB),BP
    0x00d4 00212 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    BP,(CX)
    0x00d7 00215 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    CX,(SP)
    0x00db 00219 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  ADDQ    $8,(SP)
    0x00e0 00224 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$8
    0x00e0 00224 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $1,$4
    0x00e0 00224 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  CALL    ,runtime.racewrite(SB)
    0x00e5 00229 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    "".autotmp_1291+248(SP),CX
    0x00ed 00237 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$-1
    0x00ed 00237 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  NOP ,
    0x00ed 00237 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  LEAQ    "".c+600(FP),BP
    0x00f5 00245 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    BP,8(CX)
    0x00f9 00249 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    CX,(SP)
    0x00fd 00253 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  ADDQ    $16,(SP)
    0x0102 00258 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$8
    0x0102 00258 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $1,$5
    0x0102 00258 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  CALL    ,runtime.racewrite(SB)
    0x0107 00263 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    "".autotmp_1291+248(SP),CX
    0x010f 00271 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$-1
    0x010f 00271 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  NOP ,
    0x010f 00271 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  LEAQ    "".origConn+288(SP),BP
    0x0117 00279 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  MOVQ    BP,16(CX)
    0x011b 00283 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $0,$16
    0x011b 00283 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PUSHQ   CX,
    0x011c 00284 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PUSHQ   $0,
    0x011e 00286 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  PCDATA  $1,$6
    0x011e 00286 (/Users/rsc/g/go/src/pkg/net/http/server.go:1109)  CALL    ,runtime.deferproc(SB)
There is no heap memory here. The racewrite is being called on stack addresses. Why?

@dvyukov
Copy link
Member

dvyukov commented Mar 4, 2014

Comment 2:

Here is another one I observed locally:
WARNING: DATA RACE
Write by goroutine 33:
  net/http.(*conn).serve()
      src/pkg/net/http/server.go:1109 +0xc7
Previous read by goroutine 29:
  reflect.(*structType).FieldByNameFunc()
      src/pkg/reflect/type.go:908 +0x26a
  reflect.(*structType).FieldByName()
      src/pkg/reflect/type.go:1000 +0x227
  reflect.(*rtype).FieldByName()
      src/pkg/reflect/type.go:621 +0x119
  encoding/gob.(*Decoder).compileDec()
      src/pkg/encoding/gob/decode.go:1163 +0x5a9
  encoding/gob.(*Decoder).getDecEnginePtr()
      src/pkg/encoding/gob/decode.go:1192 +0x244
  encoding/gob.(*Decoder).decOpFor()
      src/pkg/encoding/gob/decode.go:897 +0x13b2
  encoding/gob.(*Decoder).compileDec()
      src/pkg/encoding/gob/decode.go:1173 +0x87f
  encoding/gob.(*Decoder).getDecEnginePtr()
      src/pkg/encoding/gob/decode.go:1192 +0x244
  encoding/gob.(*Decoder).decodeValue()
      src/pkg/encoding/gob/decode.go:1237 +0x166
  encoding/gob.(*Decoder).recvType()
      src/pkg/encoding/gob/decoder.go:59 +0x187
  encoding/gob.(*Decoder).decodeTypeSequence()
      src/pkg/encoding/gob/decoder.go:170 +0xf9
  encoding/gob.(*Decoder).DecodeValue()
      src/pkg/encoding/gob/decoder.go:223 +0x182
  encoding/gob.(*Decoder).Decode()
      src/pkg/encoding/gob/decoder.go:202 +0x29f
  net/rpc.(*gobServerCodec).ReadRequestHeader()
      src/pkg/net/rpc/server.go:401 +0x83
  net/rpc.(*Server).readRequestHeader()
      src/pkg/net/rpc/server.go:552 +0xd5
  net/rpc.(*Server).readRequest()
      src/pkg/net/rpc/server.go:519 +0x13d
  net/rpc.(*Server).ServeCodec()
      src/pkg/net/rpc/server.go:438 +0x8e
  net/rpc.(*Server).ServeConn()
      src/pkg/net/rpc/server.go:430 +0x1ab

Labels changed: added repo-main, racedetector.

@dvyukov
Copy link
Member

dvyukov commented Mar 4, 2014

Comment 3:

> Why is it reporting a race on a stack variable?
Compiler does not always know when a pointer points to stack. E.g. if you have a
function with non-escaping pointer parameter, one caller can pass a pointer to
stack-allocated object, while another caller can pass a pointer to heap object. So we
have to do runtime check for stack accesses, we filter out everything that is not heap
nor global.
I suspect that the problem is with heap-allocated stack segments. They are processed by
race detector, but when they are malloced the shadow race state is reset. Probably the
bug is introduced in recent stack management changes.

@rsc
Copy link
Contributor Author

rsc commented Mar 4, 2014

Comment 4:

Well, okay, there's a bug in racewrite. But there is also a bug in the annotations. The
memory addresses here are clearly stack addresses (LEAQ "".autotmp_1292+416(SP),CX, and
so on). Those should not even call racewrite.

@dvyukov
Copy link
Member

dvyukov commented Mar 4, 2014

Comment 5:

This predicate is most likely incorrect, but I don't know how to fix it:
    b = basenod(n);
    // it skips e.g. stores to ... parameter array
    if(isartificial(b))
        return 0;
    class = b->class;
    // BUG: we _may_ want to instrument PAUTO sometimes
    // e.g. if we've got a local variable/method receiver
    // that has got a pointer inside. Whether it points to
    // the heap or not is impossible to know at compile time
    if((class&PHEAP) || class == PPARAMREF || class == PEXTERN
        || b->op == OINDEX || b->op == ODOTPTR || b->op == OIND || b->op == OXDOT) {

@dvyukov
Copy link
Member

dvyukov commented Mar 4, 2014

Comment 6:

I think I know what happens, the following function assumes that we always has m->curg
when allocating stack:
void
runtime·racemalloc(void *p, uintptr sz)
{
    // use m->curg because runtime·stackalloc() is called from g0
    if(m->curg == nil)
        return;
    m->racecall = true;
    m->locks++;
    runtime∕race·Malloc(m->curg->racectx, p, sz, /* unused pc */ 0);
    m->locks--;
    m->racecall = false;
}
This is now not true for shrinkstack in during GC.

@dvyukov
Copy link
Member

dvyukov commented Mar 4, 2014

Comment 7:

to resolve this I need to update race runtime, which is blocked on:
https://golang.org/cl/55100044/
(upstream race runtime requires 55100044 to be in)

@dvyukov
Copy link
Member

dvyukov commented Mar 6, 2014

Comment 8:

This issue was closed by revision a1695d2.

Status changed to Fixed.

@rsc rsc added this to the Go1.3 milestone Apr 14, 2015
@rsc rsc removed the release-go1.3 label Apr 14, 2015
@golang golang locked and limited conversation to collaborators Jun 25, 2016
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge RaceDetector
Projects
None yet
Milestone
Go1.3
Development

No branches or pull requests
3 participants
@rsc @dvyukov @gopherbot