Falsche Werte bei Zeitmessungen

[pzypher]

Hallo,

das Programm soll folgende Funktion erfüllen:

Das Programm soll als Testsuite dienen, in der ein (mehr oder weniger) beliebiger Code eingefügt werden kann, um Ausführungszeiten zu messen und bewerten. Es wird der eingefügte Testcode für 100000, 1000000, 10000000, 100000000, 1000000000 mal jeweils 10x iteritiert und danach der Durchschnitt gebildet. Zusätzlich werden die Ergebnisse ausgegeben und in eine Excel Datei geschrieben (das für das Problem jedoch nicht relevant ist).

Das Programm ist so lauffähig, zum Ausprobieren muss die jExcel api integriert sein.

import java.util.Scanner;
import java.io.File;
import java.io.IOException;
import jxl.Workbook;
import jxl.read.biff.BiffException;
import jxl.write.Label;
import jxl.write.Number;
import jxl.write.NumberFormats;
import jxl.write.WritableCellFormat;
import jxl.write.WritableSheet;
import jxl.write.WritableWorkbook;
import jxl.write.WriteException;
import jxl.write.biff.RowsExceededException;

public class Main {
	
	public static void main(String[] args) throws BiffException, IOException, RowsExceededException, WriteException {

	Scanner sc = new Scanner(System.in);
	
	 WritableCellFormat numberFormat = new WritableCellFormat(
             NumberFormats.FLOAT);
	 
    int currentColumn = 0;
    int currentRow = 0;
    int[] messungen = {100000, 1000000, 10000000, 100000000, 1000000000 };
	long[] zeiten = new long[10];
	long startTime;
	float durchschnittsZeit = 0;
     
	Workbook workbookold = Workbook.getWorkbook(new File("/home/enigma/LaufzeitMessungen.xls")); //Holt sich die zuletzt angelegte xls-Datei falls existent
	WritableWorkbook workbooknew = Workbook.createWorkbook(new File("/home/enigma/LaufzeitMessungen.xls"),workbookold);
	WritableSheet sheet = workbooknew.getSheet(0);
	
	if(sheet.getCell(0, 0).equals(null)) {
	    sheet.addCell(new Label(currentColumn, currentRow, "n"));
	    sheet.setColumnView(currentColumn++, 20);
	    
		for(int spaltenInit = 0; spaltenInit < 5; spaltenInit++) {
			sheet.addCell(new Label(currentColumn++, currentRow, String.valueOf(messungen[spaltenInit])));
			sheet.setColumnView((spaltenInit+1), 15);
		}
	}

	currentRow = sheet.getRows();
	currentColumn = 0;
	
	System.out.print("Geben Sie einen Namen für diese Messung an: ");
	sheet.addCell(new Label(currentColumn++, currentRow, sc.next()));
	
	
	for(int messung = 0; messung < 5; messung++) { //Die 5 unterschiedlichen Messungen (100000, 1000000 etc)
		
		System.out.println("Messung "+(messung+1)+" ("+messungen[messung]+")");
	
		for(int currentTimePos=0; currentTimePos < 10; currentTimePos++) { //1 von 10 Durchläufen...
			
			int iterMessung = 0;
			
			startTime = System.nanoTime();
			
			while(iterMessung < messungen[messung]) { //10000xxx Durchläufe...
				
				
				
				//HIER DEN CODE ZUM TESTEN EINFÜGEN
				
				
				
				iterMessung++;
			}
			
			zeiten[currentTimePos] = System.nanoTime()-startTime;
			
		}
		
		for(int currentTimePos=0; currentTimePos < 10; currentTimePos++) { //Durchschnitt berechnen
			durchschnittsZeit += zeiten[currentTimePos];
			System.out.println("Zeit im Durchlauf "+(currentTimePos+1)+": "+zeiten[currentTimePos]+"ns");
		}
		
		durchschnittsZeit /= 10;
		sheet.addCell(new Number(currentColumn++, currentRow, durchschnittsZeit, numberFormat));
		System.out.println("Durchschnittszeit: "+durchschnittsZeit);
		durchschnittsZeit=0;
	}
	
	System.out.println("Finished - Die Datei wurde unter /home/enigma/LaufzeitMessungen.xls abgespeichert.");
	
    workbooknew.write();
    workbooknew.close();
    workbookold.close();
	}
}

