Editing configurations a lot causes the GUI to gradually slow down and eventually crash [TIMEBOX: 2]

[Tom-Willemsen]

This issue was first spotted on NDXIRISTEST1 while doing manual system tests, and reproduced in a development environment. The GUI will slow down gradually and eventually crash. Symptoms to look out for are high CPU usage and a sluggish GUI.

Steps to reproduce:
Run through all the manual system tests that are to do with the configurations panel.

Task manager screenshots:

[AdrianPotter]

We've been getting reports of excess CPU usage from the end of last year and notably more have arrived now cycle is starting

***** Nagios *****

Notification Type: RECOVERY

Service: IBEX CLIENT CPU
Host: NDEMUONFE
Address: NDEMUONFE
State: OK

Date/Time: Fri Feb 10 12:51:25 GMT 2017

Additional Info:

OK (Sample Period 599 sec) - Found 1 Instance(s) of ibex-client running. CPU_ibex-client(PID=13716)=59.4%

Notably I started receiving alerts on 16/11/2016 shortly after v2.2 was deployed. The release notes for that version might be a good starting point.

https://github.com/ISISComputingGroup/ibex/wiki/Release-Notes-v2.2.0

There are a few candidates on that list that could be responsible for the observed behaviour

[KathrynBaker]

MUONFE may be a minor red herring, as it is probably pointing to something else that we ought to be fixing. The PSUs that MUONFE talk to are currently off, so there are a large number of messages being generated by the IOCs – so this is likely to be a lot of IOC messages, which is still a problem, but is a different one to the title of this ticket. I thought there was a ticket, and it certainly is a similar issue to #1580, as there isn’t an existing ticket I have created #2062 to ensure we look at the log messages as log messages.

[Tom-Willemsen]

The nagios alerts aren't exclusive to MUONFE; here are a couple from IMAT (which appear to show gradually increasing CPU usage):

***** Nagios *****

Notification Type: PROBLEM

Service: IBEX CLIENT CPU
Host: NDXIMAT
Address: NDXIMAT
State: WARNING

Date/Time: Sat Feb 11 20:17:22 GMT 2017

Additional Info:

WARNING (Sample Period 600 sec) - [Triggered by _AvgCPU70] - Found 1 Instance(s) of ibex-client running. CPU_ibex-client(PID=10424)=83.8%

***** Nagios *****

Notification Type: PROBLEM

Service: IBEX CLIENT CPU
Host: NDXIMAT
Address: NDXIMAT
State: CRITICAL

Date/Time: Sat Feb 11 20:27:22 GMT 2017

Additional Info:

CRITICAL (Sample Period 599 sec) - [Triggered by _AvgCPU85] - Found 1 Instance(s) of ibex-client running. CPU_ibex-client(PID=10424)=100.0%

After short discussion with @AdrianPotter I have emailed Winfried about the two alerts above, to check whether he was using Ibex at the time, and if so, what he was doing and any behaviour he observed.

From the IOC logs it does appear that configurations were being edited at around this time.

[Tom-Willemsen]

I emailed Winfried about the reports above, and he mentioned that one of his IOCs (a chopper) was disconnected at the time, which lends credence to the theory that this issue is caused by having disconnected IOCs rather than by editing configurations a lot (although editing configurations a lot in a development environment is likely to give you a few disconnected IOCs!)

Although #2062 is about memory and this is about CPU, it seems quite likely that they'll be part of the same resource leak.

---

Will turn this comment into a bit of a wiki comment of what I've found so far, for the benefit of anyone else who wants to have a look at this. This knowledge should be transferred to the wiki once the ticket is complete!

---

The stack trace when the GUI thread dies is:

*2017-02-16 16:11:15.908 [main] ERROR org.eclipse.ui.workbench - Failed to execute runnable (java.lang.OutOfMemoryError: GC overhead limit exceeded)
	org.eclipse.swt.SWT.error(SWT.java:4361)
	org.eclipse.swt.SWT.error(SWT.java:4276)
	org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:138)
	org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:4144)
	org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3761)
	org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2701)
	org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2665)
	org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2499)
	org.eclipse.ui.internal.Workbench$7.run(Workbench.java:679)
	org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
	org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:668)
	org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
	uk.ac.stfc.isis.ibex.product.Application.start(Application.java:40)
	org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
	org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
	org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
	org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:353)
	org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:180)
	sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	java.lang.reflect.Method.invoke(Unknown Source)
	org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:629)
	org.eclipse.equinox.launcher.Main.basicRun(Main.java:584)
	org.eclipse.equinox.launcher.Main.run(Main.java:1438)
	org.eclipse.equinox.launcher.Main.main(Main.java:1414)

Looking at it in a profiler doesn't reveal much, beyond the facts that:

