Expose event for 'analysis done' (#1149)

* First cut

* Move telemetry to server

* Cleanup

* Better track time spent

* Rename field

Author: Mikhail Arkhipov

src/Analysis/Ast/Impl/Analyzer/ActivityTracker.cs

@@ -0,0 +1,92 @@
+// Copyright(c) Microsoft Corporation
+// All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the License); you may not use
+// this file except in compliance with the License. You may obtain a copy of the
+// License at http://www.apache.org/licenses/LICENSE-2.0
+//
+// THIS CODE IS PROVIDED ON AN  *AS IS* BASIS, WITHOUT WARRANTIES OR CONDITIONS
+// OF ANY KIND, EITHER EXPRESS OR IMPLIED, INCLUDING WITHOUT LIMITATION ANY
+// IMPLIED WARRANTIES OR CONDITIONS OF TITLE, FITNESS FOR A PARTICULAR PURPOSE,
+// MERCHANTABILITY OR NON-INFRINGEMENT.
+//
+// See the Apache Version 2.0 License for specific language governing
+// permissions and limitations under the License.
+
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+
+namespace Microsoft.Python.Analysis.Analyzer {
+    internal static class ActivityTracker {
+        private static readonly Dictionary<string, AnalysisState> _modules = new Dictionary<string, AnalysisState>();
+        private static readonly object _lock = new object();
+        private static bool _tracking;
+        private static Stopwatch _sw;
+
+        private struct AnalysisState {
+            public int Count;
+            public bool IsComplete;
+        }
+
+        public static void OnEnqueueModule(string path) {
+            if (string.IsNullOrEmpty(path)) {
+                return;
+            }
+
+            lock (_lock) {
+                if (!_modules.TryGetValue(path, out var st)) {
+                    _modules[path] = default;
+                } else {
+                    st.IsComplete = false;
+                }
+            }
+        }
+
+        public static void OnModuleAnalysisComplete(string path) {
+            lock (_lock) {
+                if (_modules.TryGetValue(path, out var st)) {
+                    st.Count++;
+                    st.IsComplete = true;
+                }
+            }
+        }
+
+        public static bool IsAnalysisComplete {
+            get {
+                lock (_lock) {
+                    return _modules.All(m => m.Value.IsComplete);
+                }
+            }
+        }
+
+
+        public static void StartTracking() {
+            lock (_lock) {
+                if (!_tracking) {
+                    _tracking = true;
+                    _modules.Clear();
+                    _sw = Stopwatch.StartNew();
+                }
+            }
+        }
+
+        public static void EndTracking() {
+            lock (_lock) {
+                if (_tracking) {
+                    _sw?.Stop();
+                    _tracking = false;
+                }
+            }
+        }
+
+        public static int ModuleCount {
+            get {
+                lock (_lock) {
+                    return _modules.Count;
+                }
+            }
+        }
+        public static double MillisecondsElapsed => _sw?.Elapsed.TotalMilliseconds ?? 0;
+    }
+}

src/Analysis/Ast/Impl/Analyzer/Definitions/AnalysisCompleteEventArgs.cs

@@ -0,0 +1,28 @@
+// Copyright(c) Microsoft Corporation
+// All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the License); you may not use
+// this file except in compliance with the License. You may obtain a copy of the
+// License at http://www.apache.org/licenses/LICENSE-2.0
+//
+// THIS CODE IS PROVIDED ON AN  *AS IS* BASIS, WITHOUT WARRANTIES OR CONDITIONS
+// OF ANY KIND, EITHER EXPRESS OR IMPLIED, INCLUDING WITHOUT LIMITATION ANY
+// IMPLIED WARRANTIES OR CONDITIONS OF TITLE, FITNESS FOR A PARTICULAR PURPOSE,
+// MERCHANTABILITY OR NON-INFRINGEMENT.
+//
+// See the Apache Version 2.0 License for specific language governing
+// permissions and limitations under the License.
+
+using System;
+
+namespace Microsoft.Python.Analysis.Analyzer {
+    public sealed class AnalysisCompleteEventArgs : EventArgs {
+        public int ModuleCount { get; }
+        public double MillisecondsElapsed { get; }
+
+        public AnalysisCompleteEventArgs(int moduleCount, double msElapsed) {
+            ModuleCount = moduleCount;
+            MillisecondsElapsed = msElapsed;
+        }
+    }
+}

src/Analysis/Ast/Impl/Analyzer/Definitions/IPythonAnalyzer.cs

@@ -13,6 +13,7 @@
 // See the Apache Version 2.0 License for specific language governing
 // permissions and limitations under the License.
 
+using System;
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
@@ -64,5 +65,10 @@ public interface IPythonAnalyzer {
         /// Returns list of currently loaded modules.
         /// </summary>
         IReadOnlyList<IPythonModule> LoadedModules { get; }
+
+        /// <summary>
+        /// Fires when analysis is complete.
+        /// </summary>
+        event EventHandler<AnalysisCompleteEventArgs> AnalysisComplete;
     }
 }

