Kurious: java speicherverbrauch bei list & iterator

Roughael · Beitrag von **Roughael** » 02.08.2012, 00:43

ich experimentiere gerade etwas mit NIO, dabei fällt mir auf dass mein simpler ping/pong server 360 MB speicher verbraucht.
Der client hingegen gerade mal 12MB.
Nochmal ausprobiert, selbes resultat und es geschieht schon vor jeglicher verbindung.
Nach einigem auskommentieren komm ich zum Schluss es ist die Nachrichtenannahme:

Code: Alles auswählen

Iterator<NetConnection> it = connections.iterator();
while (it.hasNext()) {
	NetConnection connection = it.next();
//.....
}

Da zu dem zeitpunkt noch keine verbindungen vorhanden sind, sollte hier jedoch die Schleife nicht durchlaufen werden.
Wird sie auch nicht. Nach auskommentieren jeglichen codes innerhalb der schleife steht der verbrauch noch immer bei 360MB.
Kommentiere ich die schleife selbst aus, so sind es lediglich 10 MB.

Nun denke ich, eventuell ist es ein Iterator bug.
Nehme eine for each schleife statt dessen und sehe auch hier ist das problem.
Könnte mir jedoch vorstellen dass die for each schleife auf den iterator zugreift.
Tausche ich die ArrayList<NetConnection> gegen eine LinkedList kommt noch immer das gleiche heraus.

Dann schreib ich das ganze so um, dass es nur mit .get() arbeitet:

Code: Alles auswählen

int max = connections.size();
for(int i=0; i<max; i++) {
	NetConnection connection = connections.get(i);

und siehe da: nur 12 MB.

Kann mir jemand dieses phänomen erklären ?

Habe mal einen minimal testcase geschrieben, der das problem reproduziert:

Code: Alles auswählen

import java.util.ArrayList;

public class Main {

	public static void main(final java.lang.String[] args) {
		ArrayList<Object> connections = new ArrayList<>();
		for (; ;) {
			for (Object c : connections) {
			}
		}
	}
}

Sobald man jedoch ein sleep in die endlosschleife baut, sei es noch so klein, ist der effekt nichtmehr sichtbar.

spid · Beitrag von **spid** » 02.08.2012, 10:35

Code: Alles auswählen

[spidey:/tmp]% java -XX:+PrintGCDetails Main                   
[GC [PSYoungGen: 31872K->384K(37120K)] 31872K->384K(121856K), 0.0015520 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
[GC [PSYoungGen: 32256K->320K(68992K)] 32256K->320K(153728K), 0.0013460 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 64064K->368K(68992K)] 64064K->368K(153728K), 0.0010550 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 64112K->256K(132736K)] 64112K->256K(217472K), 0.0008890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 127744K->336K(132736K)] 127744K->336K(217472K), 0.0018120 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 127824K->320K(255424K)] 127824K->320K(340160K), 0.0010790 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 255296K->0K(255424K)] 255296K->248K(340160K), 0.0011080 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 254976K->0K(510464K)] 255224K->248K(595200K), 0.0005300 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 509952K->0K(510464K)] 510200K->248K(595200K), 0.0008980 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 509952K->0K(677312K)] 510200K->248K(762048K), 0.0005350 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677312K)] 676984K->248K(762048K), 0.0006520 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677312K)] 676984K->248K(762048K), 0.0006550 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677312K)] 676984K->248K(762048K), 0.0014590 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677184K)] 676984K->248K(761920K), 0.0005250 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677248K)] 676984K->248K(761984K), 0.0005890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676736K->0K(677376K)] 676984K->248K(762112K), 0.0003770 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676864K->0K(677376K)] 677112K->248K(762112K), 0.0008830 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676864K->0K(677248K)] 677112K->248K(761984K), 0.0007600 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676864K->0K(677312K)] 677112K->248K(762048K), 0.0012480 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 676864K->0K(644608K)] 677112K->248K(729344K), 0.0004850 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 644544K->0K(677056K)] 644792K->248K(761792K), 0.0010780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Ohne Heap-Beschränkung nimmt die JVM soviel wie sie braucht. Wie du an der Masse der New-GCs siehst, erzeugt deine Schleife eben ziemlich viel Garbage. Etwa soviel, daß sie bei mir (i7 @ 3.4 GHz) sogar 677 MB frisst.

Mit dem ParNew hingegen braucht die JVM schonmal wesentlich weniger:

Code: Alles auswählen


[spidey:/tmp]% java -XX:+UseParNewGC -XX:+PrintGCDetails Main
[GC [ParNew: 33920K->232K(38144K), 0.0015520 secs] 33920K->232K(122880K), 0.0016180 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
[GC [ParNew: 34152K->253K(38144K), 0.0012830 secs] 34152K->253K(122880K), 0.0013380 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34173K->237K(38144K), 0.0008660 secs] 34173K->237K(122880K), 0.0009090 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34157K->266K(38144K), 0.0006340 secs] 34157K->266K(122880K), 0.0006780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34186K->239K(38144K), 0.0012090 secs] 34186K->239K(122880K), 0.0012520 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34159K->263K(38144K), 0.0008270 secs] 34159K->263K(122880K), 0.0008820 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34183K->295K(38144K), 0.0008440 secs] 34183K->295K(122880K), 0.0008880 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC [ParNew: 34215K->246K(38144K), 0.0007920 secs] 34215K->246K(122880K), 0.0008360 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34166K->261K(38144K), 0.0007070 secs] 34166K->261K(122880K), 0.0007550 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34181K->274K(38144K), 0.0005540 secs] 34181K->274K(122880K), 0.0006080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34194K->264K(38144K), 0.0008720 secs] 34194K->264K(122880K), 0.0009200 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34184K->228K(38144K), 0.0007080 secs] 34184K->228K(122880K), 0.0007880 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34148K->285K(38144K), 0.0007380 secs] 34148K->285K(122880K), 0.0008100 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34205K->269K(38144K), 0.0006150 secs] 34205K->269K(122880K), 0.0006570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34189K->264K(38144K), 0.0006740 secs] 34189K->264K(122880K), 0.0007260 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [ParNew: 34184K->40K(38144K), 0.0007650 secs] 34184K->261K(122880K), 0.0008380 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

weil Default-Werte für den New- und Old-Space gesetzt werden. Genauso gut hätte ich auch -Xms und -Xmx setzen können, aber so wollte ich ausserdem noch für einen besseren GC Werbung machen

Du solltest eh einen feste Heap-Größe definieren, um die ständigen Größenveränderungen des Heaps zu verhindern. Die führen zu teils unerwünschten Effekten, bspw. zu frühen Ausführungen des CMS-GCs, wenn du den verwendest.