Querying large record sets freezes IDE while executing.

[Justin Julicher]

If you have a large record set in the query editor and you choose to query it, it is executed as a synchronous thread and prevents the usage of the IDE. This can go on for a few minutes or longer depending on the size of the record set.

‌

Can we have a way of cancelling the query and/or making it a background thread and only notify us when it is complete?

‌

[Scott Wells]

Justin, I did put some safeguards in place a bit back for situations like this. The SOQL Query tool performs several validations before executing a query to determine whether it could be prohibitively expensive to run:

The most relevant ones here are going to be the query result set size options. Were those enabled? If not, I'd recommend that you keep them enabled. If so, were you prompted? And if not, what constitutes "large record sets" in this case that wasn't caught by these checks?

I agree with the recommendation to send the query execution to a background thread and make it cancelable. In reality that proves to be quite tricky due to the IDE's allowed threading models for certain operations and the fact that a single Salesforce API call is effectively an atomic, blocking operation (albeit with a configured timeout). That's why I implemented "dry run" safeguards like these so far.

[Justin Julicher]

Hi Scott

‌

Yes it did prompt me. I was just hoping you could implement a way to execute a thread on the background… sorry I should hVe mentioned it had prompted me that it was a large recordset.

It's usually not too bad but recently I've found that are network connection (using speedtest.jsp) can drop down to 1.5Mbps to the sandbox and so makes this call excruciating slow and I think made this 1 call last close to 10 minutes and I didn't want to kill the ide to get around the issue.

Thanks

[Scott Wells]

Thanks for the info, Justin. Okay, I've implemented a few changes that should help considerably. SOQL queries like this (and several others executed under-the-hood by IC2 for its own purposes) are processed in batches of 200 rows at a time. Now when each batch is processed, before starting the next batch IC2 checks to see whether the overall process has been cancelled by the end user and, if so, it terminates the overarching process as appropriate. So if you click cancel, the longest you'd have to wait is for the current API call to complete.

[Scott Wells]

Described change delivered in 2.1.9.7. After canceling, at worst you should only have to wait until the current page of records is retrieved and the operation will stop.

[Justin Julicher]

As always - great work Scott!

[Justin Julicher]

@Scott Scott I just updated to the latest and unfortunately it’s not quite working… In the first few seconds it’s executing I can cancel it however, after 2 or 3 seconds the whole IDE freezes and I can’t click the x for the running query until the whole query completes.

Is there any way to get around this?

‌

thanks

[Scott Wells]

That's really bizarre. The query is already executing on a separate thread under a progress indicator, i.e., not on the Swing event thread, and it's yielding after each batch to check for cancellation. I tested it on several multi-batch queries and was able to cancel it after several seconds consistently, so I wonder if there's something else going on. Can you get it back in that state and then send over the resulting thread dumps for review? I'd like to see the various thread states when it's doing that.

[Justin Julicher]

  <div class="preview-container wiki-content"><!-- loaded via ajax --></div>
  <div class="mask"></div>
</div>

</div> </form>

[Justin Julicher]

@Scott Wells Is that what you were after?

‌

[Scott Wells]

Yep, that's exactly what I wanted. Thanks!

This is quite interesting:

