Fiji(ImageJ) takes too long to load (on linux), together with a lengthy error message

fiji
macro
Tags: #<Tag:0x00007fb87b5973c0> #<Tag:0x00007fb87b597280>

#1

(Reposted from StackOverflow http://stackoverflow.com/questions/43046545/fijiimagej-takes-too-long-to-load-on-linux-together-with-a-lengthy-error-me)

I’m using Fiji on linux (inside a virtual machine) from the command line. Specifically I have a python script that calls many fiji macros. Each time fiji loads it takes about a minute, making it the bottleneck of the process and slowing me considerably.

I wonder if this is normal. Could fiji perhaps be made to load more quickly? Fiji also outputs a lengthy error message when it is called. I wonder if it is related to the lengthy time it takes to load.

The command I use to call it (for example)

//shared_directory/projects/Fiji.app/ImageJ-linux64 --headless 
-macro //shared_directory/projects/retracted/fiji_scripts/patch_cropper.txt

The error message is as follows

java.awt.HeadlessException
        at java.awt.GraphicsEnvironment.checkHeadless(GraphicsEnvironment.java:204)
        at java.awt.Window.<init>(Window.java:536)
        at java.awt.Frame.<init>(Frame.java:420)
        at ij.plugin.frame.PlugInFrame.<init>(PlugInFrame.java:13)
        at ij.plugin.frame.RoiManager.<init>(RoiManager.java:94)
        at ij.macro.Interpreter.getBatchModeRoiManager(Interpreter.java:1875)
        at ij.plugin.frame.RoiManager.getInstance(RoiManager.java:1795)
        at ij.ImagePlus.deleteRoi(ImagePlus.java:1735)
        at ij.ImagePlus.close(ImagePlus.java:391)
        at ij.plugin.Commands.closeImage(Commands.java:136)
        at ij.plugin.Commands.close(Commands.java:83)
        at ij.plugin.Commands.run(Commands.java:29)
        at ij.IJ.runPlugIn(IJ.java:187)
        at ij.Executer.runCommand(Executer.java:137)
        at ij.Executer.run(Executer.java:66)
        at ij.IJ.run(IJ.java:297)
        at ij.IJ.run(IJ.java:272)
        at ij.macro.Functions.doRun(Functions.java:603)
        at ij.macro.Functions.doFunction(Functions.java:96)
        at ij.macro.Interpreter.doStatement(Interpreter.java:230)
        at ij.macro.Interpreter.doStatements(Interpreter.java:218)
        at ij.macro.Interpreter.run(Interpreter.java:115)
        at ij.macro.Interpreter.run(Interpreter.java:85)
        at ij.macro.Interpreter.run(Interpreter.java:96)
        at ij.plugin.Macro_Runner.runMacro(Macro_Runner.java:155)
        at ij.plugin.Macro_Runner.runMacroFile(Macro_Runner.java:139)
        at ij.IJ.runMacroFile(IJ.java:148)
        at net.imagej.legacy.IJ1Helper$4.call(IJ1Helper.java:1056)
        at net.imagej.legacy.IJ1Helper$4.call(IJ1Helper.java:1052)
        at net.imagej.legacy.IJ1Helper.runMacroFriendly(IJ1Helper.java:986)
        at net.imagej.legacy.IJ1Helper.runMacroFile(IJ1Helper.java:1052)
        at net.imagej.legacy.LegacyCommandline$Macro.handle(LegacyCommandline.java:188)
        at org.scijava.console.DefaultConsoleService.processArgs(DefaultConsoleService.java:102)
        at net.imagej.legacy.LegacyConsoleService.processArgs(LegacyConsoleService.java:81)
        at org.scijava.AbstractGateway.launch(AbstractGateway.java:95)
        at net.imagej.Main.launch(Main.java:62)
        at net.imagej.Main.main(Main.java:68)
        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:279)
        at net.imagej.launcher.ClassLauncher.run(ClassLauncher.java:186)
        at net.imagej.launcher.ClassLauncher.main(ClassLauncher.java:77)

