diff options
| author | bitflash-maintainer <noreply@bitflash.invalid> | 2026-09-03 21:49:35 +0000 |
|---|---|---|
| committer | bitflash-maintainer <noreply@bitflash.invalid> | 2026-09-03 21:49:35 +0000 |
| commit | 424da766b76ba572cc9a93c4dd03736dace04d80 (patch) | |
| tree | 899f6ceec730bd5e1305f1c8e59ce13e21cfb048 /src/util.cpp | |
| parent | 3c18a66ef601d90f08ea622021cb02bafab1601b (diff) | |
| parent | e63fcfff1ae24dfff8aca6581badb51a06ddae28 (diff) | |
merge: !10 fix/small-fixes into deploy/all-2026-08-24
Diffstat (limited to 'src/util.cpp')
| -rw-r--r-- | src/util.cpp | 99 |
1 files changed, 90 insertions, 9 deletions
diff --git a/src/util.cpp b/src/util.cpp index 60142be..ab29178 100644 --- a/src/util.cpp +++ b/src/util.cpp | |||
| @@ -65,6 +65,61 @@ struct LogDedupState { | |||
| 65 | static std::map<std::string, LogDedupState> g_logDedup; | 65 | static std::map<std::string, LogDedupState> g_logDedup; |
| 66 | static CCriticalSection cs_logDedup; | 66 | static CCriticalSection cs_logDedup; |
| 67 | 67 | ||
| 68 | // A pending "(N similar)" summary, lifted out of the table while the lock is | ||
| 69 | // held and written after it is released. | ||
| 70 | struct LogDedupFlush { | ||
| 71 | std::string category; | ||
| 72 | int suppressed; | ||
| 73 | int64 elapsed; // how long the window that counted them ran | ||
| 74 | std::string lastMsg; | ||
| 75 | }; | ||
| 76 | |||
| 77 | static int64 g_logDedupLastSweep = 0; | ||
| 78 | |||
| 79 | static void EmitDedupSummary(const LogDedupFlush& f) | ||
| 80 | { | ||
| 81 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | ||
| 82 | f.category.c_str(), f.suppressed, | ||
| 83 | (long long)f.elapsed, f.lastMsg.c_str()); | ||
| 84 | } | ||
| 85 | |||
| 86 | // A window is otherwise only closed out when its own call site fires again, so | ||
| 87 | // a burst that simply stops -- 100 ledger entries voided in one pass and then | ||
| 88 | // silence -- leaves its count sitting in the table and the summary is never | ||
| 89 | // written at all. That is how 99 of 100 voids went unreported, with no "(N | ||
| 90 | // similar)" line to say anything was missing (issue #3). Sweep every expired | ||
| 91 | // window instead, so a finished burst is summarised as soon as anything at all | ||
| 92 | // is logged. | ||
| 93 | // | ||
| 94 | // Expired entries are erased rather than reopened: the window is over, so there | ||
| 95 | // is no state left worth keeping, and the next call from that site then takes | ||
| 96 | // the "first time" path and prints directly -- exactly what the rollover branch | ||
| 97 | // below would have done. It also stops the table growing without bound. | ||
| 98 | // | ||
| 99 | // Caller holds cs_logDedup; the summaries are written after it is released. | ||
| 100 | static void SweepExpiredWindowsLocked(int64 now, std::vector<LogDedupFlush>& out) | ||
| 101 | { | ||
| 102 | for (std::map<std::string, LogDedupState>::iterator it = g_logDedup.begin(); | ||
| 103 | it != g_logDedup.end(); ) | ||
| 104 | { | ||
| 105 | if (now - it->second.windowStart < DEDUP_WINDOW_SECS) | ||
| 106 | { | ||
| 107 | ++it; | ||
| 108 | continue; | ||
| 109 | } | ||
| 110 | if (it->second.suppressed > 0) | ||
| 111 | { | ||
| 112 | LogDedupFlush f; | ||
| 113 | f.category = it->first.substr(0, it->first.find('|')); | ||
| 114 | f.suppressed = it->second.suppressed; | ||
| 115 | f.elapsed = now - it->second.windowStart; | ||
| 116 | f.lastMsg = it->second.lastMsg; | ||
| 117 | out.push_back(f); | ||
| 118 | } | ||
| 119 | g_logDedup.erase(it++); | ||
| 120 | } | ||
| 121 | } | ||
| 122 | |||
| 68 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) | 123 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) |
| 69 | { | 124 | { |
| 70 | // Call sites follow the existing printf() convention of ending their | 125 | // Call sites follow the existing printf() convention of ending their |
| @@ -79,11 +134,19 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 79 | 134 | ||
| 80 | int64 now = GetTime(); | 135 | int64 now = GetTime(); |
| 81 | bool fEmitNow = false; | 136 | bool fEmitNow = false; |
| 82 | int suppressedToFlush = 0; | 137 | std::vector<LogDedupFlush> flushes; |
| 83 | std::string flushedMsg; | ||
| 84 | 138 | ||
| 85 | CRITICAL_BLOCK(cs_logDedup) | 139 | CRITICAL_BLOCK(cs_logDedup) |
| 86 | { | 140 | { |
| 141 | // At most once a second. The table holds one entry per call site that | ||
| 142 | // has fired in the last few seconds, so the walk is short, but it must | ||
| 143 | // not run once per line of a burst. | ||
| 144 | if (now != g_logDedupLastSweep) | ||
| 145 | { | ||
| 146 | g_logDedupLastSweep = now; | ||
| 147 | SweepExpiredWindowsLocked(now, flushes); | ||
| 148 | } | ||
| 149 | |||
| 87 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); | 150 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); |
| 88 | if (it == g_logDedup.end()) | 151 | if (it == g_logDedup.end()) |
| 89 | { | 152 | { |
| @@ -94,10 +157,18 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 94 | } | 157 | } |
| 95 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) | 158 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) |
| 96 | { | 159 | { |
| 97 | // Window rolled over: flush what was suppressed during it (if | 160 | // Window rolled over within the same second as the last sweep: |
| 98 | // anything), then start a new window with this call printed. | 161 | // flush what was suppressed during it (if anything), then start a |
| 99 | suppressedToFlush = it->second.suppressed; | 162 | // new window with this call printed. |
| 100 | flushedMsg = it->second.lastMsg; | 163 | if (it->second.suppressed > 0) |
| 164 | { | ||
| 165 | LogDedupFlush f; | ||
| 166 | f.category = category; | ||
| 167 | f.suppressed = it->second.suppressed; | ||
| 168 | f.elapsed = now - it->second.windowStart; | ||
| 169 | f.lastMsg = it->second.lastMsg; | ||
| 170 | flushes.push_back(f); | ||
| 171 | } | ||
| 101 | it->second.windowStart = now; | 172 | it->second.windowStart = now; |
| 102 | it->second.suppressed = 0; | 173 | it->second.suppressed = 0; |
| 103 | it->second.lastMsg = msg; | 174 | it->second.lastMsg = msg; |
| @@ -112,13 +183,23 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 112 | } | 183 | } |
| 113 | } | 184 | } |
| 114 | 185 | ||
| 115 | if (suppressedToFlush > 0) | 186 | for (size_t i = 0; i < flushes.size(); i++) |
| 116 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | 187 | EmitDedupSummary(flushes[i]); |
| 117 | category, suppressedToFlush, (long long)DEDUP_WINDOW_SECS, flushedMsg.c_str()); | ||
| 118 | if (fEmitNow) | 188 | if (fEmitNow) |
| 119 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | 189 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); |
| 120 | } | 190 | } |
| 121 | 191 | ||
| 192 | // LogPrintAlways() -- see the doc comment in util.h. No window, no counting, | ||
| 193 | // no table entry: every call writes its own line. | ||
| 194 | void LogPrintNoCollapse(const char* category, const std::string& msgIn) | ||
| 195 | { | ||
| 196 | std::string msg = msgIn; | ||
| 197 | while (!msg.empty() && (msg.back() == '\n' || msg.back() == '\r')) | ||
| 198 | msg.pop_back(); | ||
| 199 | |||
| 200 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | ||
| 201 | } | ||
| 202 | |||
| 122 | 203 | ||
| 123 | 204 | ||
| 124 | 205 | ||