GUI stalling and eventually freezing while TrakEM2 generates mipmaps

I realized that current Fiji’s and TrakEM2’s UI become quickly unusable when TrakEM2 generates mipmap images on larger montages. This is the most common operation that TrakEM2 will perform so TrakEM2 has become unusable. The symptom is that the UI starts to respond slowly to user input (keys, mouse, menus, context menus in both ImageJ and TrakEM2) until it finally stops responding. While this happens, TrakEM2 keeps refreshing the window content. Occasionally the UI recovers after being unresponsive for a while, but not always. Just now I had it recover from the bad state but it was impossible to add slices to ImageJ image stacks with some AWT exception blurb that I unfortunately lost (UI broken, you get it). I am running Fiji on OpenJDK8 because the shipped Java 6 does not start on Ubuntu 15.04. So I immediately tested with OpenJDK7 (because we know that some things are broken in 8) only to see that the effect is the same, may be less severe, i.e. it survives for longer and recovers more often. Immediately, I suspected the SciJava console as TrakEM2 is verbose into System.out and err. I reintroduced the ‘fix’ that I made when it hit me earlier: https://github.com/scijava/scijava-ui-swing/commit/f6a4b9914ca5185f039897793adfc123114957bc
but it didn’t help. I then tried the Fiji lifeline version from November 2014 and realized that this doesn’t have the problem. Independent of Java version. It is, unfortunately, pretty hard to guess what that could be. My current suspicion is that it is not TrakEM2 specific but that TrakEM2 may trigger something by how it does things. During mipmap generation, it does not print too many things into the terminal but it uses all threads to make new small images. It also repaints the screen very rapidly. If there was a mechanism that would queue redraw events instead of letting them slip, that could be a candidate. Any help highly appreciated. I can do stuff on request if the search space would only be a little less unconstrained. Thanks a lot in advance!

Have you tried waiting till things get slow, then dumping stack traces in your console using Ctrl+? It might reveal the culprit.

1 Like

I agree with this completely. Also comparing the stack dump with current vs. lifeline versions may reveal the problem.

JVisualVM is good. You can also do it in Eclipse when attaching to a running instance.

Stack traces help detect deadlocks but may not reveal memory leaks (if that’s what this is) as easily. A Heap Dump with a memory analyzer produces data that can be filtered, analyzed, and shared.

To identify the problem the JVisualVM Profiler might help? Just use sampling and see which method is keeping your CPU busy?

1 Like

Thanks! @dietzc I should have thought about this myself. Had JVisualVM open all time just to see how memory and CPU behave. So the answer is (drums)

org.scijava.ui.swing.console.SwingConsolePane$1.run()

keeps the CPU busy while nothing else is happening. If it recovers from the marathon, the UI starts behaving normally again.

1 Like

Here is a thread dump

