Confusing results on using Runtime.getRuntime().totalMemory() and freeMemory() to calculate memory?

Question

I was using Runtime.getRuntime().totalMemory() and freeMemory() to calculate memory. However, I am confused by the results.

I already read the posts in:

What are Runtime.getRuntime().totalMemory() and freeMemory()?

a question on Runtime.getRuntime().totalMemory()

Here is my demo code:

package test;

class Memory

{

public static long used()

{

long total=Runtime.getRuntime().totalMemory();

long free=Runtime.getRuntime().freeMemory();

return (total-free);

}

}



package test;

import java.util.ArrayList;

public class MemTestQuestion {

    private static final long _10M = 10000000;

    public static void main(String[] args) {

        int runCount=10;
        for (int i = 0; i < runCount; i++) {
            arrayListMemTest();
        }
    }

    public static void arrayListMemTest()
    {
        long startTime = System.currentTimeMillis();
        long startMem=Memory.used();

        ArrayList<Integer>al= new ArrayList<Integer>();
        for (int i = 0; i < _10M; i++) {
            al.add(1000);
        }

        long endMem= Memory.used();
        long endEndTime = System.currentTimeMillis();

        long timeLast = endEndTime - startTime;
        long memUsed = endMem-startMem;


        System.out.print("lasts:"
                + timeLast + "ms = "+timeLast/1000.0+"s\t");
        System.out.println("mem used:"
                +memUsed+"bytes = "+new java.text.DecimalFormat("#.00").format(memUsed/(1024*1024.0))+"M");

        System.gc();
    }

}

Here are results when runCount=1(a variable located in Main method):

lasts:3606ms = 3.606s   mem used:214644488bytes = 204.70M

Here are results when runCount=10:

lasts:3643ms = 3.643s   mem used:214644488bytes = 204.70M
lasts:389ms = 0.389s    mem used:254054928bytes = 242.29M
lasts:366ms = 0.366s    mem used:219163424bytes = 209.01M
lasts:242ms = 0.242s    mem used:256265992bytes = 244.39M
lasts:222ms = 0.222s    mem used:255523768bytes = 243.69M
lasts:225ms = 0.225s    mem used:253843192bytes = 242.08M
lasts:253ms = 0.253s    mem used:253967736bytes = 242.20M
lasts:236ms = 0.236s    mem used:253994680bytes = 242.23M
lasts:234ms = 0.234s    mem used:254066232bytes = 242.30M
lasts:233ms = 0.233s    mem used:254091448bytes = 242.32M

What confused me most was that when the runCount=10, the most results are around 240M. But when the runCount=1, the results are around 200M.

I guess this is because the JAVA JVM does not collect garbage in time, so the first result are more convicing. Am I right? If not, can someone provide some clues or other suggestions? Thanks in advance.

The purpose of the demo code was trying to compare the standard java containers and ones from third party.

What is `Memory.used`? What type of class is **Memory**. – IgorGanapolsky Apr 22 '16 at 17:35 — IgorGanapolsky, Apr 22 '16 at 17:35

Stephen C · Accepted Answer · 2015-12-18T05:11:41.757

I guess this is because the JAVA JVM does not collect garbage in time, so the first result are more convicing. Am I right?

I don't think so. Running System.gc() is supposed to be a hint to make "best effort" to collect all garbage. Right now. The hint can be ignored, but if the GC does run, you would expect it to do a >>full<< collection, and only return when that had completed. There should be no question of the GC "keeping up".

If not, can someone provide some clues or other suggestions?

It could be due to JIT compilation and other JVM warmup effects.

When your application starts, your code's methods and all of the library methods that are used (transitively) are bytecodes, and will be interpreted by the bytecode interpreter. As the bytecodes are interpreted, the JVM gathers stats on various things (e.g. to assist branch prediction). Eventually, it decides to JIT compile the methods.

So how does this relate to your observation?

