reflect: large performance regression in reflect.New

[rhysh]

Please answer these questions before submitting your issue. Thanks!

1. What version of Go are you using (go version)?

go1.7beta2: go version devel +fca9fc5 Thu Jun 16 19:45:33 2016 +0000 linux/amd64

1. What operating system and processor architecture are you using (go env)?

linux/amd64

1. What did you do?

I have a program that spends most of its time marshaling and unmarshaling data that's json- and protobuf-encoded. It's been running on go1.6.x for several months (currently go1.6.2), and I upgraded it to go1.7beta2.

It's a closed-source project, and I don't currently have a small reproducer.

1. What did you expect to see?

I expected no major performance regressions.

1. What did you see instead?

The program is significantly slower, with many more cycles spent in calls to reflect.New. Over 1/3rd of the program's execution time is spent in calls to reflect.(*rtype).ptrTo, which didn't even show up on profiles of the program under go1.6.2. Most of the time with ptrTo on the stack is in calls to RLock and RUnlock a *sync.RWMutex. The ptrTo cache appears to have been removed in February in 30f93f0.

Here's a bit of a go1.6.2 profile:

(pprof) peek reflect.New
126.07s of 138.79s total (90.84%)
Dropped 526 nodes (cum <= 0.69s)
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context          
----------------------------------------------------------+-------------
                                             2.38s 54.71% |   redacted.path/vendor/github.com/golang/protobuf/proto.(*Buffer).dec_struct_message
                                             1.97s 45.29% |   redacted.path/vendor/github.com/golang/protobuf/proto.(*Buffer).dec_slice_struct
     0.33s  0.24%  0.24%      4.35s  3.13%                | reflect.New
                                             3.90s   100% |   reflect.unsafe_New
----------------------------------------------------------+-------------

And here's a bit of the profile with go1.7beta2:

(pprof) peek reflect.New
184.09s of 197.76s total (93.09%)
Dropped 587 nodes (cum <= 0.99s)
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context          
----------------------------------------------------------+-------------
                                            39.29s 51.75% |   redacted.path/vendor/github.com/golang/protobuf/proto.(*Buffer).dec_struct_message
                                            36.64s 48.25% |   redacted.path/vendor/github.com/golang/protobuf/proto.(*Buffer).dec_slice_struct
     0.35s  0.18%  0.18%     75.93s 38.40%                | reflect.New
                                            67.65s 89.57% |   reflect.(*rtype).ptrTo
                                             7.88s 10.43% |   reflect.unsafe_New
----------------------------------------------------------+-------------
(pprof) peek ptrTo
184.09s of 197.76s total (93.09%)
Dropped 587 nodes (cum <= 0.99s)
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context          
----------------------------------------------------------+-------------
                                            67.65s   100% |   reflect.New
     4.87s  2.46%  2.46%     67.65s 34.21%                | reflect.(*rtype).ptrTo
                                            37.70s 60.06% |   sync.(*RWMutex).RLock
                                            23.76s 37.85% |   sync.(*RWMutex).RUnlock
                                             1.31s  2.09% |   runtime.mapaccess1_fast64
----------------------------------------------------------+-------------

[randall77]

@crawshaw

[potocnyj]

I just tested this and observed a 25% slowdown on JSON unmarshaling for one of our own systems. I can work on making a reproducer program if that would help.

[crawshaw]

What a pity. We have a spare 4 bytes I can use for a ptrTo type offset, though I had been hoping to remove that in 1.8. I suppose for now I can add it back and try to come up with some better solution in 1.8.

[ianlancetaylor]

We could also consider adding NewPtr

// NewPtr returns a Value representing a pointer of the specific type initialized to point to a new zero
// value of the pointer's element type. This is equivalent to New(typ.Elem()).
func NewPtr(typ Type) Value {
    if typ == nil || typ.Kind() != Ptr {
        panic("reflect.NewPtr of non-pointer type")
    }
    ptr := unsafe_New(typ.Elem().(*rtype))
    return Value{typ.(*rtype), ptr, flag(Ptr)}
}

[gopherbot]

CL https://golang.org/cl/24400 mentions this issue.

[crawshaw]

@rhysh if you get a chance I'd appreciate it if you could run your performance test again with tip.

[rhysh]

@crawshaw the performance is back to usual go1.6.2 levels with e75c899. Thanks for turning this around so quickly.

[cespare]

Do the JSON decoding benchmarks not capture this regression?

[potocnyj]

I retested my benchmark with e75c899, ans I still see a 15% regression relative to Go1.6.2.

Looking at a profile comparison, I see fairly substantial time increases in reflect.(*rtype).Name (7% vs. 2%) and reflect.(*rtype).NumMethod (8% vs 1%). Also there's more time being spent in sync/atomic.AddUint32, although that appears to be coming from reflect.(*rtype).NumMethod.

I've got a copy of my benchmark available here for those interested: https://play.golang.org/p/CiB34ge82s

[quentinmit]

@cespare: The JSON decoding benchmarks do capture this regression, yes. See our analysis in #16117.

[crawshaw]

@potocnyj I tried that benchmark and found it too noisy to see a 15% variation. How exactly are you running it?