Mein Problem ist nun, dass ich sehr merkwürdige Zeiten bekomme:

Hier ein Durchlauf ohne Code (leere Iterationen), warum dauert die erste Messung mit nur 100000 Iterationen so viel länger als mit z.B 1000000000 Durchläufen?

Geben Sie einen Namen für diese Messung an: Test
Messung 1 (100000)
Zeit im Durchlauf 1: 5419246ns
Zeit im Durchlauf 2: 3714611ns
Zeit im Durchlauf 3: 2672735ns
Zeit im Durchlauf 4: 2134511ns
Zeit im Durchlauf 5: 1099092ns
Zeit im Durchlauf 6: 1097934ns
Zeit im Durchlauf 7: 1074456ns
Zeit im Durchlauf 8: 309ns
Zeit im Durchlauf 9: 308ns
Zeit im Durchlauf 10: 309ns
Durchschnittszeit: 1721350.8
Messung 2 (1000000)
Zeit im Durchlauf 1: 11065311ns
Zeit im Durchlauf 2: 7307529ns
Zeit im Durchlauf 3: 304ns
Zeit im Durchlauf 4: 311ns
Zeit im Durchlauf 5: 307ns
Zeit im Durchlauf 6: 304ns
Zeit im Durchlauf 7: 307ns
Zeit im Durchlauf 8: 303ns
Zeit im Durchlauf 9: 310ns
Zeit im Durchlauf 10: 308ns
Durchschnittszeit: 1837529.8
Messung 3 (10000000)
Zeit im Durchlauf 1: 431ns
Zeit im Durchlauf 2: 358ns
Zeit im Durchlauf 3: 374ns
Zeit im Durchlauf 4: 351ns
Zeit im Durchlauf 5: 361ns
Zeit im Durchlauf 6: 369ns
Zeit im Durchlauf 7: 360ns
Zeit im Durchlauf 8: 362ns
Zeit im Durchlauf 9: 334ns
Zeit im Durchlauf 10: 369ns
Durchschnittszeit: 366.9
Messung 4 (100000000)
Zeit im Durchlauf 1: 397ns
Zeit im Durchlauf 2: 343ns
Zeit im Durchlauf 3: 350ns
Zeit im Durchlauf 4: 366ns
Zeit im Durchlauf 5: 351ns
Zeit im Durchlauf 6: 349ns
Zeit im Durchlauf 7: 349ns
Zeit im Durchlauf 8: 389ns
Zeit im Durchlauf 9: 362ns
Zeit im Durchlauf 10: 374ns
Durchschnittszeit: 363.0
Messung 5 (1000000000)
Zeit im Durchlauf 1: 403ns
Zeit im Durchlauf 2: 354ns
Zeit im Durchlauf 3: 373ns
Zeit im Durchlauf 4: 430ns
Zeit im Durchlauf 5: 351ns
Zeit im Durchlauf 6: 338ns
Zeit im Durchlauf 7: 355ns
Zeit im Durchlauf 8: 357ns
Zeit im Durchlauf 9: 370ns
Zeit im Durchlauf 10: 339ns
Durchschnittszeit: 367.0
Finished - Die Datei wurde unter /home/enigma/LaufzeitMessungen.xls abgespeichert.

Thx!

 

[timbeau]

Initialisierung der VM z.B., einlesen des Files von der Platte in den Speicher. Die ersten 5 Durchläufe wegschmeissen wäre mein Tip.

 

[pzypher]

Aber zu stoppen fängt er doch viel später an, das Einlesen geschieht schon früher?

