FULL PRODUCT VERSION :
java version "1.5.0_02"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_02-b09)
Java HotSpot(TM) Client VM (build 1.5.0_02-b09, mixed mode, sharing)
also with 1.5.0_04
FULL OS VERSION :
Microsoft Windows XP [Version 5.1.2600]
Windows NT ver 4.0 (SP6)
A DESCRIPTION OF THE PROBLEM :
A very clear problem of over-eager soft reference collection. I have reduced it to a (relatively) simple test case (below).
The cache contains a relatively small number of large objects.
These are created on the first run through the loop, with fixed timer delay between each one, and are then re-access on the second pass through.
Depending on the combination of delay and max heap size, some of the earlier frames in the cache have been scrapped by the time of the second pass, even though mem usage is nowhere near the max heap limit.
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run PictureBox class (under Test case) with the following command line params:
- size of cache (i've been running with 10)
- delay between creations and accesses of the items in cache, in ms
(anything between 30 and 1000 is possible in my actual app, but the results below are with 200).
Vary max heap between 32m and 200m, and see how many frames get scrapped before they are re-used, even though the actual mem requirement is about 16Mb (for 10 frames).
You can change the size of each item in the cache too, but only in the code - sorry.
EXPECTED VERSUS ACTUAL BEHAVIOR :
This is an example run, where only one frames get scrapped, with maxHeap of 64m. The memory usage printouts show that the actual memory requirement is nowhere near the limit:
Memory usage: 1.8503189086914062 used out of 3.5234375MB total
Now drawing frame 0
Loading frame 1...
Now drawing frame 1
Memory usage: 3.55059814453125 used out of 5.40625MB total
Loading frame 2...
Now drawing frame 2
Memory usage: 5.130615234375 used out of 6.4609375MB total
Loading frame 3...
Memory usage: 6.70855712890625 used out of 9.20703125MB total
Now drawing frame 3
Loading frame 4...
Now drawing frame 4
Memory usage: 6.683189392089844 used out of 9.20703125MB total
Loading frame 5...
Now drawing frame 5
Memory usage: 8.264122009277344 used out of 12.05078125MB total
Loading frame 6...
Now drawing frame 6
Memory usage: 9.848731994628906 used out of 14.87890625MB total
Loading frame 7...
Now drawing frame 7
Memory usage: 11.434623718261719 used out of 17.703125MB total
Loading frame 8...
Memory usage: 13.007148742675781 used out of 20.52734375MB total
Now drawing frame 8
Loading frame 9...
Memory usage: 14.591201782226562 used out of 23.35546875MB total
Now drawing frame 9
Image 0 has been scrapped
Memory usage: 14.621696472167969 used out of 23.35546875MB total
Loading frame 0...
Memory usage: 16.21007537841797 used out of 26.1796875MB total
Now drawing frame 0
Now drawing frame 1
Now drawing frame 2
Now drawing frame 3
Now drawing frame 4
Now drawing frame 5
Now drawing frame 6
Now drawing frame 7
Now drawing frame 8
Now drawing frame 9
REPRODUCIBILITY :
This bug can be reproduced always.
---------- BEGIN SOURCE ----------
import java.lang.ref.*;
import java.awt.*;
import java.awt.event.*;
import java.awt.image.*;
import javax.swing.*;
public class PictureBox
extends JPanel
implements ActionListener
{
/** Controls playback speed by firing action events at specified intervals. */
Timer playTimer;
/** The width and height of the image displayed -
* obviously affects the size of the BufferedImage.*/
protected int imageWidth = 720;
protected int imageHeight = 576;
/** An array of all the images to be displayed. */
protected SoftReference[] allImages;
/** The next image in the sequence to be displayed.*/
protected int imageToBeDisplayed = 0;
protected BufferedImage lastKnownGood;
protected int lastKnownGoodIndex = -1;
Thread[] loaderThreads;
/**
* @param length number of frames in the sequence
* @param delay This is the delay between frames - the problem seems quite
* sensitive to this value, eg if it's down to 40ms, it might disappear
* altogether (depending on maxHeap). */
public PictureBox( int length, int delay)
{
setOpaque(false);
setPreferredSize(new Dimension(imageWidth, imageHeight));
// Set up image arrays with the correct number of slots
allImages = new SoftReference[length];
loaderThreads = new Thread[length];
playTimer = new Timer(delay, this);
//start loading the first frame
new LoaderThread(0).start();
}
/** Paints the image. If the current requested image is not
* loaded yet, tries to draw the last known good instead.
*
* @param g the graphics object to use for painting.
* */
protected void paintComponent(Graphics g)
{
if (allImages[imageToBeDisplayed] != null &&
allImages[imageToBeDisplayed].get() != null &&
imageToBeDisplayed != lastKnownGoodIndex)
{
lastKnownGood = (BufferedImage)allImages[imageToBeDisplayed].get();
lastKnownGoodIndex = imageToBeDisplayed;
System.out.println("Now drawing frame "+imageToBeDisplayed);
}
if (lastKnownGood == null)
//nothing to draw yet
return;
g.drawImage(lastKnownGood, 0, 0, imageWidth, imageHeight, this);
}
int loopCount = 0;
public void actionPerformed(ActionEvent ae)
{
//Check that the current image is fully loaded (and drawn)
//before we inadvertently create a skip-load of
//loading threads
if (lastKnownGoodIndex == imageToBeDisplayed)
{
imageToBeDisplayed++;
if (imageToBeDisplayed >= allImages.length)
{
//back to the beginning
imageToBeDisplayed = 0;
loopCount++;
if (loopCount ==2)
{
//should be enough to demonstrate the problem
System.exit(0);
}
}
if (allImages[imageToBeDisplayed] == null)
{
startLoaderThread(imageToBeDisplayed);
}
else if (allImages[imageToBeDisplayed].get() == null)
{
System.out.println("Image "+imageToBeDisplayed
+" has been scrapped");
updateMemoryUsage();
//have to re-load again
startLoaderThread(imageToBeDisplayed);
}
else
{
paintImmediately(getVisibleRect());
}
}
}
private void updateMemoryUsage()
{
long totalMem = Runtime.getRuntime().totalMemory();
System.out.println(" Memory usage: " +
( (totalMem - Runtime.getRuntime().freeMemory()) /
1048576.0) + " used out of " +
(totalMem / 1048576.0) + "MB total");
}
public static void main(String[] args)
{
int length = Integer.parseInt(args[0]);
int delay = Integer.parseInt(args[1]);
// Create a picture box in the scroll pane and set the picture box up.
PictureBox pictureBox = new PictureBox(length, delay);
JFrame mainFrame = new JFrame("SoftReference test case");
Container contentPane = mainFrame.getContentPane();
contentPane.setLayout(new BorderLayout());
contentPane.add(pictureBox, BorderLayout.CENTER);
mainFrame.setSize(800,620);
mainFrame.setVisible(true);
// Start the sequence playing .
pictureBox.playTimer.start();
}
protected void startLoaderThread(int imageIndex)
{
//check it's not being loaded already
if (loaderThreads[imageIndex] == null)
{
System.out.println("Loading frame "+imageIndex+"...");
new LoaderThread(imageIndex).start();
}
}
protected class LoaderThread
extends Thread
{
int myFrameIndex;
public LoaderThread (int frameIndex)
{
super("Loading frame "+frameIndex);
//set ourselves to highest priority
// this.setPriority(Thread.MAX_PRIORITY);
myFrameIndex = frameIndex;
loaderThreads[myFrameIndex] = this;
}
public void run()
{
BufferedImage image = new BufferedImage(imageWidth, imageHeight,
BufferedImage.TYPE_INT_RGB);
int[] temp = new int[imageWidth];
for (int i = 0; i < imageHeight; i++)
{
//transfer results to image buffer one line at a time
image.getRaster().setDataElements(0, i, imageWidth, 1, temp);
}
allImages[myFrameIndex] = new SoftReference(image);
repaint(getVisibleRect());
updateMemoryUsage();
//remove ourselves from the list of running threads
loaderThreads[myFrameIndex] = null;
}
}
}
---------- END SOURCE ----------
CUSTOMER SUBMITTED WORKAROUND :
As this is a cache, it is not the end of the world if you have to re-load some of the items. It would be nice to reflect to user that memory is low when cached items are getting scrapped, but it's certainly not the case.
java version "1.5.0_02"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_02-b09)
Java HotSpot(TM) Client VM (build 1.5.0_02-b09, mixed mode, sharing)
also with 1.5.0_04
FULL OS VERSION :
Microsoft Windows XP [Version 5.1.2600]
Windows NT ver 4.0 (SP6)
A DESCRIPTION OF THE PROBLEM :
A very clear problem of over-eager soft reference collection. I have reduced it to a (relatively) simple test case (below).
The cache contains a relatively small number of large objects.
These are created on the first run through the loop, with fixed timer delay between each one, and are then re-access on the second pass through.
Depending on the combination of delay and max heap size, some of the earlier frames in the cache have been scrapped by the time of the second pass, even though mem usage is nowhere near the max heap limit.
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run PictureBox class (under Test case) with the following command line params:
- size of cache (i've been running with 10)
- delay between creations and accesses of the items in cache, in ms
(anything between 30 and 1000 is possible in my actual app, but the results below are with 200).
Vary max heap between 32m and 200m, and see how many frames get scrapped before they are re-used, even though the actual mem requirement is about 16Mb (for 10 frames).
You can change the size of each item in the cache too, but only in the code - sorry.
EXPECTED VERSUS ACTUAL BEHAVIOR :
This is an example run, where only one frames get scrapped, with maxHeap of 64m. The memory usage printouts show that the actual memory requirement is nowhere near the limit:
Memory usage: 1.8503189086914062 used out of 3.5234375MB total
Now drawing frame 0
Loading frame 1...
Now drawing frame 1
Memory usage: 3.55059814453125 used out of 5.40625MB total
Loading frame 2...
Now drawing frame 2
Memory usage: 5.130615234375 used out of 6.4609375MB total
Loading frame 3...
Memory usage: 6.70855712890625 used out of 9.20703125MB total
Now drawing frame 3
Loading frame 4...
Now drawing frame 4
Memory usage: 6.683189392089844 used out of 9.20703125MB total
Loading frame 5...
Now drawing frame 5
Memory usage: 8.264122009277344 used out of 12.05078125MB total
Loading frame 6...
Now drawing frame 6
Memory usage: 9.848731994628906 used out of 14.87890625MB total
Loading frame 7...
Now drawing frame 7
Memory usage: 11.434623718261719 used out of 17.703125MB total
Loading frame 8...
Memory usage: 13.007148742675781 used out of 20.52734375MB total
Now drawing frame 8
Loading frame 9...
Memory usage: 14.591201782226562 used out of 23.35546875MB total
Now drawing frame 9
Image 0 has been scrapped
Memory usage: 14.621696472167969 used out of 23.35546875MB total
Loading frame 0...
Memory usage: 16.21007537841797 used out of 26.1796875MB total
Now drawing frame 0
Now drawing frame 1
Now drawing frame 2
Now drawing frame 3
Now drawing frame 4
Now drawing frame 5
Now drawing frame 6
Now drawing frame 7
Now drawing frame 8
Now drawing frame 9
REPRODUCIBILITY :
This bug can be reproduced always.
---------- BEGIN SOURCE ----------
import java.lang.ref.*;
import java.awt.*;
import java.awt.event.*;
import java.awt.image.*;
import javax.swing.*;
public class PictureBox
extends JPanel
implements ActionListener
{
/** Controls playback speed by firing action events at specified intervals. */
Timer playTimer;
/** The width and height of the image displayed -
* obviously affects the size of the BufferedImage.*/
protected int imageWidth = 720;
protected int imageHeight = 576;
/** An array of all the images to be displayed. */
protected SoftReference[] allImages;
/** The next image in the sequence to be displayed.*/
protected int imageToBeDisplayed = 0;
protected BufferedImage lastKnownGood;
protected int lastKnownGoodIndex = -1;
Thread[] loaderThreads;
/**
* @param length number of frames in the sequence
* @param delay This is the delay between frames - the problem seems quite
* sensitive to this value, eg if it's down to 40ms, it might disappear
* altogether (depending on maxHeap). */
public PictureBox( int length, int delay)
{
setOpaque(false);
setPreferredSize(new Dimension(imageWidth, imageHeight));
// Set up image arrays with the correct number of slots
allImages = new SoftReference[length];
loaderThreads = new Thread[length];
playTimer = new Timer(delay, this);
//start loading the first frame
new LoaderThread(0).start();
}
/** Paints the image. If the current requested image is not
* loaded yet, tries to draw the last known good instead.
*
* @param g the graphics object to use for painting.
* */
protected void paintComponent(Graphics g)
{
if (allImages[imageToBeDisplayed] != null &&
allImages[imageToBeDisplayed].get() != null &&
imageToBeDisplayed != lastKnownGoodIndex)
{
lastKnownGood = (BufferedImage)allImages[imageToBeDisplayed].get();
lastKnownGoodIndex = imageToBeDisplayed;
System.out.println("Now drawing frame "+imageToBeDisplayed);
}
if (lastKnownGood == null)
//nothing to draw yet
return;
g.drawImage(lastKnownGood, 0, 0, imageWidth, imageHeight, this);
}
int loopCount = 0;
public void actionPerformed(ActionEvent ae)
{
//Check that the current image is fully loaded (and drawn)
//before we inadvertently create a skip-load of
//loading threads
if (lastKnownGoodIndex == imageToBeDisplayed)
{
imageToBeDisplayed++;
if (imageToBeDisplayed >= allImages.length)
{
//back to the beginning
imageToBeDisplayed = 0;
loopCount++;
if (loopCount ==2)
{
//should be enough to demonstrate the problem
System.exit(0);
}
}
if (allImages[imageToBeDisplayed] == null)
{
startLoaderThread(imageToBeDisplayed);
}
else if (allImages[imageToBeDisplayed].get() == null)
{
System.out.println("Image "+imageToBeDisplayed
+" has been scrapped");
updateMemoryUsage();
//have to re-load again
startLoaderThread(imageToBeDisplayed);
}
else
{
paintImmediately(getVisibleRect());
}
}
}
private void updateMemoryUsage()
{
long totalMem = Runtime.getRuntime().totalMemory();
System.out.println(" Memory usage: " +
( (totalMem - Runtime.getRuntime().freeMemory()) /
1048576.0) + " used out of " +
(totalMem / 1048576.0) + "MB total");
}
public static void main(String[] args)
{
int length = Integer.parseInt(args[0]);
int delay = Integer.parseInt(args[1]);
// Create a picture box in the scroll pane and set the picture box up.
PictureBox pictureBox = new PictureBox(length, delay);
JFrame mainFrame = new JFrame("SoftReference test case");
Container contentPane = mainFrame.getContentPane();
contentPane.setLayout(new BorderLayout());
contentPane.add(pictureBox, BorderLayout.CENTER);
mainFrame.setSize(800,620);
mainFrame.setVisible(true);
// Start the sequence playing .
pictureBox.playTimer.start();
}
protected void startLoaderThread(int imageIndex)
{
//check it's not being loaded already
if (loaderThreads[imageIndex] == null)
{
System.out.println("Loading frame "+imageIndex+"...");
new LoaderThread(imageIndex).start();
}
}
protected class LoaderThread
extends Thread
{
int myFrameIndex;
public LoaderThread (int frameIndex)
{
super("Loading frame "+frameIndex);
//set ourselves to highest priority
// this.setPriority(Thread.MAX_PRIORITY);
myFrameIndex = frameIndex;
loaderThreads[myFrameIndex] = this;
}
public void run()
{
BufferedImage image = new BufferedImage(imageWidth, imageHeight,
BufferedImage.TYPE_INT_RGB);
int[] temp = new int[imageWidth];
for (int i = 0; i < imageHeight; i++)
{
//transfer results to image buffer one line at a time
image.getRaster().setDataElements(0, i, imageWidth, 1, temp);
}
allImages[myFrameIndex] = new SoftReference(image);
repaint(getVisibleRect());
updateMemoryUsage();
//remove ourselves from the list of running threads
loaderThreads[myFrameIndex] = null;
}
}
}
---------- END SOURCE ----------
CUSTOMER SUBMITTED WORKAROUND :
As this is a cache, it is not the end of the world if you have to re-load some of the items. It would be nice to reflect to user that memory is low when cached items are getting scrapped, but it's certainly not the case.