Massive performance drop in deserializeBinary method in javascript

[priyatham-aps]

Hi,

We have been using protobuf 3.0.0-beta-2 in our application and recently tried to upgrade to the latest protobuf-3.0.2 release and observed a massive performance drop when deserializing responses on our frontend.

On debugging and profiling this behavior, we have noticed that a lot of processing takes place around syncMapFields_, which is being called by setRepeatedWrapperField method on our list field, which is taking up the major chunk of time.

In order to benchmark this minimally, we made two messages.

message BenchmarkMsgTest1 {
    bytes uid = 1;
    string name = 2;
    repeated BenchmarkMsgTest2 msg = 3;
}

message BenchmarkMsgTest2 {
    bytes uid = 1;
    string name = 2;
}

And we ran the following test in protobuf-3.0.0-beta-2 and protobuf-3.0.2 versions (in our typescript world).

let m1 = new BenchmarkMsgTest1();
m1.setName("BenchmarkMsgTest1");

let arr = new Array<BenchmarkMsgTest2>(10000);
for (let i = 0; i < 10000; i++) {
    let m2 = new BenchmarkMsgTest2();
    m2.setName("" + i);
    arr[i] = m2;
}
m1.setMsgList(arr);

let ser = new Uint8Array(m1.serializeBinary());
console.log("Message length", ser.length);

let startTime = new Date().getTime();
let m = BenchmarkMsgTest1.deserializeBinary(ser);
let endTime = new Date().getTime();
console.log("deserializeBinary time", endTime - startTime);

We got the following results (time in ms):
protobuf-3.0.0-beta-2
Message length 78909
deserializeBinary time 37
protobuf-3.0.2
Message length 78909
deserializeBinary time 1408

As you can see, the amount of time taken for deserializing this message has gone up by 50 times. And it goes higher and higher for larger messages. We have noticed that response messages in our application which were taking a couple of seconds to deserialize earlier are now taking 5 - 10 minutes to deserialize.

Is anyone else facing this issue? Any kind of help appreciated if there is a way to circumvent this problem. Also, happy to help in further investigation if needed.

Thanks!

[xfxyjwf]

@haberman @acozzette

[acozzette]

Thanks for the detailed report, Priyatham. We expected there to be some performance hit from syncMapFields_ but it's surprising that it would be so big. I will look into this some more tomorrow and see if I can find a way to fix the regression. One idea suggested in a comment is that we can potentially determine statically that a message cannot transitively contain any map fields and then skip the expensive syncing in that case, so that is one option.

[acozzette]

I looked into this a bit and I think there must have been at least two separate regressions. I replicated your benchmark and found that adding maps support (around c64d86e and other commits) roughly doubled the deserialization time from about 700 ms to about 1500. Before that 3b3c8ab increased the time from about 30 ms up to around 700. I'm still trying to narrow down the cause further.

[acozzette]

I think I've found what's going on. Here's a snippet from the generated deserialization code for BenchmarkMsgTest1:

    switch (field) {
    ...
    case 3:
      var value = new proto.jspb.test.BenchmarkMsgTest2;
      reader.readMessage(value,proto.jspb.test.BenchmarkMsgTest2.deserializeBinaryFromReader);
      msg.getMsgList().push(value);
      msg.setMsgList(msg.getMsgList());
      break;
    ...

That msg.setMsgList(msg.getMsgList()); line is copying over all elements we have parsed so far, so deserializing a non-packed repeated field is effectively quadratic in the number of elements. I'm guessing that the performance of syncMapFields_ is probably not a problem after all, it's just that we're calling it way too many times in the course of this quadratic copying.

That line is there for a reason according to this comment in the compiler: https://github.com/google/protobuf/blob/master/src/google/protobuf/compiler/js/js_generator.cc#L2682 So directly removing that line will probably introduce a bug and we'll have to figure out another way to refactor things. I'll spend some more time on it tomorrow and hopefully send a fix out.

[acozzette]

This is now fixed in the 3.1.0 release so I'll go ahead and close this. Note that the master branch does not have the fix merged yet, so for now you may want to check out the 3.1.x branch.

[priyatham-aps]

We started using the 3.1.0 release and can see that the performance is back to normal now. Many thanks @acozzette , this is really helpful.

[acozzette]

Great, I'm glad to hear that fixed it!