压测过程中，发现数据库中某个字段（json字符串）在解析的过程中提示，json字符串不符合json格式要求，增加日志打印后，发现json打印如下：
47^A0^MTCKSGroup1773
1540984132
1540984232^D6000^F749279^K52057485773^A1^K18888881773
1540984137^A1ü4^B{"complete_code": "", "promise_delivery_time_second": 1800, "aoi_type": 1, "receive_user_money": 0, "app_id": "0", "need_invoice": 0, "user_lat": "40.014593", "user_id": 0, "pickup_code": "", "user_lng": "125.149658", "co
nfig": "", "resource_station": 10003371, "dish_type_nums": 0, "brand": "è<80><81>å¨<98>è<88><85>", "settlement_type": 1, "verify_code_type": 0, "assessment_time": 0, "shop_lng": "116.347791", "dispatch_strategy": "common", "remark": "", "
product_type": 1, "shop_la],json parser extend info failed,err:[invalid character '\x01' after top-level value
但是我们在数据库里面查到的结果却是正确的json字符串。所以我们怀疑是多线程之间使用mysql存在数据公用的问题。
上race工具，验证是否存在内存相互竞争问题，发现有data race
> go run -race *.go
==================
WARNING: DATA RACE
Write at 0x00c000e2fa98 by goroutine 218:
internal/race.WriteRange()
/home/doctorq/soft/go/src/internal/race/race.go:49 +0x42
syscall.Read()
/home/doctorq/soft/go/src/syscall/syscall_unix.go:175 +0x9a
internal/poll.(*FD).Read()
/home/doctorq/soft/go/src/internal/poll/fd_unix.go:165 +0x194
net.(*netFD).Read()
/home/doctorq/soft/go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/doctorq/soft/go/src/net/net.go:177 +0xa0
net.(*TCPConn).Read()
<autogenerated>:1 +0x69
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*buffer).fill()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/buffer.go:68 +0x1a5
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*buffer).readNext()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/buffer.go:97 +0x1bf
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlConn).readPacket()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/packets.go:67 +0x25d
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlConn).readUntilEOF()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/packets.go:786 +0x45
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlRows).Close()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/rows.go:116 +0x186
gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*textRows).Close()
<autogenerated>:1 +0x43
database/sql.(*Rows).close.func1()
/home/doctorq/soft/go/src/database/sql/sql.go:2968 +0x70
database/sql.withLock()
/home/doctorq/soft/go/src/database/sql/sql.go:3076 +0x74
database/sql.(*Rows).close()
/home/doctorq/soft/go/src/database/sql/sql.go:2967 +0x192
database/sql.(*Rows).awaitDone()
/home/doctorq/soft/go/src/database/sql/sql.go:2631 +0x12d
Previous read at 0x00c000e2fa9f by goroutine 61:
runtime.slicebytetostring()
/home/doctorq/soft/go/src/runtime/string.go:75 +0x0
gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).ParserRows()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:102 +0x32d
gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).OrderQuery()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:73 +0x36a
gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlProxy).GetOrderInfoByOrderId()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_proxy.go:111 +0x1c6c
gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetOrderByOrderId()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:32 +0xa8
gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetUndistributedOrder()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:82 +0x159
gitlab.sftcwl.com/dispatch/data/handler/service.(*GetOrder).Access()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/service/get_order.go:35 +0x3dc
gitlab.sftcwl.com/dispatch/data/handler.(*DataServiceHandler).GetOrderDetail()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/DataService_handler.go:45 +0xba
gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2725 +0xa1
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:31 +0x2d3
gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter.UnaryServerInterceptor.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter/perfcounter.go:58 +0x127
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34 +0x1d9
gitlab.sftcwl.com/dispatch/data/framework/interceptor/header.UnaryServerInterceptor.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/header/header.go:74 +0x33e
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:39 +0x33d
gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2727 +0x1d8
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).processUnaryRPC()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1026 +0xa8b
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleStream()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1252 +0x1384
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:699 +0xac
Goroutine 218 (running) created at:
database/sql.(*Rows).initContextClose()
/home/doctorq/soft/go/src/database/sql/sql.go:2615 +0xf9
database/sql.(*DB).queryDC()
/home/doctorq/soft/go/src/database/sql/sql.go:1555 +0x9cf
database/sql.(*DB).query()
/home/doctorq/soft/go/src/database/sql/sql.go:1519 +0x182
database/sql.(*DB).QueryContext()
/home/doctorq/soft/go/src/database/sql/sql.go:1496 +0xe6
gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/golang-lib-inner/xmysql.(*Client).QueryContext()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/golang-lib-inner/xmysql/client.go:190 +0xb1
gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).OrderQuery()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:61 +0x19b
gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlProxy).GetOrderInfoByOrderId()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_proxy.go:111 +0x1c6c
gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetOrderByOrderId()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:32 +0xa8
gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetUndistributedOrder()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:82 +0x159
gitlab.sftcwl.com/dispatch/data/handler/service.(*GetOrder).Access()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/service/get_order.go:35 +0x3dc
gitlab.sftcwl.com/dispatch/data/handler.(*DataServiceHandler).GetOrderDetail()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/DataService_handler.go:45 +0xba
gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2725 +0xa1
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:31 +0x2d3
gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter.UnaryServerInterceptor.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter/perfcounter.go:58 +0x127
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34 +0x1d9
gitlab.sftcwl.com/dispatch/data/framework/interceptor/header.UnaryServerInterceptor.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/header/header.go:74 +0x33e
gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:39 +0x33d
gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2727 +0x1d8
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).processUnaryRPC()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1026 +0xa8b
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleStream()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1252 +0x1384
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:699 +0xac
Goroutine 61 (running) created at:
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:697 +0xb8
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport/http2_server.go:432 +0x14cb
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport/http2_server.go:472 +0x37a
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:695 +0x170
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleRawConn.func2()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:649 +0x53
gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleRawConn.func3()
/home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:657 +0x34
==================
上面的检测证明确实buffer被多个线程同时读取。
Truncate internal buffer when rows.Close() is called
目前还没合到master，我在本地按照这个pull request修改后，data trace没有出现，串数据的问题也没再出现。
当使用QueryContext读取mysql数据库时，当在rows.Next过程中，context超时了，会直接退出读取过程，会自动调用defer rows.Close()，而在Close的过程中，没有处理已经读取的那部分数据，那部分数据还存在buffer里面，而当下一次的rows.Scan读取的时候，就有几率读到这部分数据，就会跟当前的数据串了。看官方的修复操作，也是强制在Close过程中把这部分数据截取丢弃掉。
database/sql从1.10开始要求rows.Close()的操作不能覆盖rows.Next使用的buffer，但是go-sql-driver/sql还没遵守这个规则，而这个问题出现的概率很低，如果不是高并发的情况一般不容易发生。
database/sql: buffers provided to Rows.Next should not be modified by