boost::timer trop lent.

Version imprimable

26/01/2011, 11h03
nuKs

boost::timer trop lent.
Bonjour à tous.
Je ne comprend pas pourquoi mon timer fonctionne très lentement.
Après 30 secondes j'arrive à un output +- égal à 3.…
boost.timer est donc 10x trop lent, sachant que selon les spec, elapsed() renvoi des secondes.
Pour info j'utilise boost 1.44 et je suis sous mac os 10.6.5. J'utilise GCC 4.0 et je compile pour le SDK Mac OS 10.5 en 32bit universal.
Code:

1 2 3 boost::timer t; while(1) LOGInfo << t.elapsed();
Quelqu'un aurait-il une idée du problème ?
Merci d'avance :)
26/01/2011, 18h59
vikki
Étrange, chez moi ce simple code fonctionne très bien (sous Win):
Code:

1 2 3 boost::timer t; while(1) std::cout << t.elapsed()<<std::endl;
Ce ne serait pas plutôt ton système de log qui pose problème? genre retard à l'affichage?
26/01/2011, 20h24
Emmanuel Deloget

C'est quoi LOGInfo ?
27/01/2011, 08h49
nuKs
LOGInfo est mon système de log.
Oui en effet lorsque j'effectue l'affichage 1x sur 100 000 ça fonctionne à une vitesse relativement normale. C'est ce que je craignais.

En réalité mon code utilise un timer boost qui est comparé à chaque frame avec une map contenant comme clé un double et comme valeur une fonction callback. Après 3secondes, l'écran est sensé changé. Il en faut malheureusement bien plus, et sans output j'ai donc aussi un retard assez important.
J'en conclus que dans mon cas, ce n'est pas l'affichage qui est en décalage avec le temps mais bien le timer.

J'ai essayé de limité ma boucle d'une telle manière :
Code:

1 2 3 4 if(_secSinceLastFrame.elapsed() < 1.0f/25) // Limit fps to 25 return true; LOGInfo << " " << _secSinceStart.elapsed(); …
et c'est toujours très imprécis. (Pour info LOGInfo n'est pas beaucoup plus lent que std::cout).

Même en utilisant nanosleep le résultat est toujours aussi décevant. C'est comme si boost::timer utilisait un temps relatif (à chaque appel, on augmente le temps de (timestamp actuel - timestamp au dernier appel) ) au lieu d'un temps absolu (temps = timestamp actuel - timestamp au démarrage). Quelqu'un peut-il me confirmer cela ? Dans ce cas présent, connaîtriez vous une bonne alternative portable à boost::timer ?

Merci d'avoir répondu :)
27/01/2011, 09h24
Emmanuel Deloget

Le utilisé par boost::timer n'est pas relatif. Chaque appel de elapsed() force un appel à std::clock(). Je ne vois pas comment ça ne pourrait pas fonctionner correctement, d'où ma question. Je pense qu'il est possible qu'un problème se soit glissé dans ton code pour LOGInfo (je me doutais bien qu'avec un nom comme ça, il y avait des chances que ça soit un système de log :))

Est-ce que tu pourrais nous faire profiter de ce code, histoire de vérifier s'il n'y a pas un problème ?
27/01/2011, 10h16
nuKs
Woups. Désolé pour ma réponse un peu stupide :lol:
Pour en revenir au sujet, je me suis mal exprimé. La lenteur n'est pas due au LOGInfo. J'ai essayé la même chose avec std::cout.
Code:

1 2 3 boost::timer t; while(1) std::cout << t.elapsed()<<std::endl;
Ca affiche un résultat beaucoup trop lent. Ces instructions sont bien au début du main (donc ce bout de code est testé indépendamment du reste).
Lorsque je n'affiche le résultat qu'une fois sur 100 000 000, le résultat est plus probant.

La réponse de Vikki me porte à penser que c'est peut-être mon OS qui est en cause étant donné que ça semble fonctionner à une vitesse normale chez lui.

Je pense malheureusement que ce n'est pas l'affichage qui est décalé par rapport au programme mais bien le timer qui est en retard sur la réalité. J'en arrive à cette conclusion car dans mon code original, il n'y a aucun Log dans la boucle elle même, mais les actions devant se réaliser après un certain temps se réalisent bien trop tard.

Pour le code, voici une partie de mon "FrameEngine"
http://pastebin.com/fAzLiFd7
Je doute que ça soit de grande aide. Si vous souhaitez tout de même le code du Logger je vous le fournirai directement.
27/01/2011, 10h23
Emmanuel Deloget

La boucle est exécutée au début du main. Y-a-t-il des variables globales ou des singletons qui sont initialisés avant que main ne commence son exécution ? Des threads qui tournent qui peuvent perturber le résultat ? (ça ne m'étonnerais qu'à moitié ; j'entends parler de Ogre, j'ai peur... :))