"AWT-EventQueue-0" prio=0 tid=0x0 nid=0x0 runnable
     java.lang.Thread.State: RUNNABLE
    at java.base@11.0.12/java.util.Hashtable.get(Hashtable.java:383)
    at java.desktop@11.0.12/javax.swing.JTree.getExpandedDescendants(JTree.java:1989)
    at java.desktop@11.0.12/javax.swing.plaf.basic.BasicTreeUI.updateExpandedDescendants(BasicTreeUI.java:1977)
    at java.desktop@11.0.12/javax.swing.plaf.basic.BasicTreeUI$Handler.treeExpanded(BasicTreeUI.java:4212)
    at java.desktop@11.0.12/javax.swing.JTree.fireTreeExpanded(JTree.java:2801)
    at java.desktop@11.0.12/javax.swing.JTree.setExpandedState(JTree.java:3702)
    at java.desktop@11.0.12/javax.swing.JTree.expandPath(JTree.java:2244)
    at com.intellij.util.ui.tree.TreeUtil.expandPathWithDebug(TreeUtil.java:1400)
    at com.intellij.util.ui.tree.TreeUtil.lambda$promiseMakeVisible$32(TreeUtil.java:1558)
    at com.intellij.util.ui.tree.TreeUtil$$Lambda$2183/0x000000080171b040.visit(Unknown Source)
    at com.intellij.util.ui.tree.TreeUtil.visitModel(TreeUtil.java:1796)
    at com.intellij.util.ui.tree.TreeUtil.lambda$promiseVisit$41(TreeUtil.java:1761)
    at com.intellij.util.ui.tree.TreeUtil$$Lambda$3472/0x0000000801f24840.run(Unknown Source)
    at com.intellij.util.ui.EdtInvocationManager.invokeLaterIfNeeded(EdtInvocationManager.java:101)
    at com.intellij.util.ui.UIUtil.invokeLaterIfNeeded(UIUtil.java:2183)
    at com.intellij.util.ui.tree.TreeUtil.promiseVisit(TreeUtil.java:1761)
    at com.intellij.util.ui.tree.TreeUtil.promiseMakeVisible(TreeUtil.java:1546)
    at com.intellij.util.ui.tree.TreeUtil.promiseExpand(TreeUtil.java:1016)
    at com.intellij.util.ui.tree.TreeUtil.promiseExpandAll(TreeUtil.java:980)
    at com.intellij.util.ui.tree.TreeUtil.expandAll(TreeUtil.java:956)
    at com.illuminatedcloud.intellij.toolwindow.soql.SoqlQueryToolWindow.lambda$execute$9(SourceFile:752)
    at com.illuminatedcloud.intellij.toolwindow.soql.SoqlQueryToolWindow$$Lambda$5064/0x000000080287f040.run(Unknown Source)
    at com.intellij.openapi.application.TransactionGuardImpl.runWithWritingAllowed(TransactionGuardImpl.java:214)
    at com.intellij.openapi.application.TransactionGuardImpl.access$200(TransactionGuardImpl.java:21)
    at com.intellij.openapi.application.TransactionGuardImpl$2.run(TransactionGuardImpl.java:196)

All that that's doing is expanding the SOQL query tree after setting the tree model based on the query results:

queryResultsTree.setModel(new SoqlQueryResultsTreeModel(soqlQueryResults.sobjects));
TreeUtil.expandAll(queryResultsTree);

The second line above is where it's seemingly locked up, and that is on the event thread, so that explains the UI freezing. WAY back when, I found a major inefficiency in how large tree views are expanded and found/implemented a workaround for it that made large tree expansion orders of magnitude more efficient. Let me see if I just need to use that same workaround here. I won't get a chance to do so until tomorrow, but assuming I can get that wired in, I'll post a test build with the change for you to try if you don't mind.

[Scott Wells]

Okay, I found the tree expansion optimization and implemented it for the SOQL query results tree. I'm attaching a build with that change here. Please install it and let me know whether it resolves this issue for you or not. If it does, I'll clean it up and include it in the next build (which will be week-after-next as I'll be out-of-town all of next week).

[Justin Julicher]

Sounds good.

[Justin Julicher]

Yep that fixed it. thanks!

[Justin Julicher]

Well it did then something else froze… I’ll upload the thread dump again.

[Justin Julicher]

  <div class="preview-container wiki-content"><!-- loaded via ajax --></div>
  <div class="mask"></div>
</div>

</div> </form>

[Scott Wells]

Okay, that one is quite different. It looks like it's just waiting for a slow-running force:org:list. I'm attaching another build that moves execution of that to a modal progress thread so that it doesn't occur on the Swing event thread (it shouldn't have been anyway). If the problem still occurs for you, I'd like to see a debug log with Salesforce DX enabled for debug logging. I'll also start to clean up the other change for the next official release since it did seem to help with the previous issue.

[Justin Julicher]

Awesome, thanks for the update.

[Scott Wells]

2.1.9.8 includes the fast tree expand optimization and ensures that listing connections occurs on its own progress indicator thread. Hopefully the combination of all of these fixes will provide a much, much better experience when querying large result sets.

[Justin Julicher]

Amazing! Thanks!

[Justin Julicher]

@Scott Wells I seem to be experiencing this issue again - It seems to work for about the first 30 seconds but then the ide will freeze until the SOQL query is complete.

Have there been any changes in this area recently? I’ll get some debug logs for you.

[Justin Julicher]

Thread Dumps from execution of query.

[Justin Julicher]

Log output at time:

2022-08-15 16:42:27,611 [26611256]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 24362ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220815-164208-WS-222.3345.108-24sec
2022-08-15 16:42:41,372 [26625017]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 13527ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220815-164232-WS-222.3345.108-13sec
2022-08-15 16:44:30,365 [26734010]   WARN - #c.i.d.PerformanceWatcherImpl - Unable to create freeze folder C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220815-164246-WS-222.3345.108-108sec
2022-08-15 16:44:30,365 [26734010]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 108993ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220815-164246-WS-222.3345.108
2022-08-15 16:44:30,657 [26734302]   INFO - #c.i.o.c.i.s.StoreUtil - saveProjectsAndApp took 122696 ms

‌

[Scott Wells]

Justin, nothing has changed in this area in IC2 since the changes in 2.1.9.8. In the provided thread dumps, I only see the EDT setting the table model which in turn sets the table column widths based on the widest string that would reside in that table. That logic is unchanged since April, 2020.

Assuming you're on the latest build of the JetBrains IDE, though, what has changed is the JRE used to host the IDE. There was a significant update from Java 11 to Java 17. Maybe that could have changed some of these timings? What would likely be most useful next is a profiling snapshot from this stretch of time, specifically after the query results have been retrieved and when they're being used to populate the table. Can you provide that? Let me know if you're not sure how to get a CPU profiling snapshot.

[Justin Julicher]

Hmmm it’s been a little while since I cpu profiled a jvm. I’ve only got Webstorm so I don’t have the profiling in the IDE. It seems the webstorm JVM doesn’t have jvmtop.

‌

‌

[Scott Wells]

Justin, it should be built into the IDE:

Start when you're about to query, then assuming/hoping it's possible to do, use the same menu option to capture the snapshot once there's been sufficient burn time.

[Justin Julicher]

ah of course! ha.

attached.

[Scott Wells]

Hmmmm...unfortunately that snapshot is failing to open in YourKit. It tries and then throws an "unexpected value: 128" error. Do you mind capturing another one to see if perhaps this failure is a one-off or something I need to send to the YourKit folks?

[Justin Julicher]

Sure - I have an idea of what might be happening. It seems to stop responding after a little while perhaps because it’s finished collecting the results but is just creating the tree which is taking a lot of processing. The reason I say this is because it seems it takes about the same amount of time to switch to the tab once it has the results (does it regenerate the tree or something again?).

It seems this whole process is done under the status of ‘Executing SOQL Query’. Perhaps once the SOQL has finished executing and the tree is generating it could switch to the status of ‘Processing results’?

‌

‌

[Scott Wells]

Okay, that one opened, and it points to the same thing that I was seeing in the thread dumps you provided earlier, specifically "the EDT setting the table model which in turn sets the table column widths based on the widest string that would reside in that table". My guess is that this is a very tall result set and calculating the optimal column widths is quite expensive since it has to perform a dry run rendering of each and every cell value. I can think of a couple of potential optimizations there that I may try to implement today and provide via a test build here for you to try.

Out of curiosity, how many rows are in this result set? And how many columns? And finally, does the result set include MBCS data by chance? As odd as it might sound, that would come into play as well if present.

[Scott Wells]

Okay, let's try this. This build includes two things: 1) a few optimizations in what seems to be the key hotspot; 2) additional debug logging in that same area so I can see what's going on. Please install this build and add the following to Help>Diagnostic Tools>Debug Log Settings:

#com.illuminatedcloud.intellij.ui.TableColumnAdjuster

Then try to reproduce the behavior. Let me know if it still happens or not, and either way please provide your idea.log so I can see what's going on. Also let me know if you see any change in the way that the column widths are computed based on the result set in the query results table.

[Justin Julicher]

So just checking MBCS = Multi Byte Characters? If so then I don’t think they did.

The query was returning 25 fields with about 5.5k rows. I’ll give that build a go. In regards to column sizing could you just have that done in the UI like excel? ie. have a button to auto adjust what rows are visible (if intellij allows you to do that)\. That way (if you can determine the visible rows) you would only be going over a few rows. Or double click the column header to auto adjust the column?

‌

cheers

‌

[Justin Julicher]

Attached as requested

[Scott Wells]

Thanks. I see the logs from three queries:

2022-08-18 09:22:27,177 [  80325]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column header width for column 0.
2022-08-18 09:22:27,177 [  80325]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 19.
2022-08-18 09:22:27,178 [  80326]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 0.
2022-08-18 09:22:27,178 [  80326]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 18.
2022-08-18 09:22:27,178 [  80326]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 5 rows with values of that size.
2022-08-18 09:22:27,178 [  80326]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:22:27,188 [  80336]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 0 is 163.
2022-08-18 09:22:27,188 [  80336]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,188 [  80336]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 1 is 163.
2022-08-18 09:22:27,188 [  80336]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,189 [  80337]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 2 is 163.
2022-08-18 09:22:27,189 [  80337]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,189 [  80337]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 3 is 163.
2022-08-18 09:22:27,189 [  80337]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,190 [  80338]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 4 is 163.
2022-08-18 09:22:27,190 [  80338]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,190 [  80338]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 163.
...
2022-08-18 09:22:27,219 [  80367]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 24.
2022-08-18 09:22:27,219 [  80367]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 76.
2022-08-18 09:22:27,219 [  80367]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 1 rows with values of that size.
2022-08-18 09:22:27,219 [  80367]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:22:27,220 [  80368]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 1 is 666.
2022-08-18 09:22:27,220 [  80368]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:22:27,220 [  80368]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 666.

2022-08-18 09:53:15,289 [  86678]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column header width for column 0.
2022-08-18 09:53:15,291 [  86680]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 19.
2022-08-18 09:53:15,291 [  86680]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 0.
2022-08-18 09:53:15,291 [  86680]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 18.
2022-08-18 09:53:15,292 [  86681]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 5 rows with values of that size.
2022-08-18 09:53:15,292 [  86681]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:53:15,297 [  86686]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 0 is 163.
2022-08-18 09:53:15,298 [  86687]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,298 [  86687]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 1 is 163.
2022-08-18 09:53:15,298 [  86687]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,299 [  86688]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 2 is 163.
2022-08-18 09:53:15,299 [  86688]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,299 [  86688]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 3 is 163.
2022-08-18 09:53:15,299 [  86688]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,300 [  86689]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 4 is 163.
2022-08-18 09:53:15,300 [  86689]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,300 [  86689]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 163.
...
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column header width for column 2.
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 39.
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 2.
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 25.
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 5 rows with values of that size.
2022-08-18 09:53:15,301 [  86690]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:53:15,302 [  86691]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 49 is 224.
2022-08-18 09:53:15,302 [  86691]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,302 [  86691]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 53 is 224.
2022-08-18 09:53:15,303 [  86692]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,303 [  86692]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 56 is 224.
2022-08-18 09:53:15,303 [  86692]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,304 [  86693]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 59 is 224.
2022-08-18 09:53:15,304 [  86693]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,304 [  86693]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 61 is 224.
2022-08-18 09:53:15,305 [  86694]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:15,305 [  86694]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 224.

2022-08-18 09:53:59,089 [ 130478]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column header width for column 0.
2022-08-18 09:53:59,089 [ 130478]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 99.
2022-08-18 09:53:59,089 [ 130478]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 0.
2022-08-18 09:53:59,094 [ 130483]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 6.
2022-08-18 09:53:59,094 [ 130483]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 5 rows with values of that size.
2022-08-18 09:53:59,095 [ 130484]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 0 is 59.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 1 is 59.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 2 is 59.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 3 is 59.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 4 is 59.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,096 [ 130485]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 59.
...
2022-08-18 09:53:59,334 [ 130723]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column header width for column 33.
2022-08-18 09:53:59,334 [ 130723]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 113.
2022-08-18 09:53:59,334 [ 130723]   FINE - #c.i.i.u.TableColumnAdjuster - Calculating the column data width for column 33.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The largest raw value width is 0.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   Testing 5 rows with values of that size.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The maximum width for this column is 2147483647.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 0 is 7.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 1 is 7.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 2 is 7.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 3 is 7.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   The cell data width for row 4 is 7.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   That's the largest width.
2022-08-18 09:53:59,336 [ 130725]   FINE - #c.i.i.u.TableColumnAdjuster -   Calculated as 7.

Overall those look fine in terms of the amount of time required to calculate the initial column widths based on the data in each column. The longest one was ~250 ms. However, then I see these:

