WaitForSingleObject et timeout

**trop_wizz** · 03/03/2010, 19h18

Salut à tous,

Je suis en face d'une situation un peu inexplicable pour le moment :

j'ai un thread qui execute le bout de code suivant:

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
30
31
32
33
34
35
36
37
38
39
40
 
void DMX::doTimer()
{
	CMesurePrecision myT;
	DWORD ret;
	FILE* tmp;
	int cpt = 0;
 
	while(1)
	{
 
		myT.Start();
 
		ret = WaitForSingleObject(decodeIsFinished,10);
		double timeFordecode2 = myT.GetTimeFromStart();
		ResetEvent(decodeIsFinished);
 
 
 
		cpt++;
 
 
 
		if (ret==WAIT_TIMEOUT)
		{			
			if (ACTIVATE_TIMEOUT)
			{
				quitNow=true;
				timeFordecode=myT.GetTimeFromStart();
				tmp = fopen("mydeduglog.txt","a+");
				fprintf(tmp,"Timeout Reached in %.2f and %.2f\n",1000*timeFordecode2,1000*timeFordecode);
				fclose(tmp);
 
			}
		}
 
 		//printf("sleep time= %fms , timeout=%d\n", a*1000, out);
 
	}
}

A noter que DecodeIsFinished n'est JAMAIS signalé!

En éxecutant cette boucle, on s'attendrait à ce qu'on arrive toujours en timeout avec des valeurs proches du timeout de 10ms qui est codé en dur dans le programme.

Pourtant, voilà ce que j'ai en sortie dans mon fichier texte:

Timeout Reached in 3.60 and 3.60
Timeout Reached in 3.55 and 3.55
Timeout Reached in 3.56 and 3.56
Timeout Reached in 3.55 and 3.56
Timeout Reached in 3.53 and 3.53
Timeout Reached in 3.56 and 3.56

etc etc

Ce résulttat arrive sur 3 Pcs de tests...configurations variées

Plus intéressant encore, sur un autre PC, le même code donne le résultat suivant:

Timeout Reached in 10.20 and 10.20
Timeout Reached in 10.64 and 10.64
Timeout Reached in 10.45 and 10.45
Timeout Reached in 10.82 and 10.82

etc

Ce qui est un comportement nettement plus normal...

WaitForSingleObject fait partie de kernel32.dll, y-aurait-il quelque chose à ce niveau là? Je suis un peu perdu sur comment debugger ce truc maintenant...

Ah oui, tous les PCs on la même version de kernel32.dll...

Merci d'avance pour toute aide, info ou idée sur le sujet!

++

Frantz

**Mac LAK** · 04/03/2010, 11h01

Ta méthode GetTimeFromStart() est implémentée comment ? Tu n'utiliserais pas le QueryPerformanceCounter dedans, par hasard ?

**trop_wizz** · 04/03/2010, 13h20

oui oui tout à fait, c'est du queryperformancecounter..

Un souci à ce niveau là plutôt?

++

**Mac LAK** · 04/03/2010, 13h35

Envoyé par trop_wizz

oui oui tout à fait, c'est du queryperformancecounter..

Un souci à ce niveau là plutôt?

Oui, tu l'as certainement mal utilisé. La valeur récupérée par QueryPerformanceFrequency est VARIABLE. Tu dois donc, en début de programme, récupérer cette fréquence de façon systématique, et déterminer quelle est l'unité de temps qui lui correspond. En théorie, tu devrais même le faire à chaque changement du mode d'alimentation, car cette valeur peut varier si l'ordinateur passe en veille et/ou est débranché du secteur.

Ceci explique en tout cas l'écart des mesures entre les différents PC, pas le reste.

**trop_wizz** · 04/03/2010, 13h44

En fait le QueryperformanceFrequency est récupéré pour chaque mesure de temps effectuée...

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
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
 
#include "MesurePrecision.h"
 
/**
                Constructor
                Just initialize lastError string
*/
CMesurePrecision::CMesurePrecision()
{
    strncpy(lastError,"No Error",9);
}
 
/**
                Destructor
                Does nothing ... no dynamic allocation
*/
CMesurePrecision::~CMesurePrecision(){}
 
/**
                Start counting time...
                Return true if the systems has a performance counter
                                
                \return bool
*/
bool CMesurePrecision::Start()
{
    if (!QueryPerformanceFrequency(&frequence))
    {
        LPVOID lpMsgBuf; 
        FormatMessage(FORMAT_MESSAGE_ALLOCATE_BUFFER |
            FORMAT_MESSAGE_FROM_SYSTEM |
            FORMAT_MESSAGE_IGNORE_INSERTS, NULL, 
            ::GetLastError(), 0, (LPTSTR) &lpMsgBuf, 0, NULL); 
        strcpy(lastError,(LPCSTR)lpMsgBuf);
        LocalFree( lpMsgBuf );
        return false;
 
    }
    if(!QueryPerformanceCounter (&debut))
    {
        LPVOID lpMsgBuf; 
        FormatMessage(FORMAT_MESSAGE_ALLOCATE_BUFFER | 
            FORMAT_MESSAGE_FROM_SYSTEM | 
            FORMAT_MESSAGE_IGNORE_INSERTS, 
            NULL, ::GetLastError(), 0, (LPTSTR) &lpMsgBuf, 0, NULL); 
        strcpy(lastError,(LPCSTR)lpMsgBuf);   
        LocalFree( lpMsgBuf );    
        return false;
    }
    strncpy(lastError,"No Error",9);
    return true;
}
 
