IMAT: investigate high client CPU

[FreddieAkeroyd]

According to nagios, on NDXIMAT

CRITICAL (Sample Period 601 sec) - [Triggered by _AvgCPU>85] - Found 1 Instance(s) of "ibex-client" running. CPU_ibex-client(PID=24208)=180.7% 

which means ibex-client.exe is using nearly 2 cores worth of cpu

It should be possible to connect via the ssh java debugging port to investigate

acceptance criteria

• it is understood why client is now using so much CPU and appropriate tickets to fix are created

[Chsudeepta]

It is clearly the heaviest process as per the snap of the task manager - with very high page fault numbers

[Tom-Willemsen]

Elevated CPU use is currently being seen on ZOOM - investigated non-invasively via VisualVM sampler.

• The root cause of the CPU usage on ZOOM, and to a lesser extent LARMOR which is showing similar but less severe symptoms, is a thread-contention issue on the PVMgr worker threadpool
  • The relevant threadpool is made up of num_cores - 1 threads
• There is contention on getting the next task out of the pool (not performing the actual tasks themselves, but each worker thread acquiring the next runnable task). This is protected by a lock shared by every thread in the pool.
  • This means you never see 1 thread using 100% cpu in the sampler, but rather cores - 1 threads each using (100/(cores-1))% CPU - which adds up to looking like 1 thread's worth of usage.
  • Worth noting that both the threadpool & task queue are core java classes - so the issue is likely not in these classes directly, but rather we are adding too many tasks or generally using them in an unintended way. These core java classes have been well-tested on much larger-scale deployments than we're doing.
• The tasks are recurring at short intervals, and added to the threadpool by an object called ActiveScanDecoupler from diirt. The tasks themselves are very small amounts of work, but each ActiveScanDecoupler schedules a recurring job with a very short delay onto the threadpool.
• ActiveScanDecoupler objects are leaked when opening some OPIs, e.g. jaws and motors.
  • Seen via VisualVM memory sampler
  • Likely related to scripts in OPIs, at a guess.
  • A "healthy" client (e.g. SANS2D currently) should only have one ActiveScanDecoupler, or maybe one for IBEX GUI PVs and one other for CS-Studio PVs (e.g. OPIs). However there should not be a large/unbounded number of these objects, as each of these object schedules a recurring task on the PVMgr worker threadpool.
• I've been able to reproduce both the thread contention and then (eventually) elevated CPU usage locally by repeatedly opening and closing a jaws-like OPI (locally, I used an OPI which includes 100 jaws OPIs via linking containers to speed up the leak - but it can also be triggered just with the jaws OPI).
  • It's much harder to reproduce the issue on a fast dev machine than the instruments - likely as the instruments are VMs so somewhat slower than usual, and likely have less cores & potentially older architecture compared to a dev machine.
• Solution will be to not leak ActiveScanDecouplers on opening OPIs (e.g. jaws.opi)
  • I haven't figured out exactly how to prevent this yet.
  • It should be easy to verify a potential fix using VisualVM - just check using the memory sampler that the Live object instance count (post-GC) for ActiveScanDecoupler does not increase after opening and then closing a representative selection of OPIs.

---

• Reproducer OPIs in \\isis\shares\ISIS_Experiment_Controls\data for tickets\Ticket8278
  • leak_minimal.opi leaks a single object at a time
  • leak_1000.opi is 1000 copies of the action button in leak_minimal.opi, which leaks 1000 objects at a time
• Looks like the issue may be caused by triggering a rule/script from a PV called =1 - not yet sure what this was meant to do...
• Happens regardless of the script using fast or slow path rule handlers.
• Leak also happens if opening the OPI (runtime) via cs-studio directly.
• Probably related (sounds rather similar): https://github.com/ControlSystemStudio/cs-studio/issues/84#issuecomment-30524535

[Tom-Willemsen]

PRs:

• https://github.com/ISISComputingGroup/ibex_gui/pull/1727
• https://github.com/ISISComputingGroup/IBEX/pull/8442

To review:

Somewhat fiddly. Check that my explanations above make sense. If you want evidence that this actually fixes the problem as currently being seen on ZOOM, follow the following instructions. Note that you will need to leak a lot (~250k?) of objects on a dev machine to see the constant CPU load as per ZOOM, so I recommend following these instructions to see the problem "at source" instead, and check that you think my interpretation of the problem makes sense:

On master (locally)

• Open an IBEX client
• Open VisualVM
  • Connect it to the client you just opened
  • Under sampler tab, select settings, remove all classes from "do not profile classes" list
  • Activate CPU sampler
  • Open "hot spots" pane
  • Right click, filter, filter to anything not containing [native] (which is native code - e.g. a lot of locks, I/O etc which will be reported by VVM as taking a lot of time but not really contributing to CPU use)
  • Open a selection of IBEX perspectives
  • Sort hot spots by "self" time
  • siftDown should not appear near the top of CPU usage stats
  • Go to memory profiler and right click -> filter to a class named ActiveScanDecoupler
  • A small number of ActiveScanHandler objects should be reported, e.g. <10 (if the view now displays as empty, that means 0 ActiveScanHandlers are present, this is also fine)
  • Copy leak_1000.opi from \\isis\shares\ISIS_Experiment_Controls\data for tickets\Ticket8278 over one of your local OPIs
  • Open leak_1000.opi
  • Verify that ~1000 ActiveScanHandler objects are now active
  • Verify that they remain alive after forcing a GC
  • Verify that ~1000 more get added each time you open and close the relevant OPI.

Connect VisualVM to a client showing healthy CPU use on nagios (e.g. SANS2D)

• As above, check that siftDown is not present in "hot" methods by self time in cpu sampler
• As above, check a small number of ActiveScanHandler objects are reported in memory sampler

Connect VisualVM to a client showing unhealthy CPU use on nagios (e.g. ZOOM)

• As above, check that siftDown is present in "hot" methods by self time in cpu sampler, and is using significant CPU "self" time
• As above, check a large number of ActiveScanHandler objects are reported in memory sampler

On this ticket branch (locally)

• In your local copy of leak_1000.opi, do a global find-and-replace from >=1 to >loc://$(DID)_CONST_1(1)
• Follow instructions as per local master branch
• Verify that ActiveScanHandler objects are no longer leaked using memory sampler
• Verify that siftDown no longer appears as a "hot" method by self time after opening and closing leak_1000.opi a bunch of times in a fresh client.

Code review

• Verify that the code change is all =N triggers to loc://-prefixed PVs initialised to the same values
• Verify that relevant OPIs have equivalent functionality to before