Build Server Woes (mptscsi task abort)

I'm posting this here for two reasons:

• in the hope that someone out there will find this useful


• personal therapy

Scenario:

We've got a couple of build servers (x86_64 linux, openVZ) that have been having some disk I/O problems. These boxes (boxen) run various virtual machines related to our product builds - hudson masters & slaves, distribution servers, puppet master, test mail server, munin server... yada yada. You get the idea. They're kinda important.

The problem manifests itself by first reporting errors like the following:

Sep 16 14:28:51 hn3 mptscsih: ioc0: attempting task abort! (sc=ffff880422a348c0)
Sep 16 14:28:51 hn3 sd 0:1:2:0: [sda] CDB: cdb[0]=0x2a: 2a 00 12 b2 fc 9f 00 00 08 00
Sep 16 14:28:51 hn3 mptscsih: ioc0: Issue of TaskMgmt failed!

followed shortly by the volume in question getting offlined into readonly mode:

Sep 16 14:29:41 hn3 mptscsih: ioc0: host reset: SUCCESS (sc=ffff880422a348c0)
Sep 16 14:29:41 hn3 sd 0:1:2:0: Device offlined - not ready after error recovery

This ain't that helpful when you've got a whole load of hungry VMs wanting to write stuff to disk. A closer look at the disk controller yields the following:

>lspci
...
0b:00.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1068E PCI-Express Fusion-MPT SAS (rev 08)
...

A quick search through our messages shows the following related information:

>dmesg | grep -i mpt
Fusion MPT base driver 3.04.07
Fusion MPT SPI Host driver 3.04.07
Fusion MPT FC Host driver 3.04.07
Fusion MPT SAS Host driver 3.04.07
mptsas 0000:0b:00.0: PCI INT A -> GSI 35 (level, low) -> IRQ 35
mptbase: ioc0: Initiating bringup
mptbase: ioc0: PCI-MSI enabled
mptsas 0000:0b:00.0: setting latency timer to 64
Fusion MPT misc device (ioctl) driver 3.04.07
mptctl: Registered with Fusion MPT base driver
mptctl: /dev/mptctl @ (major,minor=10,220)

A quick google turns up quite a few different issues with these controllers but no clear resolution (no surprise).

To cut a (very) long story short we appear to have a solution by using the drivers supplied by LSI rather than those shipped with the latest linux kernel. Patching the kernel (by replacing the drivers/message/fusion folder with the equivalent found in LSI's MPTLINUX_RHEL5_SLES10_PH16-4.18.00.00-1.zip distribution) with version 4.18 of the MPT drivers has yielded an (apparently) stable system, tested under reasonably high load (load average ~20).

Incidentally, for those of you who like acronyms, MPT stands for 'Message passing technology'.

My work here is done.

Dynamic UrlMapping using request parameters

Might be old news to some, but I just found you can assign closures to the action and controller values in URL mappings, e.g.

"/update/$controller/$target" {
   action = {
      "update" + params.target[0].toUpperCase() + params.target.substring(1);
   }
}

Great for mapping restful style urls to meaningful action names, e.g.

"/update/patient/speciality" => PatientController.updateSpeciality

Selenium IDE 1.0.1

I recently upgraded to Selenium 1.0.1 and found that everything worked fine except that some asserts were failing around stored variables. e.g.

storeText //h2 varname


It turned out that if the text is hidden on the page then all that is stored is ''. In our case it was fixture pages that was returning some data as hidden page elements for reference.

Selenium IDE

Just a quick post to say that if any of you out there spend your day resizing and moving Selenium IDE after reopening it (it doesn't remember the previous window state), you can write a little script to do it for you using the handy 'wmctrl' :)

(on linux)
wmctrl -r 'Mozilla Firefox' -e 0,0,25,1330,1125
wmctrl -r "Mozilla Firefox" -b remove,maximized_vert,maximized_horz
wmctrl -a 'Mozilla Firefox'
wmctrl -r 'Selenium IDE' -e 0,1350,25,575,1125
wmctrl -a 'Selenium IDE'


The snippet above moves, unmaximises and raises firefox before moving and activiating the Selenium IDE.

Custom constraint

The other day we were doing some refactoring and we started to look into how all our validation is done. We noticed that we have a lot of duplication in our validators and wanted to do something about it. We came across the following blog post that describes how to create a custom validator. This is a great little blog post and allowed us to kill a lot code.

One thing that we did notice was that they suggest that you put the registering of the custom validator in the Config.groovy file. We found this problematic and found that the better solution was to put it in the resources.groovy file. Another problem that we came across was that you needed to register the constraint in the unit test if you wanted to be able to test constraints. This makes sense because resources.groovy isn't called in unit tests.

To register your constraint use the following line of groovy code:

ConstrainedProperty.registerNewConstraint(PhoneNumberConstraint.NAME, PhoneNumberConstraint)

Hopefully this helps with some refactoring.
Glenn

Selenium CSS locators

We've got a project with quite a large set of tests, and we have both Firefox and IE7 continuous builds using selenium. The annoying thing is that something that takes 5 minutes in Firefox can take 30+ minutes with IE (I kid you not!).

It turns out this is a common problem and is due to the lack for native xpath support in IE. So for all the selenium tests that use xpath=//..... in IE the xpath is actually being evaluated using javascript ... ouch. An alternative is to use css locators, you can't do this everywhere but as well as improving the IE performance it can also provide some rather tidy rules. For example

xpath=//div[contains(@class,'balance')]
or
css=.balance

xpath=//div[@id,'topLeft')//span[contains(@class,'name')]  
or 
css=#topLeft .name

So even if you dont' care about IE using css selectors might be a lot nicer. (It might also improve your css skills!)

GMock Talk

I'll be giving a talk about GMock next wednesday the 29th.

Please register if you are interested:

http://skillsmatter.com/event/java-jee/gmock-be-groovy-when-writing-tests

instanceof vs. HibernateProxy and inheritance

I posted something over on my blog about the exciting things that can happen when Hibernate proxies your base class to wrap an instance of your sub-class.

IE hangs with "Waiting for 1 resource to load"

Turns out this is a common problem with libraries like prototype and jquery. There's a good discussion of it here...

http://groups.google.com/group/prototype-scriptaculous/browse_thread/thread/a1c745463251a95d?pli=1

The suggested solution of replacing src=:// with src=blank.js worked for us.

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 }

}