/**
                Retrieves the difference of the current value of the high-resolution performance counter
                and the value when Start() has been called.
                                
                \return double
*/
double CMesurePrecision::GetTimeFromStart()
{
    if (!QueryPerformanceCounter (&fin))
    {
 
        LPVOID lpMsgBuf; 
        FormatMessage(FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_FROM_SYSTEM |
            FORMAT_MESSAGE_IGNORE_INSERTS, NULL, 
            ::GetLastError(), 0, (LPTSTR) &lpMsgBuf, 0, NULL);
        strcpy(lastError,(LPCSTR)lpMsgBuf);
        LocalFree( lpMsgBuf );
        return 0;
 
    }
    strncpy(lastError,"No Error",9);
    return ((double)((__int64)fin.QuadPart)-((__int64)debut.QuadPart)) / 
            (double)frequence.QuadPart;
}
 
/**
                Get the text for the last error (Time message)
                                
                \return char *
*/
char * CMesurePrecision::GetLastError()
{
return lastError;
}

C'est un code que j'ai utilisé sans probèmes auparavant. Je suis un peu perplexe quand à un disfonctionnement à ce niveau là.

**Mac LAK** · 04/03/2010, 14h38

Envoyé par trop_wizz

En fait le QueryperformanceFrequency est récupéré pour chaque mesure de temps effectuée...

Un peu bourrin, mais pourquoi pas. Tu as pas mal d'overhead sur les fonctions d'affichage / test / lasterror, mais cela ne devrait pas ajouter un tel écart quoi qu'il en soit.

Envoyé par trop_wizz

C'est un code que j'ai utilisé sans probèmes auparavant. Je suis un peu perplexe quand à un disfonctionnement à ce niveau là.

Moi aussi. Tu pourrais tester rapidement un truc, à savoir récupérer la valeur entière de la fréquence sur les deux types de machines ? Je n'y crois qu'à moitié, mais peut-être est-ce un problème à ce niveau.

Également : quel est le nombre de cœurs sur chacune de ces machines ? Est-ce que tu es threadé, dans ton programme ?

**trop_wizz** · 05/03/2010, 10h22

Hello

Merci pour les réponses.

Je vient de tester le bout code sur une machine

Timeout Reached in 10.01 and 10.01, Freq=3579545.00
Timeout Reached in 9.97 and 9.97, Freq=3579545.00
Timeout Reached in 10.03 and 10.03, Freq=3579545.00
Timeout Reached in 9.83 and 9.83, Freq=3579545.00
Timeout Reached in 10.04 and 10.05, Freq=3579545.00
Timeout Reached in 9.94 and 9.94, Freq=3579545.00
Timeout Reached in 10.05 and 10.05, Freq=3579545.00
Timeout Reached in 9.96 and 9.97, Freq=3579545.00
Timeout Reached in 10.02 and 10.03, Freq=3579545.00

le même exe sur une deuxième machine (même modèle)

imeout Reached in 15.02 and 15.03, Freq=3579545.00
Timeout Reached in 15.05 and 15.05, Freq=3579545.00
Timeout Reached in 14.93 and 14.93, Freq=3579545.00
Timeout Reached in 15.05 and 15.05, Freq=3579545.00
Timeout Reached in 15.06 and 15.07, Freq=3579545.00
Timeout Reached in 15.08 and 15.08, Freq=3579545.00

...

je suis un peu à sec d'idées

pour les deux machines, même config:

Intel Core2 Duo p8400 @2.26GHz
2.96 Gb RAM
CPU Throttle : NONE

**Mac LAK** · 08/03/2010, 12h53

Franchement bizarre, ce truc... Derniers points à regarder :

Tu appelles bien le "start" et le "stop" dans le même thread ?
Les machines ont-elles une différence de charge, genre moteur de BDD résident, serveur web, etc. qui pourraient expliquer que l'une des deux est plus "chargée" que l'autre ?

**trop_wizz** · 15/03/2010, 11h09

Hello,

Pour info, la réponse à ce problème bizarre vient de la résolution des timers windows.

En fait il s'avère que par défaut, les timers ont une résolution de 15 ms mais que via un appel à timeBeginPeriod(), on peux changer la

http://msdn.microsoft.com/en-us/libr...24(VS.85).aspx

Du coup sur certains PCs, la résolution était à 15ms, donc toute tentative pour fixer un timeout à des valeurs inférieures mène à un comportement erratique.
Sur d'aitres plateformes, certaines applications (genre Chrome p.ex.) fixent cette résolution à 1ms, d'ou un comportement correct. On ferme Chrome et hopla, le timeout par en sucette.

Une belle prise de tête en tous cas

+++

F.

**Mac LAK** · 15/03/2010, 11h59

Envoyé par trop_wizz

En fait il s'avère que par défaut, les timers ont une résolution de 15 ms mais que via un appel à timeBeginPeriod(), on peux changer la

Arf, vicieux, celui-là... Je n'y avais pas pensé une seule seconde !

A noter soigneusement sur les tablettes comme piste à suivre en cas de timers à comportement bizarres...

Merci d'avoir posté l'explication, en tout cas.

WaitForSingleObject et timeout

C++

Discussions similaires

Partager

Partager