rubberduck-vba / Rubberduck

Every programmer needs a rubberduck. COM add-in for the VBA & VB6 IDE (VBE).
https://rubberduckvba.com
GNU General Public License v3.0
1.91k stars 299 forks source link

Code inspection does not finish #4150

Closed Gener4tor closed 6 years ago

Gener4tor commented 6 years ago

This it how it looks now for more than 30 minutes:

grafik

And it slows the VBE massively down.

I have a new installation and a ~50 forms + 100 modules project.

The memory consumtion is also very high. Before rubberduck, the process needed ~50mb Ram. Now it is beteen 500 and 800 Mb.

Vogel612 commented 6 years ago

What version do you have installed? Could you please try pasting the Logs (preferrably at Trace-Level) to help us nail down the issue? Thanks!

Gener4tor commented 6 years ago

I use:

Version 2.2.0.3468 OS: Microsoft Windows NT 10.0.16299.0, x64 Host Product: Microsoft Office 2016 x86 Host Version: 16.0.4666.1000 Host Executable: MSACCESS.EXE

I restarted access and restarted my code inspection again:

This is the log after ~5 minutes (the memory consumtion is ~ 600 mb): RubberduckLog.txt

Gener4tor commented 6 years ago

This is the log after ~15 minutes (Memory is still ~600 mb):

RubberduckLog after 15 minutes.txt

Gener4tor commented 6 years ago

ok...now it seems to have finished (after ~25 minutes) after restarting.

Here is the Log:

RubberduckLog.txt

Vogel612 commented 6 years ago

okay let's get some overview out of the final log:

12:44:25.2802 Rubberduck starts parsing
12:44:27.4863 Loading References
12:44:44.6311 Parsing Complete
12:44:45.6793 Start Resolving Declarations
12:44:47.6825 Declarations are Resolved
12:44:49.7591 Start Resolving References
12:45:29.1239 Rubberduck Reports "Ready" status
// Parsing run finished after 65,3371173s;

Then there's another two parse passes, the first taking 5 seconds and the second taking 8 seconds actually triggering the Inspections.

The UnreachableCaseInspection throws a NullReferenceException

Now there's a metric ton of command and hotkey rewirings, I assume you've been tabbing in and out of the VBE, and lastly we get the following messages:

2018-07-04 13:06:26.4155;TRACE-2.2.0.3468;Rubberduck.Inspections.Abstract.InspectionBase;Intercepted invocation of 'ObjectVariableNotSetInspection.DoGetInspectionResults' returned 307 objects.;
2018-07-04 13:06:26.4155;TRACE-2.2.0.3468;Rubberduck.Inspections.Abstract.InspectionBase;Intercepted invocation of 'ObjectVariableNotSetInspection.DoGetInspectionResults' ran for 1229404ms;
2018-07-04 13:06:26.5645;TRACE-2.2.0.3468;Rubberduck.UI.Inspections.InspectionResultsViewModel;Inspections loaded in 1231232ms;

So we have the following final stats:

Parse Run 1: ~65 ecconds
Parse Run 2: ~ 5 seconds
Parse Run 3: ~ 8 seconds
Inspections:  307 Results, two exceptions, ~1230 seconds

That translates to almost exactly 20 minutes running time for the inspections. That is not acceptable...

Vogel612 commented 6 years ago

According to the log, the culprit is the ObjectVariableNotSetInspection ...

The code for that inspection iterates over the references between different User modules and thus it's runtime in the worst case is exponential in the number of user modules. That is ... not ideal.

Vogel612 commented 6 years ago

A bit of log-analysis suggests that Rubberduck parsed 180 modules.

comintern commented 6 years ago

Linking chat so I don't forget why ObjectVariableNotSetInspection is so slow.

comintern commented 6 years ago

Removing memory-management tag - this is purely CPU bound, and over 99% of the processing time is spent on one line of code:

screenshot from 2018-08-27 23-09-22