Timing Selenium

We finally figured a pain free way of profiling our selenium test suite. It could use some refinement, but we were only looking for a quick win.

Add the following test to the start of your suite

open|/|
storeEval|{lastTime = new Date().getTime(); 'x'}|x
storeEval|{LOG.info = function(message) { var now = new Date().getTime(); var duration = now - lastTime; this.warn(message + duration); lastTime = now}; 'x';}|x

When your run your suite the log file file contain lines like...


warn: Starting test /selenium-server/tests/suite-tests/conversation/SearchConversationTest.html119
warn: Executing: |open | /fixture/tearDownTestData | |47
warn: Executing: |assertTitle | Fixture | |239
warn: Executing: |invokeUrl | /fixture/reindexSearch | |28
warn: Executing: |invokeUrl | /fixture/setUpPersons | |121
warn: Executing: |invokeUrl | /fixture/setUpConversationsForSearch | |212
warn: Executing: |createCookie | splash=false | path=/ |16638


The duration for each step has been appended to the NEXT log line, i.e. setUpConversationsForSearch took 16638ms
The next step is to parse this file into something readable. We wrote a groovy script (see below), which generates output like:


===SELENIUM TEST TIMINGS===
69763=HomepageTest
54106=SubscribeToTribeConversationTest
50902=SubscribeToTagTest
48734=TagDedupingTest
44614=SubscribeToPrivateConversationTest

===INDIVIDUAL COMMAND TIMINGS===
153127=loginAndWait hits=291 avg=526.2096219931
103428=open /person/ hits=241 avg=429.1618257261
90431=open /logout hits=224 avg=403.7098214286
70059=invokeUrl /fixture/setUpConversationsForSearch hits=4 avg=17514.75
61926=open /login hits=246 avg=251.7317073171
61851=open / hits=133 avg=465.045112782
61034=createMessageAndWait hits=114 avg=535.3859649123


So now it's trivial to identify slow running tests / test steps when optimising our build. It's also useful to spot slow loading pages.


Here's the groovy script, it's tailored to our environment but a good starting point.

import org.codehaus.groovy.tools.LoaderConfiguration
import org.codehaus.groovy.tools.RootLoader
import org.codehaus.groovy.grails.commons.cfg.ConfigurationHelper
import org.codehaus.groovy.grails.commons.ConfigurationHolder
import groovy.text.GStringTemplateEngine
import org.apache.commons.lang.StringUtils

Ant.property(environment:'env')
grailsHome = Ant.antProject.properties.'env.GRAILS_HOME'
grailsEnv = System.properties.'grails.env';
pluginDir = this.binding['seleniumPluginDir']

includeTargets <<> timings = []

int nextId = 0
String currentTest = 'anonymous-test'
SeleniumTiming previousTiming
SeleniumTiming currentTiming

class SeleniumTiming {
  String id
  String test
  String command
  String target
  String value
  int duration = 0

  String getTargetKey() {

      def trimmedTarget = target?.trim()
      def trimmedCommand = command?.trim()

      if (trimmedCommand == 'open' && trimmedTarget ==~ '/person/\\w+') {
          return '/person/'
      } else if (trimmedCommand == 'open' && trimmedTarget ==~ '/tag/[\\w-]+') {
          return '/tag/'
      } else if (trimmedCommand == 'open' && trimmedTarget ==~ '/station/[\\w-]+') {
          return '/station/'
      } else if (trimmedCommand == 'open' && trimmedTarget ==~ '/line/[\\w-]+') {
          return '/line/'
      } else if (trimmedCommand == 'open' && trimmedTarget ==~ '/conversation/subscribe?.*') {
          return '/conversation/subscribe'
      } else if (trimmedCommand == 'open' && trimmedTarget ==~ '/conversation/unsubscribe?.*') {
          return '/conversation/unsubscribe'
      } else if (trimmedCommand == 'loginAndWait') {
          return ''
      } else if (trimmedCommand == 'sendMessageAndWait') {
          return ''
      } else if (trimmedCommand == 'createMessageAndWait') {
          return ''
      } else if (trimmedCommand == 'reply') {
          return ''
      } else if (trimmedCommand == 'replyAndWait') {
          return ''
      } else if (trimmedCommand == 'registerAndWait') {
          return ''
      } else if (trimmedCommand == 'reportThisAndWait') {
          return ''
      } else {
          return target
      }
  }

  String toString() {
      "[$test] $command($target,$value):$duration"
  }
}

def parseTestLine = { String input ->
  currentTest = input.substring(input.lastIndexOf(File.separator)+1, input.lastIndexOf('.html'))
}

def parseCommandLine = { String input ->
  List data = input.tokenize('|')
  if(data.size() == 5) {
      previousTiming = currentTiming
      currentTiming = new SeleniumTiming(id:nextId++, test: currentTest, command:data[1],
          target:data[2], value:data[3])
      timings << duration =" Integer.parseInt(data[4])" parsefile =" {">
  input.eachLine { String line ->
      if(line.startsWith('warn: Starting test')) {
          parseTestLine line          
      } else if(line.startsWith('warn: Executing: |')) {
          parseCommandLine line
      }
  }
}

target ('default': 'Generate Selenium Timings Report') {
loadSeleniumConfig seleniumConfig
new File(seleniumConfig.reportdir).eachFileMatch(~/.*\.html/, parseFile)

  def longestFirst = [ compare: { a, b -> a.equals(b) ? 0: Math.abs(a) < overalltimings =" new">
  overallTimings[(values*.duration).sum()] = key
}

  Map commandTimings = new TreeMap(longestFirst)
timings.groupBy({ "${it.command} ${it.targetKey}" }).each { key, values ->
   int totalDuration = (values*.duration).sum()
      int noOfValues = values.size()
      commandTimings[totalDuration] = "$key hits=${noOfValues} avg=${totalDuration / noOfValues}"

}

  new File(seleniumConfig.reportdir, 'timings.txt').withPrintWriter { writer ->
      writer.println '===SELENIUM TEST TIMINGS==='
      overallTimings.each { writer.println it }
      writer.println '===INDIVIDUAL COMMAND TIMINGS==='
      commandTimings.each { writer.println it }
  }
    
  commandTimings.each { println it }

}