elodina / go-avro

Apache Avro for Golang
http://elodina.github.io/go-avro/
Apache License 2.0
129 stars 55 forks source link

Issues in enum caching code. #68

Open crast opened 8 years ago

crast commented 8 years ago

I was going to take issue with the enum caching code from 2f447d10e09f6dea9c38bcf8acec9a3ba46af8e3 partially because it disambiguates on the schema name and I don't feel like that's a good idea; enums can have very common names like 'Type' which is a type of thing that is contextually different based on what the enclosing schema is. I have a potential solution to that coming down the line which still provides the speedup advantage.

However, more importantly while reading it over, I found a data race. The source of the issue is that the map reads are not locked via mutexes. This is not allowed if the map can be written to (even if the writes are locked via mutex); and the end result is this can cause run-time crashes when running an application which runs multiple goroutines.

With these tests: https://github.com/crast/avro/commit/enum-data-race-proof

Runtime with go test -race finds this race:

$ go test -race -run Race -v
=== RUN   TestEnumCachingRace
==================
WARNING: DATA RACE
Read by goroutine 8:
  runtime.mapaccess1_faststr()
      /usr/local/Cellar/go/1.5.3/libexec/src/runtime/hashmap_fast.go:179 +0x0
  github.com/elodina/go-avro.(*GenericDatumReader).mapEnum()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:477 +0x1a9
  github.com/elodina/go-avro.(*GenericDatumReader).readValue()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:422 +0x14a
  github.com/elodina/go-avro.(*GenericDatumReader).findAndSet()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:382 +0xb5
  github.com/elodina/go-avro.(*GenericDatumReader).mapRecord()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:555 +0x266
  github.com/elodina/go-avro.(*GenericDatumReader).readValue()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:430 +0xd4
  github.com/elodina/go-avro.(*GenericDatumReader).Read()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:364 +0x1c6
  github.com/elodina/go-avro.enumRaceTest.func1()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:363 +0x3b7
  github.com/elodina/go-avro.parallelF.func1()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:375 +0x74

Previous write by goroutine 7:
  runtime.mapassign1()
      /usr/local/Cellar/go/1.5.3/libexec/src/runtime/hashmap.go:411 +0x0
  github.com/elodina/go-avro.(*GenericDatumReader).mapEnum()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:484 +0x438
  github.com/elodina/go-avro.(*GenericDatumReader).readValue()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:422 +0x14a
  github.com/elodina/go-avro.(*GenericDatumReader).findAndSet()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:382 +0xb5
  github.com/elodina/go-avro.(*GenericDatumReader).mapRecord()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:555 +0x266
  github.com/elodina/go-avro.(*GenericDatumReader).readValue()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:430 +0xd4
  github.com/elodina/go-avro.(*GenericDatumReader).Read()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader.go:364 +0x1c6
  github.com/elodina/go-avro.enumRaceTest.func1()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:363 +0x3b7
  github.com/elodina/go-avro.parallelF.func1()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:375 +0x74

Goroutine 8 (running) created at:
  github.com/elodina/go-avro.parallelF()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:377 +0xb4
  github.com/elodina/go-avro.enumRaceTest()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:364 +0x18d
  github.com/elodina/go-avro.TestEnumCachingRace()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:346 +0xc2
  testing.tRunner()
      /usr/local/Cellar/go/1.5.3/libexec/src/testing/testing.go:456 +0xdc

Goroutine 7 (running) created at:
  github.com/elodina/go-avro.parallelF()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:377 +0xb4
  github.com/elodina/go-avro.enumRaceTest()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:364 +0x18d
  github.com/elodina/go-avro.TestEnumCachingRace()
      $GOPATH/src/github.com/elodina/go-avro/datum_reader_test.go:346 +0xc2
  testing.tRunner()
      /usr/local/Cellar/go/1.5.3/libexec/src/testing/testing.go:456 +0xdc
==================
--- PASS: TestEnumCachingRace (0.01s)
=== RUN   TestEnumCachingRace2
--- PASS: TestEnumCachingRace2 (0.00s)
PASS
Found 1 data race(s)
exit status 66
FAIL    github.com/elodina/go-avro  1.090s
serejja commented 8 years ago

Hi @crast, I've merged #69, thanks for posting it.

I agree that having an enum cache could cause some problems with equal names, however that's what are namespaces for? The point of this cache is that the symbol to index map is created every single time the enum is created, which is obviously a performance bottleneck. If you can come up with a different solution that could avoid creating symbol-index map each time, this is more than welcome.

Thanks!

crast commented 8 years ago

@serejja I agree; I think there's another way around it though.

See this comment https://github.com/elodina/go-avro/pull/70#issuecomment-181630949

crast commented 8 years ago

also I found in my organization (where we have over 70 avro schemas) there can be two records in the same namespace that both have an enum with a very common name like Type which references some type of thing.

crast commented 8 years ago

A more common scenario - Going through a bunch of avro files and one of the later files has a newer version of the schema - the namespace doesn't change, but the new schema has more entries in the enum.