(add https:// in front of this, I could not make this a link because the Forum says “Sorry, new users can post only 2 links in a post”, and rejects the post—that should may be corrected).

BTW. I have to correct myself. TrakEM2 generates a lot of output while doing this. In this case 12 threads concurrently generate mipmaps and trigger repaints, each repaint generates several lines into System.out for each image that has not yet been regenerated. The number of images is ~1000. I.e. several threads trigger repaints, each repaint generates more than 1000 lines of output into System.out. I understand that this is not cool, but System.out does not have a problem with it, neither does logging this into files (we do that on the cluster).

I raised your trust level to “4-Leader” and made you a moderator.

Any chance you can use LogService.debug for these, so they are off by default, but can be enabled by enabling debug logging?

Regarding disabling the Console: did we add a system property yet that turns it off? We could certainly do that, as long as it is “opt in” via tech-savvy power users only…

I will look into making the output use LogService.debug, but I would also love to have an option to switch off the Console in such cases to get a short term solution. I do not know if you added a property to switch that off yet—but that’d be awesome!

Please test.

Which implementation of LogService would I use and how do I access it? TrakEM2 has its own log abstraction with message delay and threading that Albert invented to circumvent slowness in IJ.log and issues with multi-threading. Replacing this consistently will be a major pile of work with low return. But I would look into replacing it’s System.out/err fallback by whatever mechanism SciJava provides.

I assume TrakEM2 is thoroughly in IJ1-land—in which case, you can obtain the SciJava Context and subsequently the LogService as follows:

Context context = (Context) IJ.runPlugIn("org.scijava.Context", "");
LogService log = context.service(LogService.class);

It might be enough to s/System.(out|err)/log.debug/g and call it good.

1 Like

This is neat! Good to know!!!

The reason the IJ.runPlugIn trick is not advertised more explicitly is because it is generally not the best way of doing things. The preferred way is to write an IJ2-style thing, which already can tap in to its Context in some less static way. For example, if you write a Command then all you need to do is write:

@Parameter
private Context context;

And it will be injected automatically by the framework.

But if you have an ij.plugin.PlugIn, and changing that is somehow difficult, then IJ.runPlugIn is a pragmatic and low-impact way forward.

I need some help to test this. I temporarily fixed the parent of ui-swing to the snapshot of common, skipped the enforcer and compiled both. Then copied into Fiji’s jar directory. Doesn’t run because other dependencies are not satisfied. Do you have ideas which dependencies? For me it is very unconstrained territory again.

To be precise, I am getting

Error while executing the main() method of class 'net.imagej.Main':
java.lang.IllegalArgumentException: Invalid service: net.imagej.legacy.LegacyConsoleService
	at org.scijava.service.ServiceHelper.createExactService(ServiceHelper.java:280)
	at org.scijava.service.ServiceHelper.loadService(ServiceHelper.java:231)
	at org.scijava.service.ServiceHelper.loadService(ServiceHelper.java:194)
	at org.scijava.service.ServiceHelper.loadServices(ServiceHelper.java:166)
	at org.scijava.Context.<init>(Context.java:267)
	at org.scijava.Context.<init>(Context.java:224)
	at org.scijava.Context.<init>(Context.java:163)
	at org.scijava.Context.<init>(Context.java:149)
	at net.imagej.ImageJ.<init>(ImageJ.java:79)
	at net.imagej.Main.launch(Main.java:61)
	at net.imagej.Main.main(Main.java:73)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at net.imagej.launcher.ClassLauncher.launch(ClassLauncher.java:258)
	at net.imagej.launcher.ClassLauncher.run(ClassLauncher.java:184)
	at net.imagej.launcher.ClassLauncher.main(ClassLauncher.java:76)
Caused by: java.lang.IllegalArgumentException: Invalid service: net.imagej.legacy.LegacyService
	at org.scijava.service.ServiceHelper.createExactService(ServiceHelper.java:280)
	at org.scijava.service.ServiceHelper.loadService(ServiceHelper.java:231)
	at org.scijava.service.ServiceHelper.createServiceRecursively(ServiceHelper.java:340)
	at org.scijava.service.ServiceHelper.createExactService(ServiceHelper.java:269)
	... 17 more
Caused by: java.lang.IllegalArgumentException: No compatible service: org.scijava.log.LogService
	at org.scijava.service.ServiceHelper.loadService(ServiceHelper.java:243)
	at org.scijava.service.ServiceHelper.createServiceRecursively(ServiceHelper.java:340)
	at org.scijava.service.ServiceHelper.createExactService(ServiceHelper.java:269)
	... 20 more

when I start ImageJ-linux64.

I built and replaced the two JARs on top of a fully up-to-date Fiji, and Fiji launches successfully for me:

cd ~/code/scijava/scijava-common
git fetch && git checkout suppress-console
mvn -DskipTests install
rm -rf $FIJI_DIR/jars/scijava-common-*.jar
cp target/scijava-common-2.47.1-SNAPSHOT.jar $FIJI_DIR/jars
cd ~/code/scijava/scijava-ui-swing
git fetch && git checkout suppress-console
mvn -Denforcer.skip -DskipTests -Dscijava-common.version=2.47.1-SNAPSHOT install
rm -rf $FIJI_DIR/jars/scijava-ui-swing-*.jar
cp target/scijava-ui-swing-0.7.1-SNAPSHOT.jar $FIJI_DIR/jars

Maybe you had Eclipse open at the same time and it interfered with your builds?

Anyway, after setting that up, I ran into a couple of problems:

  1. Passing -Dfoo=bar style flags to the Launcher seems to be broken now. So passing -Dscijava.noConsole=true was insufficient for testing this, because it simply responds:

    [WARNING] Ignoring invalid argument: -Dscijava.noConsole=true
    
  2. To work around that, I did fiji --dry-run and then copy-pasted the long version, prepending -Dscijava.noConsole=true in the right place… and it still didn’t work. Specifically, a BeanShell script that does System.err.println("Hello"); still results in a console window popup.

Digging now.

Right. The Console logic is duplicated in imagej-legacy. Ugh.

https://github.com/imagej/imagej-legacy/compare/suppress-console

And now it works.

Thanks @ctrueden. I followed your instructions and note that the problem is still not solved, the UI stalls. Updated stack trace during it freezing is at

Your stack trace says:

at org.scijava.ui.swing.console.SwingConsolePane$1.run(SwingConsolePane.java:123)

Which means a SwingConsolePane was still created. Did you build the imagej-legacy snapshot and replace it as well? You are passing -Dscijava.noConsole=true on the CLI, right? When you run a System.err.println("Hello"); from the Script Editor in BeanShell, do you see a console window pop?