[GODRIVER-507] bson.(*decoder).Decode performance is very poor, how to improve it Created: 21/Jul/18  Updated: 27/Oct/23  Resolved: 10/Jan/19

Status: Closed
Project: Go Driver
Component/s: BSON, Performance
Affects Version/s: 0.0.9
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: orange.jackylee Assignee: Unassigned
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

go1.10.3, linux


Issue Links:
Depends
depends on GODRIVER-494 BSON Codec Redesign Closed

 Description   

when i use mongodb-go-driver load 300,000 records , the total size is about 130MB, i use runtime.pprof to analyse performance of cpu and memory, i found that cur.Decode(elem) use lots of cpu and memory. can anyone tell me how to improve it

cpu analysis

macbookpro:fpr_index fredlee$ go tool pprof fpr_index logs_profile/cpu-profile-2018-07-21_18-38-28.prof
File: fpr_index
Type: cpu
Time: Jul 21, 2018 at 6:38pm (CST)
Duration: 2.90mins, Total samples = 2.45mins (84.23%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20 -cum
Showing nodes accounting for 43.10s, 29.37% of 146.74s total
Dropped 453 nodes (cum <= 0.73s)
Showing top 20 nodes out of 119
flat flat% sum% cum cum%
0 0% 0% 97.01s 66.11% huoli/fpr_index/singleton.(*M1).handle
0.05s 0.034% 0.034% 90.02s 61.35% huoli/fpr_index/util.(*Orderinfos).LoadFromDb
0.05s 0.034% 0.068% 82.30s 56.09% github.com/mongodb/mongo-go-driver/core/topology.(*cursor).Decode
0.10s 0.068% 0.14% 82.01s 55.89% github.com/mongodb/mongo-go-driver/bson.(*decoder).Decode
0.03s 0.02% 0.16% 81.93s 55.83% github.com/mongodb/mongo-go-driver/bson.(*decoder).reflectDecode
0.32s 0.22% 0.37% 81.83s 55.77% github.com/mongodb/mongo-go-driver/bson.(*decoder).decodeIntoStruct
0 0% 0.37% 80.62s 54.94% huoli/fpr_index/singleton.(*M1).check.func1
0.14s 0.095% 0.47% 67.86s 46.25% reflect.Value.FieldByNameFunc
0.15s 0.1% 0.57% 67.32s 45.88% reflect.(*rtype).FieldByNameFunc
2.55s 1.74% 2.31% 66.87s 45.57% reflect.(*structType).FieldByNameFunc
0.73s 0.5% 2.81% 62.37s 42.50% github.com/mongodb/mongo-go-driver/bson.(*decoder).decodeIntoStruct.func1
2.74s 1.87% 4.67% 54.65s 37.24% github.com/mongodb/mongo-go-driver/bson.matchesField
0.10s 0.068% 4.74% 50.52s 34.43% runtime.systemstack
0 0% 4.74% 43.06s 29.34% runtime.gcBgMarkWorker
0 0% 4.74% 43.05s 29.34% runtime.gcBgMarkWorker.func2
0.46s 0.31% 5.06% 43.05s 29.34% runtime.gcDrain
15.71s 10.71% 15.76% 42.92s 29.25% runtime.scanobject
0.83s 0.57% 16.33% 38.62s 26.32% github.com/mongodb/mongo-go-driver/bson.(*decoder).getReflectValue
0.04s 0.027% 16.36% 36.93s 25.17% github.com/mongodb/mongo-go-driver/bson.(*decoder).decodeBSONArrayToSlice
19.10s 13.02% 29.37% 26.71s 18.20% runtime.mallocgc
(pprof) web
(pprof) list LoadFromDb
Total: 2.45mins
ROUTINE ======================== huoli/fpr_index/util.(*Orderinfos).LoadFromDb in /Users/fredlee/Documents/develop/go/workspace/src/huoli/fpr_index/util/mongo_orderinfo.go
30ms 1.50mins (flat, cum) 61.33% of Total
. . 67: }
. . 68: defer mongo.Close()
. . 69: coll := mongo.C()
. . 70:
. . 71: _map := make(map[string]Orderinfo)
. 10ms 72: cur, err := coll.Find(context.Background(), nil)
. . 73: if err != nil

{ . . 74: return num, err . . 75: }

