Skip to content
This repository has been archived by the owner on Oct 4, 2021. It is now read-only.

Commit

Permalink
[IDE] Track startup metadata in one place
Browse files Browse the repository at this point in the history 
Fixes VSTS #823325 The startup telemetry metadata code should be consolidated into one class
  • Loading branch information
iain holmes committed Mar 27, 2019
1 parent 0b270e4 commit 8f8af65
Show file tree
Hide file tree
Showing 5 changed files with 231 additions and 182 deletions.
8 changes: 4 additions & 4 deletions main/src/addins/MacPlatform/MacPlatform.cs
View file
Expand Up @@ -640,7 +640,7 @@ void GlobalSetup ()
//OpenFiles may pump the mainloop, but can't do that from an AppleEvent
GLib.Idle.Add (delegate {
Ide.WelcomePage.WelcomePageService.HideWelcomePageOrWindow ();
var trackTTC = IdeApp.StartTimeToCodeLoadTimer ();
var trackTTC = IdeStartupTracker.StartupTracker.StartTimeToCodeLoadTimer ();
IdeApp.OpenFiles (e.Documents.Select (
doc => new FileOpenInformation (doc.Key, null, doc.Value, 1, OpenDocumentOptions.DefaultInternal)),
null
Expand All @@ -651,7 +651,7 @@ void GlobalSetup ()
var firstFile = e.Documents.First ().Key;
IdeApp.TrackTimeToCode (GetDocumentTypeFromFilename (firstFile));
IdeStartupTracker.StartupTracker.TrackTimeToCode (GetDocumentTypeFromFilename (firstFile));
});
return false;
});
Expand All @@ -660,7 +660,7 @@ void GlobalSetup ()

ApplicationEvents.OpenUrls += delegate (object sender, ApplicationUrlEventArgs e) {
GLib.Idle.Add (delegate {
var trackTTC = IdeApp.StartTimeToCodeLoadTimer ();
var trackTTC = IdeStartupTracker.StartupTracker.StartTimeToCodeLoadTimer ();
// Open files via the monodevelop:// URI scheme, compatible with the
// common TextMate scheme: http://blog.macromates.com/2007/the-textmate-url-scheme/
IdeApp.OpenFiles (e.Urls.Select (url => {
Expand Down Expand Up @@ -690,7 +690,7 @@ void GlobalSetup ()
}
var firstFile = e.Urls.First ();
IdeApp.TrackTimeToCode (GetDocumentTypeFromFilename (firstFile));
IdeStartupTracker.StartupTracker.TrackTimeToCode (GetDocumentTypeFromFilename (firstFile));
});
return false;
});
Expand Down
1 change: 1 addition & 0 deletions main/src/core/MonoDevelop.Ide/MonoDevelop.Ide.csproj
View file
Expand Up @@ -4238,6 +4238,7 @@
<Compile Include="MonoDevelop.Ide.TypeSystem\HackyWorkspaceFilesCache.cs" />
<Compile Include="MonoDevelop.Ide.Gui.Dialogs\NewFolderDialog.cs" />
<Compile Include="MonoDevelop.Components.PropertyGrid\IPropertyGrid.cs" />
<Compile Include="MonoDevelop.Ide\IdeStartupTracker.cs" />
</ItemGroup>
<ItemGroup>
<Data Include="options\DefaultEditingLayout.xml" />
Expand Down
75 changes: 1 addition & 74 deletions main/src/core/MonoDevelop.Ide/MonoDevelop.Ide/Ide.cs
View file
Expand Up @@ -103,22 +103,8 @@ public static class IdeApp
}
}

static TimeToCodeMetadata ttcMetadata;
static Stopwatch ttcStopwatch;
static long startupCompletedTicks;
static long ttcDuration = 3 * TimeSpan.TicksPerSecond; // Wait 3 seconds before ignoring TTC events

internal static void OnStartupCompleted (StartupMetadata startupMetadata, Stopwatch ttcTimer)
internal static void OnStartupCompleted ()
{
ttcMetadata = new TimeToCodeMetadata {
StartupTime = startupMetadata.CorrectedStartupTime
};
ttcMetadata.AddProperties (startupMetadata);

ttcStopwatch = ttcTimer;
startupCompletedTicks = ttcStopwatch.ElapsedTicks;
LoggingService.LogDebug ("TTC starting");

startupCompleted?.Invoke (null, EventArgs.Empty);
}