Java HotSpot(TM) 64-Bit Server VM warning: ignoring option PermSize=128m; support was removed in 8.0
Java HotSpot(TM) 64-Bit Server VM warning: Using incremental CMS is deprecated and will likely be removed in a future release
java.lang.IllegalArgumentException: Cannot handle app name in ij.gui.YesNoCancelDialog's public <init>(java.awt.Frame parent, java.lang.String title, java.lang.String msg)
        at net.imagej.patcher.CodeHacker.replaceAppNameInCall(CodeHacker.java:446)
        at net.imagej.patcher.LegacyExtensions.insertAppNameHooks(LegacyExtensions.java:419)
        at net.imagej.patcher.LegacyExtensions.injectHooks(LegacyExtensions.java:291)
        at net.imagej.patcher.LegacyInjector.inject(LegacyInjector.java:308)
        at net.imagej.patcher.LegacyInjector.injectHooks(LegacyInjector.java:109)
        at net.imagej.patcher.LegacyEnvironment.initialize(LegacyEnvironment.java:101)
        at net.imagej.patcher.LegacyEnvironment.applyPatches(LegacyEnvironment.java:495)
        at net.imagej.patcher.LegacyInjector.preinit(LegacyInjector.java:397)
        at net.imagej.patcher.LegacyInjector.preinit(LegacyInjector.java:376)
        at net.imagej.legacy.LegacyService.<clinit>(LegacyService.java:134)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
        at java.lang.Class.newInstance(Class.java:442)
        at org.scijava.service.ServiceHelper.createServiceRecursively(ServiceHelper.java:302)
        at org.scijava.service.ServiceHelper.createExactService(ServiceHelper.java:269)
        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)
        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:278)
        at org.scijava.Context.<init>(Context.java:234)
        at org.scijava.Context.<init>(Context.java:174)
        at org.scijava.Context.<init>(Context.java:160)
        at net.imagej.ImageJ.<init>(ImageJ.java:77)
        at net.imagej.Main.launch(Main.java:61)
        at net.imagej.Main.main(Main.java:68)
        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:279)
        at net.imagej.launcher.ClassLauncher.run(ClassLauncher.java:186)
        at net.imagej.launcher.ClassLauncher.main(ClassLauncher.java:77)
Caused by: javassist.CannotCompileException: No code replaced!
        at net.imagej.patcher.CodeHacker$EagerExprEditor.instrument(CodeHacker.java:1280)
        at net.imagej.patcher.CodeHacker.replaceAppNameInCall(CodeHacker.java:443)
        ... 36 more

Thanks!


#2

Welcome to the forum, @Elad!

As I already noted on stackoverflow, the error message clearly points to the ij1-patcher's CodeHacker class trying to handle YesNoCancelDialog which it currently can’t.

It would be helpful if you can also post the macro you’re trying to run, so others can try to reproduce your issue.


#3

Thank you for the warm welcome.

I would like to note that I get the error for merely calling fiji in a headless mode
//shared_directory/projects/Fiji.app/ImageJ-linux64 --headless -macro
So I don’t think it is related to my macro.

A macro for example

for (n=2;n<7;n++) 
    { 
    	open("//shared_directory/projects/work_area/input/input.jpg");
    	id = getImageID();
    	title = getTitle();
    	getLocationAndSize(locX, locY, sizeW, sizeH);
    	width = getWidth();
    	height = getHeight();
    	tileWidth = width / n;
    	tileHeight = height / n;
    	for (y = 0; y < n; y++) {
    	offsetY = y * height / n;
    	 for (x = 0; x < n; x++) {
    	offsetX = x * width / n;
    	selectImage(id);
    	 call("ij.gui.ImageWindow.setNextLocation", locX + offsetX, locY + offsetY);
    	tileTitle = title + " [" + x + "," + y + "]";
    	 run("Duplicate...", "title=" + tileTitle);
    	makeRectangle(offsetX, offsetY, tileWidth, tileHeight);
    	 run("Crop");
    	}
    	}
    	N=nImages; 
    	for (i=0;i<N;i++)
    	{ 
    		//print (i);
    		saveAs("Jpeg", "//shared_directory/projects/work_area/process/patches/input_"+n+"_"+i+".jpg");
    		close();
    	}

    }

