Application loading time concerns

At last week’s meeting (October 9th) there were some reports of slow initial loading of an FFTools-based web page. Attempts to reproduce it during the meeting led to some concerns that the server node might have some problems, and the UIUC group was going to look into that.

Any news on that, @jjt? If there’s a reproducible effect, @tatianag and I would like to have a chance to test it out from here before the meeting.

Thanks!
Gregory

@gpdf sorry for the late reply. I put all my code on github at this directory.
That is only the code for the static file serving. And currently since there is only static files, I am using python3 -m http.server 80 for simple hosting. The firefly is sitting on the same server at port 8080.

Hope that will help.

I put the logfile into a gist

You can use the java command line option -Xms1GB to change the heap size of JVM. For an image as big as 500MB, the default heap size is not enough.

Thank you!

Looking at just the “create plot” messages in the file, I see this:

    create plot   - file   : Total: 4.375 sec, Find-   809 ms, Read-1.173 sec, Ctx:WebPlot-lsst--1
    create plot   - file   : Total: 1.914 sec, Find- 1.67 sec, Read-     1 ms, Ctx:WebPlot-lsst--2
    create plot   - file   : Total: 1.223 sec, Find-   559 ms, Read-     0 ms, Ctx:WebPlot-lsst--3
    create plot   - file   : Total: 1.219 sec, Find-   673 ms, Read-     0 ms, Ctx:WebPlot-lsst--4
    create plot   - file   : Total: 1.183 sec, Find-   622 ms, Read-     1 ms, Ctx:WebPlot-lsst--5
    create plot   - file   : Total: 1.168 sec, Find-   521 ms, Read-     0 ms, Ctx:WebPlot-lsst--6
    create plot   - file   : Total: 1.509 sec, Find-   534 ms, Read-     1 ms, Ctx:WebPlot-lsst--7
    create plot   - file   : Total: 1.615 sec, Find-   758 ms, Read-     1 ms, Ctx:WebPlot-lsst--8
    create plot   - file   : Total: 1.80 sec, Find-   630 ms, Read-     0 ms, Ctx:WebPlot-lsst--9
    create plot   - file   : Total: 1.705 sec, Find-   875 ms, Read-     0 ms, Ctx:WebPlot-lsst--10
    create plot   - file   : Total: 1.190 sec, Find-   594 ms, Read-     1 ms, Ctx:WebPlot-lsst--11
    create plot   - file   : Total: 1.255 sec, Find-   553 ms, Read-     0 ms, Ctx:WebPlot-lsst--12
    create plot   - file   : Total: 1.403 sec, Find-   597 ms, Read-     0 ms, Ctx:WebPlot-lsst--13
    create plot   - file   : Total: 1.498 sec, Find-   659 ms, Read-     1 ms, Ctx:WebPlot-lsst--14
    create plot   - file   : Total: 1.303 sec, Find-   710 ms, Read-     0 ms, Ctx:WebPlot-lsst--15
    create plot   - file   : Total: 1.117 sec, Find-   551 ms, Read-     1 ms, Ctx:WebPlot-lsst--16
    create plot   - file   : Total: 2.116 sec, Find-   588 ms, Read-   780 ms, Ctx:WebPlot-lsst--17
    create plot   - file   : Total: 1.23 sec, Find-   584 ms, Read-     1 ms, Ctx:WebPlot-lsst--18
    create plot   - file   : Total: 954 ms, Find-   470 ms, Read-     0 ms, Ctx:WebPlot-lsst--19
    create plot   - file   : Total: 20.46 sec, Find-19.76 sec, Read-     1 ms, Ctx:WebPlot-lsst--20
    create plot   - file   : Total: 1.84 sec, Find-   545 ms, Read-     0 ms, Ctx:WebPlot-lsst--21
    create plot   - file   : Total: 11.338 sec, Find-10.379 sec, Read-     0 ms, Ctx:WebPlot-lsst--22
    create plot   - file   : Total: 824 ms, Find-   396 ms, Read-     0 ms, Ctx:WebPlot-lsst--23
    create plot   - file   : Total: 832 ms, Find-   376 ms, Read-     0 ms, Ctx:WebPlot-lsst--24
    create plot   - file   : Total: 829 ms, Find-   335 ms, Read-     0 ms, Ctx:WebPlot-lsst--25
    create plot   - file   : Total: 924 ms, Find-   442 ms, Read-     1 ms, Ctx:WebPlot-lsst--26
    create plot   - file   : Total: 1.93 sec, Find-   631 ms, Read-     0 ms, Ctx:WebPlot-lsst--27
    create plot   - file   : Total: 922 ms, Find-   372 ms, Read-     0 ms, Ctx:WebPlot-lsst--28
    create plot   - file   : Total: 1.208 sec, Find-   619 ms, Read-     0 ms, Ctx:WebPlot-lsst--29
    create plot   - file   : Total: 786 ms, Find-   329 ms, Read-     0 ms, Ctx:WebPlot-lsst--30

I notice that there are a couple of cases of very long times (11 and 20 s), which seem to arise from the “Find” time.

The first “create plot” has an unusually large value of (total - find - read). I’ll let @tatianag see if she can help decode this further.

This is a starting point for more poking around:

 grep '  create plot  ' fftools.log | tr '-' ' ' | awk '{totalt = $6*($7=="sec,"?1000:1); findt = $9*($10=="sec,"?1000:1); readt = $12*($13=="sec,"?1000:1); print totalt, readt, findt }'

Dingcheng,

Please let us know how much memory you are requesting when starting the embedded Firefly.

In the following command, I am requesting min 1G, max 8G of heap size and 256m initial permanent space size for reflective data, such as classes:
java -Xms1g -Xmx8g -XX:PermSize=256m -jar fftools-exec.war -Dserver_config_dir=./config -httpPort 8000

Out of 30 occasions when a plot was created from file, I see two that took abnormal time (11 sec and 20 sec), both of these for locating already cached file. (Notice there are only 2 “Read Fits” lines.)

It might be garbage collection, but if you were running with a few gigs, it must be something else.

Please, let us know.

Tatiana

I am using the default settings, so I did not touch the parameters at this point. Is there a way to confirm the parameters?

If it’s still running, ps -e | grep fftools-exec.war

In future, you might want to save the startup command into a script.

I ran the following command and this is what I have got.

$ ps ax -o rss,command | sort -nr | head -n 2
269580 java -Xmx8g -jar fftools-exec.war -Dserver_config_dir=./config -httpPort 8000
197036 java -jar fftools-exec.war

When I looked up, there are only two java instances and I figured they are both around tomcat.

The log was produced by the second process. This process has the default memory settings.
(Note the names of the threads http-bio-8080-* in the log: they contain the default port 8080.)

It appears that you are running two tomcat instances on this machine. You don’t want to do that. Tomcat will only start one process.

If the other tomcat process is owned by another user then that is fine but you should not need to start multiple.

Firefly needs more memory that the default, you need to run it with a least 2G. 8G is better if the machine allows that. When you get into visualizing very large FITS files you might be running it with 25G to 50G!

I think we found a memory leak problem. It is especially bad using the fftools api (your case). This should also improve performance as well since there will not be as much thrashing before the server runs out of memory. Tatiana and I have both tested it by running some of the 1/2 Gig raft files you provided through 30 or 40 times. It seems to be doing the right thing.

We are working getting you a new build. We hope to have it out on Thursday (10/29).