Zeitmessung mit boost in Verbindung mit Java Server

dispy

Moin,

Kontext:

Ich entwickele momentan ein Programm, das auf Anfragen eines Servers (Java), innerhalb von 2 Sekunden antworten muss.
Wenn diese zwei Sekunden von meinem Programm überschritten werden, so gibt der Server ein Timeout zurück.

Das Schema von dem Script, welches ich benutze:

startTimeMeasurement();
receiveAllRequests();
answerAllRequests();
OutputTimeMeasurement();

Die Kommunikation erfolgt über XML und Sockets, dafür benutze ich boost::asio low-Level-funktionen (write, read, mehr nicht).
Tests haben ergeben, dass es für den Timeout-Fehler unerheblich ist, ob receiveAllRequests(); answerAllRequests(); etwas Sinnvolles tut oder nur Zeit verschwendet.

Kompilierung:
Das Script habe ich sowohl unter Win XP 32bit (MingW TDragon) als auch unter Linux Ubuntu 32bit (GCC mitgeliefert) komiliert.

Das Programm wird auf dem Server ausgeführt, auf dem eine virtuelle Maschine (kA, welche genau) mit Ubuntu 32bit Server Edition läuft. Wenn ich ein Windows-Kompilat hochlade, wird das per Wine ausgeführt.

Problem:
Der Server behauptet, mein Programm habe länger als 2 Sekunden gebraucht (Timeout-Antwort). Mein Programm wiederum behauptet, es hätte nur ca. 1,7 Sekunden gedauert.

Ich habe die Zeit auf zweierlei Weise ermittelt:
boost::timer, wobei ich CLOCKS_PER_SEC an das System zur Laufzeit mit einem Umrechnungsfaktor angepasst habe
boost::date_time mit einer Auflösung von Millisekunden

Beide geben Zeiten um 1,7 zurück - also deutlich unter 2.

Ich habe einen Freund gefragt, der hat dann ein Dummy-Programm in Java verfasst, das einfach nur 1,7 Sekunden wartet und dann etwas Sinnloses zurückgibt - das funktioniert prima.

Schlusswort:
Ich habe überhaupt keine Ahnung, was mit meinem Programm schief laufen könnte. Insbesondere, da Tests eben zeigen, dass die Logik meines Programms keinen Einfluß auf die widersprüchlichen Zeitangaben hat.
Ich bin den Code schon mehrfach durchgegangen, aber mir ist nie was in die Augen gesprungen, was damit zu tun haben könnte.

Ich bin für jeden Hinweis dankbar

MfG

Codeauszüge:

while(!trans.hasEnded()){

        Timer timer;
        std::string input = con.readAll();

        if(input.size() != 0){

            if(!parse(input)){
                throw std::runtime_error("ProtocolClient::runLoop() Unable to parse chunk");
            }

            std::cout<<"Altogether that were "<<timer.elapsed() <<" seconds."<<std::endl;
        }
    }

Timer.h:

#ifndef TIMER_H
#define TIMER_H

#include <boost/date_time.hpp>

using namespace boost::posix_time;

class Timer{
    protected:
        ptime t1;

    public:
        Timer(): t1(microsec_clock::local_time()){}

        float elapsed() const{
            return (ptime(microsec_clock::local_time()) - t1).total_milliseconds() / 1000.0;
        }
};
#endif

DocShoe

1.7 Sekunden sind eine Ewigkeit auf modernen Rechnern...
Mir fallen dazu 2 Ansätze ein, um dem Problem auf die Schliche zu kommen:

Loggin Ausgaben schreiben. Zu Beginn und zum Ende deines Programms gibts du den aktuellen Zeitstempel möglichst millisekundengenau aus, entweder auf einer Konsole oder du schreibst sie in eine Log Datei
Führ dein Programm mal im Stand-alone Modus mit den Parametern aus, die du im Anwendungsfall bekommst. Vielleicht bekommst du da einen Hinweise, ob und wo´s hakt.

dispy

Wo ist der Unterschied zu meiner Timer-Klasse? ob ich die jetzt einzeln ausgebe oder gleich eine Differenz berechne, macht keinen Unterschied.
Im Anwendungsfall werden routinemäßig Logs erstellt - diese Logs zeigen mir auch, dass das Script meint, nur ~ 1,7 Sekunden gelaufen zu sein.

MfG