2022-08-18 09:54:30,073 [ 161462]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 30432ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220818-095404-WS-222.3345.108-30sec
2022-08-18 09:54:36,461 [ 167850]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 6383ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220818-095435-WS-222.3345.108-6sec
2022-08-18 09:55:12,456 [ 203845]   WARN - #c.i.d.PerformanceWatcherImpl - UI was frozen for 35983ms, details saved to C:\Users\justinj\AppData\Local\JetBrains\WebStorm2022.2\log\threadDumps-freeze-20220818-095441-WS-222.3345.108-35sec

Do you mind sending me those thread dumps if you still have them handy? I won't get a chance to look at them until tomorrow, but I'd like to see where they're stuck.

[Justin Julicher]

attached

[Scott Wells]

Thanks. So this is weird. Basically of the three provided thread dumps, only one of them--the shortest one--has any threads going through IC2 logic. That one is updating the tree UI after expanding all nodes in the model. Is this still the 25 columns x 5.5K rows result set? If so, I guess that's not entirely surprising, and I could certainly perform a full tree expansion conditionally based on the volume of data in the result set.

What's worth noting, though, is that the main hotspot from the original thread dumps and profiling snapshot no longer shows at all in these new ones, so I do think we're making progress. I could provide a new build that doesn't auto-expand the tree view for result sets over a certain size and we could see how that looks. To some extent I'm trying to make things work as-is for the normal case of a smaller result set and work reasonably well for the more extreme case of a larger result set.

[Justin Julicher]

Yeah it was still 25 columns - it was actually 6.5k rows.

I think maybe you should, for the larger rows, only check maybe the first 1000 rows. I would think that would give you a big enough data set. Also are you check number columns too? I would probably ignore them and default them to 6 or 7 digits. I don’t think anyone would complain about that.

‌

[Scott Wells]

I've added logic to skip tree view expansion for result sets of 1K rows. The last(?) remaining long pole seems to be the table computing its initial row heights based on its contents which tests every cell for its preferred height:

    at java.desktop/javax.swing.table.DefaultTableCellRenderer.setValue(DefaultTableCellRenderer.java:378)
    at com.illuminatedcloud.intellij.ui.MultiFontCellRenderer.setValue(MultiFontCellRenderer.java:95)
    at java.desktop/javax.swing.table.DefaultTableCellRenderer.getTableCellRendererComponent(DefaultTableCellRenderer.java:262)
    at com.intellij.ui.table.JBTable.calculateRowHeight(JBTable.java:260)
    at com.intellij.ui.table.JBTable.getRowHeight(JBTable.java:238)
    at java.desktop/javax.swing.JTable.getRowHeight(JTable.java:1064)
    at java.desktop/javax.swing.JTable.getCellRect(JTable.java:2983)
    at java.desktop/javax.swing.plaf.basic.BasicTableUI.createTableSize(BasicTableUI.java:1754)
    at java.desktop/javax.swing.plaf.basic.BasicTableUI.getPreferredSize(BasicTableUI.java:1793)
    at java.desktop/javax.swing.JComponent.getPreferredSize(JComponent.java:1728)
    at com.intellij.ui.table.JBTable.getPreferredSize(JBTable.java:219)
    at com.intellij.ui.components.JBScrollPane$Layout.layoutContainer(JBScrollPane.java:519)

I'll tinker with that a bit to see if I can pre-compute those values so that it's constant-time instead of based on the table's dimensions, then I'll provide a new build for you to try. At this point that'll almost certainly slide into next week. I'll let you know when I have something ready for you to try.

[Scott Wells]

Turns out I did have time to work on this a bit this morning (in part because otherwise I couldn't get it out of my head). Here's a new build for you to try. It includes (a better version of) the previous optimizations plus logic to avoid tree view auto-expansion for result sets >1K rows and a change to have the initial row height calculation only sample a very limited amount of data assuming a uniform font height for in the result set table.

Please install it and let me know whether it helps, and if there's still a notable pause after the query has completed execution, attach the respective diagnostic info for review.

[Justin Julicher]

Ok yeah that works really well - couldn’t really tell the difference between the presentation of the table and there was virtually no delay after the retrieval of the records.

I ran a query with a limit of 999 and there was a 20 second delay in processing the result (99 columns) done by just doing a SEL* query.

‌

[Scott Wells]

Thanks for the feedback. Just to confirm, "there was a 20 second delay..." is meant to say that it behaved as expected based on the queried data, or is there still an issue?

[Scott Wells]

New optimizations delivered in 2.2.3.3.