Instrument with open tracing (#6347)

* add tracing of bootstrap phase * Added tracing of plugin and API calls * added opentracing-zipkin * remove commented tags * add tracing to actions to be propogated to onCreateNode * added cli option for open tracing config file * remove console log * use api-runner instance to store parentSpan * added build phase tracing * finish build-node-types span * added tracer util * added stop tracer functionality * added docs on how to use tracing * doc fixes * remove custom tracing section * remove activity boolean tag * general cleanup before PR * address linter issues * fixed failing test cases including jest update * added tracing image example * npm run format * merge tracerStop ifs into &&
gatsbyjs · Jul 11, 2018 · d863bcb · d863bcb
1 parent 554d8ec
commit d863bcb
Show file tree

Hide file tree

Showing 20 changed files with 429 additions and 90 deletions.
diff --git a/docs/docs/images/zipkin-trace.png b/docs/docs/images/zipkin-trace.png
diff --git a/docs/docs/performance-tracing.md b/docs/docs/performance-tracing.md
@@ -0,0 +1,54 @@
+---
+title: "Performance tracing"
+---
+
+Gatsby allows a build to be traced, enabling you to find which plugins or parts of the build are taking the longest. The trace information can be viewed in any [open tracing](http://opentracing.io/) compatible tool such as [https://www.jaegertracing.io/](https://www.jaegertracing.io/). You can also use Zipkin compatible tools such as [Zipkin](https://zipkin.io/) or [Honeycomb](https://www.honeycomb.io/).
+
+![Example Zipkin Trace](./images/zipkin-trace.png)
+
+## Running Gatsby with tracing turned on
+
+Gatsby code is instrumented with Open Tracing, which is a general tracing API that is implementation agnostic. Therefore, you'll need to include and configure an open tracing compatible library in your application, as well as a backend to collect the trace data.
+
+The steps required to add tracing are below. Including an [example](/docs/performance-tracing/#local-zipkin-with-docker) of how to get tracing working with zipkin locally using docker
+
+### 1. Library dependency
+
+Add an [open-tracing compatible library](https://github.com/opentracing) to your site's `package.json` dependencies.
+
+### 2. Library configuration file
+
+Each open tracing library must be configured. For example, what is the URL of the tracing backend? How often should spans be sent to the backend? What service name should the trace be recorded under? Etc.
+
+The configuration file is a javascript file that exports two functions. `create` and `stop`
+
+- **create**: Create and return an [open tracing compatible Tracer](https://github.com/opentracing/opentracing-javascript/blob/master/src/tracer.ts). It is called at the start of the build
+- **stop**: Called at the end of the build. Any cleanup required by the tracer should be performed here. Such as clearing out any span queues and sending them to the tracing backend.
+
+### 3. Start Gatsby with tracing turned on
+
+The above configuration file can be passed to Gatsby with the `--open-tracing-config-file` command-line option. When Gatsby is started with this option, it will load the supplied tracing configuration file, and call its `create` function. The returned Tracer will be used for tracing the build. Once the build has stopped, the configuration file's `stop` method will be called, allowing the tracing implementation to perform any cleanup.
+
+## Tracing backend examples
+
+There are many open tracing compatible backends available. Below is an example of how to hook zipkin into Gatsby
+
+### local Zipkin with Docker
+
+[Zipkin](https://zipkin.io/) is an open source Tracing system that can be run locally using docker.
+
+1.  Add following dependencies to your site's `package.json`
+
+    - [zipkin](https://www.npmjs.com/package/zipkin)
+    - [zipkin-javascript-opentracing](https://www.npmjs.com/package/zipkin-javascript-opentracing)
+    - [zipkin-transport-http](https://www.npmjs.com/package/zipkin-transport-http)
+
+2.  Run Zipkin all-in-one docker instance with `docker run -d -p 9411:9411 openzipkin/zipkin`. See [Zipkin Getting Started](https://zipkin.io/pages/quickstart.html) for more information.
+
+3.  Start Gatsby `build` or `develop` with `--open-tracing-config-file` pointing at the Zipkin configuration file. An example file is provided in the gatsby project under `node_modules/gatsby/dist/utils/tracer/zipkin-local.js` that will send tracing spans to your local docker instance. E.g
+
+    ```
+    gatsby build --open-tracing-config-file node_modules/gatsby/dist/utils/tracer/zipkin-local.js
+    ```
+
+4.  Once the build is complete, view your tracing information at [http://localhost:9411](http://localhost:9411)
diff --git a/packages/gatsby-cli/src/create-cli.js b/packages/gatsby-cli/src/create-cli.js
@@ -116,6 +116,10 @@ function buildLocalCommands(cli, isLocalSite) {
           type: `string`,
           default: ``,
           describe: `Custom HTTPS key file (relative path; also required: --https, --cert-file). See https://www.gatsbyjs.org/docs/local-https/`,
+        })
+        .option(`open-tracing-config-file`, {
+          type: `string`,
+          describe: `Tracer configuration file (open tracing compatible). See https://www.gatsbyjs.org/docs/performance-tracing/`,
         }),
     handler: handlerP(
       getCommandHandler(`develop`, (args, cmd) => {
@@ -137,11 +141,16 @@ function buildLocalCommands(cli, isLocalSite) {
         type: `boolean`,
         default: false,
         describe: `Build site with link paths prefixed (set prefix in your config).`,
-      }).option(`no-uglify`, {
-        type: `boolean`,
-        default: false,
-        describe: `Build site without uglifying JS bundles (for debugging).`,
-      }),
+      })
+        .option(`no-uglify`, {
+          type: `boolean`,
+          default: false,
+          describe: `Build site without uglifying JS bundles (for debugging).`,
+        })
+        .option(`open-tracing-config-file`, {
+          type: `string`,
+          describe: `Tracer configuration file (open tracing compatible). See https://www.gatsbyjs.org/docs/performance-tracing/`,
+        }),
     handler: handlerP(
       getCommandHandler(`build`, (args, cmd) => {
         process.env.NODE_ENV = `production`

diff --git a/packages/gatsby-cli/src/reporter/index.js b/packages/gatsby-cli/src/reporter/index.js
@@ -3,6 +3,7 @@
 const { createReporter } = require(`yurnalist`)
 const { stripIndent } = require(`common-tags`)
 const convertHrtime = require(`convert-hrtime`)
+const tracer = require(`opentracing`).globalTracer()
 const { getErrorFormatter } = require(`./errors`)
 
 const VERBOSE = process.env.gatsby_log_level === `verbose`
@@ -11,6 +12,10 @@ const errorFormatter = getErrorFormatter()
 const reporter = createReporter({ emoji: true, verbose: VERBOSE })
 const base = Object.getPrototypeOf(reporter)
 
+type ActivityArgs = {
+  parentSpan: Object,
+}
+
 /* Reporter module.
  * @module reporter
  */
@@ -70,9 +75,10 @@ module.exports = Object.assign(reporter, {
   /**
    * Time an activity.
    * @param {string} name - Name of activity.
+   * @param {activityArgs} activityArgs - optional object with tracer parentSpan
    * @returns {string} The elapsed time of activity.
    */
-  activityTimer(name) {
+  activityTimer(name, activityArgs: ActivityArgs = {}) {
     const spinner = reporter.activity()
     const start = process.hrtime()
     let status
@@ -82,6 +88,10 @@ module.exports = Object.assign(reporter, {
       return `${convertHrtime(elapsed)[`seconds`].toFixed(3)} s`
     }
 
+    const { parentSpan } = activityArgs
+    const spanArgs = parentSpan ? { childOf: parentSpan } : {}
+    const span = tracer.startSpan(name, spanArgs)
+
     return {
       start: () => {
         spinner.tick(name)
@@ -91,12 +101,14 @@ module.exports = Object.assign(reporter, {
         spinner.tick(`${name} — ${status}`)
       },
       end: () => {
+        span.finish()
         const str = status
           ? `${name} — ${elapsedTime()} — ${status}`
           : `${name} — ${elapsedTime()}`
         reporter.success(str)
         spinner.end()
       },
+      span: span,
     }
   },
 })
diff --git a/packages/gatsby/package.json b/packages/gatsby/package.json
@@ -94,6 +94,7 @@
     "node-libs-browser": "^2.0.0",
     "normalize-path": "^2.1.1",
     "null-loader": "^0.1.1",
+    "opentracing": "^0.14.3",
     "opn": "^5.3.0",
     "parse-filepath": "^1.0.1",
     "path-exists": "^3.0.0",

diff --git a/packages/gatsby/src/bootstrap/index.js b/packages/gatsby/src/bootstrap/index.js
@@ -16,6 +16,7 @@ const loadPlugins = require(`./load-plugins`)
 const { initCache } = require(`../utils/cache`)
 const report = require(`gatsby-cli/lib/reporter`)
 const getConfigFile = require(`./get-config-file`)
+const tracer = require(`opentracing`).globalTracer()
 
 // Show stack trace on unhandled promises.
 process.on(`unhandledRejection`, (reason, p) => {
@@ -44,9 +45,13 @@ const preferDefault = m => (m && m.default) || m
 type BootstrapArgs = {
   directory: string,
   prefixPaths?: boolean,
+  parentSpan: Object,
 }
 
 module.exports = async (args: BootstrapArgs) => {
+  const spanArgs = args.parentSpan ? { childOf: args.parentSpan } : {}
+  const bootstrapSpan = tracer.startSpan(`bootstrap`, spanArgs)
+
   const program = {
     ...args,
     // Fix program directory path for windows env.
@@ -59,7 +64,9 @@ module.exports = async (args: BootstrapArgs) => {
   })
 
   // Try opening the site's gatsby-config.js file.
-  let activity = report.activityTimer(`open and validate gatsby-config`)
+  let activity = report.activityTimer(`open and validate gatsby-config`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   const config = await preferDefault(
     getConfigFile(program.directory, `gatsby-config`)
@@ -84,15 +91,20 @@ module.exports = async (args: BootstrapArgs) => {
   activity.end()
 
   // onPreInit
-  activity = report.activityTimer(`onPreInit`)
+  activity = report.activityTimer(`onPreInit`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
-  await apiRunnerNode(`onPreInit`)
+  await apiRunnerNode(`onPreInit`, { parentSpan: activity.span })
   activity.end()
 
   // Delete html and css files from the public directory as we don't want
   // deleted pages and styles from previous builds to stick around.
   activity = report.activityTimer(
-    `delete html and css files from previous builds`
+    `delete html and css files from previous builds`,
+    {
+      parentSpan: bootstrapSpan,
+    }
   )
   activity.start()
   await del([
@@ -176,7 +188,9 @@ module.exports = async (args: BootstrapArgs) => {
   activity.end()
 
   // Copy our site files to the root of the site.
-  activity = report.activityTimer(`copy gatsby files`)
+  activity = report.activityTimer(`copy gatsby files`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   const srcDir = `${__dirname}/../../cache-dir`
   const siteDir = `${program.directory}/.cache`
@@ -281,15 +295,19 @@ module.exports = async (args: BootstrapArgs) => {
   activity.end()
 
   // Source nodes
-  activity = report.activityTimer(`source and transform nodes`)
+  activity = report.activityTimer(`source and transform nodes`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
-  await require(`../utils/source-nodes`)()
+  await require(`../utils/source-nodes`)({ parentSpan: activity.span })
   activity.end()
 
   // Create Schema.
-  activity = report.activityTimer(`building schema`)
+  activity = report.activityTimer(`building schema`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
-  await require(`../schema`)()
+  await require(`../schema`)({ parentSpan: activity.span })
   activity.end()
 
   // Collect resolvable extensions and attach to program.
@@ -298,6 +316,7 @@ module.exports = async (args: BootstrapArgs) => {
   // for adding extensions.
   const apiResults = await apiRunnerNode(`resolvableExtensions`, {
     traceId: `initial-resolvableExtensions`,
+    parentSpan: bootstrapSpan,
   })
 
   store.dispatch({
@@ -311,43 +330,55 @@ module.exports = async (args: BootstrapArgs) => {
   }
 
   // Collect pages.
-  activity = report.activityTimer(`createPages`)
+  activity = report.activityTimer(`createPages`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   await apiRunnerNode(`createPages`, {
     graphql: graphqlRunner,
     traceId: `initial-createPages`,
     waitForCascadingActions: true,
+    parentSpan: activity.span,
   })
   activity.end()
 
   // A variant on createPages for plugins that want to
   // have full control over adding/removing pages. The normal
   // "createPages" API is called every time (during development)
   // that data changes.
-  activity = report.activityTimer(`createPagesStatefully`)
+  activity = report.activityTimer(`createPagesStatefully`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   await apiRunnerNode(`createPagesStatefully`, {
     graphql: graphqlRunner,
     traceId: `initial-createPagesStatefully`,
     waitForCascadingActions: true,
+    parentSpan: activity.span,
   })
   activity.end()
 
-  activity = report.activityTimer(`onPreExtractQueries`)
+  activity = report.activityTimer(`onPreExtractQueries`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
-  await apiRunnerNode(`onPreExtractQueries`)
+  await apiRunnerNode(`onPreExtractQueries`, { parentSpan: activity.span })
   activity.end()
 
   // Update Schema for SitePage.
-  activity = report.activityTimer(`update schema`)
+  activity = report.activityTimer(`update schema`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
-  await require(`../schema`)()
+  await require(`../schema`)({ parentSpan: activity.span })
   activity.end()
 
   require(`../schema/type-conflict-reporter`).printConflicts()
 
   // Extract queries
-  activity = report.activityTimer(`extract queries from components`)
+  activity = report.activityTimer(`extract queries from components`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   await extractQueries()
   activity.end()
@@ -358,7 +389,9 @@ module.exports = async (args: BootstrapArgs) => {
   }
 
   // Run queries
-  activity = report.activityTimer(`run graphql queries`)
+  activity = report.activityTimer(`run graphql queries`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   const startQueries = process.hrtime()
   queryQueue.on(`task_finish`, () => {
@@ -373,7 +406,9 @@ module.exports = async (args: BootstrapArgs) => {
   activity.end()
 
   // Write out files.
-  activity = report.activityTimer(`write out page data`)
+  activity = report.activityTimer(`write out page data`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   try {
     await writePages()
@@ -383,7 +418,9 @@ module.exports = async (args: BootstrapArgs) => {
   activity.end()
 
   // Write out redirects.
-  activity = report.activityTimer(`write out redirect data`)
+  activity = report.activityTimer(`write out redirect data`, {
+    parentSpan: bootstrapSpan,
+  })
   activity.start()
   await writeRedirects()
   activity.end()
@@ -396,24 +433,31 @@ module.exports = async (args: BootstrapArgs) => {
       report.log(``)
 
       // onPostBootstrap
-      activity = report.activityTimer(`onPostBootstrap`)
-      activity.start()
-      apiRunnerNode(`onPostBootstrap`).then(() => {
-        activity.end()
-        resolve({
-          graphqlRunner,
-        })
+      activity = report.activityTimer(`onPostBootstrap`, {
+        parentSpan: bootstrapSpan,
       })
+      activity.start()
+      apiRunnerNode(`onPostBootstrap`, { parentSpan: activity.span }).then(
+        () => {
+          activity.end()
+          bootstrapSpan.finish()
+          resolve({ graphqlRunner })
+        }
+      )
     }
   }, 100)
 
   if (store.getState().jobs.active.length === 0) {
     // onPostBootstrap
-    activity = report.activityTimer(`onPostBootstrap`)
+    activity = report.activityTimer(`onPostBootstrap`, {
+      parentSpan: bootstrapSpan,
+    })
     activity.start()
-    await apiRunnerNode(`onPostBootstrap`)
+    await apiRunnerNode(`onPostBootstrap`, { parentSpan: activity.span })
     activity.end()
 
+    bootstrapSpan.finish()
+
     report.log(``)
     report.info(`bootstrap finished - ${process.uptime()} s`)
     report.log(``)