Und auch dann erklärt es (mMn) nicht, warum die Durchläufe bei 1 Mia. gleich lang dauern, wie bei 100 Mio?

 

[SlaterB]

der Grund dürfte hier in der Tat ein anderer sein bzw. zusätzlich:
Optimierung des Java-Compilers, irgendwann merkt der dass da nichts passiert, und kürzt die Schleifen ab,
finde ich auch immer wieder erstaunlich, hier mit so klaren Zahlen scheint es aber eindeutig,

ich führen in meinen Tests, so kurz sie auch sind, immer irgendwas durch, alle Zahlen von 1 bis n addieren (und zur Kontrolle auch mitausgeben),
das zum Endergebnis zu optimieren wäre schon etwas gewagter, obwohl innerhalb einer Methode durchaus denkbar wie ich jetzt bewerte,
mit einem Instanzattribut, welches vorher auf 0 gesetzt wird, schon eher nicht mehr, das hat ja gewaltige Nebeneffekte

 

[pzypher]

der Grund dürfte hier in der Tat ein anderer sein bzw. zusätzlich:
Optimierung des Java-Compilers, irgendwann merkt der dass da nichts passiert, und kürzt die Schleifen ab,
finde ich auch immer wieder erstaunlich, hier mit so klaren Zahlen scheint es aber eindeutig

Treffer! Stichwort: Loop unrolling ? Wikipedia Habs mit einer einfachen Ausgabe durchlaufen lassen und siehe da - die Zeiten stimmen.

das zum Endergebnis zu optimieren wäre schon etwas gewagter, obwohl innerhalb einer Methode durchaus denkbar wie ich jetzt bewerte,
mit einem Instanzattribut, welches vorher auf 0 gesetzt wird, schon eher nicht mehr, das hat ja gewaltige Nebeneffekte

Kannst du mir das bitte nochmal erläutern? ^^

 

[SlaterB]

hast du denn den vorherigen Satz
> ich führe in meinen Tests, so kurz sie auch sind, immer irgendwas durch, alle Zahlen von 1 bis n addieren (und zur Kontrolle auch mitausgeben)
verstanden?
dasselbe nun mit einem Instanzattribut statt einer lokalen Variable für die Summe, das ist doch keine große Änderung,
und wie gesagt in der Hoffnung/ Annahme, dass das noch weniger optimiert wird, denn ein Instanzattribut ist z.B. nach außen für andere Threads sichtbar, da wäre es schon ein Unterschied ob die Variable hochgezählt wird oder auf das Endergebnis springt

Loop unrolling
muss nicht unbedingt optimieren, hier passt es vielleicht weil die Schleife leer ist,
aber allgemein gibt es da glaube ich noch andere Fachbegriffe

 

[SlaterB]

das hier kann es vielleicht auch sein, was dann nicht unbedingt Verkürzung der Schleife, sondern vielleicht nur schnellere Ausführung bedeutet,
wobei leere Schleife wirklich ein Sonderfall zur extremen Abkürzung sein könnte

Just-in-time compilation - Wikipedia, the free encyclopedia

One possible optimization, used by Sun's HotSpot Java Virtual Machine, is to combine interpretation and JIT compilation. The application code is initially interpreted, but the JVM monitors which sequences of bytecode are frequently executed and translates them to machine code for direct execution on the hardware. For bytecode which is executed only a few times, this saves the compilation time and reduces the initial latency; for frequently executed bytecode, JIT compilation is used to run at high speed, after an initial phase of slow interpretation. Additionally, since a program spends most time executing a minority of its code, the reduced compilation time is significant. Finally, during the initial code interpretation, execution statistics can be collected before compilation, which helps to perform better optimization.[3]

gut möglich dass ansonsten Schleifen überhaupt nicht gegen Endergebnisse ausgetauscht werden,
in solchen Bereichen merke ich mir gerne falsche Dinge

 

[pzypher]

Alles klar, danke!