Merge pull request #4324 from MDoerner/BetterParseTimeLogging

Fix massive parser slowdown

Author: retailcoder

Rubberduck.Main/Root/RubberduckIoCInstaller.cs

@@ -842,6 +842,9 @@ private void RegisterParsingEngine(IWindsorContainer container)
             container.Register(Component.For<IStringParser>()
                 .ImplementedBy<TokenStreamParserStringParserAdapterWithPreprocessing>()
                 .LifestyleSingleton());
+            container.Register(Component.For<ITokenStreamParser>()
+                .ImplementedBy<VBATokenStreamParser>()
+                .LifestyleSingleton());
             container.Register(Component.For<IModuleParser>()
                 .ImplementedBy<ModuleParser>()
                 .DependsOn(Dependency.OnComponent("codePaneSourceCodeProvider", typeof(CodePaneSourceCodeHandler)),

Rubberduck.Parsing/Common/ParsingStageTimer.cs

@@ -0,0 +1,28 @@
+using System.Diagnostics;
+using NLog;
+
+namespace Rubberduck.Parsing.Common
+{
+    public class ParsingStageTimer
+    {
+        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
+
+        public static ParsingStageTimer StartNew()
+        {
+            var timer = new ParsingStageTimer();
+            timer.Start();
+            return timer;
+        }
+
+        private readonly Stopwatch _stopwatch = new Stopwatch();
+
+        public void Start() => _stopwatch.Start();
+        public void Stop() => _stopwatch.Stop();
+        public void Restart() => _stopwatch.Restart();
+
+        public void Log(string message)
+        {
+            Logger.Debug(message, _stopwatch.ElapsedMilliseconds);
+        }
+    }
+}

Rubberduck.Parsing/Rubberduck.Parsing.csproj

@@ -144,6 +144,7 @@
     <Compile Include="Binding\Bindings\ParenthesizedDefaultBinding.cs" />
     <Compile Include="Binding\TypeBindingContext.cs" />
     <Compile Include="Binding\ExpressionClassification.cs" />
+    <Compile Include="Common\ParsingStageTimer.cs" />
     <Compile Include="ComReflection\ComLibraryProvider.cs" />
     <Compile Include="ComReflection\IComLibraryProvider.cs" />
     <Compile Include="ComReflection\ISerializableProjectBuilder.cs" />

Rubberduck.Parsing/VBA/ComReferenceLoading/COMReferenceSynchronizerBase.cs

@@ -6,6 +6,7 @@
 using System.Runtime.InteropServices;
 using System.Threading;
 using NLog;
+using Rubberduck.Parsing.Common;
 using Rubberduck.Parsing.ComReflection;
 using Rubberduck.Parsing.VBA.Extensions;
 using Rubberduck.VBEditor;
@@ -68,6 +69,8 @@ protected COMReferenceSynchronizerBase(RubberduckParserState state, IParserState
 
         public void SyncComReferences(CancellationToken token)
         {
+            var parsingStageTimer = ParsingStageTimer.StartNew();
+
             LastSyncOfCOMReferencesLoadedReferences = false;
             _unloadedCOMReferences.Clear();
             RefreshReferencedByProjectId();
@@ -94,6 +97,9 @@ public void SyncComReferences(CancellationToken token)
             {
                 UnloadComReference(reference);
             }
+
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Loaded and unloaded referenced libraries in {0}ms.");
         }
 
         private Dictionary<string, List<ReferenceInfo>> ReferencedByProjectId()

Rubberduck.Parsing/VBA/DeclarationResolving/DeclarationResolveRunner.cs

@@ -1,8 +1,10 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
+using Rubberduck.Parsing.Common;
 using Rubberduck.Parsing.VBA.ComReferenceLoading;
 using Rubberduck.VBEditor;
 
@@ -29,6 +31,8 @@ public override void ResolveDeclarations(IReadOnlyCollection<QualifiedModuleName
                 return;
             }
 
+            var parsingStageTimer = ParsingStageTimer.StartNew();
+
             _projectDeclarations.Clear();
             token.ThrowIfCancellationRequested();
 
@@ -56,6 +60,9 @@ public override void ResolveDeclarations(IReadOnlyCollection<QualifiedModuleName
                 _parserStateManager.SetStatusAndFireStateChanged(this, ParserState.ResolverError, token);
                 throw;
             }
+
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Resolved user declaration in {0}ms.");
         }
     }
 }

Rubberduck.Parsing/VBA/DeclarationResolving/DeclarationResolveRunnerBase.cs

