Zeitmessung in C++ eines externen Programms

[Kobe]

Hallo

Ich habe in C++ mir bereits 2 Funktionen für die Zeitmessung geschrieben

Code: Alles auswählen

// fuer zeitmessung
#include<sys/times.h>
#include<unistd.h>

	//! parameter fuer die zeitmessung
	struct tms x1,x2;
	//! parameter fuer die zeitmessung
	long ticks;
	//! parameter fuer die zeitmessung
	float tu,ts;

void TinaHandling::setTimeStart()
{
	ticks=sysconf(_SC_CLK_TCK);  //maschinenspezifische Ticks der Uhr
	times(&x1);	
}

void TinaHandling::setTimeEnd(string Message)
{
	// ende zeitmessung
	times(&x2);
	tu=(x2.tms_utime-x1.tms_utime)/ ( (float) ticks);
	ts=(x2.tms_stime-x1.tms_stime)/ ( (float) ticks);
	cout << "user: " << tu << " sec  system: " << ts << " sec : \t" << Message << endl;
}

Nun rufe ich in diesem C++ Konstrukt ein externes Programm auf

Code: Alles auswählen

	setTimeStart();

	ostringstream cmd;
	// kommando zum ausfuehren "./tina output.abs.net > output.abs.tina
	// -Cm ZAHL damit "A -> A B" erkannt wird: 0 macht falsche Aequivalenzklassen, besser 1
	// -g keine Liveness-Analyse
	// -lt : Aktionen anstatt Transitionen im Erreichbarkeitsgraph "0 -> a/1, b/5"
	cmd << Tina << " -Cm " << CMDepth << " -g " << filename_net << " > " << filename_abs << ".tina";
	// TODO: Zeitmessung stimmt nicht, es wird nicht auf das System gewartet, Zeit ist immer 0s!
	system(cmd.str().c_str());

	setTimeEnd("Tina hat die Analyse beendet");

Er wartet nicht, bis das System das Kommando beendet hat sondern gibt immer 0s aus. Allerdings kommt diese Ausgabe erst nachdem der Befehl fertig abgearbeitet wurde.
Wie kann ich sagen, er soll bei der Zeitmessung auf das Ende vom Systembefehl warten?


mfg
Stephan

[schorsch_76]

Hi,

ich nutze für Solche Sachen sowohl unter M$ Windows als auch unter Linux boost::date_time. Soweit ich weis ist boost vorgesehen im neuen C++ Standard aufgenommen zu werden.

Hier ein Beispiel:

Code: Alles auswählen

#include <iostream>

#include <boost/date_time/posix_time/posix_time.hpp>


namespace pt = boost::posix_time;

int main(int argc, const char** argv)
{
	pt::ptime t1 = pt::microsec_clock::universal_time();
	for (int i = 0; i < 10e6;++i)
	{
		int a = i * 5;
	}

	pt::ptime t2 = pt::microsec_clock::universal_time();

	std::cout << "Zeit: " << (t2-t1).total_microseconds() << "u sec" << std::endl;
	return 0;
}

Code: Alles auswählen

./zeit 
Zeit: 87374u sec

Gruß

schorsch

EDIT:
Hier der Link zu boost http://www.boost.org/doc/libs/1_37_0/do ... _time.html

[The Torso]

Soweit ich weis ist boost vorgesehen im neuen C++ Standard aufgenommen zu werden.

Soweit ich weiss sind nur Teile von boost wirklich als C++ Standard vorgesehen, oder taeusch ich mich da?

[schorsch_76]

Da bin ich mir eben nicht ganz sicher was dazukommt und nicht. Ich lese die mailingliste nicht
de.comp.lang.iso-c++ behandelt aber eigentlich alle boost themen da die Moderatoren sagen dass boost eh bald dazugehöre. Aber wie gesagt ... ich bin nicht ganz sicher was alles dazukommt und was nicht

Gruß

schorsch

[Kobe]

Danke, das sieht schon besser aus.
Jetzt muss ich mich aber erstmal erkundigen, ob boost auf dem Server installiert ist.

[cosmac]

hi,

nochmal zurück zum Anfang: deine Zeitmessung liefert die Zeiten für das aufrufende Programm. Da das nichts weiter tut, als auf tina zu warten, sollte dabei tatsächlich 0 rauskommen. Die gewünschten Zeiten bekommst du (hoffentlich; ungetestet) mit getrusage(RUSAGE_CHILDREN, &x2) nach dem system().

Wenn das nicht klappt, müsstest du system() durch fork(), exec() und wait3() ersetzen. Oder, etwas seltsamer, mit popen() und time(1) und dessen Ausgabe parsen.

[gms]

nochmal zurück zum Anfang: deine Zeitmessung liefert die Zeiten für das aufrufende Programm. Da das nichts weiter tut, als auf tina zu warten, sollte dabei tatsächlich 0 rauskommen.

völlig korrekt

Die gewünschten Zeiten bekommst du (hoffentlich; ungetestet) mit getrusage(RUSAGE_CHILDREN, &x2) nach dem system().