Expand Down Expand Up @@ -321,65 +307,6 @@ static void KeyBindingFailed (object sender, KeyBindingFailedEventArgs e)
Ide.IdeApp.Workbench.StatusBar.ShowWarning (e.Message);
}

internal static void TrackTimeToCode (TimeToCodeMetadata.DocumentType documentType)
{
LoggingService.LogDebug("Tracking TTC");
if (ttcStopwatch == null || timeToCodeSolutionTimer == null) {
LoggingService.LogDebug("Ignoring TTC");
return;
}

ttcStopwatch.Stop ();
timeToCodeSolutionTimer.Stop ();

if (ttcMetadata == null) {
timeToCodeSolutionTimer = null;
ttcStopwatch = null;
throw new Exception ("SendTimeToCode called before initialisation completed");
}

LoggingService.LogDebug ("Processing TTC");
ttcMetadata.SolutionLoadTime = timeToCodeSolutionTimer.ElapsedMilliseconds;

ttcMetadata.CorrectedDuration = ttcStopwatch.ElapsedMilliseconds;
ttcMetadata.Type = documentType;

Counters.TimeToCode.Inc ("SolutionLoaded", ttcMetadata);

timeToCodeSolutionTimer = null;
timeToCodeWorkspaceTimer = Stopwatch.StartNew ();

MonoDevelopWorkspace.LoadingFinished += CompleteTimeToIntellisense;
}

static void CompleteTimeToIntellisense (object sender, EventArgs e)
{
// Reuse ttcMetadata, as it already has other information set.
MonoDevelopWorkspace.LoadingFinished -= CompleteTimeToIntellisense;

timeToCodeWorkspaceTimer.Stop ();

ttcMetadata.IntellisenseLoadTime = timeToCodeWorkspaceTimer.ElapsedMilliseconds;
ttcMetadata.CorrectedDuration += timeToCodeWorkspaceTimer.ElapsedMilliseconds;

Counters.TimeToIntellisense.Inc ("IntellisenseLoaded", ttcMetadata);
}


static Stopwatch timeToCodeSolutionTimer = new Stopwatch ();
static Stopwatch timeToCodeWorkspaceTimer = null;
internal static bool StartTimeToCodeLoadTimer ()
{
if (ttcStopwatch.ElapsedTicks - startupCompletedTicks > ttcDuration) {
LoggingService.LogDebug ($"Not starting TTC timer: {ttcStopwatch.ElapsedTicks - startupCompletedTicks}");
return false;
}
LoggingService.LogDebug ("Starting TTC timer");
timeToCodeSolutionTimer.Start ();

return true;
}

