Time consumption in IDACall Servlet

[mve]

Dear Isomorphic

I'm using SmartGWT Pro Release 2.4, IE8 and JBOSS 5.1 as Application Server.

Can you tell me what happens between the first and the second log entry? It takes about 6 seconds (21:44:11,265 ... 21:44:17,953) between these to log entries...

2011-08-09 21:44:11,265 [CID: ] INFO  [STDOUT] (http-0.0.0.0-8080-3) === 2011-08-09 21:44:11,265 [80-3] INFO  RequestContext - URL: '/BGM2_GUI/bgm2/sc/IDACall', User-Agent: 'Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; .NET4.0C; MS-RTC LM 8)': MSIE with Accept-Encoding header, ready for compressed JS
2011-08-09 21:44:17,953 [CID: ] INFO  [STDOUT] (http-0.0.0.0-8080-3) === 2011-08-09 21:44:17,953 [80-3] DEBUG XML - Parsed XML from (in memory stream): 0ms
2011-08-09 21:44:17,968 [CID: ] INFO  [STDOUT] (http-0.0.0.0-8080-3) === 2011-08-09 21:44:17,968 [80-3] DEBUG RPCManager - Processing 1 requests.
2011-08-09 21:44:17,968 [CID: ] INFO  [STDOUT] (http-0.0.0.0-8080-3) === 2011-08-09 21:44:17,968 [80-3] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    criteria:{
        fromDate:new Date(1276034400000),
        toDate:new Date(1276034400000),
        interval:"interval24",
        DayAhead:true,
        senderFilter:"",
        counterpartFilter:"",
        ruleZone:"",
        showCounterparts:true,
        groupByBusiness:true,
        statusOK:true,
        statusNeu:true,
        statusAchtung:true,
        showCurrentVersionOnly:true
    },
    operationConfig:{
        dataSource:"scheduleTimeseries24-96hInterval",
        operationType:"fetch"
    },
    endRow:100,
    appID:"builtinApplication",
    operation:"scheduleTimeseries24-96hInterval_fetch",
    oldValues:{
        fromDate:new Date(1276034400000),
        toDate:new Date(1276034400000),
        interval:"interval24",
        DayAhead:true,
        senderFilter:"",
        counterpartFilter:"",
        ruleZone:"",
        showCounterparts:true,
        groupByBusiness:true,
        statusOK:true,
        statusNeu:true,
        statusAchtung:true,
        showCurrentVersionOnly:true
    }
}
2011-08-09 21:44:17,968 [CID: ] INFO  [STDOUT] (http-0.0.0.0-8080-3) 4986875 [http-0.0.0.0-8080-3] DEBUG ch.swissgrid.bgm2.gui.server.servlet.BGM2IDACall.handleDSRequest(BGM2IDACall.java:32)  - Handle DSRequest...

Thanks in advance
Marco

[Isomorphic]

If JIT is enabled, what you are seeing is the time for the JVM to create native bytecode. SmartGWT does almost nothing in between those two logs and it is common to see them logged with the same millisecond timecode.

[mve]

Wow, that was a fast answer - thanks.
Unfortunately disabling JIT does not improve the performance.
However, I've figured out that if the SmartClient Dev Console is open the time between the two log entries is much greater than when the console is closed. But still not in the same millisecond (about 200 ms if console is closed).
Any other idea what I could try?

Thanks
Marco

[Isomorphic]

That claim about the Developer Console makes no sense at all. These are server logs. Nothing going on in the browser can have an effect once the request has arrived.

This still seems pretty clearly to be just bad data - if it's not JIT then there's some other explanation, but we've never seen an environment where these logs are separated by any appreciable time at all, so we can't be of much help unless you tell us all the steps necessary to set up an environment where this occurs.

[mve]

Due to the time shift (Switzerland) my answer is a bit late...

I'm fully agree with you that once a request has arrived to the server the client can not have any influence.
But it is possible that the request from the client looks different if the console is open or not?

However I made some further investigations and tried different browsers (e.g. chrome). Apart from the significant better client performance with chrome the log entries are also different. With IE8 there are several milliseconds between the first and the second log entry with chrome the two log entries have the same millisecond timecode - as you described (of course for exactly the same operation ).

Any Idea...?

[Isomorphic]

No, we have no idea as to a possible cause. Again, from a theoretical perspective, there is no possible way this could be influenced by the browser, and from a practical perspective, we have many deployments we directly manage, and our users have thousands of deployments, and no one has ever reported anything similar.

You should probably begin trying multiple machines both as server and client, and also cranking the global server log setting to DEBUG for both SmartGWT (log4j.isc.xml) and JBoss, to see if you can get any finer-grained information.