src/Analysis/Ast/Impl/Analyzer/PythonAnalyzer.cs

@@ -194,11 +194,22 @@ public void ResetAnalyzer() {
             }
         }
 
-        public IReadOnlyList<IPythonModule> LoadedModules 
-            => _analysisEntries.Values.ExcludeDefault().Select(v => v.Module).ExcludeDefault().ToArray();
+        public IReadOnlyList<IPythonModule> LoadedModules {
+            get {
+                lock (_syncObj) {
+                    return _analysisEntries.Values.ExcludeDefault().Select(v => v.Module).ExcludeDefault().ToArray();
+                }
+            }
+        }
+
+        public event EventHandler<AnalysisCompleteEventArgs> AnalysisComplete;
+
+        internal void RaiseAnalysisComplete(int moduleCount, double msElapsed) 
+            => AnalysisComplete?.Invoke(this, new AnalysisCompleteEventArgs(moduleCount, msElapsed));
 
         private void AnalyzeDocument(AnalysisModuleKey key, PythonAnalyzerEntry entry, ImmutableArray<AnalysisModuleKey> dependencies) {
             _analysisCompleteEvent.Reset();
+            ActivityTracker.StartTracking();
             _log?.Log(TraceEventType.Verbose, $"Analysis of {entry.Module.Name}({entry.Module.ModuleType}) queued");
 
             var graphVersion = _dependencyResolver.ChangeValue(key, entry, entry.IsUserModule, dependencies);

src/Analysis/Ast/Impl/Analyzer/PythonAnalyzerSession.cs

@@ -137,20 +137,25 @@ private async Task StartAsync() {
                 stopWatch.Stop();
 
                 bool isCanceled;
+                bool isFinal;
                 lock (_syncObj) {
                     isCanceled = _isCanceled;
                     _state = State.Completed;
+                    isFinal = _walker.MissingKeys.Count == 0 && !isCanceled && remaining == 0;
                     _walker = null;
                 }
 
                 if (!isCanceled) {
                     _progress.ReportRemaining(remaining);
+                    if(isFinal) {
+                        ActivityTracker.EndTracking();
+                        (_analyzer as PythonAnalyzer)?.RaiseAnalysisComplete(ActivityTracker.ModuleCount, ActivityTracker.MillisecondsElapsed);
+                        _log?.Log(TraceEventType.Verbose, $"Analysis complete: {ActivityTracker.ModuleCount} modules in { ActivityTracker.MillisecondsElapsed} ms.");
+                    }
                 }
             }
 
             var elapsed = stopWatch.Elapsed.TotalMilliseconds;
-
-            SendTelemetry(_telemetry, elapsed, originalRemaining, remaining, Version);
             LogResults(_log, elapsed, originalRemaining, remaining, Version);
             ForceGCIfNeeded(originalRemaining, remaining);
         }
@@ -162,38 +167,6 @@ private static void ForceGCIfNeeded(int originalRemaining, int remaining) {
             }
         }
 
