Where Does the Test Spend Its Time?

No one likes slow tests. But before we can make a test faster, we need to understand where the test actually spends its time. In this blog post I will show how to report the total test duration and time per individual Cypress command.

Note: you can find the test source code shown in this blog post in the speed-spec.js file inside the recipe "Vue + Vuex + REST Testing" in our cypress-example-recipes repository.

The Test

Let's write a test that exercises a Todo application. We will visit the application's page, enter several todo items, then delete one of them. The test might look like this:

describe('speed', () => {
  it('loads the app', () => {
    // reset the backend data
    cy.request({
      method: 'POST',
      url: '/reset',
      body: {
        todos: [],
      },
    })

    // load the application
    cy.visit('/')
    cy.get('.todoapp').should('be.visible')

    // add several todo items
    cy.get('.new-todo')
    .type('learn testing{enter}')
    .type('be cool{enter}')

    cy.get('.todo-list li')
    .should('have.length', 2)

    // delete one item and confirm it was deleted
    cy.server()
    cy.route('DELETE', '/todos/*').as('delete')
    cy.contains('.todo-list li', 'be cool').find('.destroy').click({ force: true })
    cy.wait('@delete')

    cy.get('.todo-list li')
    .should('have.length', 1)
  })
})

This test finishes quickly - the Test Runner GUI reports about 0.74 seconds to run this test.

Can we see a more precise measurement? Yes - Cypress keeps track of the test duration and you can get the precise number by listening to `test:after:run` event.

Cypress.on('test:after:run', (attributes) => {
  /* eslint-disable no-console */
  console.log('Test "%s" has finished in %dms', 
    attributes.title, attributes.duration)
})
// the test suite

We run the test again with DevTools open to see a precise test duration of 814ms. The GUI shows 0.84s because there is overhead to process the event you just added.

Tip: look at the recipe "CSV load and table test" where we use this test duration measurement to find the fastest way to check the table's contents.

The Commands

Where does the test spend its time? There are multiple commands inside the test - is there a slow one? Can we measure and report the duration of an individual Cypress command?

Yes - and again we can use the events emitted by the Test Runner.  Here is the code:

let commands = []

Cypress.on('test:after:run', (attributes) => {
  /* eslint-disable no-console */
  console.log('Test "%s" has finished in %dms', 
    attributes.title, attributes.duration)
  console.table(commands)
  commands.length = 0
})

Cypress.on('command:start', (c) => {
  commands.push({
    name: c.attributes.name,
    started: +new Date(),
  })
})

Cypress.on('command:end', (c) => {
  const lastCommand = commands[commands.length - 1]

  if (lastCommand.name !== c.attributes.name) {
    throw new Error('Last command is wrong')
  }

  lastCommand.endedAt = +new Date()
  lastCommand.elapsed = lastCommand.endedAt - lastCommand.started
})

// the test suite

When a command starts, we save the timestamp. When a command ends, we save the end timestamp and compute the command's duration. When the test finishes, we use console.table to print the results.

Let's look at the results. Visiting the local site takes 155ms - which is a lot, but that is what end-to-end tests must do, right? But then, there are a couple of surprises - 3 commands that are the real turtles: cy.type (twice) and cy.click (to remove the todo item)

Taken together these commands take 344 + 175 + 62 = 581ms, about 70% of the test's total time! These commands are slow ... because they involve communication with the server. Notice the (XHR) messages in the Command Log under each command. Cypress Test Runner "notices" the network communication and DOM change immediately after each command and keeps a running "watch" before closing the command. This is how Cypress can show you the DOM snapshots before and after the command.

The Network

We can make these commands faster by stubbing the XHR communication. Note that there is a 4th XHR call - to load the initial list of Todos on application's load.

it('stubs the network calls', () => {
  // if we stub all network calls,
  // there is no need to reset the backend data

  // stub all network calls
  cy.server()
  // initially return an empty list of todos
  cy.route('GET', '/todos', [])
  cy.route('POST', '/todos', {})
  cy.route('DELETE', '/todos/*', {}).as('delete')

  // load the application
  cy.visit('/')
  cy.get('.todoapp').should('be.visible')

  // add several todo items
  cy.get('.new-todo')
  .type('learn testing{enter}')
  .type('be cool{enter}')

  cy.get('.todo-list li')
  .should('have.length', 2)

  // delete one item and confirm it was deleted
  cy.contains('.todo-list li', 'be cool').find('.destroy').click({ force: true })
  cy.wait('@delete')

  cy.get('.todo-list li')
  .should('have.length', 1)
})