Si tu fais un programme court, lié à aucune autre lib, et qui ne fait que ça, est-ce que ça marche correctement ?
27/01/2011, 10h34
nuKs

Malheureusement non, rien de tout ça.
Je viens d'essayer de copier le code dans un nouveau projet xCode sans aucune dépendance. Même problème.

En réalité je suis surpris que le comportement soit différent chez vous. Si je comprend bien vous n'avez pas de décalage même sans limiter le nombre de sorties ?
27/01/2011, 12h23
Emmanuel Deloget

Ah. OS X.

Que dit man 2 clock ? (ou man 3 clock) ?
27/01/2011, 16h29
vikki
L'implémentation de clock() diffère en fonction de l'os. Sous les unix like, il me semble que clock mesure un temps processeur, alors qu'il mesure un temps réel sous windows. Essaye le test suivant et dis nous ce que ca retourne:
Code:

1 2 3 4 boost::timer t; Sleep(5000); //n'importe quelle fonction de sleep sur 5s std::cout<<t.elapsed()<<std::endl;
28/01/2011, 08h23
nuKs
@Emmanuel Deloget > man 3 clock :

Citation:

The clock() function determines the amount of processor time used since the invocation of the calling process, measured in CLOCKS_PER_SECs of a second.

@vikki >
Code:

1 2 3 boost::timer t; sleep(5); //n'importe quelle fonction de sleep sur 5s std::cout<<t.elapsed()<<std::endl;
=> 2.4e-05

Il y a un problème avec clock(), ou avec son utilisation dans boost.

Est-ce que tu peux tester directement clock() ?
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 #include <unistd.h> // sleep() #include <time> // #include <iostream> int main() { clock_t t = clock(); std::cout << "temps de départ = " << t << std::endl; sleep(5); clock_t t2 = clock(); std::cout << "temps après 5 sec: " << t2 << std::endl; std::cout << "difference = " << t2 - t << std::endl; std::cout << "CLOCK_PER_SEC = " << CLOCKS_PER_SEC << std::endl; }
La sortie complète du programme serait un atout intéressant pour comprendre ce qui se passe.

28/01/2011, 10h10
nuKs

Citation:

temps de départ = 11081
temps après 5 sec: 11175
difference = 94
CLOCK_PER_SEC = 1000000

Après quelques recherches, j'ai découvert boost.chrono qui apparemment permet d'éviter le problème. Malheureusement la bibliothèque n'a pas encore été approuvée. Je pense que je vais coder mon propre timer basé sur boost.Date_Time.

Pour ceux que ça intéresse:

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
#ifndef _nCoreEngine_Timer
#define _nCoreEngine_Timer
 
#include <boost/date_time/posix_time/posix_time_types.hpp>
 
namespace nCoreEngine {
 
	class Timer {
	private:
		boost::posix_time::ptime _startTime;
 
	public:
		Timer() : _startTime(boost::posix_time::microsec_clock::local_time()) {}
 
		void restart() {
			_startTime = boost::posix_time::ptime(boost::posix_time::microsec_clock::local_time());
		}
 
		double elapsed() const { // return seconds with 10E-3 precision
			boost::posix_time::ptime now(boost::posix_time::microsec_clock::local_time());
			boost::posix_time::time_duration elapsed = now - _startTime;
 
			return elapsed.total_milliseconds()/1000.f;
		}
	};
 
} // namespace nCoreEngine
 
#endif // _nCoreEngine_Timer

Merci beaucoup pour votre aide !