alternativ könnten auch die tms_cutime bzw tms_cstime verwendet werden, damit werden auch die Child-Prozesse einbezogen

Gruß
gms

[cosmac]

Kaffeemangel

[gms]

Kaffeemangel

Ich hatte gerade Kaffee mit Gugelhupf

[Kobe]

Hallo cosmac

alternativ könnten auch die tms_cutime bzw tms_cstime verwendet werden, damit werden auch die Child-Prozesse einbezogen

Meinst du das so?

Code: Alles auswählen

   tu=(x2.tms_cutime-x1.tms_cutime)/ ( (float) ticks);
   ts=(x2.tms_cstime-x1.tms_cstime)/ ( (float) ticks);

Das funktioniert nicht; zeigt ebenfalls immer 0.

Die gewünschten Zeiten bekommst du (hoffentlich; ungetestet) mit getrusage(RUSAGE_CHILDREN, &x2) nach dem system().

Insofern ich keinen Fehler habe, klappt es nicht. Kommt immernoch nur 0 raus.

Code: Alles auswählen

void setTimeEnd(string Message)
{
	// ende zeitmessung
	times(&x2);
	tu=(x2.tms_cutime-x1.tms_cutime)/ ( (float) ticks);
	ts=(x2.tms_cstime-x1.tms_cstime)/ ( (float) ticks);
	cout << Message << "\tuser: " << tu << " sec  system: " << ts << " sec" << endl;

	struct rusage usage;
	cout << getrusage(RUSAGE_CHILDREN, &usage) << endl;
	cout << usage.ru_utime.tv_usec << "    " << usage.ru_stime.tv_usec << endl;
}

Bei 'setTimeStart()' habe ich nichts geändert.

Wenn das nicht klappt, müsstest du system() durch fork(), exec() und wait3() ersetzen. Oder, etwas seltsamer, mit popen() und time(1) und dessen Ausgabe parsen.

Werde ich das wohl mal probieren müssen.

[Kobe]

Es tut mir leid, aber ich bekomme keine Zeitmessung hin, außer boost.

Code: Alles auswählen

#include <string>
#include <iostream>

using namespace std;

// fuer zeitmessung mit boost
#include <boost/graph/depth_first_search.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>

namespace pt = boost::posix_time;

// fuer zeitmessung mit ticks
#include<sys/times.h>
#include<unistd.h>

#include<sys/resource.h>

// parameter fuer die zeitmessung mit ticks
struct tms x1,x2;
long ticks;
float tu,ts,tcu,tcs;

void setTimeStart()
{
	ticks=sysconf(_SC_CLK_TCK);  //maschinenspezifische Ticks der Uhr
	times(&x1);
}

void setTimeEnd(string Message)
{
	// ende zeitmessung
	times(&x2);
	tu=(x2.tms_utime-x1.tms_utime)/ ( (float) ticks);
	ts=(x2.tms_stime-x1.tms_stime)/ ( (float) ticks);
	cout << Message << "\tuser: " << tu << " sec  system: " << ts << " sec" << endl;
	tcu=(x2.tms_cutime-x1.tms_cutime)/ ( (float) ticks);
	tcs=(x2.tms_cstime-x1.tms_cstime)/ ( (float) ticks);
	cout << Message << "\tuser: " << tcu << " sec  system: " << tcs << " sec" << endl;

	struct rusage usage;
	getrusage(RUSAGE_CHILDREN, &usage);
	cout << "getrusage\tutime=" << usage.ru_utime.tv_usec << " sec  stime=" << usage.ru_stime.tv_usec << endl;
}

#include <sys/wait.h> // waitpid()

int main(int argc, char** argv)
{
	// zeitmessung start
	pt::ptime t1 = pt::microsec_clock::universal_time();
	setTimeStart();

	// zeit verstreichen lassen
	//cout << "Enter druecken"; getchar();
	pid_t cpid,child_pid;
	cpid = fork();
	switch (cpid) {
		case -1: printf("Fork failed; cpid == -1\n");
			break;
		
		case 0: child_pid = getpid();
			printf("this is the child, pid = %d\n", child_pid);
			//system("vim test.cpp");
			//execvp("vim test.cpp", NULL);
			//getchar();
			sleep(1);
			exit(0);
		
		default: printf("This is the parent: waiting for %d to finish\n", cpid);
			waitpid(cpid, NULL, 0);
			printf("Ttttthat's all, folks\n");
	}

	// zeitmessung ende
	pt::ptime t2 = pt::microsec_clock::universal_time();
	cout << "Zeit mit Boost:\t" << ((t2-t1).total_microseconds())/1000/1000.0 << "s sec" << endl;
	setTimeEnd("Mit Ticks");

	return 0;
}

Was mache ich falsch?

[gms]

Was mache ich falsch?

nachdem ich gerade wenig Zeit habe, kann ich dir das leider auch nicht sagen. Ich habe mir nur deinen Sourcecode hergenommen, etwas modifiziert ( ich denke aber keine wesentlichen Änderungen gemacht ) und bei mir funktionierts:
http://nopaste.debianforum.de/18377

Code: Alles auswählen