#4

You were right, it seems this is an issue with the latest ImageJ 1.x version that introduced a new method in said class YesNoCancelDialog that is not yet patched by ij1-patcher.

This was noted by @ctrueden here:

And a PR by @stelfrich is in the works:


ImageJ-win64.exe: cannot start plugin in headless mode
#5

This is not normal—but you are not the only person reporting this issue. Unfortunately, it is difficult to troubleshoot, because active Fiji developers (AFAIK) cannot reproduce it on their machines. In my Ubuntu 64-bit VM, for example, Fiji starts up in <5 seconds. My educated guess is that it is related to your network configuration somehow.

One experiment you could try is to move the file jars/imagej-updater-0.8.2.jar (or whatever version suffix you have) out of the jars folder, and see if Fiji starts any faster. If so, this gives us a hint. But we’ll need to do more digging to solve this problem once and for all for everyone afflicted.


#6

Hi all!

Can I help to debug this? Fiji takes about 20 seconds to start on my machine (Kubuntu 16.10 64bit). But if I start it a second time, it pops up quite immediately (~3s). Moving jars/imagej-updater-0.8.2 changes nothing, the first start after a reboot is always slow, following startups are fine.

Also I get the same error message about the YesNoCancelDialog.

Cheers,
Deborah

Edit: Maybe this is something different. There is no delay (also for the first time) when I run the master branch version from github via Eclipse.


#7

This sounds more like a consequence of caching: your OS will temporarily store data read from disk into RAM (which is much faster), in case you read it a second time. That might be what’s going on here.

The bug is fixed, but the fix has not yet been released and uploaded.

Your offer is much appreciated.

I have already asked multiple times (on various threads about this topic) for people to generate thread dumps during the prolonged startup period. But no one has responded with hard data.

You could try it on your system; perhaps it will shed some light on what takes so long during the first startup.


#8

Sure.

http://pastebin.ca/3792580


#9

Thanks @frauzufall!

The relevant bit is here:

"main" #1 prio=5 os_prio=0 tid=0x00000000019fb800 nid=0x9ad runnable [0x00007ffe6e791000]                         
   java.lang.Thread.State: RUNNABLE                                                                               
        at java.util.zip.ZipFile.open(Native Method)                                                             
        at java.util.zip.ZipFile.<init>(ZipFile.java:219)                                                         
        at java.util.zip.ZipFile.<init>(ZipFile.java:149)
        at java.util.jar.JarFile.<init>(JarFile.java:166)
        at java.util.jar.JarFile.<init>(JarFile.java:103)
        at sun.misc.URLClassPath$JarLoader.getJarFile(URLClassPath.java:893)

Which tells me that indeed, the time is being taken opening up all the JAR files on the classpath, and getting them loaded. And is very likely faster on subsequent executions because your OS has cached the contents.

I am guessing that Fiji would start much faster the first time if you put it onto a solid state drive (SSD) rather than an old-fashioned HD.


#10

You are right, 3s startup from SSD :slight_smile:

Thanks for the explanation and for pointing out the relevant part of the log.

For C++ I used Valgrind in QtCreator to understand how long certain functions take to be executed - is there something similar available for Java and Eclipse or Intellij? I installed VisualVM but it wasn’t super intuitive on the first try.


#11

The VisualVM docs might help you get started; you want to do CPU profiling. This blog entry—parts 1 and 2—may also be helpful. I personally am not an expert on profiling, since I do not do it very much.

In this case, I think profiling will simply show the same thing we already concluded: class loading takes the bulk of the time.