The test above will never make a REST API call - we have stubbed the initial load, posting new items and deleting them. Let's see how the test flies now.

The test runs ... the same. This is surprising, because we assumed ... and that is the dangerous part. Never optimize anything without measuring it first, otherwise you might be chasing the wrong thing down the blind alley.

The Typing

There is one thing in the command durations that kind of stands out to me. The command cy.type('learn testing') takes about 320ms to execute, while the command cy.type('be cool') takes about half of that - 180ms. Is it a coincidence that learn testing has 13 characters and be cool has about half of that - 7 characters?

Yes - the length of the text matters when typing because Cypress sends an event for each letter. In fact it sends several events for each letter: keydown, keypress, textInput, input, and keyup. You can see those events by clicking on the "TYPE" in the Command Log and expanding the Keyboard Events table.

The more events Cypress sends, the longer the command takes. Let's shorten our test strings. I will also remove our network stubs - if they do not help with the speed, we might as well exercise the full stack.

We did cut the total time per cy.type command. But the second type command is still half the duration of the first type command. Again, let's go to the DevTools console and click on the first type command. Notice it has a mouse events table before the keyboard events table.

The second type command only has the keyboard events. As described in our `cy.type` documentation, before typing, Cypress checks if the element has focus, and if not sets the focus on the element. The extra time spent on the first type is due to the focus! We can make both commands run the same by sending the blur event in between them.

cy.get('.new-todo')
  .type('a{enter}')
  // force the next type to set focus again
  .blur()

cy.get('.new-todo')
  .type('b{enter}')

The Fixture

Now that we understand where the test is spending time and why, let's step back and rethink the big picture. What are we trying to confirm using this test? If this is the only test in our application, then it goes through the basic features of our application (loading the page, adding and deleting items), and in my opinion the test is fast enough.

However, if there are other tests already, then they probably already cover adding items and our test does not need to actually use cy.type to be able to test deleting an item.

Tip: using code coverage is a great way to see what the existing tests already cover.

Let's say that our test is focused on deleting todo items feature. Then we can set our data using a fixture file - and go directly to deleting an item.

it('deletes an item', () => {
  // reset the backend data using a fixture file
  cy.fixture('todos').then((todos) => {
    cy.request({
      method: 'POST',
      url: '/reset',
      body: {
        todos,
      },
    })
  })

  // spy on the application's XHR calls
  cy.server()
  cy.route('DELETE', '/todos/*').as('delete')

  // load the application
  cy.visit('/')
  cy.get('.todoapp').should('be.visible')

  cy.get('.todo-list li')
  .should('have.length', 2)

  // delete one item and confirm it was deleted
  cy.contains('.todo-list li', 'mock second')
    .find('.destroy').click({ force: true })
  cy.wait('@delete')

  cy.get('.todo-list li')
  .should('have.length', 1)
})

Perfect, the end-to-end test is fast and focused.

The Cypress Run

We have printed the test duration and command timings in the interactive cypress open mode. Let's print these numbers in the terminal so we can see them when using cypress run.

We need to collect all timing information in one place. Let's refactor our code a little bit and store test title, duration and commands in a single variable testAttributes.

let commands = []
let testAttributes

Cypress.on('test:before:run', () => {
  commands.length = 0
})

Cypress.on('test:after:run', (attributes) => {
  /* eslint-disable no-console */
  console.log('Test "%s" has finished in %dms', 
    attributes.title, attributes.duration)
  console.table(commands)
  testAttributes = {
    title: attributes.title,
    duration: attributes.duration,
    commands: Cypress._.cloneDeep(commands),
  }
})
```

Our test runs in the browser and we want to print testAttributes in the terminal - thus we will need to use cy.task command to send this object from the browser process to the background process that runs in Node. We cannot run an asynchronous command from the test:after:run event hook, thus we will use separate "normal" Mocha hooks for that.

// sends test results to the plugins process
// using cy.task https://on.cypress.io/task
const sendTestTimings = () => {
  if (!testAttributes) {
    return
  }

  const attr = testAttributes
  testAttributes = null
  cy.task('testTimings', attr)
}

beforeEach(sendTestTimings)

after(sendTestTimings)

The combination of beforeEach and after ensures that the results of every time is sent "down" to the Node process. In cypress/plugins/index.js we can define a new task and print the table with results.

module.exports = (on, config) => {
  on('task', {
    testTimings (attributes) {
      console.log('Test "%s" has finished in %dms', 
        attributes.title, attributes.duration)
      console.table(attributes.commands)

      return null
    },
  })
}

When the tests run, after each one you will see the timings

Perfect.

Happy (and fast) testing!