. . 76: defer cur.Close(context.Background())
. 6.63s 77: for cur.Next(context.Background()) {
. 200ms 78: elem := Orderinfo{}
10ms 1.37mins 79: err1 := cur.Decode(&elem)
. . 80: if err1 != nil

{ . . 81: //_mylog := mylog.GetMylog().Regular() . . 82: //_mylog.Errorf("cur.Decode(elem) fail,%v", err1) . . 83: log.Printf("cur.Decode(elem) fail,%v\n", err1) . . 84: }

else

{ 20ms 850ms 85: _map[elem.Id] = elem . . 86: }

. . 87: }
. . 88: num = len(_map)
. . 89: if num > 0 { //表里无数据,仍使用旧数据
. . 90: m._map = _map

memory analysis
192:fpr_index fredlee$ go tool pprof fpr_index logs_profile/mem-profile-2018-07-21_18-41-20.prof
File: fpr_index
Type: inuse_space
Time: Jul 21, 2018 at 6:41pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web
(pprof) top10 -cum
Showing nodes accounting for 221.24MB, 64.69% of 342MB total
Dropped 17 nodes (cum <= 1.71MB)
Showing top 10 nodes out of 37
flat flat% sum% cum cum%
0 0% 0% 339.78MB 99.35% huoli/fpr_index/singleton.(*M1).check.func1
0 0% 0% 339.78MB 99.35% huoli/fpr_index/singleton.(*M1).handle
105.73MB 30.92% 30.92% 339.28MB 99.20% huoli/fpr_index/util.(*Orderinfos).LoadFromDb
0 0% 30.92% 221.51MB 64.77% github.com/mongodb/mongo-go-driver/bson.(*decoder).Decode
0 0% 30.92% 221.51MB 64.77% github.com/mongodb/mongo-go-driver/bson.(*decoder).decodeIntoStruct
0 0% 30.92% 221.51MB 64.77% github.com/mongodb/mongo-go-driver/bson.(*decoder).reflectDecode
0 0% 30.92% 221.51MB 64.77% github.com/mongodb/mongo-go-driver/core/topology.(*cursor).Decode
0 0% 30.92% 215.01MB 62.87% github.com/mongodb/mongo-go-driver/bson.(*decoder).getReflectValue
0 0% 30.92% 136.51MB 39.92% github.com/mongodb/mongo-go-driver/bson.(*decoder).decodeBSONArrayToSlice
115.50MB 33.77% 64.69% 115.50MB 33.77% github.com/mongodb/mongo-go-driver/bson.(*Value).StringValue
(pprof) list LoadFromDb
Total: 342MB
ROUTINE ======================== huoli/fpr_index/util.(*Orderinfos).LoadFromDb in /Users/fredlee/Documents/develop/go/workspace/src/huoli/fpr_index/util/mongo_orderinfo.go
105.73MB 339.28MB (flat, cum) 99.20% of Total
. . 72: cur, err := coll.Find(context.Background(), nil)
. . 73: if err != nil

{ . . 74: return num, err . . 75: }

. . 76: defer cur.Close(context.Background())
. 12.03MB 77: for cur.Next(context.Background()) {
512.09kB 512.09kB 78: elem := Orderinfo{}
. 221.51MB 79: err1 := cur.Decode(&elem)
. . 80: if err1 != nil

{ . . 81: //_mylog := mylog.GetMylog().Regular() . . 82: //_mylog.Errorf("cur.Decode(elem) fail,%v", err1) . . 83: log.Printf("cur.Decode(elem) fail,%v\n", err1) . . 84: }

else

{ 105.23MB 105.23MB 85: _map[elem.Id] = elem . . 86: }

. . 87: }
. . 88: num = len(_map)
. . 89: if num > 0 { //表里无数据,仍使用旧数据
. . 90: m._map = _map



 Comments   
Comment by Ian Whalen (Inactive) [ 10/Jan/19 ]

closing as gone away since we have since rewritten the bson decoder.  please feel free to open a new ticket with any new performance numbers you might have.

Comment by orange.jackylee [ 02/Aug/18 ]

thank you Kris Brandow
hope more efficiency decoder

Comment by Kristofer Brandow (Inactive) [ 30/Jul/18 ]

Hi jackylee,

Thanks for the report! We've noticed this in other areas as well. We are currently working on a new implementation to solve performance issues with the BSON decoder. You can track the progress of this in GODRIVER-494, which has been linked to this ticket.

Thanks!

--Kris

Generated at Thu Feb 08 08:34:21 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.