• Each time you edit a configuration, a little bit more memory is used up (even after the garbage collector has done it's work)
• Forcing garbage collection manually doesn't help, which means that we still have references to all of those objects.
• The thing taking up the most memory is a java.lang.Object[], followed by a java.util.HashMap$Node[] which isn't terribly helpful.

Things to try:

• Look through source code for obvious areas of concern. Are we storing all of the past configurations accidentally?
• Specialised static analysis tools - might be able to spot potential memory leaks.
• More advanced profiling tool(s) - might give more information about where we're leaking memory from.

The following is a screenshot showing the leak (while I was performing manual system tests to do with configurations).

And a memory profile just before it crashes:

---

It is possible to reproduce this just by repeatedly adding/deleting blank configurations (which saves time over reading and performing all the various manual system tests)!

Further observations:

• SwitchableObservables are created when I make a new configuration.
• SwitchableObservables may not be deleted when I delete that configuration...?

---

The objects are freed properly on switching instrument. Suggest that we need to do the same when editing a configuration.

The root object that's leaking memory is protected Collection<Switchable> switchables; in uk.ac.stfc.isis.ibex.epics.switching : Switcher.java

---

After some slight refactoring of the Observables, we're getting a lot of the following exceptions:

Feb 21, 2017 11:17:22 AM org.epics.pvmanager.PVDirector isActive
WARNING: PVReader wasn't properly closed and it was garbage collected. Closing the associated connections...
java.lang.Exception: PV was never closed (stack trace for creation)
	at org.epics.pvmanager.PVDirector.<init>(PVDirector.java:52)
	at org.epics.pvmanager.PVReaderConfiguration.prepareDirector(PVReaderConfiguration.java:140)
	at org.epics.pvmanager.PVReaderConfiguration.maxRate(PVReaderConfiguration.java:128)
	at uk.ac.stfc.isis.ibex.epics.pvmanager.PVManagerObservable.<init>(PVManagerObservable.java:73)
	at uk.ac.stfc.isis.ibex.epics.pv.Channels.convertObservablePV(Channels.java:205)
	at uk.ac.stfc.isis.ibex.epics.pv.Channels.access$0(Channels.java:204)
	at uk.ac.stfc.isis.ibex.epics.pv.Channels$Strings.reader(Channels.java:75)
	at uk.ac.stfc.isis.ibex.instrument.channels.StringChannel.reader(StringChannel.java:29)
	at uk.ac.stfc.isis.ibex.epics.switching.ObservableFactory.getPVObservable(ObservableFactory.java:93)
	at uk.ac.stfc.isis.ibex.epics.switching.ObservableFactory.getForwardingObservable(ObservableFactory.java:88)
	at uk.ac.stfc.isis.ibex.configserver.ConfigServerVariables.iocDescription(ConfigServerVariables.java:222)
	at uk.ac.stfc.isis.ibex.configserver.ConfigServer.iocDescription(ConfigServer.java:167)
	at uk.ac.stfc.isis.ibex.configserver.editing.ObservableEditableConfiguration.getDescription(ObservableEditableConfiguration.java:69)
	at uk.ac.stfc.isis.ibex.configserver.editing.EditableConfiguration.setIocDescriptions(EditableConfiguration.java:615)
	at uk.ac.stfc.isis.ibex.configserver.editing.EditableConfiguration.<init>(EditableConfiguration.java:178)
	at uk.ac.stfc.isis.ibex.configserver.editing.ObservableEditableConfiguration.transform(ObservableEditableConfiguration.java:59)
	at uk.ac.stfc.isis.ibex.configserver.editing.ObservableEditableConfiguration.transform(ObservableEditableConfiguration.java:1)
	at uk.ac.stfc.isis.ibex.epics.observing.TransformingObservable$1.onValue(TransformingObservable.java:37)
	at uk.ac.stfc.isis.ibex.epics.observing.ClosableObservable.setValue(ClosableObservable.java:83)
	at uk.ac.stfc.isis.ibex.epics.observing.ForwardingObservable$1.onValue(ForwardingObservable.java:36)
	at uk.ac.stfc.isis.ibex.epics.observing.ClosableObservable.setValue(ClosableObservable.java:83)
	at uk.ac.stfc.isis.ibex.epics.observing.TransformingObservable$1.onValue(TransformingObservable.java:38)
	at uk.ac.stfc.isis.ibex.epics.observing.ClosableObservable.setValue(ClosableObservable.java:83)
	at uk.ac.stfc.isis.ibex.epics.observing.ForwardingObservable$1.onValue(ForwardingObservable.java:36)
	at uk.ac.stfc.isis.ibex.epics.observing.ClosableObservable.setValue(ClosableObservable.java:83)
	at uk.ac.stfc.isis.ibex.epics.observing.TransformingObservable$1.onValue(TransformingObservable.java:38)
	at uk.ac.stfc.isis.ibex.epics.observing.ClosableObservable.setValue(ClosableObservable.java:83)
	at uk.ac.stfc.isis.ibex.epics.pvmanager.PVManagerObservable.access$3(PVManagerObservable.java:1)
	at uk.ac.stfc.isis.ibex.epics.pvmanager.PVManagerObservable$1.pvChanged(PVManagerObservable.java:61)
	at org.epics.pvmanager.PVReaderImpl.firePvValueChanged(PVReaderImpl.java:110)
	at org.epics.pvmanager.PVReaderImpl.setValue(PVReaderImpl.java:220)
	at org.epics.pvmanager.PVDirector$4.run(PVDirector.java:340)
	at uk.ac.stfc.isis.ibex.epics.pvmanager.CurrentThreadExecutor.execute(CurrentThreadExecutor.java:26)
	at org.epics.pvmanager.PVDirector.notifyPv(PVDirector.java:311)
	at org.epics.pvmanager.PVDirector.access$500(PVDirector.java:37)
	at org.epics.pvmanager.PVDirector$6.desiredRateEvent(PVDirector.java:385)
	at org.epics.pvmanager.SourceDesiredRateDecoupler.sendDesiredRateEvent(SourceDesiredRateDecoupler.java:160)
	at org.epics.pvmanager.PassiveScanDecoupler$1.run(PassiveScanDecoupler.java:50)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)