proto: performance degradation with v1.1.0

[srenatus]

Hi there -- updating our dependency on golang/protobuf to v1.1.0, I've noticed an unexpected dip in performance when running some microbenchmarks.

👉 I've put up a reproduction case here: https://github.com/srenatus/pb-bench -- you can also look at the output on travis

The gist is that marshaling (of a rather big message) is getting a lot worse in all three metrics; ranging from +165.77% (alloc/op) to +751.93% (allocs/op).

I've brought this up in #protobuf of the gopher slack, where @dsnet asked for further input -- here it is (👋 @dsnet 😃).

[dsnet]

\cc @randall77 @LMMilewski

[srenatus]

Heya -- Is there any way I could help you with this? 😃

[LMMilewski]

Could you add a LICENSE file?

[LMMilewski]

Alternatively, could you run both benchmarks with --test.cpuprofile flag and attach generated files?

[srenatus]

@LMMilewski ✔️ Added a LICENSE. :)

[LMMilewski]

It seems that the problem is with processing maps (see profiles below). Your proto contains a large, deeply nested map ("node" key in https://github.com/srenatus/pb-bench/blob/master/data/converge-success-report.json is a google.protobuf.Struct which is a map that can contain nested maps https://github.com/golang/protobuf/blob/master/ptypes/struct/struct.proto#L52-L55).

Maps processing is expected to be slow. That path was considered rare and uses reflection extensively. That was true in 1.0.0 too but that version didn't reflectively iterate over maps to calculate their sizes (which is what shows up in the profile).

Also, calculating size is at the top of the v1.1.0 profile accounting for 65.36%. Perhaps it is quadratic in some case (probably maps) which would happen if it's not cached.

v1.0.0 top

Showing nodes accounting for 3.14s, 94.01% of 3.34s total
Dropped 53 nodes (cum <= 0.02s)
Showing top 100 nodes out of 130
      flat  flat%   sum%        cum   cum%
     0.29s  8.68%  8.68%      0.29s  8.68%  runtime.memmove
     0.26s  7.78% 16.47%      0.42s 12.57%  runtime.mapaccess2
     0.18s  5.39% 21.86%      0.42s 12.57%  runtime.mallocgc
     0.17s  5.09% 26.95%      2.84s 85.03%  github.com/srenatus/pb-bench/v1.0.0/vendor/github.com/golang/protobuf/proto.(*Buffer).enc_len_thing
     0.15s  4.49% 31.44%      0.15s  4.49%  runtime.futex
     0.10s  2.99% 34.43%      0.10s  2.99%  github.com/srenatus/pb-bench/v1.0.0/vendor/github.com/golang/protobuf/proto.(*Buffer).EncodeVarint
     0.10s  2.99% 37.43%      0.10s  2.99%  runtime.mapiternext
     0.08s  2.40% 39.82%      2.84s 85.03%  github.com/srenatus/pb-bench/v1.0.0/vendor/github.com/golang/protobuf/proto.(*Buffer).enc_struct
     0.08s  2.40% 42.22%      0.38s 11.38%  reflect.Value.MapIndex
     0.08s  2.40% 44.61%      0.08s  2.40%  runtime.heapBitsSetType
     0.07s  2.10% 46.71%      2.81s 84.13%  github.com/srenatus/pb-bench/v1.0.0/vendor/github.com/golang/protobuf/proto.(*Buffer).enc_new_map
     0.07s  2.10% 48.80%      0.51s 15.27%  reflect.Value.MapKeys
     0.07s  2.10% 50.90%      0.07s  2.10%  runtime.greyobject
     0.06s  1.80% 52.69%      2.71s 81.14%  github.com/srenatus/pb-bench/v1.0.0/vendor/github.com/golang/protobuf/ptypes/struct._Value_OneofMarshaler
     0.06s  1.80% 54.49%      0.18s  5.39%  reflect.Value.Set
     0.06s  1.80% 56.29%      0.06s  1.80%  runtime.(*itabTableType).find
     0.06s  1.80% 58.08%      0.06s  1.80%  runtime.memclrNoHeapPointers
     0.06s  1.80% 59.88%      0.08s  2.40%  runtime.resolveTypeOff
     0.06s  1.80% 61.68%      0.13s  3.89%  runtime.scanobject
     0.05s  1.50% 63.17%      0.05s  1.50%  reflect.packEface

v1.1.0 top

     0.13s  7.26%  7.26%      1.17s 65.36%  github.com/srenatus/pb-bench/v1.1.0/vendor/github.com/golang/protobuf/proto.(*marshalInfo).size
     0.11s  6.15% 13.41%      0.13s  7.26%  runtime.heapBitsSetType
     0.09s  5.03% 18.44%      0.10s  5.59%  reflect.Value.Elem
     0.08s  4.47% 22.91%      0.36s 20.11%  runtime.mallocgc
     0.07s  3.91% 26.82%      0.09s  5.03%  runtime.mapaccess2
     0.07s  3.91% 30.73%      0.10s  5.59%  runtime.mapiternext
     0.06s  3.35% 34.08%      0.11s  6.15%  runtime.mapaccess1
     0.06s  3.35% 37.43%      0.35s 19.55%  runtime.newobject
     0.06s  3.35% 40.78%      0.06s  3.35%  runtime.nextFreeFast (inline)
     0.04s  2.23% 43.02%      1.05s 58.66%  github.com/srenatus/pb-bench/v1.1.0/vendor/github.com/golang/protobuf/proto.makeMapMarshaler.func1
     0.04s  2.23% 45.25%      1.35s 75.42%  github.com/srenatus/pb-bench/v1.1.0/vendor/github.com/golang/protobuf/proto.makeMessageMarshaler.func2
     0.04s  2.23% 47.49%      0.10s  5.59%  reflect.(*rtype).ptrTo
     0.04s  2.23% 49.72%      0.05s  2.79%  reflect.Value.Interface
     0.04s  2.23% 51.96%      0.14s  7.82%  reflect.Value.MapIndex
     0.04s  2.23% 54.19%      0.04s  2.23%  runtime.aeshash64
     0.04s  2.23% 56.42%      0.04s  2.23%  runtime.futex
     0.03s  1.68% 58.10%      1.16s 64.80%  github.com/srenatus/pb-bench/v1.1.0/vendor/github.com/golang/protobuf/proto.makeOneOfMarshaler.func1
     0.03s  1.68% 59.78%      0.03s  1.68%  github.com/srenatus/pb-bench/v1.1.0/vendor/github.com/golang/protobuf/proto.pointer.getPointer (inline)
     0.03s  1.68% 61.45%      0.14s  7.82%  reflect.NewAt
     0.03s  1.68% 63.13%      0.03s  1.68%  runtime.heapBitsForObject

[randall77]

@cherryyz Any idea if we can make Size faster in this case?

[randall77]

@cherrymui

[LMMilewski]

FWIW. I created a small benchmark (code below) with nested maps (depth 1, 2, 4, 8, 16). Every map has a single key and the value is either a nested map or a number (the leaf). I got those results:

Benchmark1-40     	 1000000	      1540 ns/op
Benchmark2-40     	  500000	      3777 ns/op
Benchmark4-40     	  200000	      9927 ns/op
Benchmark8-40     	   50000	     29783 ns/op
Benchmark16-40    	   20000	     98279 ns/op

So it grows faster than it should.

The web graph shows that size is driven by map and oneof. I'm not sure how to attach an svg here though.

Code:

func Benchmark1(b *testing.B) {
	m := &pb.Struct{
		Fields: map[string]*pb.Value{
			"0": &pb.Value{Kind: &pb.Value_NumberValue{1}},
		},
	}
	for i := 0; i < b.N; i++ {
		if _, err := proto.Marshal(m); err != nil {
			b.Fatal(err)
		}
	}
}

func Benchmark2(b *testing.B) {
	m := &pb.Struct{
		Fields: map[string]*pb.Value{
			"0": &pb.Value{
				Kind: &pb.Value_StructValue{
					&pb.Struct{
						Fields: map[string]*pb.Value{
							"0": &pb.Value{Kind: &pb.Value_NumberValue{1}},
						},
					},
				},
			},
		},
	}
	for i := 0; i < b.N; i++ {
		if _, err := proto.Marshal(m); err != nil {
			b.Fatal(err)
		}
	}
}

func Benchmark4(b *testing.B) {
	m := &pb.Struct{
		Fields: map[string]*pb.Value{
			"0": &pb.Value{
				Kind: &pb.Value_StructValue{
					&pb.Struct{
						Fields: map[string]*pb.Value{
							"0": &pb.Value{
								Kind: &pb.Value_StructValue{
									&pb.Struct{
										Fields: map[string]*pb.Value{
											"0": &pb.Value{
												Kind: &pb.Value_StructValue{
													&pb.Struct{
														Fields: map[string]*pb.Value{
															"0": &pb.Value{Kind: &pb.Value_NumberValue{1}},
														},
													},
												},
											},
										},
									},
								},
							},
						},
					},
				},
			},
		},
	}
	for i := 0; i < b.N; i++ {
		if _, err := proto.Marshal(m); err != nil {
			b.Fatal(err)
		}
	}
}

func Benchmark8(b *testing.B) {
	m := &pb.Struct{
		Fields: map[string]*pb.Value{
			"0": &pb.Value{
				Kind: &pb.Value_StructValue{
					&pb.Struct{
						Fields: map[string]*pb.Value{
							"0": &pb.Value{
								Kind: &pb.Value_StructValue{
									&pb.Struct{
										Fields: map[string]*pb.Value{
											"0": &pb.Value{
												Kind: &pb.Value_StructValue{
													&pb.Struct{
														Fields: map[string]*pb.Value{
															"0": &pb.Value{
																Kind: &pb.Value_StructValue{
																	&pb.Struct{
																		Fields: map[string]*pb.Value{
																			"0": &pb.Value{
																				Kind: &pb.Value_StructValue{
																					&pb.Struct{
																						Fields: map[string]*pb.Value{
																							"0": &pb.Value{
																								Kind: &pb.Value_StructValue{
																									&pb.Struct{
																										Fields: map[string]*pb.Value{
																											"0": &pb.Value{
																												Kind: &pb.Value_StructValue{
																													&pb.Struct{
																														Fields: map[string]*pb.Value{
																															"0": &pb.Value{Kind: &pb.Value_NumberValue{1}},
																														},
																													},
																												},
																											},
																										},
																									},
																								},
																							},
																						},
																					},
																				},
																			},
																		},
																	},
																},
															},
														},
													},
												},
											},
										},
									},
								},
							},
						},
					},
				},
			},
		},
	}
	for i := 0; i < b.N; i++ {
		if _, err := proto.Marshal(m); err != nil {
			b.Fatal(err)
		}
	}
}

func Benchmark16(b *testing.B) {
	m := &pb.Struct{
		Fields: map[string]*pb.Value{
			"0": &pb.Value{
				Kind: &pb.Value_StructValue{
					&pb.Struct{
						Fields: map[string]*pb.Value{
							"0": &pb.Value{
								Kind: &pb.Value_StructValue{
									&pb.Struct{
										Fields: map[string]*pb.Value{
											"0": &pb.Value{
												Kind: &pb.Value_StructValue{
													&pb.Struct{
														Fields: map[string]*pb.Value{
															"0": &pb.Value{
																Kind: &pb.Value_StructValue{
																	&pb.Struct{
																		Fields: map[string]*pb.Value{
																			"0": &pb.Value{
																				Kind: &pb.Value_StructValue{
																					&pb.Struct{
																						Fields: map[string]*pb.Value{
																							"0": &pb.Value{
																								Kind: &pb.Value_StructValue{
																									&pb.Struct{
																										Fields: map[string]*pb.Value{
																											"0": &pb.Value{
																												Kind: &pb.Value_StructValue{
																													&pb.Struct{

																														Fields: map[string]*pb.Value{
																															"0": &pb.Value{
																																Kind: &pb.Value_StructValue{
																																	&pb.Struct{
																																		Fields: map[string]*pb.Value{
																																			"0": &pb.Value{
																																				Kind: &pb.Value_StructValue{
																																					&pb.Struct{
																																						Fields: map[string]*pb.Value{
																																							"0": &pb.Value{
																																								Kind: &pb.Value_StructValue{
																																									&pb.Struct{
																																										Fields: map[string]*pb.Value{
																																											"0": &pb.Value{
																																												Kind: &pb.Value_StructValue{
																																													&pb.Struct{
																																														Fields: map[string]*pb.Value{
																																															"0": &pb.Value{
																																																Kind: &pb.Value_StructValue{
																																																	&pb.Struct{
																																																		Fields: map[string]*pb.Value{
																																																			"0": &pb.Value{
																																																				Kind: &pb.Value_StructValue{
																																																					&pb.Struct{
																																																						Fields: map[string]*pb.Value{
																																																							"0": &pb.Value{
																																																								Kind: &pb.Value_StructValue{
																																																									&pb.Struct{
																																																										Fields: map[string]*pb.Value{
																																																											"0": &pb.Value{
																																																												Kind: &pb.Value_StructValue{
																																																													&pb.Struct{
																																																														Fields: map[string]*pb.Value{
																																																															"0": &pb.Value{Kind: &pb.Value_NumberValue{1}},
																																																														},
																																																													},
																																																												},
																																																											},
																																																										},
																																																									},
																																																								},
																																																							},
																																																						},
																																																					},
																																																				},
																																																			},
																																																		},
																																																	},
																																																},
																																															},
																																														},
																																													},
																																												},
																																											},
																																										},
																																									},
																																								},
																																							},
																																						},
																																					},
																																				},
																																			},
																																		},
																																	},
																																},
																															},
																														},
																													},
																												},
																											},
																										},
																									},
																								},
																							},
																						},
																					},
																				},
																			},
																		},
																	},
																},
															},
														},
													},
												},
											},
										},
									},
								},
							},
						},
					},
				},
			},
		},
	}
	for i := 0; i < b.N; i++ {
		if _, err := proto.Marshal(m); err != nil {
			b.Fatal(err)
		}
	}
}

[cherrymui]

Yeah, map is the rare slow case. It all uses reflection. And it allocates a lot. I just tried to write a specialized version just for string-message maps. There is good speed up. But in practice we would need NxM key-value type combinations. Given that maps are considered rare, I'm not sure we want to go this way.

While writing it, I did find a quadratic behavior in the reflection-based code. We call valSizer during marshal. If the value is a message with deeply nested maps, like this one, we will run sizer at each level. We should use cached size for message value. I have a CL for that. Benchmark results (using Lukasz's benchmark above):

name   old time/op    new time/op    delta
1-12     1.96µs ±19%    1.76µs ±18%     ~     (p=0.075 n=10+10)
2-12     5.10µs ± 6%    3.84µs ± 8%  -24.69%  (p=0.000 n=9+10)
4-12     14.2µs ±12%     8.2µs ±15%  -42.77%  (p=0.000 n=10+10)
8-12     43.0µs ±10%    15.6µs ±11%  -63.81%  (p=0.000 n=9+10)
16-12     138µs ±12%      33µs ±17%  -76.32%  (p=0.000 n=10+10)

name   old alloc/op   new alloc/op   delta
1-12       376B ± 0%      376B ± 0%     ~     (all equal)
2-12       928B ± 0%      752B ± 0%  -18.97%  (p=0.000 n=10+10)
4-12     2.54kB ± 0%    1.49kB ± 0%  -41.51%  (p=0.000 n=10+10)
8-12     7.89kB ± 0%    2.96kB ± 0%  -62.47%  (p=0.000 n=10+10)
16-12    27.0kB ± 0%     5.9kB ± 0%  -78.11%  (p=0.000 n=10+10)

name   old allocs/op  new allocs/op  delta
1-12       12.0 ± 0%      12.0 ± 0%     ~     (all equal)
2-12       28.0 ± 0%      23.0 ± 0%  -17.86%  (p=0.000 n=10+10)
4-12       75.0 ± 0%      45.0 ± 0%  -40.00%  (p=0.000 n=10+10)
8-12        229 ± 0%        89 ± 0%  -61.14%  (p=0.000 n=10+10)
16-12       777 ± 0%       177 ± 0%  -77.22%  (p=0.000 n=10+10)

[LMMilewski]

I just tried to write a specialized version just for string-message maps. There is good speed up. But in practice we would need NxM key-value type combinations.

I guess it depends on the speedup you can get but (without pushing for / against the specialization) I want to note that string->message is most likely the only case where "maps are rare" doesn't hold. It's popular because the protobuf spec provides a way to represent arbitrary json as protos.

That leads to arbitrary string->anything maps ("anything" is represented as a message with a single oneof). Apparently it's used even in Google cloud APIs (I don't remember which ones though). That's also what OP's benchmark does.

[dsnet]

Here's a crude histogram of map types across a large corpus:

   8412 map<string,MessageOrEnum>   // 35.7%
   4499 map<string,string>          // 54.9%
   1598 map<int32,MessageOrEnum>    // 61.7%
    924 map<string,int64>           // 65.6%
    781 map<int64,MessageOrEnum>    // 68.9%
    749 map<string,int32>           // 72.1%
    603 map<string,double>          // 74.7%
    548 map<int32,int32>            // 77.0%
    508 map<string,float>           // 79.2%
    332 map<int32,string>           // 80.6%
    312 map<uint64,MessageOrEnum>   // 81.9%
    281 map<int64,int64>            // 83.1%
    253 map<string,bool>            // 84.2%
    243 map<string,bytes>           // 85.2%
    186 map<int32,double>           // 86.0%
    174 map<int32,int64>            // 86.8%
    156 map<uint32,MessageOrEnum>   // 87.4%
    154 map<int64,string>           // 88.1%
    141 map<int32,float>            // 88.7%
    118 map<string,uint32>          // 89.2%
    112 map<string,uint64>          // 89.7%
    104 map<uint32,uint32>          // 90.1%
    100 map<uint64,uint64>          // 90.5%
     92 map<int32,bool>             // 90.9%
     90 map<bool,bool>              // 91.3%
     86 map<fixed64,fixed64>        // 91.7%
     84 map<sint64,sint64>          // 92.0%
     84 map<sint32,sint32>          // 92.4%
     84 map<sfixed64,sfixed64>      // 92.7%
     84 map<sfixed32,sfixed32>      // 93.1%
     84 map<fixed32,fixed32>        // 93.5%
     70 map<int64,int32>            // 93.8%
     66 map<fixed64,MessageOrEnum>  // 94.0%
     65 map<int32,bytes>            // 94.3%
     62 map<int64,double>           // 94.6%
     46 map<int32,uint64>           // 94.8%
     44 map<bool,MessageOrEnum>     // 95.0%
     40 map<bool,string>            // 95.1%
     39 map<uint64,string>          // 95.3%
     39 map<uint64,int64>           // 95.5%
     36 map<int64,float>            // 95.6%
     30 map<uint64,int32>           // 95.7%
     30 map<sint64,MessageOrEnum>   // 95.9%
     27 map<uint32,string>          // 96.0%
     27 map<bool,bytes>             // 96.1%
     24 map<bool,int32>             // 96.2%
     23 map<int64,bool>             // 96.3%
     22 map<uint64,double>          // 96.4%
     20 map<uint64,bool>            // 96.5%
     20 map<uint32,uint64>          // 96.6%
     20 map<uint32,int32>           // 96.6%
     18 map<uint32,int64>           // 96.7%
     17 map<uint64,float>           // 96.8%
     17 map<fixed64,int32>          // 96.9%
     16 map<fixed32,MessageOrEnum>  // 96.9%
     15 map<uint32,double>          // 97.0%
     15 map<int32,uint32>           // 97.1%
     13 map<sint32,MessageOrEnum>   // 97.1%
     13 map<int64,uint64>           // 97.2%
     12 map<sfixed64,MessageOrEnum> // 97.2%
     12 map<sfixed32,MessageOrEnum> // 97.3%
     11 map<uint64,bytes>           // 97.3%
     11 map<uint32,bool>            // 97.4%
     11 map<int32,fixed64>          // 97.4%
     ...

Since this was done purely by parsing, I couldn't tell if MessageOrEnum refers to a message type or enum type.