gms@gms2 ~ $ g++ -o x x.cpp
gms@gms2 ~ $ ./x
tar: Entferne führende „/“ von Elementnamen

real    0m18.218s
user    0m16.036s
sys     0m0.591s
Mit Ticks       user: 16.03 sec  system: 0.59 sec

Die Zeilen mit "real", "user", "sys" stammen vom "time" Kommando und stimmen ganz gut mit den ermittelten Werten überein

Gruß
gms

[Kobe]

Code: Alles auswählen

system("time vim x.cpp");

Geht. Aber so habe ich die Zeit in der Konsole bzw. als Ausgabe auf die Konsole.
Ich brauche die Zeit im Programm, so dass ich es in einem bestehenden Ausgabestrom reinhängen kann.


//edit:
Nach der Installation von boost, findet er den Befehl 'system()' nicht mehr, solange ich nicht

Code: Alles auswählen

#include <boost/date_time/posix_time/posix_time.hpp>

einbinde. Was soll das denn???

[gms]

Code: Alles auswählen

system("time vim x.cpp");

Geht. Aber so habe ich die Zeit in der Konsole bzw. als Ausgabe auf die Konsole.
Ich brauche die Zeit im Programm, so dass ich es in einem bestehenden Ausgabestrom reinhängen kann.

na wenn du ein bißchen die Augen aufmachen würdest, dann würdest du erkennen, daß die Zeiten zweimal ausgegeben werden, einmal von "time" und einmal vom Programm und wenn du dann noch diese Zeiten vergleichst, dann wirst du auch noch feststellen, daß diese Zeiten ziemlich gleich sind

[Kobe]

Stimmt, bei dir stehen dann wirklich die Zeiten. Das habe ich übersehen, da es bei mir nicht der Fall ist

Code: Alles auswählen

$ ./x

real    0m12.448s
user    0m0.000s
sys     0m0.012s
Mit Ticks       user: 0 sec system: 0.02 sec

Ich habe als Befehl "time vim x.cpp":

Code: Alles auswählen

#include <string>
#include <iostream>

using namespace std;

// fuer zeitmessung mit ticks
#include<sys/times.h>
#include<unistd.h>

#include<boost/date_time/posix_time/posix_time.hpp>

// parameter fuer die zeitmessung mit ticks
struct tms x1,x2;
double ticks;
float tu,ts,tcu,tcs;

void setTimeStart()
{
	ticks=sysconf(_SC_CLK_TCK); //maschinenspezifische Ticks der Uhr
	times(&x1);
}

void setTimeEnd(string Message)
{
	// ende zeitmessung
	times(&x2);
	tcu=(x2.tms_cutime-x1.tms_cutime)/ticks;
	tcs=(x2.tms_cstime-x1.tms_cstime)/ticks;
	cout << Message << "\tuser: " << tcu << " sec system: " << tcs << " sec" << endl;
}


int main(int argc, char** argv)
{
	// zeitmessung start
	setTimeStart();
	system("time vim x.cpp");
	setTimeEnd("Mit Ticks");
	
	return 0;
} 

Den boost-Header brauche ich zur Zeit wegen dem system-Befehl. Ich werde mal boost deinstallieren, ob es daran liegt.

//edit
Ok, system ist in

Code: Alles auswählen

#include <stdlib.h>

aber die korrekte Zeitmessung ist bei mir immernoch nicht.


//edi2
Kann es sein, dass ein vim Aufruf schlecht zum testen ist?
Wenn ich mein eigentlich zu messendes Prog aufrufe kommt immerhin

Code: Alles auswählen

real    0m13.949s
user    0m4.064s
sys     0m7.448s
Mit Ticks       user: 4.06 sec system: 7.45 sec

[Kobe]

Sooooooooooooooo, danke euch allen.

Wichtig sind 'tms_cutime' bzw. 'tms_cstime'

Code: Alles auswählen

void TinaHandling::setTimeEnd(string Message)
{
	// ende zeitmessung
	times(&x2);
//	tu=(x2.tms_utime-x1.tms_utime)/ ( (float) ticks);
//	ts=(x2.tms_stime-x1.tms_stime)/ ( (float) ticks);
	tu=(x2.tms_cutime-x1.tms_cutime)/(float)ticks;
	ts=(x2.tms_cstime-x1.tms_cstime)/(float)ticks;
	cout << "user: " << tu << " sec  system: " << ts << " sec : \t" << Message << endl;
}

und dass dem system-Befehl ein 'time ' vorangestellt wird.

Das einzige was mich noch ein wenig stört, ist die Ausgabe von 'time', die ich eigentlich nicht möchte - weder auf der Konsole noch in einem Logfile. Der 'time' Befehl ist ja nur nötig damit die Zeit korrekt berechnet wird.

Wobei es nicht mal ins Logfile gepipet wird

Code: Alles auswählen

$ ./x > log
WARNING: priorities forgotten

real    0m11.492s
user    0m3.352s
sys     0m5.360s

PS: Nach erneutem Testen geht es nun sogar ohne 'time'.

PPS: Das 'WARNING: priorities forgotten' kommt von dem Tool, das ich aufrufe.