-        private static void SendTelemetry(ITelemetryService telemetry, double elapsed, int originalRemaining, int remaining, int version) {
-            if (telemetry == null) {
-                return;
-            }
-
-            if (remaining != 0 || originalRemaining < 100) {
-                return;
-            }
-
-            double privateMB;
-            double peakPagedMB;
-            double workingMB;
-
-            using (var proc = Process.GetCurrentProcess()) {
-                privateMB = proc.PrivateMemorySize64 / 1e+6;
-                peakPagedMB = proc.PeakPagedMemorySize64 / 1e+6;
-                workingMB = proc.WorkingSet64 / 1e+6;
-            }
-
-            var e = new TelemetryEvent {
-                EventName = "python_language_server/analysis_complete", // TODO: Move this common prefix into Core.
-            };
-
-            e.Measurements["privateMB"] = privateMB;
-            e.Measurements["peakPagedMB"] = peakPagedMB;
-            e.Measurements["workingMB"] = workingMB;
-            e.Measurements["elapsedMs"] = elapsed;
-            e.Measurements["entries"] = originalRemaining;
-            e.Measurements["version"] = version;
-
-            telemetry.SendTelemetryAsync(e).DoNotWait();
-        }
 
         private static void LogResults(ILogger logger, double elapsed, int originalRemaining, int remaining, int version) {
             if (logger == null) {
@@ -226,6 +199,8 @@ private async Task<int> AnalyzeAffectedEntriesAsync(Stopwatch stopWatch) {
                     continue;
                 }
 
+                ActivityTracker.OnEnqueueModule(node.Value.Module.FilePath);
+
                 if (Interlocked.Increment(ref _runningTasks) >= _maxTaskRunning || _walker.Remaining == 1) {
                     Analyze(node, null, stopWatch);
                 } else {
@@ -241,7 +216,7 @@ private async Task<int> AnalyzeAffectedEntriesAsync(Stopwatch stopWatch) {
 
             if (_walker.MissingKeys.Count == 0 || _walker.MissingKeys.All(k => k.IsTypeshed)) {
                 Interlocked.Exchange(ref _runningTasks, 0);
-                
+
                 if (!isCanceled) {
                     _analysisCompleteEvent.Set();
                 }
@@ -279,6 +254,7 @@ private void Analyze(IDependencyChainNode<PythonAnalyzerEntry> node, AsyncCountd
                 var startTime = stopWatch.Elapsed;
                 AnalyzeEntry(entry, module, ast, _walker.Version);
                 node.Commit();
+                ActivityTracker.OnModuleAnalysisComplete(node.Value.Module.FilePath);
 
                 LogCompleted(module, stopWatch, startTime);
             } catch (OperationCanceledException oce) {

src/Analysis/Ast/Impl/Dependencies/IDependencyChainWalker.cs

@@ -23,7 +23,6 @@ internal interface IDependencyChainWalker<TKey, TValue> {
         ImmutableArray<TValue> AffectedValues { get; }
         int Version { get; }
         int Remaining { get; }
-
         Task<IDependencyChainNode<TValue>> GetNextAsync(CancellationToken cancellationToken);
     }
 }

src/LanguageServer/Impl/Implementation/Server.Telemetry.cs

@@ -0,0 +1,55 @@
+// Copyright(c) Microsoft Corporation
+// All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the License); you may not use
+// this file except in compliance with the License. You may obtain a copy of the
+// License at http://www.apache.org/licenses/LICENSE-2.0
+//
+// THIS CODE IS PROVIDED ON AN  *AS IS* BASIS, WITHOUT WARRANTIES OR CONDITIONS
+// OF ANY KIND, EITHER EXPRESS OR IMPLIED, INCLUDING WITHOUT LIMITATION ANY
+// IMPLIED WARRANTIES OR CONDITIONS OF TITLE, FITNESS FOR A PARTICULAR PURPOSE,
+// MERCHANTABILITY OR NON-INFRINGEMENT.
+//
+// See the Apache Version 2.0 License for specific language governing
+// permissions and limitations under the License.
+
+using System.Diagnostics;
+using Microsoft.Python.Analysis.Analyzer;
+using Microsoft.Python.Core;
+using Microsoft.Python.Core.Services;
+
+namespace Microsoft.Python.LanguageServer.Implementation {
+    public sealed partial class Server {
+        private void OnAnalysisComplete(object sender, AnalysisCompleteEventArgs e) {
+            if (e.MillisecondsElapsed < 500) {
+                return;
+            }
+            var telemetry = _services.GetService<ITelemetryService>();
+            if (telemetry == null) {
+                return;
+            }
+
+            double privateMB;
+            double peakPagedMB;
+            double workingMB;
+
+            using (var proc = Process.GetCurrentProcess()) {
+                privateMB = proc.PrivateMemorySize64 / 1e+6;
+                peakPagedMB = proc.PeakPagedMemorySize64 / 1e+6;
+                workingMB = proc.WorkingSet64 / 1e+6;
+            }
+
+            var te = new TelemetryEvent {
+                EventName = "python_language_server/analysis_complete", // TODO: Move this common prefix into Core.
+            };
+
+            te.Measurements["privateMB"] = privateMB;
+            te.Measurements["peakPagedMB"] = peakPagedMB;
+            te.Measurements["workingMB"] = workingMB;
+            te.Measurements["elapsedMs"] = e.MillisecondsElapsed;
+            te.Measurements["moduleCount"] = e.ModuleCount;
+
+            telemetry.SendTelemetryAsync(te).DoNotWait();
+        }
+    }
+}

src/LanguageServer/Impl/Implementation/Server.cs

@@ -107,6 +107,9 @@ public async Task<InitializeResult> InitializeAsync(InitializeParams @params, Ca
             var analyzer = new PythonAnalyzer(_services, cacheFolderPath);
             _services.AddService(analyzer);
 
+            analyzer.AnalysisComplete += OnAnalysisComplete;
+            _disposableBag.Add(() => analyzer.AnalysisComplete -= OnAnalysisComplete);
+
             _services.AddService(new RunningDocumentTable(_services));
             _rdt = _services.GetService<IRunningDocumentTable>();