DataSource Serialization Slowness

[aderosso]

We're having an issue with slow fetches from a particular data source. We turned on the timing data and have seen multiple seconds is spent in the "DSResponse serialization" step.

The data source is a HibernateDataSource, it has a ton of joins and includes from other data sources. This data source is feeding a primary ListGrid that is central to our application. The actual query time is slow as well, we've been looking into the actual SQL that is generated and we're working on improving that. I'm wondering if there's something that can be done about the slowness that we're encountering in the serialization step.

Here's the data source:

<DataSource ID="OpeningTest"
            serverType="hibernate"
            beanClassName="com.assaabloy.protech.domain.Opening"
            configBean="protechSessionFactory"
            autoDeriveSchema="false"
            dropExtraFields="true">
    <fields>
        <!-- ... omitted for brevity ... -->
    </fields>

    <operationBindings>
        <operationBinding operationType="fetch">
            <!-- Function executes standard fetch to opening, then subsequent fetch to opening_door using regular ds.xml and joins results -->
            <serverObject lookupStyle="spring" bean="openingService" className="com.assaabloy.protech.server.services.impl.OpeningServiceImpl"/>
            <criteria fieldName="deleted" value="false"/>
        </operationBinding>
</DataSource>

There are 74 fields in the data source, however because of the joins to other entities, the SQL has 550 columns in the select. This causes the query to be slow, I'm not sure if this affects serialization.

In our operation binding, we're doing 2 separate fetches and joining the results. This is done to eliminate a 1+n fetch to get records from a man-to-many relationship. Instead of returning the hibernate entity, we're returning a List<Map<String, Object>>, maybe that's the cause of serialization slowness?

Here's what our fetch method does (pseudo code for brevity):

    public DSResponse fetch(final DSRequest dsRequest, final RPCManager rpcManager) throws Exception {
        // Execute standard fetch
        final DSResponse dsResponse = dsRequest.execute();

        // Fetch the related data from other data source
        DSRequest openingDoorRequest = ... (other fetch)
        DSResponse openingDoorResponse = openingDoorRequest.execute();

        // Join data together
        final List<Map> data = dsResonse.getRecords();
        data.forEach(o -> {
            // add data from openingDoorResponse
        }

        // Update the response data
        dsResponse.setData(data);

        return dsResponse;
    }

Is there something obvious we're missing that would be making the serialization so slow?

We're using GWT 2.8.2 and SmartClient Version: v12.0p_2019-11-02/Enterprise Deployment (built 2019-11-02)

[Isomorphic]

You are almost certainly not using all 550 fields, so just set operationBinding.outputs to the list of fields you actually need.

[Isomorphic]

The above advice probably obviates any need for further tuning, but in case it doesn't..

Our serialization uses Java Reflection to call the getter methods on your Hibernate beans.

Individual getters might be very slow if you've added logic. Or you may have getters that are triggering additional, lazy database fetches. All this should be obviously with basic profiling attempts.

If you determine that every single getter is plenty fast, then the only remaining thing to eliminate would be the need to make Java Reflection calls. Reflection is quite fast, so this would only matter if you have an actual requirement to deliver absolutely spectacular quantities - and probably not even then. But ultimately, you could hand-code the getter calls and deliver the data to our serialization system as a List of Maps.

Again, don't even look into this approach until you have tried all of the above approaches. If one of the other causes above is the real problem, then optimizing Reflection out would have a negligible impact.

[aderosso]

I tried the outputs option quickly, however it's now complaining about some of the fields not being in the entity. We've added fields to the data source that get filled in when the data is joined together that aren't necessarily in the actual entity class.

We're actually already delivering the data as list of maps. In my abbreviated example code from above, we take the results of 2 different ds.xml fetches, then merge them together and the dsResponse.detData() is set with a list of maps. That was my main reason for asking, it seems odd to me that serializing that would be slow.

[Isomorphic]

As far as the outputs, if you're doing your own conversion to List of Maps, you can limit the outputs yourself very easily.

However, if there's no Reflection going on in the serialization layer, slowness makes no sense. Look closely at the profiling data - you may see that a big chunk of time is downstream of the serialization layer, but the actual methods eating up time may not be ours. It may be, for example, very slow IO, with a cause outside of our system.

[aderosso]

We've put timing statements in our fetch in the DMI, it exactly matches what is coming in the timing data from the response. Here's the timing node from a response:

 timing:{
        name:"Server processing", 
        start:1577996056604, 
        children:[
            {
                name:"RPCManager construction", 
                start:1577996056604, 
                children:[
                    {
                        name:"DSRequest construction", 
                        start:1577996056612, 
                        children:[
                        ], 
                        end:1577996056612
                    }
                ], 
                end:1577996056612
            }, 
            {
                name:"RPCManager processing", 
                start:1577996056612, 
                children:[
                    {
                        name:"DSRequest processing", 
                        start:1577996056612, 
                        children:[
                            {
                                name:"includeFrom processing", 
                                start:1577996056612, 
                                children:[
                                ], 
                                end:1577996056615
                            }, 
                            {
                                name:"groupBy processing", 
                                start:1577996056615, 
                                children:[
                                ], 
                                end:1577996056615
                            }, 
                            {
                                name:"Declarative security checks", 
                                start:1577996056615, 
                                children:[
                                ], 
                                end:1577996056616
                            }, 
                            {
                                name:"Field-level declarative security checks", 
                                start:1577996056616, 
                                children:[
                                ], 
                                end:1577996056616
                            }, 
                            {
                                name:"Prepare DSRequest for DMI", 
                                start:1577996056616, 
                                children:[
                                ], 
                                end:1577996056617
                            }, 
                            {
                                name:"DMI", 
                                start:1577996056617, 
                                children:[
                                    {
                                        name:"DSRequest processing", 
                                        start:1577996056617, 
                                        children:[
                                            {
                                                name:"Declarative security checks", 
                                                start:1577996056617, 
                                                children:[
                                                ], 
                                                end:1577996056618
                                            }, 
                                            {
                                                name:"transformMultipleFields processing", 
                                                start:1577996056618, 
                                                children:[
                                                ], 
                                                end:1577996056618
                                            }
                                        ], 
                                        end:1577996056963
                                    }
                                ], 
                                end:1577996059490
                            }
                        ], 
                        end:1577996059490
                    }
                ], 
                end:1577996059490
            }, 
            {
                name:"DSResponse serialization", 
                start:1577996059490, 
                end:1577996063436
            }
        ], 
        end:1577996063436
    },

Here's that same data in a summary:

Server processing: 6832ms
        RPCManager construction: 8ms
                DSRequest construction: 0ms
        RPCManager processing: 2878ms
                DSRequest processing: 2878ms
                        includeFrom processing: 3ms
                        groupBy processing: 0ms
                        Declarative security checks: 1ms
                        Field-level declarative security checks: 0ms
                        Prepare DSRequest for DMI: 1ms
                        DMI: 2873ms
                                DSRequest processing: 346ms
                                        Declarative security checks: 1ms
                                        transformMultipleFields processing: 0ms
        DSResponse serialization: 3946ms

The DMI time is 2873ms, I'm getting that value in both my logs and in the timing data from the response. From what I'm looking in the above timing data it looks like 3946ms is being spent in the "DSResponse serialization".

I don't think there's anything wrong with IO, I'm running the application on my PC locally, and everything else is very fast.

[Isomorphic]

Sorry that we weren't clear. The next step is use any standard Java profiler to identify the bottleneck that is happening somewhere in the serialization phase.

We've already tuned that area of the code a number of times so whatever is going wrong is abnormal and probably unique to your system.