@@ -15,7 +15,7 @@ namespace Rubberduck.Parsing.VBA.DeclarationResolving
     public abstract class DeclarationResolveRunnerBase : IDeclarationResolveRunner
     {
         protected readonly ConcurrentDictionary<string, Declaration> _projectDeclarations = new ConcurrentDictionary<string, Declaration>();
-        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
+        protected static readonly Logger Logger = LogManager.GetCurrentClassLogger();
 
         protected readonly RubberduckParserState _state;
         protected readonly IParserStateManager _parserStateManager;

Rubberduck.Parsing/VBA/Parsing/ParseRunner.cs

@@ -3,6 +3,7 @@
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
+using Rubberduck.Parsing.Common;
 using Rubberduck.VBEditor;
 
 namespace Rubberduck.Parsing.VBA.Parsing
@@ -29,6 +30,8 @@ public override void ParseModules(IReadOnlyCollection<QualifiedModuleName> modul
 
             token.ThrowIfCancellationRequested();
 
+            var parsingStageTimer = ParsingStageTimer.StartNew();
+
             var options = new ParallelOptions();
             options.CancellationToken = token;
             options.MaxDegreeOfParallelism = _maxDegreeOfParserParallelism;
@@ -49,6 +52,9 @@ public override void ParseModules(IReadOnlyCollection<QualifiedModuleName> modul
                 StateManager.SetStatusAndFireStateChanged(this, ParserState.Error, token);
                 throw;
             }
+
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Parsed user modules in {0}ms.");
         }
     }
 }

Rubberduck.Parsing/VBA/Parsing/TokenStreamParserBase.cs

@@ -44,23 +44,25 @@ private IParseTree ParseWithFallBack(string moduleName, CommonTokenStream tokenS
         {
             try
             {
-                return ParseLl(moduleName, tokenStream, codeKind);
+                return ParseSll(moduleName, tokenStream, codeKind);
             }
             catch (ParsePassSyntaxErrorException syntaxErrorException)
             {
                 var message = $"SLL mode failed while parsing the {codeKind} version of module {moduleName} at symbol {syntaxErrorException.OffendingSymbol.Text} at L{syntaxErrorException.LineNumber}C{syntaxErrorException.Position}. Retrying using LL.";
                 LogAndReset(tokenStream, message, syntaxErrorException);
-                return ParseSll(moduleName, tokenStream, codeKind);
+                return ParseLl(moduleName, tokenStream, codeKind);
             }
             catch (Exception exception)
             {
                 var message = $"SLL mode failed while parsing the {codeKind} version of module {moduleName}. Retrying using LL.";
                 LogAndReset(tokenStream, message, exception);
-                return ParseSll(moduleName, tokenStream, codeKind);
+                return ParseLl(moduleName, tokenStream, codeKind);
             }
         }
 
-        private void LogAndReset(CommonTokenStream tokenStream, string logWarnMessage, Exception exception)
+        //This method is virtual only because a CommonTokenStream cannot be mocked in tests
+        //and there is no interface for it or a base class that has the Reset member.
+        protected virtual void LogAndReset(CommonTokenStream tokenStream, string logWarnMessage, Exception exception)
         {
             Logger.Warn(logWarnMessage);
             Logger.Debug(exception);

Rubberduck.Parsing/VBA/ReferenceManagement/ReferenceResolveRunnerBase.cs

@@ -5,6 +5,7 @@
 using System.Threading;
 using Antlr4.Runtime.Tree;
 using NLog;
+using Rubberduck.Parsing.Common;
 using Rubberduck.Parsing.Symbols;
 using Rubberduck.Parsing.VBA.Extensions;
 using Rubberduck.Parsing.VBA.Parsing;
@@ -75,21 +76,40 @@ public void ResolveReferences(IReadOnlyCollection<QualifiedModuleName> toResolve
             PerformPreResolveCleanup(_toResolve.AsReadOnly(), token);
             token.ThrowIfCancellationRequested();
 
+            var parsingStageTimer = ParsingStageTimer.StartNew();
+
             ExecuteCompilationPasses(_toResolve.AsReadOnly(), token);
             token.ThrowIfCancellationRequested();
 
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Executed compilation passes in {0}ms.");
+            parsingStageTimer.Restart();
+
             AddSupertypesForDocumentModules(_toResolve.AsReadOnly(), _state);
             token.ThrowIfCancellationRequested();
 
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Added supertypes for document modules in {0}ms.");
+
             var parseTreesToResolve = _state.ParseTrees.Where(kvp => _toResolve.Contains(kvp.Key)).ToList();
             token.ThrowIfCancellationRequested();
 
+            parsingStageTimer.Restart();
+
             ResolveReferences(parseTreesToResolve, token);
             token.ThrowIfCancellationRequested();
 
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Resolved references in {0}ms.");
+            parsingStageTimer.Restart();
+
             AddModuleToModuleReferences(_state.DeclarationFinder, token);
             token.ThrowIfCancellationRequested();
 
+            parsingStageTimer.Stop();
+            parsingStageTimer.Log("Determined module to module references in {0}ms.");
+            parsingStageTimer.Restart();
+
             AddNewUndeclaredVariablesToDeclarations();
             AddNewUnresolvedMemberDeclarations();