Discussion :

[nuKs]

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 :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
	boost::timer t;
	while(1)
		LOGInfo << t.elapsed();

Quelqu'un aurait-il une idée du problème ?
Merci d'avance

[vikki]

Étrange, chez moi ce simple code fonctionne très bien (sous Win):

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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?

[Emmanuel Deloget]

C'est quoi LOGInfo ?

[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 :

Sélectionner tout - Visualiser dans une fenêtre à part

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

[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 ?

[nuKs]

Woups. Désolé pour ma réponse un peu stupide
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 :

Sélectionner tout - Visualiser dans une fenêtre à part

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.

[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 ?

[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 ?

[Emmanuel Deloget]

Ah. OS X.

Que dit man 2 clock ? (ou man 3 clock) ?

[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 :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
 
boost::timer t;
Sleep(5000); //n'importe quelle fonction de sleep sur 5s
std::cout<<t.elapsed()<<std::endl;

[nuKs]

@Emmanuel Deloget > man 3 clock :

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 :

Sélectionner tout - Visualiser dans une fenêtre à part

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

[Emmanuel Deloget]

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

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

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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.

[nuKs]

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.

[nuKs]

Pour ceux que ça intéresse:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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 !