Uploaded image for project: 'Go Driver'
  1. Go Driver
  2. GODRIVER-507

bson.(*decoder).Decode performance is very poor, how to improve it

    • Type: Icon: Improvement Improvement
    • Resolution: Gone away
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 0.0.9
    • Component/s: BSON, Performance
    • None
    • Environment:
      go1.10.3, linux

      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

            Assignee:
            Unassigned Unassigned
            Reporter:
            jackylee orange.jackylee
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: