Significant performance variation for defining times

[jacksontj]

First off, thanks for this amazing library. I have been using this for a few projects and it is simply amazing.

While working on a project I ran into a seemingly confusing performance issue. I need to pass a time around in my rpc messages, my current implementation is using a single int64, but I decided that I'd move to using the google timestamp (int64 + int32) to get better granularity etc. After doing so my benchmarks are showing a significant performance cost for doing so.

As a baseline, doing a single message with an int64 takes 61/38 ns to Marshal/Unmarshal respectively. Doing so with a google.Timestamp is 98/131 (which is ~1.5x/~3x slowdown respectively). I tried a variety of gogo options (stdtime, nullable=false, etc.). From doing those I see 2 patterns:

1. stdtime always returns a *time.Time which means even in the nullable=false case it seems to be heap allocating -- which is causing some slowdown
2. having the timestamp in a type within the message is significantly slower

I have created a repo with my test code that these benchmarks where done with. I'll paste the output below here for convenience:

goos: linux
goarch: amd64
pkg: github.com/jacksontj/timestampProto
BenchmarkProto3/marshal/EmbeddedGoogleTimestamp-8                       	20000000	        98.3 ns/op	       4 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/EmbeddedGoogleTimestamp-8       	                10000000	       131 ns/op	      48 B/op	       1 allocs/op
BenchmarkProto3/marshal/EmbeddedGoogleTimestampStdTimeNonNull-8         	 3000000	       450 ns/op	     148 B/op	       4 allocs/op
BenchmarkProto3/unmarshal/EmbeddedGoogleTimestampStdTimeNonNull-8       	10000000	       141 ns/op	      48 B/op	       1 allocs/op
BenchmarkProto3/marshal/MyTimestamp-8                                   	20000000	        66.3 ns/op	       2 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/MyTimestamp-8                                 	50000000	        35.4 ns/op	       0 B/op	       0 allocs/op
BenchmarkProto3/marshal/EmbeddedStdTime-8                               	 3000000	       443 ns/op	     148 B/op	       4 allocs/op
BenchmarkProto3/unmarshal/EmbeddedStdTime-8                             	10000000	       212 ns/op	      80 B/op	       2 allocs/op
BenchmarkProto3/marshal/EmbeddedStdTimeNonNull-8                        	 3000000	       451 ns/op	     148 B/op	       4 allocs/op
BenchmarkProto3/unmarshal/EmbeddedStdTimeNonNull-8                      	10000000	       141 ns/op	      48 B/op	       1 allocs/op
BenchmarkProto3/marshal/EmbeddedGoogleTimestampStdTime-8                	20000000	       100 ns/op	       4 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/EmbeddedGoogleTimestampStdTime-8              	10000000	       127 ns/op	      48 B/op	       1 allocs/op
BenchmarkProto3/marshal/EmbeddedGoogleTimestampNonNull-8                	20000000	        93.0 ns/op	       4 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/EmbeddedGoogleTimestampNonNull-8              	30000000	        49.2 ns/op	       0 B/op	       0 allocs/op
BenchmarkProto3/marshal/Int64-8                                         	20000000	        61.6 ns/op	       2 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/Int64-8                                       	30000000	        38.7 ns/op	       0 B/op	       0 allocs/op
BenchmarkProto3/marshal/Embedded-8                                      	20000000	        90.7 ns/op	       4 B/op	       1 allocs/op
BenchmarkProto3/unmarshal/Embedded-8                                    	20000000	        87.0 ns/op	      16 B/op	       1 allocs/op
PASS

[donaldgraham]

Thanks so much for your work on this. We'll take a careful look at it.

[jacksontj]

@donaldgraham thanks! And if there is any additional information I can provide please let me know!

[timpalpant]

I have a change out (#509) to eliminate intermediate heap allocations when using StdTime + nullable=false. Since you have created a nice set of benchmarks (thanks!), I ran them* to compare the effect of the PR:

This obviously doesn't change your main conclusion that there is significant overhead compared to a single int64 field, but it does at least seem to help in the cases that were really being slowed down by the heap allocations.

(*) I made a slight change to the benchmarks to reuse the buffer slice, since I find that I can often reuse it. The effects are the same.

[jacksontj]

That is dramatically better. I'm still curious why the remaining gap, but with that PR merged its at least just ~4x CPU time (much better than ~10x) :)

[jacksontj]

I've also opened up #513; it turns out the way it was converting time.Time -> *Timestamp was also quite inefficient-- with that fix its ~30% improvement. That makes it still roughly 2x an inline value, but we're getting closer!

[jacksontj]

So, after some more time working on this, its possible to get the performance for marshal down to ~33 ns/op (which is ~2x direct ints in proto files). To achieve this I had to do 2 things locally

~15% improvement

In the .pb.go file's MarshalTo method there are sections that look like so:

i = encodeVarintTest(dAtA, i, uint64(github_com_gogo_protobuf_types.SizeOfStdTime(m.Timestamp)))
n8, err := github_com_gogo_protobuf_types.StdTimeMarshalTo(m.Timestamp, dAtA[i:])

This (1) gets the size of the timestamp and (2) writes the timestamp. If we look at SizeOfStdTime it actually does the conversion from a time.Time to a Timestamp, gets the size, and throws that away. If we added a method to get a Timestamp direct (a non-pointer to avoid the heap allocation) we could change this codegen to look like:

	ts, err := github_com_gogo_protobuf_types.TimestampProtoDirect(m.Timestamp)
	if err != nil {
		return 0, err
	}
	i = encodeVarintTest(dAtA, i, uint64(ts.Size()))
	n8, err := ts.MarshalTo(dAtA[i:])

This makes it so we do the conversion once, and use that same object for (1) size calculation and (2) marshaling.

~50% speedup

timestampProto is (1) converting the time.Time to a Timestamp and (2) validating the timestamp. The validateTimestamp call accounts for ~50% of the time (if I remove the check it drops the time by 50%). Interestingly if I change the validateTimestamp method to simply return nil it has the same performance. I'm not certain there is a way to speed that up, as it seems that the additional function call is what is causing the slowdown. I'm not sure how valid it would be to remove these? TBH I'm not sure what the normal expected behavior is for unmarshal validation here. For most types there aren't checks in the unmarshal flow, as you can't define them in proto format, so maybe we could make this optional somehow? (such that users could decide if they wanted this or not, maybe with another gogoproto flag?)