Performance issue with preparing the file for download

[subashk]

1.SRC=isomorphic/system/modules/ISC_Core.js?isc_version=v9.0p_2013-11-03.js

2. ALL

3. N/A

4. N/A

5.N/A

6.

 userResultList.exportData({exportAs: "csv",exportFilename:"USER_DOWNLOAD",exportSpanTitleSeparator:" ",exportShowHeaderSpanTitles:true,exportHeader:"USER_DOWNLOAD\n"});

This is a Performance issue:
The fetch() for the download is taking the same time as the fetch() to populate the ListGrid for the user to see, but the download is taking 3-4 seconds longer than the fetch() is. The file is fine once it gets to the user I'm trying to track down why it is taking 3-4 seconds to build the csv file. I set the SmartClient logging to DEBUG and saw this in the the log when downloading a file.

with arg types: com.isomorphic.servlet.RequestContext, com.isomorphic.datasource.DSRequest, com.isomorphic.servlet.ISCHttpServletRequest
=== 2015-07-21 15:32:59,459 [c-10] INFO DSResponse - DSResponse: List with 1029 items
=== 2015-07-21 15:32:59,470 [c-10] INFO ProxyHttpServletResponse - content-disposition set to: attachment; fileName=USER_DOWNLOAD.csv - unwrapping response output stream (CompressionFilter)

these 38 lines are then printed for every 1029 item, for a total of 39102 lines of log and spanning 3 seconds

=== 2015-07-21 15:32:59,474 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,475 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,476 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,476 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,477 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,478 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'comboBox' instance of datasources: 1ms
=== 2015-07-21 15:32:59,478 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,479 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,479 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,480 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,481 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'short' instance of datasources: 0ms
=== 2015-07-21 15:32:59,482 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 1ms
=== 2015-07-21 15:32:59,482 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,482 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,483 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,483 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,483 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,488 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 1ms
=== 2015-07-21 15:32:59,488 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,488 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,489 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,489 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,490 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 1ms
=== 2015-07-21 15:32:59,490 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'select' instance of datasources: 0ms
=== 2015-07-21 15:32:59,490 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'test' instance of datasources: 0ms
=== 2015-07-21 15:32:59,491 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'test' instance of datasources: 0ms
=== 2015-07-21 15:32:59,491 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,491 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,492 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,492 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'short' instance of datasources: 0ms
=== 2015-07-21 15:32:59,493 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'test' instance of datasources: 0ms
=== 2015-07-21 15:32:59,493 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'boolean' instance of datasources: 0ms
=== 2015-07-21 15:32:59,493 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,494 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,494 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,494 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,495 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms
=== 2015-07-21 15:32:59,495 [c-10] DEBUG DataStructCache - getInstanceFile (failure): 'text' instance of datasources: 0ms


Why are these lines getting printed in the log and why is it taking so long to prepare a csv file to download?
and
Is there anything I can do to make this faster?

[Isomorphic]

You're seeing those lines because you enabled DEBUG logging. DEBUG-level logging is expensive and resetting the logging to the default level will restore some performance.

If you think there's a performance problem *aside from* the issue you created by enabling too much logging, you should first of all update the latest patched build of a recent version. Then, to establish a framework bug, you would need to submitted detailed Java profiler analysis showing the framework taking unnecessary actions.

An alternative would be to engage our Consulting team to troubleshoot the issue, and determine whether it's due to your application code or settings, or any kind of framework flaw.

[subashk]

I know they are getting printed out because i set the level to debug,my question is why are there so many failures I would expect not to see any failures while preparing a CSV file for download. The extra time is NOT from the logging, the time it takes with out logging is only 1 second faster so the logging is only adding a second and the preparation of the CSV file is still taking ~3 seconds after the fetch.

[Isomorphic]

If something is unusual and worthy of concern, it's logged as a warning. These are debug level logs and what they are telling you is the rough equivalent of a "cache miss" - totally normal and expected.

The fact that a bunch of logs occur is not an indication that those logs have anything to do with how the time is being spent. Profiling is how you figure out where time is being spent.