Re: Protocol buffer performance degrading with time

[Feng Xiao]

What makes you think it's protobuf's problem?

On Friday, January 11, 2013 2:50:54 PM UTC+8, debo...@2pirad.com wrote:

My application uses Google Protocol Buffer with Apache MINA. There are clients who connect to the MINA Connector, send request to the server and then wait for the response from the server. The flow of control is as follows:

1. Client sends request

    2. Request received at MINA filter (<Class> extends CumulativeProtocolDecoder)

        3. doDecode() method is called

            4. A request object (generated from *.proto file) is created using the <RequestObject>.parseFrom(bytes)

                5. The request is passed on to the IOHandler (<Class> extends IoHandlerAdapter)

                    6. messageReceived() method is called

                        7. In this method, the request object (from #7) is processed to create the list of requests which has been sent by the client. 

                        8. At this point, we have noticed that the time taken to process the request object (#7) is gradually degrading with time. From a initial period of around 2 ms, the time period is going up to 200 ms in just 8 days of continuous usage. And this value gradually increases with time.

                            9. The request list is processed in the application

                          10. The response object is created

                      11. The response is sent to the client.

Any suggestion would be highly appreciated.

[debo...@2pirad.com]

Because, to process the request object (in #7), the methods which are present in the google protobuf generated file are called. The protobuf request object contains multiple requests, and the time taken to extract these (requests) is gradually increasing with time.

I think this is protobuf problem because these classes where generated by the protobuf compiler (from the .proto file). 

On Friday, January 11, 2013 12:41:35 PM UTC+5:30, Feng Xiao wrote:

What makes you think it's protobuf's problem?

On Friday, January 11, 2013 2:50:54 PM UTC+8, debo...@2pirad.com wrote:

My application uses Google Protocol Buffer with Apache MINA. There are clients who connect to the MINA Connector, send request to the server and then wait for the response from the server. The flow of control is as follows:

1. Client sends request

    2. Request received at MINA filter (<Class> extends CumulativeProtocolDecoder)

        3. doDecode() method is called

            4. A request object (generated from *.proto file) is created using the <RequestObject>.parseFrom(bytes)

                5. The request is passed on to the IOHandler (<Class> extends IoHandlerAdapter)

                    6. messageReceived() method is called

                        7. In this method, the request object (from #6) is processed to create the list of requests which has been sent by the client. 

[Henner Zeller]

On 10 January 2013 23:30, <debo...@2pirad.com> wrote:
> Because, to process the request object (in #7), the methods which are
> present in the google protobuf generated file are called. The protobuf
> request object contains multiple requests, and the time taken to extract
> these (requests) is gradually increasing with time.

If you think about it, it is pretty unlikely that the generated code
will get 'slower' over time.
Typically, I have seen JVMs slow down because they get busy with
garbage collecting. So this kind of behavior might be related to
memory allocation in the system and subsequently slower garbage
collection (from your description it sounds like you're using Java).
Garbage collection that kicks in in the middle of processing will make
things slower. If you see such huge degradation of performance, then
doing a memory profiling will bring you do some good insight what is
happening. The JVM has some built-in diagnosis as well that you can
use initially (such as percentage of time it spends garbage
collecting).

Of course, it could be as something else, like increasing size of the
data you parse with the protocol buffers ? Or maybe somewhere in the
IO sub-system a buffer is not cleared and you parse a huge chunk of
byte-array ? You could probably see that by adding a debugging log
that shows you the byte-buffer size before you call parseFrom().

Hope this helps,
-h

> --
> You received this message because you are subscribed to the Google Groups
> "Protocol Buffers" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/protobuf/-/IRKxKX0EKRUJ.
>
> To post to this group, send email to prot...@googlegroups.com.
> To unsubscribe from this group, send email to
> protobuf+u...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/protobuf?hl=en.

[Feng Xiao]

On Friday, January 11, 2013 3:30:26 PM UTC+8, debo...@2pirad.com wrote:

Because, to process the request object (in #7), the methods which are present in the google protobuf generated file are called. The protobuf request object contains multiple requests, and the time taken to extract these (requests) is gradually increasing with time.

Do you have a running code example to prove this? Have you checked that if the received object is getting larger and lager? Or maybe your program is consuming more and more memory as it's running?

[Дмитрий Дьяченко]

if i undestand correctly, You have a looong-run application.
- at start You have 2 ms cycle request-response
- after a week You have 200 ms cycle
- Your app is correct and only place where problem may lay is protobuf?

can You do the following?
-- run 'latencytop' at start and after a week?
-- run 'oprofile' at start and after a week?
-- may be its reasonable to writeout times from crititical points of Ypur app? smth like: before req? after req? before response - after response

from my [very limited] exp a such problems traditionally becomes from unintendend sources -- memory allocator, log sub-system, database, swap, etc...

Thanks,
Dmitry

пятница, 11 января 2013 г., 10:50:54 UTC+4 пользователь debo...@2pirad.com написал:

My application uses Google Protocol Buffer with Apache MINA. There are clients who connect to the MINA Connector, send request to the server and then wait for the response from the server. The flow of control is as follows:

1. Client sends request

    2. Request received at MINA filter (<Class> extends CumulativeProtocolDecoder)

        3. doDecode() method is called

            4. A request object (generated from *.proto file) is created using the <RequestObject>.parseFrom(bytes)

                5. The request is passed on to the IOHandler (<Class> extends IoHandlerAdapter)

                    6. messageReceived() method is called

                        7. In this method, the request object (from #7) is processed to create the list of requests which has been sent by the client. 

[debo...@2pirad.com]

Initially I also thought that the problem lies in the garbage collector (your assumption is correct, I am using JVM), or memory leakage. However, I have been monitoring the application's memory and thread profiles (using JConsole), but found no irregularities.

I also agree with you that there is apparently no reason for which a piece of code will become slow over time. Especially when the other parameters are remaining the same. By other parameters, I am referring to the network and the request packet size (its around 250 KB).

[debo...@2pirad.com]

At present I do not have a short and running example code for this. Also, the received request object is not getting larges (it is never more than 250KB). I did some memory profiling, but did not find any irregularities over there.

I am using JDK 6. 

[debo...@2pirad.com]

Thanks for your suggestions. Please find my response below:

On Friday, January 11, 2013 1:16:19 PM UTC+5:30, Дмитрий Дьяченко wrote:

if i undestand correctly, You have a looong-run application.

Yes, you are right, my application is a really looooong running one. It is expected to run 24 x 7 x 365.

 

- at start You have 2 ms cycle request-response

The actual request response cycle is a bit more than 2 ms, because after the request is recieved by the application (#9 in my list), it does a few things, which may take longer. But, the time taken to decode the protobuf request is 2 ms at start.

 

- after a week You have 200 ms cycle

Right, the time taken to decode gradually increases and becomes 200 ms. If left running for longer, it even reached 1 sec in 15 days time.

 

- Your app is correct and only place where problem may lay is protobuf?

From the logs which are there in my application, I have seen that only the time taken to decode is gradually increasing. I have also done some memory and thread profiling of my application, but did not find any irregularities (like increase in memory/threads)

 

can You do the following?
-- run 'latencytop' at start and after a week?
-- run 'oprofile' at start and after a week?

My application is running on IBM AIX server (using IBM JVM). Are the above tools available for AIX?

 

-- may be its reasonable to writeout times from crititical points of Ypur app? smth like: before req? after req? before response - after response

I have logs specific for this purpose which are there at the start and end of these points. Like, before decode and after decode, etc. From these logs I found out the point which was gradually slowing down.

from my [very limited] exp a such problems traditionally becomes from unintendend sources -- memory allocator, log sub-system, database, swap, etc...

The only other component involved over here (other than the application and JMV) is the network. But, I don't think network is the issue because the decoding is done after the request object is fully received from the client. Apache MINA is responsible for getting the request from the client.

[Дмитрий Дьяченко]

ohhh... AIX..
oprofile & latencytop is for Linux only :(

so. If i understand correctly
-- You know that slowdown you are interesting lay in protobuf
-- all other [network / request data size / request complexity ] is the same at the start and after the week

from my exp [oh, also very limited] AIX networking is the last thing to check

definitely, i cant to propose smth usefull... :(

may be,
-- You alloc tooo memory
-- You need to use profiling tools
-- reduce problem to smth small & publish code

Dmitry

пятница, 11 января 2013 г., 12:45:40 UTC+4 пользователь debo...@2pirad.com написал:

[Feng Xiao]

[adding back the group]

On Fri, Jan 11, 2013 at 5:53 PM, Debopam Ghoshal <deb...@2pirad.com> wrote:

Hi Xiao Feng, please find below the relevant sections of my applications code:

This is the point where Apache MINA receives the request from the client. The MultiRequest is a generated class from the protobuf compiler. The .proto file and the java source code is attached for your reference.

public class ProtocolBufferDecoder extends CumulativeProtocolDecoder {

.....

@Override

    protected boolean doDecode(IoSession session, IoBuffer in, ProtocolDecoderOutput out)

            throws Exception {

        if (!in.prefixedDataAvailable(4)) {

            return false;

        }

        double randomId = Math.random();

        session.setAttribute("requestId", randomId);

        // read the bytes

        in.rewind();

        byte[] bytes = new byte[in.getInt()];

        in.get(bytes);

        // parse the bytes

        LOGGER.trace("creating request object from bytes for request id: {}", randomId);

        MultiRequest request = MultiRequest.parseFrom(bytes);

Is it this line of code that you found gets slower over time? I see no reason why it should behave like that unless "bytes" is getting larger.

 

        LOGGER.debug("MultiRequest[{}] created successfully for request id: {}", 

                randomId);

        

        // send the request

        out.write(request);

        LOGGER.trace("sending request to io handler for request id: {}", randomId);

        return true;

    }

}

After the Multirequest object is created, it is passed on to the MINA IO Handler in the following section:

public class SocketIoHandler extends IoHandlerAdapter {

.........

    public void messageReceived(IoSession session, Object message)

            throws Exception {

        // decode requests

        LOGGER.trace("starting to decode request with id: {}",session.getAttribute("requestId"));

        List<Request> requestList = requestCodec.decodeAll(message);

        LOGGER.trace("finished decoding request with id: {}", session.getAttribute("requestId"));

        .........

    }

.........

}

The SimpleProtocolBufferDecoder (attached) decodes the MultiRequest and returns a list of request objects.

Thanks & Best Regards,
Debopam

Cell: +919830410041
------------------------------------------------------------------
      -|-

--o-0-(.)-0-o--

visit us at www.2pirad.com

On Fri, Jan 11, 2013 at 3:06 PM, Feng Xiao <xiao...@google.com> wrote:

Can you show us how the decoding code looks like? I.e., the range of code that you found is slowing over time.

____________________________________
Visit us at http://www.2pirad.com

[debo...@2pirad.com]

Hi Xiao Feng,

The line which is getting slower with time is highlighted in yellow, below.

[Henner Zeller]

So if decodeAll() is getting slower, what is the implementation of
decodeAll() ? You left it out in the post.
Something returning a List _is_ suspicious in particular if the list
returned is big or if the implementation has to do some expensive
discovery what the message it gets (here the parameter is just an
Object ?) actually is.

> --
> You received this message because you are subscribed to the Google Groups
> "Protocol Buffers" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/protobuf/-/Ev5MhXqi_FgJ.

[debo...@2pirad.com]

Hi Henner,

The implementation of decode is attached herewith. The protoc compiled java file (GenericRequest is also attached). It would be of much help if you spare some time to look into the code.

Thanks

-DG