//this method is MIT/X11, 2009, Michael Hutchinson / (c) Novell
public static void OpenFiles (IEnumerable<FileOpenInformation> files)
{
Expand Down
124 changes: 20 additions & 104 deletions main/src/core/MonoDevelop.Ide/MonoDevelop.Ide/IdeStartup.cs
View file
Expand Up @@ -68,10 +68,6 @@ public class IdeStartup: IApplication
bool initialized;
static StartupInfo startupInfo;
static readonly int ipcBasePort = 40000;
static Stopwatch startupTimer = new Stopwatch ();
static Stopwatch startupSectionTimer = new Stopwatch ();
static Stopwatch timeToCodeTimer = new Stopwatch ();
static Dictionary<string, long> sectionTimings = new Dictionary<string, long> ();
static bool hideWelcomePage;

static TimeToCodeMetadata ttcMetadata;
Expand All @@ -92,12 +88,10 @@ int Run (MonoDevelopOptions options)

//ensure native libs initialized before we hit anything that p/invokes
Platform.Initialize ();
sectionTimings ["PlatformInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("PlatformInitialization");

GettextCatalog.Initialize ();
sectionTimings ["GettextInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("GettextInitialization");

LoggingService.LogInfo ("Operating System: {0}", SystemInformation.GetOperatingSystemDescription ());

Expand Down Expand Up @@ -142,8 +136,7 @@ int Run (MonoDevelopOptions options)
var args = options.RemainingArgs.ToArray ();
IdeTheme.InitializeGtk (BrandingService.ApplicationName, ref args);

sectionTimings["GtkInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("GtkInitialization");
LoggingService.LogInfo ("Using GTK+ {0}", IdeVersionInfo.GetGtkVersion ());

// XWT initialization
Expand All @@ -154,8 +147,7 @@ int Run (MonoDevelopOptions options)
Xwt.Toolkit.CurrentEngine.RegisterBackend<IExtendedTitleBarDialogBackend,GtkExtendedTitleBarDialogBackend> ();
IdeTheme.SetupXwtTheme ();

sectionTimings["XwtInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("XwtInitialization");

//default to Windows IME on Windows
if (Platform.IsWindows && GtkWorkarounds.GtkMinorVersion >= 16) {
Expand All @@ -174,14 +166,12 @@ int Run (MonoDevelopOptions options)
SynchronizationContext.SetSynchronizationContext (DispatchService.SynchronizationContext);
Runtime.MainSynchronizationContext = SynchronizationContext.Current;

sectionTimings["DispatchInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("DispatchInitialization");

// Initialize Roslyn's synchronization context
RoslynServices.RoslynService.Initialize ();

sectionTimings["RoslynInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("RoslynInitialization");

AddinManager.AddinLoadError += OnAddinError;

Expand All @@ -203,8 +193,7 @@ int Run (MonoDevelopOptions options)
Counters.Initialization.Trace ("Initializing Runtime");
Runtime.Initialize (true);

sectionTimings ["RuntimeInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("RuntimeInitialization");

bool restartRequested = PropertyService.Get ("MonoDevelop.Core.RestartRequested", false);
startupInfo.Restarted = restartRequested;
Expand All @@ -216,8 +205,7 @@ int Run (MonoDevelopOptions options)

IdeTheme.SetupGtkTheme ();

sectionTimings["ThemeInitialized"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("ThemeInitialized");

ProgressMonitor monitor = new MonoDevelop.Core.ProgressMonitoring.ConsoleProgressMonitor ();

Expand All @@ -227,8 +215,7 @@ int Run (MonoDevelopOptions options)
Counters.Initialization.Trace ("Initializing Platform Service");
DesktopService.Initialize ();

sectionTimings["PlatformInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("PlatformInitialization");

monitor.Step (1);

Expand Down Expand Up @@ -262,8 +249,7 @@ int Run (MonoDevelopOptions options)

CheckFileWatcher ();

sectionTimings["FileWatcherInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("FileWatcherInitialization");

Exception error = null;
int reportedFailures = 0;
Expand All @@ -273,8 +259,7 @@ int Run (MonoDevelopOptions options)
//force initialisation before the workbench so that it can register stock icons for GTK before they get requested
ImageService.Initialize ();

sectionTimings ["ImageInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("ImageInitialization");

// If we display an error dialog before the main workbench window on OS X then a second application menu is created
// which is then replaced with a second empty Apple menu.
Expand All @@ -283,8 +268,7 @@ int Run (MonoDevelopOptions options)

hideWelcomePage = options.NoStartWindow || startupInfo.HasFiles || IdeApp.Preferences.StartupBehaviour.Value != OnStartupBehaviour.ShowStartWindow;
IdeApp.Initialize (monitor, hideWelcomePage);
sectionTimings ["AppInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("AppInitialization");

if (errorsList.Count > 0) {
using (AddinLoadErrorDialog dlg = new AddinLoadErrorDialog (errorsList.ToArray (), false)) {
Expand Down Expand Up @@ -339,8 +323,7 @@ int Run (MonoDevelopOptions options)
errorsList = null;
AddinManager.AddinLoadError -= OnAddinError;

sectionTimings["BasicInitializationCompleted"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("BasicInitializationCompleted");

// FIXME: we should probably track the last 'selected' one
// and do this more cleanly
Expand All @@ -352,15 +335,13 @@ int Run (MonoDevelopOptions options)
// Socket already in use
}

sectionTimings["SocketInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("SocketInitialization");

initialized = true;
MessageService.RootWindow = IdeApp.Workbench.RootWindow;
Xwt.MessageDialog.RootWindow = Xwt.Toolkit.CurrentEngine.WrapWindow (IdeApp.Workbench.RootWindow);

sectionTimings["WindowOpened"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("WindowOpened");

Thread.CurrentThread.Name = "GUI Thread";
Counters.Initialization.Trace ("Running IdeApp");
Expand All @@ -375,11 +356,8 @@ int Run (MonoDevelopOptions options)
// we show the main window.
DispatchService.RunPendingEvents ();

sectionTimings ["PumpEventLoop"] = startupSectionTimer.ElapsedMilliseconds;
startupTimer.Stop ();
startupSectionTimer.Stop ();

CreateStartupMetadata (startupInfo, sectionTimings);
IdeStartupTracker.StartupTracker.MarkSection ("PumpEventLoop");
IdeStartupTracker.StartupTracker.Stop (startupInfo);

GLib.Idle.Add (OnIdle);
IdeApp.Run ();
Expand Down Expand Up @@ -455,19 +433,6 @@ static bool OnIdle ()
return false;
}

void CreateStartupMetadata (StartupInfo si, Dictionary<string, long> timings)
{
var result = DesktopService.PlatformTelemetry;
if (result == null) {
return;
}

var startupMetadata = GetStartupMetadata (si, result, timings);
Counters.Startup.Inc (startupMetadata);

IdeApp.OnStartupCompleted (startupMetadata, timeToCodeTimer);
}

static DateTime lastIdle;
static bool lockupCheckRunning = true;

Expand Down Expand Up @@ -745,13 +710,8 @@ static int HashSdbmBounded (string input)

public static int Main (string[] args, IdeCustomizer customizer = null)
{
// Using a Stopwatch instead of a TimerCounter since calling
// TimerCounter.BeginTiming here would occur before any timer
// handlers can be registered. So instead the startup duration is
// set as a metadata property on the Counters.Startup counter.
startupTimer.Start ();
startupSectionTimer.Start ();
timeToCodeTimer.Start ();

IdeStartupTracker.StartupTracker.Start ();

var options = MonoDevelopOptions.Parse (args);
if (options.ShowHelp || options.Error != null)
Expand All @@ -776,8 +736,7 @@ public static int Main (string[] args, IdeCustomizer customizer = null)
exename = exename.ToLower ();
Runtime.SetProcessName (exename);

sectionTimings ["mainInitialization"] = startupSectionTimer.ElapsedMilliseconds;
startupSectionTimer.Restart ();
IdeStartupTracker.StartupTracker.MarkSection ("mainInitialization");

var app = new IdeStartup ();
ret = app.Run (options);
Expand Down Expand Up @@ -821,49 +780,6 @@ static IdeCustomizer LoadBrandingCustomizer ()
return null;
}

enum StartupType
{
Normal = 0x0,
ConfigurationChange = 0x1,
FirstLaunch = 0x2,
DebuggerPresent = 0x10,
CommandExecuted = 0x20,
LaunchedAsDebugger = 0x40,
FirstLaunchSetup = 0x80,

// Monodevelop specific
FirstLaunchAfterUpgrade = 0x10000
}

static StartupMetadata GetStartupMetadata (StartupInfo startupInfo, IPlatformTelemetryDetails platformDetails, Dictionary<string, long> timings)
{
var assetType = StartupAssetType.FromStartupInfo (startupInfo);
StartupType startupType = StartupType.Normal;

if (startupInfo.Restarted && !IdeApp.IsInitialRunAfterUpgrade) {
startupType = StartupType.ConfigurationChange; // Assume a restart without upgrading was the result of a config change
} else if (IdeApp.IsInitialRun) {
startupType = StartupType.FirstLaunch;
} else if (IdeApp.IsInitialRunAfterUpgrade) {
startupType = StartupType.FirstLaunchAfterUpgrade;
} else if (Debugger.IsAttached) {
startupType = StartupType.DebuggerPresent;
}

return new StartupMetadata {
CorrectedStartupTime = startupTimer.ElapsedMilliseconds,
StartupType = Convert.ToInt32 (startupType),
AssetTypeId = assetType.Id,
AssetTypeName = assetType.Name,
IsInitialRun = IdeApp.IsInitialRun,
IsInitialRunAfterUpgrade = IdeApp.IsInitialRunAfterUpgrade,
TimeSinceMachineStart = (long)platformDetails.TimeSinceMachineStart.TotalMilliseconds,
TimeSinceLogin = (long)platformDetails.TimeSinceLogin.TotalMilliseconds,
Timings = timings,
StartupBehaviour = IdeApp.Preferences.StartupBehaviour.Value
};
}

internal static OpenWorkspaceItemMetadata GetOpenWorkspaceOnStartupMetadata ()
{
var metadata = new OpenWorkspaceItemMetadata {
Expand Down

0 comments on commit 8f8af65

Please sign in to comment.