Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add markers for more granular logging of startup time #19297

Merged
merged 3 commits into from May 10, 2019

Conversation

Projects
None yet
2 participants
@rafeca
Copy link
Contributor

commented May 9, 2019

Context

Currently we're only logging two measures to give us information about the startup performance of Atom: the shell load time and the core load time.

They have been useful to identify performance regressions so far, but they are not enough to debug potential bottlenecks in Atom startup in real-life conditions.

Summary of changes

This PR aims to give us much more granular data about the startup performance of Atom by doing two things:

  • Allowing us to create arbitrary markers at any point during the startup of Atom which will get logged via the metrics package.
  • Unifying the startup time taken by the main process and the renderer process by allowing to create markers anywhere.

As an example, with this PR these are the markers created during the startup of Atom (the ones happening in the main process are prepended by main-process: and the ones happening in the renderer process start with window:):

{
  "startTime":1557502272939,
  "markers":[
    {
      "label":"main-process:start",
      "time":0
    },
    {
      "label":"main-process:electron-onready:start",
      "time":51
    },
    {
      "label":"main-process:electron-onready:end",
      "time":252
    },
    {
      "label":"main-process:atom-application:open",
      "time":324
    },
    {
      "label":"main-process:atom-application:constructor:start",
      "time":324
    },
    {
      "label":"main-process:atom-application:constructor:end",
      "time":329
    },
    {
      "label":"main-process:atom-application:initialize:start",
      "time":329
    },
    {
      "label":"main-process:atom-application:create-window",
      "time":446
    },
    {
      "label":"main-process:atom-window:start",
      "time":447
    },
    {
      "label":"main-process:atom-window:end",
      "time":463
    },
    {
      "label":"main-process:atom-application:initialize:end",
      "time":480
    },
    {
      "label":"window:start",
      "time":687
    },
    {
      "label":"window:onload:start",
      "time":693
    },
    {
      "label":"window:setup-window:start",
      "time":729
    },
    {
      "label":"window:initialize:start",
      "time":1156
    },
    {
      "label":"window:environment:start-editor-window:start",
      "time":1197
    },
    {
      "label":"window:onload:end",
      "time":1198
    },
    {
      "label":"window:environment:start-editor-window:display-window",
      "time":1206
    },
    {
      "label":"window:environment:start-editor-window:load-packages",
      "time":1445
    },
    {
      "label":"window:environment:start-editor-window:deserialize-state",
      "time":1598
    },
    {
      "label":"window:environment:start-editor-window:activate-packages",
      "time":3222
    },
    {
      "label":"window:environment:start-editor-window:open-editor",
      "time":3862
    },
    {
      "label":"window:environment:start-editor-window:end",
      "time":3893
    },
    {
      "label":"window:initialize:end",
      "time":3894
    },
    {
      "label":"window:setup-window:end",
      "time":3894
    }
  ]
}

Verification steps

  • Check that the markers get correctly created when opening a new Atom window from scratch.
  • Check that markers do not get created under the following conditions:
    • When refreshing the Atom window
    • When opening a new window via Open new WIndow"
    • When opening a new window via Re-open project"
    • When running atom CLI on a different path (which opens a new window).

Next steps

  • Create some automated tests.

@rafeca rafeca requested review from jasonrudolph and nathansobo May 9, 2019

@rafeca

This comment has been minimized.

Copy link
Contributor Author

commented May 9, 2019

For now, I'm keeping the code to log the shell load time and core load time, so we can keep detecting potential regressions until the new metrics get some history.

@rafeca rafeca force-pushed the startup-timing-markers branch from f4ad4fd to b59d6d8 May 10, 2019

@rafeca

This comment has been minimized.

Copy link
Contributor Author

commented May 10, 2019

This has made me realize that the timings that we're currently logging don't give us a very accurate image of the real times that it takes to load Atom.

In the startup example posted on the issue description, I had to wait for ~3-4s from when I launched Atom until some content was display in the Atom window.

This aligns with the new marker measures, but the old logged measures were ~500ms for the shell and 500ms for the window, which is way smaller than the reality.

@nathansobo
Copy link
Contributor

left a comment

This seems really good. I'm a bit worried about the synchronous RPC to the main process to import the startup times into the window. Might be good to just check on its cost.

Also, I wonder how we could include the time to start a secondary Electron when launching an Atom window from the command line when Atom is already running. Could we send timing data from that Electron as well? (This could be in another PR, just bringing it up while we're discussing this stuff)

const entryPointDirPath = __dirname
let blobStore = null
let useSnapshot = false

const startupMarkers = electron.remote.getCurrentWindow().startupMarkers

This comment has been minimized.

Copy link
@nathansobo

nathansobo May 10, 2019

Contributor

Have you profiled the overhead of this? Under the hood it does a synchronous RPC and might cost us a few milliseconds. On the other hand I don't have a great idea for an alternative approach other than finding some async approach to perform the RPC.

This comment has been minimized.

Copy link
@rafeca

rafeca May 10, 2019

Author Contributor

Good point! Just measured it with performance.now() and that call takes 3.2-3.5ms (the time is quite consistent on my machine).

If we consider that this is too much, we can always add some sampling to e.g only log the markers data on 1/10 of the starts.

This comment has been minimized.

Copy link
@nathansobo

nathansobo May 10, 2019

Contributor

That feels like an unfortunate amount of time. Is there any way we can fetch this asynchronously?

This comment has been minimized.

Copy link
@rafeca

rafeca May 10, 2019

Author Contributor

I'm not sure, we're following the same pattern in a few other places (like getting all the loadSettings) so I thought it was ok.

I'm gonna check if I can speed this up somehow... if not we can just sample it

This comment has been minimized.

Copy link
@rafeca

rafeca May 10, 2019

Author Contributor

Ok I took more measures and compared the time this call takes to [the call to load the settings](all the loadSettings](https://github.com/atom/atom/blob/master/src/get-window-load-settings.js#L7), which happens a few lines below this, and turns out that these 3ms may include some bootstrap time for the IPC or something... let me show you the timings:

With this call:

  • getTimingSettings: 3.5ms
  • getWindowLoadSettings: 1.5ms

Removing this call:

  • getWindowLoadSettings: 4ms

So basically, the net time that's added by this call is ~1ms

This comment has been minimized.

Copy link
@nathansobo

nathansobo May 10, 2019

Contributor

Okay, I think it's reasonable to just proceed for now. Measuring this will allow us to attack other aspects and we'll probably get the time back and then some.

@rafeca

This comment has been minimized.

Copy link
Contributor Author

commented May 10, 2019

Also, I wonder how we could include the time to start a secondary Electron when launching an Atom window from the command line when Atom is already running. Could we send timing data from that Electron as well? (This could be in another PR, just bringing it up while we're discussing this stuff)

Yup, we should definitely do that! (in a different PR though 😄 )

@rafeca rafeca merged commit db6031d into master May 10, 2019

2 checks passed

Atom Pull Requests #20190510.10 succeeded
Details
continuous-integration/appveyor/pr AppVeyor build succeeded
Details

@rafeca rafeca referenced this pull request May 10, 2019

Merged

⬆️ metrics@1.7.4 #19305

@rafeca rafeca deleted the startup-timing-markers branch May 10, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.