The stats are stored in the heap, and will be reachable ... until the JIT compiler "consumes" them.
The JIT compiler runs asynchronously, and when it is running it will also be using heap space to hold its data structures.
At startup, the JVM has to load classes, and this also consumes heap space to hold temporary objects.
The heap size is not constant. It will grow (and sometimes shrink) depending on how much free space is available after each GC cycle.

All of these combine to give local "highs" and "lows" in heap sizes and heap space usage, during the JVM warmup phase.

Calling `System.gc()` is not recommended, as stated here: https://docs.oracle.com/cd/E13150_01/jrockit_jvm/jrockit/geninfo/devapps/codeprac.html#wp998554 — IgorGanapolsky, Apr 22 '16 at 17:35
Agreed. But this Q&A is really about explaining the "odd" behavior of a test, not using this technique to measure memory usage in *production* code. — Stephen C, Apr 23 '16 at 01:15

score 2 · Answer 2 · answered Dec 18 '15 at 03:09

I create the ArrayList as follows..

    ArrayList<Integer> al = new ArrayList<Integer>(){

        @Override
        protected void finalize() throws Throwable {
            super.finalize(); 
            System.out.println("finalize");
        }

    };

After I run your code, I realized that your confusing result did not happened because JVM didn't garbage collected. The result of the above code is as follows..

lasts:4875ms = 4.875s mem used:250675056bytes = 239.06M
lasts:437ms = 0.437s mem used:278614888bytes = 265.71M
finalize
finalize
lasts:594ms = 0.594s mem used:252543848bytes = 240.84M
finalize
lasts:266ms = 0.266s mem used:277680536bytes = 264.82M
finalize
lasts:312ms = 0.312s mem used:280390568bytes = 267.40M
finalize
lasts:297ms = 0.297s mem used:278106248bytes = 265.22M
finalize
lasts:297ms = 0.297s mem used:277852312bytes = 264.98M
finalize
lasts:312ms = 0.312s mem used:277885640bytes = 265.01M
finalize
lasts:297ms = 0.297s mem used:277897448bytes = 265.02M
finalize
lasts:312ms = 0.312s mem used:277899896bytes = 265.03M
finalize

In this code also, first time it gets run, it shows a value (239.06M) less than the average value.

Then I change the main method

public static void main(String[] args) throws InterruptedException {
    Thread.sleep(7000);
    int runCount = 10;
    for (int i = 0; i < runCount; i++) {
        arrayListMemTest();
    }
}

And the result was:

lasts:2640ms = 2.64s mem used:275635104bytes = 262.87M
lasts:624ms = 0.624s mem used:253167968bytes = 241.44M
finalize
finalize
lasts:411ms = 0.411s mem used:303362328bytes = 289.31M
finalize
lasts:527ms = 0.527s mem used:253055288bytes = 241.33M
finalize
lasts:329ms = 0.329s mem used:280855512bytes = 267.84M
finalize
lasts:340ms = 0.34s mem used:252478904bytes = 240.78M
finalize
lasts:350ms = 0.35s mem used:277791960bytes = 264.92M
finalize
lasts:312ms = 0.312s mem used:277059280bytes = 264.22M
finalize
lasts:314ms = 0.314s mem used:279330968bytes = 266.39M
finalize
lasts:376ms = 0.376s mem used:278511960bytes = 265.61M
finalize

And this time, it shows a average value around 260M.

As I think, JVM needs some time to fully load its libraries. The programs get run before initializing JVM fully..

Warning: adding a finalizer is going to CHANGE the behavior of the garbage collector. In particular, the finalizable objects are enqueued and processed AFTER the GC run run completes. — Stephen C, Dec 18 '15 at 03:16
I think using `finalize` method is futile, as there is no guarantee when (if at all) it will have effect during program execution. Also, according to Oracle: ~ "Using finalizers is also inherently bad for performance since it imposes an additional burden on the memory management system that needs to handle execution of finalizers and let objects live longer." — IgorGanapolsky, Apr 22 '16 at 17:40

Confusing results on using Runtime.getRuntime().totalMemory() and freeMemory() to calculate memory?

2 Answers2