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
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
|
/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
/* vim:set ts=2 sw=2 sts=2 et cindent: */
/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at http://mozilla.org/MPL/2.0/. */
// Implement TimeStamp::Now() with QueryPerformanceCounter() controlled with
// values of GetTickCount().
// XXX Forcing log to be able to catch issues in the field. Should be removed
// before this reaches the Release or even Beta channel.
#define FORCE_PR_LOG
#include "mozilla/TimeStamp.h"
#include "mozilla/Mutex.h"
#include "mozilla/Services.h"
#include "nsIObserver.h"
#include "nsIObserverService.h"
#include "nsThreadUtils.h"
#include "nsAutoPtr.h"
#include <pratom.h>
#include <windows.h>
#include "prlog.h"
#include <stdio.h>
#if defined(PR_LOGGING)
// Log module for mozilla::TimeStamp for Windows logging...
//
// To enable logging (see prlog.h for full details):
//
// set NSPR_LOG_MODULES=TimeStampWindows:5
// set NSPR_LOG_FILE=nspr.log
//
// this enables PR_LOG_DEBUG level information and places all output in
// the file nspr.log
PRLogModuleInfo* timeStampLog = PR_NewLogModule("TimeStampWindows");
#define LOG(x) PR_LOG(timeStampLog, PR_LOG_DEBUG, x)
#else
#define LOG(x)
#endif /* PR_LOGGING */
// Estimate of the smallest duration of time we can measure.
static volatile ULONGLONG sResolution;
static volatile ULONGLONG sResolutionSigDigs;
static const double kNsPerSecd = 1000000000.0;
static const LONGLONG kNsPerSec = 1000000000;
static const LONGLONG kNsPerMillisec = 1000000;
// ----------------------------------------------------------------------------
// Global constants
// ----------------------------------------------------------------------------
// After this time we always recalibrate the skew.
//
// On most platforms QPC and GTC have not quit the same slope, so after some
// time the two values will disperse. The 4s calibration interval has been
// chosen mostly arbitrarily based on tests.
//
// Mostly, 4 seconds has been chosen based on the sleep/wake issue - timers
// shift after wakeup. I wanted to make the time as reasonably short as
// possible to always recalibrate after even a very short standby time (quit
// reasonable test case). So, there is a lot of space to prolong it
// to say 20 seconds or even more, needs testing in the field, though.
//
// Value is number of [ms].
static const ULONGLONG kCalibrationInterval = 4000;
// On every read of QPC we check the overflow of skew difference doesn't go
// over this number of milliseconds. Both timer functions jitter so we have
// to have some limit. The value is based on tests.
//
// Changing kCalibrationInterval influences this limit: prolonging
// just kCalibrationInterval means to be more sensitive to threshold overflows.
//
// How this constant is used (also see CheckCalibration function):
// First, adjust the limit linearly to the calibration interval:
// LIMIT = (GTC_now - GTC_calib) / kCalibrationInterval
// Then, check the skew difference overflow is in this adjusted limit:
// ABS((QPC_now - GTC_now) - (QPC_calib - GTC_calib)) - THRESHOLD < LIMIT
//
// Thresholds are calculated dynamically, see sUnderrunThreshold and
// sOverrunThreshold below.
//
// Value is number of [ms].
static const ULONGLONG kOverflowLimit = 100;
// If we are not able to get the value of GTC time increment, use this value
// which is the most usual increment.
static const DWORD kDefaultTimeIncrement = 156001;
// ----------------------------------------------------------------------------
// Global variables, not changing at runtime
// ----------------------------------------------------------------------------
/**
* The [mt] unit:
*
* Many values are kept in ticks of the Performance Coutner x 1000,
* further just referred as [mt], meaning milli-ticks.
*
* This is needed to preserve maximum precision of the performance frequency
* representation. GetTickCount values in milliseconds are multiplied with
* frequency per second. Therefor we need to multiply QPC value by 1000 to
* have the same units to allow simple arithmentic with both QPC and GTC.
*/
#define ms2mt(x) ((x) * sFrequencyPerSec)
#define mt2ms(x) ((x) / sFrequencyPerSec)
#define mt2ms_d(x) (double(x) / sFrequencyPerSec)
// Result of QueryPerformanceFrequency
static LONGLONG sFrequencyPerSec = 0;
// Lower and upper bound that QueryPerformanceCounter - GetTickCount must not
// go under or over when compared to the calibrated QPC - GTC difference (skew)
// Values are based on the GetTickCount update interval.
//
// Schematically, QPC works correctly if ((QPC_now - GTC_now) -
// (QPC_calib - GTC_calib)) is in [sUnderrunThreshold, sOverrunThreshold]
// interval every time we access them.
//
// Kept in [mt]
static LONGLONG sUnderrunThreshold;
static LONGLONG sOverrunThreshold;
// ----------------------------------------------------------------------------
// Global lock
// ----------------------------------------------------------------------------
// Thread spin count before entering the full wait state for sTimeStampLock.
// Inspired by Rob Arnold's work on PRMJ_Now().
static const DWORD kLockSpinCount = 4096;
// Common mutex (thanks the relative complexity of the logic, this is better
// then using CMPXCHG8B.)
// It is protecting the globals bellow.
CRITICAL_SECTION sTimeStampLock;
// ----------------------------------------------------------------------------
// Globals heavily chaning at runtime, protected with sTimeStampLock mutex
// ----------------------------------------------------------------------------
// The calibrated difference between QPC and GTC.
//
// Kept in [mt]
static LONGLONG sSkew = 0;
// Keeps the last result we have returned from TickCount64 (bellow). Protects
// from roll over and going backward.
//
// Kept in [ms]
static ULONGLONG sLastGTCResult = 0;
// Holder of the last result of our main hi-res function. Protects from going
// backward.
//
// Kept in [mt]
static ULONGLONG sLastResult = 0;
// Time of the last performed calibration.
//
// Kept in [ms]
static ULONGLONG sLastCalibrated;
// After we have detected a run out of bounderies set this to true. This
// then disallows use of QPC result for the hi-res timer.
static bool sFallBackToGTC = false;
// Set to true to force recalibration on QPC read. This is generally set after
// system wake up, during which skew can change a lot.
static bool sForceRecalibrate = false;
namespace mozilla {
static ULONGLONG
CalibratedPerformanceCounter();
// ----------------------------------------------------------------------------
// Critical Section helper class
// ----------------------------------------------------------------------------
class AutoCriticalSection
{
public:
AutoCriticalSection(LPCRITICAL_SECTION section)
: mSection(section)
{
::EnterCriticalSection(mSection);
}
~AutoCriticalSection()
{
::LeaveCriticalSection(mSection);
}
private:
LPCRITICAL_SECTION mSection;
};
// ----------------------------------------------------------------------------
// System standby and wakeup status observer. Needed to ignore skew jump after
// the system has been woken up, happens mostly on XP.
// ----------------------------------------------------------------------------
class StandbyObserver : public nsIObserver
{
NS_DECL_ISUPPORTS
NS_DECL_NSIOBSERVER
public:
StandbyObserver()
{
LOG(("TimeStamp: StandByObserver::StandByObserver()"));
}
~StandbyObserver()
{
LOG(("TimeStamp: StandByObserver::~StandByObserver()"));
}
static inline void Ensure()
{
if (sInitialized)
return;
// Not available to init on other then the main thread since using
// the ObserverService.
if (!NS_IsMainThread())
return;
nsCOMPtr<nsIObserverService> obs = services::GetObserverService();
if (!obs)
return; // Too soon...
sInitialized = true;
nsRefPtr<StandbyObserver> observer = new StandbyObserver();
obs->AddObserver(observer, "wake_notification", false);
// There is no need to remove the observer, observer service is the only
// referer and we don't hold reference back to the observer service.
}
private:
static bool sInitialized;
};
NS_IMPL_THREADSAFE_ISUPPORTS1(StandbyObserver, nsIObserver)
bool
StandbyObserver::sInitialized = false;
NS_IMETHODIMP
StandbyObserver::Observe(nsISupports *subject,
const char *topic,
const PRUnichar *data)
{
AutoCriticalSection lock(&sTimeStampLock);
// Clear the potentiall fallback flag now and try using
// QPC again after wake up.
sFallBackToGTC = false;
sForceRecalibrate = true;
LOG(("TimeStamp: system has woken up, reset GTC fallback"));
return NS_OK;
}
// ----------------------------------------------------------------------------
// The timer core implementation
// ----------------------------------------------------------------------------
static void
InitThresholds()
{
DWORD timeAdjustment = 0, timeIncrement = 0;
BOOL timeAdjustmentDisabled;
GetSystemTimeAdjustment(&timeAdjustment,
&timeIncrement,
&timeAdjustmentDisabled);
if (!timeIncrement)
timeIncrement = kDefaultTimeIncrement;
// Ceiling to a millisecond
// Example values: 156001, 210000
DWORD timeIncrementCeil = timeIncrement;
// Don't want to round up if already rounded, values will be: 156000, 209999
timeIncrementCeil -= 1;
// Convert to ms, values will be: 15, 20
timeIncrementCeil /= 10000;
// Round up, values will be: 16, 21
timeIncrementCeil += 1;
// Convert back to 100ns, values will be: 160000, 210000
timeIncrementCeil *= 10000;
// How many milli-ticks has the interval
LONGLONG ticksPerGetTickCountResolution =
(int64_t(timeIncrement) * sFrequencyPerSec) / 10000LL;
// How many milli-ticks has the interval rounded up
LONGLONG ticksPerGetTickCountResolutionCeiling =
(int64_t(timeIncrementCeil) * sFrequencyPerSec) / 10000LL;
// I observed differences about 2 times of the GTC resolution. GTC may
// jump by 32 ms in two steps, therefor use the ceiling value.
sUnderrunThreshold =
LONGLONG((-2) * ticksPerGetTickCountResolutionCeiling);
// QPC should go no further then 2 * GTC resolution
sOverrunThreshold =
LONGLONG((+2) * ticksPerGetTickCountResolution);
}
static void
InitResolution()
{
// 10 total trials is arbitrary: what we're trying to avoid by
// looping is getting unlucky and being interrupted by a context
// switch or signal, or being bitten by paging/cache effects
ULONGLONG minres = ~0ULL;
int loops = 10;
do {
ULONGLONG start = CalibratedPerformanceCounter();
ULONGLONG end = CalibratedPerformanceCounter();
ULONGLONG candidate = (end - start);
if (candidate < minres)
minres = candidate;
} while (--loops && minres);
if (0 == minres) {
minres = 1;
}
// Converting minres that is in [mt] to nanosecods, multiplicating
// the argument to preserve resolution.
ULONGLONG result = mt2ms(minres * kNsPerMillisec);
if (0 == result) {
result = 1;
}
sResolution = result;
// find the number of significant digits in mResolution, for the
// sake of ToSecondsSigDigits()
ULONGLONG sigDigs;
for (sigDigs = 1;
!(sigDigs == result
|| 10*sigDigs > result);
sigDigs *= 10);
sResolutionSigDigs = sigDigs;
}
// Function protecting GetTickCount result from rolling over, result is in [ms]
// @param gtc
// Result of GetTickCount(). Passing it as an arg lets us call it out
// of the common mutex.
static inline ULONGLONG
TickCount64(DWORD now)
{
ULONGLONG lastResultHiPart = sLastGTCResult & (~0ULL << 32);
ULONGLONG result = lastResultHiPart | ULONGLONG(now);
// It may happen that when accessing GTC on multiple threads the results
// may differ (GTC value may be lower due to running before the others
// right around the overflow moment). That falsely shifts the high part.
// Easiest solution is to check for a significant difference.
if (sLastGTCResult > result) {
if ((sLastGTCResult - result) > (1ULL << 31))
result += 1ULL << 32;
else
result = sLastGTCResult;
}
sLastGTCResult = result;
return result;
}
// Result is in [mt]
static inline ULONGLONG
PerformanceCounter()
{
LARGE_INTEGER pc;
::QueryPerformanceCounter(&pc);
return pc.QuadPart * 1000ULL;
}
// Called when we detect a larger deviation of QPC to disable it.
static inline void
RecordFlaw()
{
sFallBackToGTC = true;
LOG(("TimeStamp: falling back to GTC :("));
#if 0
// This code has been disabled, because we:
// 0. InitResolution must not be called under the lock (would reenter) while
// we shouldn't release it here just to allow it
// 1. may return back to using QPC after system wake up
// 2. InitResolution for GTC will probably return 0 anyway (increments
// only every 15 or 16 ms.)
//
// There is no need to drop sFrequencyPerSec to 1, result of TickCount64
// is multiplied and later divided with sFrequencyPerSec. Changing it
// here may introduce sync problems. Syncing access to sFrequencyPerSec
// is overkill. Drawback is we loose some bits from the upper bound of
// the 64 bits timer value, usualy up to 7, it means the app cannot run
// more then some 4'000'000 years :)
InitResolution();
#endif
}
// Check the current skew is in bounderies and occasionally recalculate it.
// Return true if QPC is OK to use, return false to use GTC only.
//
// Arguments:
// overflow - the calculated overflow out of the bounderies for skew difference
// qpc - current value of QueryPerformanceCounter
// gtc - current value of GetTickCount, more actual according possible system
// sleep between read of QPC and GTC
static inline bool
CheckCalibration(LONGLONG overflow, ULONGLONG qpc, ULONGLONG gtc)
{
if (sFallBackToGTC) {
// We are forbidden to use QPC
return false;
}
ULONGLONG sinceLastCalibration = gtc - sLastCalibrated;
if (overflow && !sForceRecalibrate) {
// Calculate trend of the overflow to correspond to the calibration
// interval, we may get here long after the last calibration because we
// either didn't read the hi-res function or the system was suspended.
ULONGLONG trend = LONGLONG(overflow *
(double(kCalibrationInterval) / sinceLastCalibration));
LOG(("TimeStamp: calibration after %llus with overflow %1.4fms"
", adjusted trend per calibration interval is %1.4fms",
sinceLastCalibration / 1000,
mt2ms_d(overflow),
mt2ms_d(trend)));
if (trend > ms2mt(kOverflowLimit)) {
// This sets sFallBackToGTC, we have detected
// an unreliability of QPC, stop using it.
RecordFlaw();
return false;
}
}
if (sinceLastCalibration > kCalibrationInterval || sForceRecalibrate) {
// Recalculate the skew now
sSkew = qpc - ms2mt(gtc);
sLastCalibrated = gtc;
LOG(("TimeStamp: new skew is %1.2fms (force:%d)",
mt2ms_d(sSkew), sForceRecalibrate));
sForceRecalibrate = false;
}
return true;
}
// The main function. Result is in [mt] ensuring to not go back and be mostly
// reliable with highest possible resolution.
static ULONGLONG
CalibratedPerformanceCounter()
{
// XXX This is using ObserverService, cannot instantiate in the static
// startup, really needs a better initation code here.
StandbyObserver::Ensure();
// Don't hold the lock over call to QueryPerformanceCounter, since it is
// the largest bottleneck, let threads read the value concurently to have
// possibly a better performance.
ULONGLONG qpc = PerformanceCounter();
DWORD gtcw = GetTickCount();
AutoCriticalSection lock(&sTimeStampLock);
// Rollover protection
ULONGLONG gtc = TickCount64(gtcw);
LONGLONG diff = qpc - ms2mt(gtc) - sSkew;
LONGLONG overflow = 0;
if (diff < sUnderrunThreshold) {
overflow = sUnderrunThreshold - diff;
}
else if (diff > sOverrunThreshold) {
overflow = diff - sOverrunThreshold;
}
ULONGLONG result = qpc;
if (!CheckCalibration(overflow, qpc, gtc)) {
// We are back on GTC, QPC has been observed unreliable
result = ms2mt(gtc) + sSkew;
}
#if 0
LOG(("TimeStamp: result = %1.2fms, diff = %1.4fms",
mt2ms_d(result), mt2ms_d(diff)));
#endif
if (result > sLastResult)
sLastResult = result;
return sLastResult;
}
// ----------------------------------------------------------------------------
// TimeDuration and TimeStamp implementation
// ----------------------------------------------------------------------------
double
TimeDuration::ToSeconds() const
{
return double(mValue) / (sFrequencyPerSec * 1000ULL);
}
double
TimeDuration::ToSecondsSigDigits() const
{
AutoCriticalSection lock(&sTimeStampLock);
// don't report a value < mResolution ...
LONGLONG resolution = sResolution;
LONGLONG resolutionSigDigs = sResolutionSigDigs;
LONGLONG valueSigDigs = resolution * (mValue / resolution);
// and chop off insignificant digits
valueSigDigs = resolutionSigDigs * (valueSigDigs / resolutionSigDigs);
return double(valueSigDigs) / kNsPerSecd;
}
TimeDuration
TimeDuration::FromMilliseconds(double aMilliseconds)
{
return TimeDuration::FromTicks(int64_t(ms2mt(aMilliseconds)));
}
TimeDuration
TimeDuration::Resolution()
{
AutoCriticalSection lock(&sTimeStampLock);
return TimeDuration::FromTicks(int64_t(sResolution));
}
struct TimeStampInitialization
{
TimeStampInitialization() {
TimeStamp::Startup();
}
~TimeStampInitialization() {
TimeStamp::Shutdown();
}
};
static TimeStampInitialization initOnce;
nsresult
TimeStamp::Startup()
{
// Decide which implementation to use for the high-performance timer.
InitializeCriticalSectionAndSpinCount(&sTimeStampLock, kLockSpinCount);
LARGE_INTEGER freq;
BOOL QPCAvailable = ::QueryPerformanceFrequency(&freq);
if (!QPCAvailable) {
// No Performance Counter. Fall back to use GetTickCount.
sFrequencyPerSec = 1;
sFallBackToGTC = true;
InitResolution();
LOG(("TimeStamp: using GetTickCount"));
return NS_OK;
}
sFrequencyPerSec = freq.QuadPart;
ULONGLONG qpc = PerformanceCounter();
sLastCalibrated = TickCount64(::GetTickCount());
sSkew = qpc - ms2mt(sLastCalibrated);
InitThresholds();
InitResolution();
LOG(("TimeStamp: initial skew is %1.2fms", mt2ms_d(sSkew)));
return NS_OK;
}
void
TimeStamp::Shutdown()
{
DeleteCriticalSection(&sTimeStampLock);
}
TimeStamp
TimeStamp::Now()
{
return TimeStamp(uint64_t(CalibratedPerformanceCounter()));
}
} // namespace mozilla
|