Appium / selendroid code is slowing down over time

Question

I've put together what seemed like a straightforward, informal performance test using Robot Framework, WebDriver and Python connecting to an Android device via Appium. The application under test is a wrapped application with a local database to which records can be stored when the device is off line. My test involves using selenium to automate the filling out of 'diaries' which are then written to the local database (the device wifi is disabled during the test to keep the records from being pushed to the server automatically). It's a very repetitive test filling out form after form and keeping track of the count, as well as the time it takes to fill out and then submit a form (diary).

What I've been noticing is that the times grow significantly as the count increases, to the point where the automation fails due to a missed click or something less easy to define (sorry to be vague). This happens over the course of several hours, so changing parameters and re-running the test is a very time consuming affair. Monitoring the cpu usage on the android shows that the app under test is not working too hard (average of 35%, occasional climbs into low 60's) with no other applications running. Appium is running on a Mac mini i5, which I believe has 2 cores and 2 virtual cores for a total of 4. Appium hovers around 200% and a bit below, which seems okay.

I'm at my wits end as to why the automation is slowing over time, and welcome any thoughts as to why it's occurring. I realize this is a very difficult thing to troubleshoot without seeing the code run, but the program is quite large and there doesn't appear to be any one specific point of failure. It just seems to balloon out over time to the point of bursting. Once that happens, I go back to the app on the device and I can manually continue to enter forms without any problem, so it's not as if the database is full or the application has fallen over somehow.

I'm using Appium 0.18.0, btw. I can't get the automation to work with 1.1 which is another issue altogether.

EDIT:

I did another run last night, this time using the console version of appium server and using the -q flag to turn off logging. It went a good deal further in terms of the number of diaries (forms) that were filled out and written to the local off-line database, but the times to do so got longer and longer until finally the application broke. This time, however, there was a much more useful message, more clearly indicating memory issue with Selendroid/webdriver:

(apologies ahead of time for putting a stackdump here, but I don't know how to make this any prettier)

WebDriverException: Message: u'java.lang.OutOfMemoryError\n\tat java.lang.AbstractStringBuilder.enlargeBuffer(AbstractStringBuilder.java:94)\n\tat java.lang.AbstractStringBuilder.append0(AbstractStringBuilder.java:145)\n\tat java.lang.StringBuilder.append(StringBuilder.java:216)\n\tat io.selendroid.server.model.SelendroidWebDriver.executeAtom(SelendroidWebDriver.java:182)\n\tat io.selendroid.server.model.SelendroidWebDriver.executeAtom(SelendroidWebDriver.java:169)\n\tat io.selendroid.server.model.DefaultSelendroidDriver$WebviewSearchScope.lookupElement(DefaultSelendroidDriver.java:427)\n\tat io.selendroid.server.model.internal.AbstractWebElementContext.findElementByCssSelector(AbstractWebElementContext.java:211)\n\tat io.selendroid.server.model.internal.AbstractWebElementContext.findElement(AbstractWebElementContext.java:156)\n\tat io.selendroid.server.model.By$ByCssSelector.findElement(By.java:45)\n\tat io.selendroid.server.model.DefaultSelendroidDriver.findElement(DefaultSelendroidDriver.java:114)\n\tat io.selendroid.server.handler.FindElement.handle(FindElement.java:46)\n\tat io.selendroid.server.AndroidServlet.handleRequest(AndroidServlet.java:286)\n\tat io.selendroid.server.BaseServlet.handleHttpRequest(BaseServlet.java:70)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:62)\n\tat io.selendroid.server.inspector.InspectorServlet.handleHttpRequest(InspectorServlet.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:62)\n\tat org.webbitserver.handler.PathMatchHandler.handleHttpRequest(PathMatchHandler.java:33)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:62)\n\tat org.webbitserver.handler.DateHeaderHandler.handleHttpRequest(DateHeaderHandler.java:21)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:62)\n\tat org.webbitserver.handler.ServerHeaderHandler.handleHttpRequest(ServerHeaderHandler.java:25)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:78)\n\tat org.webbitserver.netty.NettyHttpControl.nextHandler(NettyHttpControl.java:67)\n\tat org.webbitserver.netty.NettyHttpChannelHandler$2.run(NettyHttpChannelHandler.java:72)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)\n\tat java.lang.Thread.run(Thread.java:841)'

I found this online in regards to the browser automation atoms, which appear to be involved in the failure. The error references 'fineElement' which of course is used a lot in my automation.

https://code.google.com/p/selenium/wiki/AutomationAtoms

I'm going to try and file an issue with either the Appium or Selendroid folks, but if anyone in the meantime can help me parse out what's going on here (and/or a possible solution or workaround) I'd be very grateful.

EDIT:

Logged an issue with the Selendroid team here: https://github.com/selendroid/selendroid/issues/438

Answer 1

The first step is to figure out which keyword or keywords is taking all the time. That will narrow down where to focus your investigation.

Based on answers to my comments, it seems like the slowdown is isolated to one python-based keyword. The next step would be to instrument that keyword to see what part is going slowly. You can do that with decorators on your functions and methods, or just sprinkle in print statements to report elapsed time.

Since this is a test that runs for hours, another culprit may be the robot logging mechanism. It could be that the log file is consuming all of the available memory. So, you might want to monitor memory usage when your tests start to slow down.

One option to try would be to break your test run into smaller pieces. Run a few hundred test cases then stop. Run another few hundred and stop, and so on. When you've run through all of the scenarios you can use the rebot tool to join all of the logs into a single report.