1 | //============================================================================ |
2 | // |
3 | // SSSS tt lll lll |
4 | // SS SS tt ll ll |
5 | // SS tttttt eeee ll ll aaaa |
6 | // SSSS tt ee ee ll ll aa |
7 | // SS tt eeeeee ll ll aaaaa -- "An Atari 2600 VCS Emulator" |
8 | // SS SS tt ee ll ll aa aa |
9 | // SSSS ttt eeeee llll llll aaaaa |
10 | // |
11 | // Copyright (c) 1995-2019 by Bradford W. Mott, Stephen Anthony |
12 | // and the Stella Team |
13 | // |
14 | // See the file "License.txt" for information on usage and redistribution of |
15 | // this file, and for a DISCLAIMER OF ALL WARRANTIES. |
16 | //============================================================================ |
17 | |
18 | #include "StaggeredLogger.hxx" |
19 | #include "Logger.hxx" |
20 | |
21 | #include <ctime> |
22 | |
23 | using namespace std::chrono; |
24 | |
25 | namespace { |
26 | string currentTimestamp() |
27 | { |
28 | std::tm now = BSPF::localTime(); |
29 | |
30 | char formattedTime[100]; |
31 | formattedTime[99] = 0; |
32 | std::strftime(formattedTime, 99, "%H:%M:%S" , &now); |
33 | |
34 | return formattedTime; |
35 | } |
36 | } |
37 | |
38 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
39 | StaggeredLogger::StaggeredLogger(const string& message, Logger::Level level) |
40 | : myMessage(message), |
41 | myLevel(level), |
42 | myCurrentEventCount(0), |
43 | myIsCurrentlyCollecting(false), |
44 | myCurrentIntervalSize(100), |
45 | myMaxIntervalFactor(9), |
46 | myCurrentIntervalFactor(1), |
47 | myCooldownTime(1000), |
48 | myTimer(new TimerManager()), |
49 | myTimerCallbackId(0) |
50 | {} |
51 | |
52 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
53 | StaggeredLogger::~StaggeredLogger() |
54 | { |
55 | myTimer->clear(myTimerId); |
56 | |
57 | // make sure that the worker thread joins before continuing with the destruction |
58 | delete myTimer; |
59 | |
60 | // the worker thread has joined and there will be no more reentrant calls -> |
61 | // continue with destruction |
62 | } |
63 | |
64 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
65 | void StaggeredLogger::log() |
66 | { |
67 | std::lock_guard<std::mutex> lock(myMutex); |
68 | |
69 | _log(); |
70 | } |
71 | |
72 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
73 | void StaggeredLogger::_log() |
74 | { |
75 | if (!myIsCurrentlyCollecting) startInterval(); |
76 | |
77 | ++myCurrentEventCount; |
78 | } |
79 | |
80 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
81 | void StaggeredLogger::logLine() |
82 | { |
83 | high_resolution_clock::time_point now = high_resolution_clock::now(); |
84 | Int64 millisecondsSinceIntervalStart = |
85 | duration_cast<duration<Int64, std::milli>>(now - myLastIntervalStartTimestamp).count(); |
86 | |
87 | stringstream ss; |
88 | ss |
89 | << currentTimestamp() << ": " |
90 | << myMessage |
91 | << " (" << myCurrentEventCount << " times in " |
92 | << millisecondsSinceIntervalStart << " milliseconds" |
93 | << ")" ; |
94 | |
95 | Logger::log(ss.str(), myLevel); |
96 | } |
97 | |
98 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
99 | void StaggeredLogger::increaseInterval() |
100 | { |
101 | if (myCurrentIntervalFactor >= myMaxIntervalFactor) return; |
102 | |
103 | ++myCurrentIntervalFactor; |
104 | myCurrentIntervalSize *= 2; |
105 | } |
106 | |
107 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
108 | void StaggeredLogger::decreaseInterval() |
109 | { |
110 | if (myCurrentIntervalFactor <= 1) return; |
111 | |
112 | --myCurrentIntervalFactor; |
113 | myCurrentIntervalSize /= 2; |
114 | } |
115 | |
116 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
117 | void StaggeredLogger::startInterval() |
118 | { |
119 | if (myIsCurrentlyCollecting) return; |
120 | |
121 | myIsCurrentlyCollecting = true; |
122 | |
123 | high_resolution_clock::time_point now = high_resolution_clock::now(); |
124 | Int64 msecSinceLastIntervalEnd = |
125 | duration_cast<duration<Int64, std::milli>>(now - myLastIntervalEndTimestamp).count(); |
126 | |
127 | while (msecSinceLastIntervalEnd > myCooldownTime && myCurrentIntervalFactor > 1) { |
128 | msecSinceLastIntervalEnd -= myCooldownTime; |
129 | decreaseInterval(); |
130 | } |
131 | |
132 | myCurrentEventCount = 0; |
133 | myLastIntervalStartTimestamp = now; |
134 | |
135 | myTimer->clear(myTimerId); |
136 | myTimerId = myTimer->setTimeout(std::bind(&StaggeredLogger::onTimerExpired, this, ++myTimerCallbackId), myCurrentIntervalSize); |
137 | } |
138 | |
139 | // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - |
140 | void StaggeredLogger::onTimerExpired(uInt32 timerCallbackId) |
141 | { |
142 | std::lock_guard<std::mutex> lock(myMutex); |
143 | |
144 | if (timerCallbackId != myTimerCallbackId) return; |
145 | |
146 | logLine(); |
147 | |
148 | myIsCurrentlyCollecting = false; |
149 | increaseInterval(); |
150 | |
151 | myLastIntervalEndTimestamp = high_resolution_clock::now(); |
152 | } |
153 | |