]>
Commit | Line | Data |
---|---|---|
8638fc66 | 1 | /* |
b8ae064d | 2 | * Copyright (C) 1996-2023 The Squid Software Foundation and contributors |
e25c139f | 3 | * |
bbc27441 AJ |
4 | * Squid software is distributed under GPLv2+ license and includes |
5 | * contributions from numerous individuals and organizations. | |
6 | * Please see the COPYING and CONTRIBUTORS files for details. | |
8638fc66 | 7 | */ |
8 | ||
bbc27441 AJ |
9 | /* DEBUG: section 20 Store Rebuild Routines */ |
10 | ||
582c2af2 | 11 | #include "squid.h" |
675b8408 | 12 | #include "debug/Messages.h" |
a553a5a3 | 13 | #include "event.h" |
d448e1eb | 14 | #include "fde.h" |
582c2af2 FC |
15 | #include "globals.h" |
16 | #include "md5.h" | |
602d9612 | 17 | #include "SquidConfig.h" |
e4f1fdae | 18 | #include "StatCounters.h" |
e6ccf245 | 19 | #include "Store.h" |
b3f7fd88 | 20 | #include "store/Disk.h" |
d448e1eb | 21 | #include "store/SwapMetaIn.h" |
35a28a37 | 22 | #include "store_digest.h" |
602d9612 | 23 | #include "store_key_md5.h" |
687f5275 | 24 | #include "store_rebuild.h" |
c8f4eac4 | 25 | #include "StoreSearch.h" |
98cacedb | 26 | #include "time/gadgets.h" |
f09f5b26 | 27 | |
1a30fdf5 AJ |
28 | #include <cerrno> |
29 | ||
211e9ce2 | 30 | static StoreRebuildData counts; |
62e76326 | 31 | |
9bea1d5b | 32 | static void storeCleanup(void *); |
f09f5b26 | 33 | |
8ecbe78d EB |
34 | // TODO: Either convert to Progress or replace with StoreRebuildData. |
35 | // TODO: Handle unknown totals (UFS cache_dir that lost swap.state) correctly. | |
26ac0430 | 36 | typedef struct { |
5a797987 | 37 | /* total number of "swap.state" entries that will be read */ |
38 | int total; | |
39 | /* number of entries read so far */ | |
40 | int scanned; | |
2fadd50d | 41 | } store_rebuild_progress; |
5a797987 | 42 | |
aee3523a | 43 | static store_rebuild_progress *RebuildProgress = nullptr; |
5a797987 | 44 | |
8ecbe78d EB |
45 | void |
46 | StoreRebuildData::updateStartTime(const timeval &dirStartTime) | |
47 | { | |
48 | startTime = started() ? std::min(startTime, dirStartTime) : dirStartTime; | |
49 | } | |
50 | ||
908daabd EB |
51 | /// handles the completion of zero or more post-rebuild storeCleanup() steps |
52 | static void | |
53 | storeCleanupComplete() | |
54 | { | |
55 | assert(StoreController::store_dirs_rebuilding == 1); // we are the last act | |
56 | --StoreController::store_dirs_rebuilding; | |
57 | ||
58 | if (store_digest) | |
59 | storeDigestNoteStoreReady(); | |
60 | } | |
61 | ||
12784378 | 62 | static void |
ced8def3 | 63 | storeCleanup(void *) |
f09f5b26 | 64 | { |
9bea1d5b | 65 | static int store_errors = 0; |
c8f4eac4 | 66 | static StoreSearchPointer currentSearch; |
67 | static int validated = 0; | |
52dce2fe | 68 | static int seen = 0; |
c8f4eac4 | 69 | |
aee3523a | 70 | if (currentSearch == nullptr || currentSearch->isDone()) |
2745fea5 | 71 | currentSearch = Store::Root().search(); |
c8f4eac4 | 72 | |
73 | size_t statCount = 500; | |
74 | ||
26031546 | 75 | // TODO: Avoid the loop (and ENTRY_VALIDATED) unless opt_store_doublecheck. |
c8f4eac4 | 76 | while (statCount-- && !currentSearch->isDone() && currentSearch->next()) { |
c8f4eac4 | 77 | StoreEntry *e; |
78 | ||
79 | e = currentSearch->currentItem(); | |
80 | ||
52dce2fe AR |
81 | ++seen; |
82 | ||
c8f4eac4 | 83 | if (EBIT_TEST(e->flags, ENTRY_VALIDATED)) |
84 | continue; | |
85 | ||
86 | /* | |
5f33b71d | 87 | * Calling StoreEntry->release() has no effect because we're |
c8f4eac4 | 88 | * still in 'store_rebuilding' state |
89 | */ | |
4310f8b0 | 90 | if (!e->hasDisk()) |
c8f4eac4 | 91 | continue; |
92 | ||
93 | if (opt_store_doublecheck) | |
5d84beb5 | 94 | if (e->disk().doubleCheck(*e)) |
5db6bf73 | 95 | ++store_errors; |
c8f4eac4 | 96 | |
97 | EBIT_SET(e->flags, ENTRY_VALIDATED); | |
98 | ||
99 | /* | |
100 | * Only set the file bit if we know its a valid entry | |
101 | * otherwise, set it in the validation procedure | |
102 | */ | |
e2851fe7 | 103 | |
c8f4eac4 | 104 | if ((++validated & 0x3FFFF) == 0) |
105 | /* TODO format the int with with a stream operator */ | |
e0236918 | 106 | debugs(20, DBG_IMPORTANT, " " << validated << " Entries Validated so far."); |
f09f5b26 | 107 | } |
62e76326 | 108 | |
c8f4eac4 | 109 | if (currentSearch->isDone()) { |
52dce2fe | 110 | debugs(20, 2, "Seen: " << seen << " entries"); |
c59baaa8 EB |
111 | debugs(20, Important(43), "Completed Validation Procedure" << |
112 | Debug::Extra << "Validated " << validated << " Entries" << | |
113 | Debug::Extra << "store_swap_size = " << (Store::Root().currentSize()/1024.0) << " KB"); | |
c8f4eac4 | 114 | |
2f6fcab1 AR |
115 | if (opt_store_doublecheck && store_errors) { |
116 | fatalf("Quitting after finding %d cache index inconsistencies. " \ | |
117 | "Removing cache index will force its slow rebuild. " \ | |
118 | "Removing -S will let Squid start with an inconsistent " \ | |
119 | "cache index (at your own risk).\n", store_errors); | |
120 | } | |
c8f4eac4 | 121 | |
908daabd | 122 | storeCleanupComplete(); |
c8f4eac4 | 123 | |
aee3523a | 124 | currentSearch = nullptr; |
c8f4eac4 | 125 | } else |
aee3523a | 126 | eventAdd("storeCleanup", storeCleanup, nullptr, 0.0, 1); |
f09f5b26 | 127 | } |
128 | ||
f09f5b26 | 129 | /* meta data recreated from disk image in swap directory */ |
b2c141d4 | 130 | void |
62e76326 | 131 | |
211e9ce2 | 132 | storeRebuildComplete(StoreRebuildData *dc) |
f09f5b26 | 133 | { |
8ecbe78d EB |
134 | if (dc) { |
135 | counts.objcount += dc->objcount; | |
136 | counts.expcount += dc->expcount; | |
137 | counts.scancount += dc->scancount; | |
138 | counts.clashcount += dc->clashcount; | |
139 | counts.dupcount += dc->dupcount; | |
140 | counts.cancelcount += dc->cancelcount; | |
141 | counts.invalid += dc->invalid; | |
142 | counts.badflags += dc->badflags; | |
143 | counts.bad_log_op += dc->bad_log_op; | |
144 | counts.zero_object_sz += dc->zero_object_sz; | |
145 | counts.validations += dc->validations; | |
146 | counts.updateStartTime(dc->startTime); | |
147 | } | |
148 | // else the caller was not responsible for indexing its cache_dir | |
149 | ||
150 | assert(StoreController::store_dirs_rebuilding > 1); | |
151 | --StoreController::store_dirs_rebuilding; | |
908daabd EB |
152 | if (StoreController::store_dirs_rebuilding > 1) |
153 | return; // wait for more rebuilding cache_dirs to call us | |
8ecbe78d | 154 | |
908daabd | 155 | // rebuilt all cache_dirs (if any) |
62e76326 | 156 | |
908daabd EB |
157 | safe_free(RebuildProgress); |
158 | ||
159 | if (!counts.started()) { | |
160 | assert(!counts.scancount); | |
161 | debugs(20, 5, "not responsible for rebuilding any cache_dirs: " << Config.cacheSwap.n_configured); | |
162 | // we did not even try to load any entries so we skip storeCleanup()'s | |
163 | // entry validation reports | |
164 | storeCleanupComplete(); | |
62e76326 | 165 | return; |
908daabd | 166 | } |
62e76326 | 167 | |
8ecbe78d | 168 | const auto dt = tvSubDsec(counts.startTime, current_time); |
62e76326 | 169 | |
c59baaa8 EB |
170 | debugs(20, Important(46), "Finished rebuilding storage from disk." << |
171 | Debug::Extra << std::setw(7) << counts.scancount << " Entries scanned" << | |
172 | Debug::Extra << std::setw(7) << counts.invalid << " Invalid entries" << | |
173 | Debug::Extra << std::setw(7) << counts.badflags << " With invalid flags" << | |
174 | Debug::Extra << std::setw(7) << counts.objcount << " Objects loaded" << | |
175 | Debug::Extra << std::setw(7) << counts.expcount << " Objects expired" << | |
176 | Debug::Extra << std::setw(7) << counts.cancelcount << " Objects canceled" << | |
177 | Debug::Extra << std::setw(7) << counts.dupcount << " Duplicate URLs purged" << | |
178 | Debug::Extra << std::setw(7) << counts.clashcount << " Swapfile clashes avoided" << | |
179 | Debug::Extra << "Took " << std::setprecision(2) << dt << " seconds (" << | |
bf8fe701 | 180 | ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec)."); |
c59baaa8 | 181 | debugs(20, Important(56), "Beginning Validation Procedure"); |
62e76326 | 182 | |
aee3523a | 183 | eventAdd("storeCleanup", storeCleanup, nullptr, 0.0, 1); |
f09f5b26 | 184 | } |
185 | ||
b2c141d4 | 186 | /* |
187 | * this is ugly. We don't actually start any rebuild threads here, | |
188 | * but only initialize counters, etc. The rebuild threads are | |
189 | * actually started by the filesystem "fooDirInit" function. | |
190 | */ | |
f09f5b26 | 191 | void |
9bea1d5b | 192 | storeRebuildStart(void) |
f09f5b26 | 193 | { |
b56b37cf | 194 | counts = StoreRebuildData(); // reset counters |
9bea1d5b | 195 | /* |
b07b21cc | 196 | * Note: store_dirs_rebuilding is initialized to 1. |
26ac0430 AJ |
197 | * |
198 | * When we parse the configuration and construct each swap dir, | |
bef81ea5 | 199 | * the construction of that raises the rebuild count. |
200 | * | |
908daabd EB |
201 | * This prevents us from trying to write clean logs until we finished |
202 | * rebuilding - including after a reconfiguration that opens an existing | |
203 | * swapdir. The corresponding decrement occurs in storeCleanupComplete(). | |
9bea1d5b | 204 | */ |
e6ccf245 | 205 | RebuildProgress = (store_rebuild_progress *)xcalloc(Config.cacheSwap.n_configured, |
62e76326 | 206 | sizeof(store_rebuild_progress)); |
5a797987 | 207 | } |
208 | ||
209 | /* | |
210 | * A fs-specific rebuild procedure periodically reports its | |
211 | * progress. | |
212 | */ | |
213 | void | |
9bea1d5b | 214 | storeRebuildProgress(int sd_index, int total, int sofar) |
5a797987 | 215 | { |
9bea1d5b | 216 | static time_t last_report = 0; |
8ecbe78d | 217 | // TODO: Switch to int64_t and fix handling of unknown totals. |
9bea1d5b | 218 | double n = 0.0; |
219 | double d = 0.0; | |
62e76326 | 220 | |
9bea1d5b | 221 | if (sd_index < 0) |
62e76326 | 222 | return; |
223 | ||
9bea1d5b | 224 | if (sd_index >= Config.cacheSwap.n_configured) |
62e76326 | 225 | return; |
226 | ||
aee3523a | 227 | if (nullptr == RebuildProgress) |
62e76326 | 228 | return; |
229 | ||
9bea1d5b | 230 | RebuildProgress[sd_index].total = total; |
62e76326 | 231 | |
9bea1d5b | 232 | RebuildProgress[sd_index].scanned = sofar; |
62e76326 | 233 | |
9bea1d5b | 234 | if (squid_curtime - last_report < 15) |
62e76326 | 235 | return; |
236 | ||
5db6bf73 | 237 | for (sd_index = 0; sd_index < Config.cacheSwap.n_configured; ++sd_index) { |
62e76326 | 238 | n += (double) RebuildProgress[sd_index].scanned; |
239 | d += (double) RebuildProgress[sd_index].total; | |
5a797987 | 240 | } |
62e76326 | 241 | |
c59baaa8 | 242 | debugs(20, Important(57), "Indexing cache entries: " << Progress(n, d)); |
9bea1d5b | 243 | last_report = squid_curtime; |
f09f5b26 | 244 | } |
e2851fe7 | 245 | |
8ecbe78d EB |
246 | void |
247 | Progress::print(std::ostream &os) const | |
248 | { | |
249 | if (goal > 0) { | |
9fa45f86 | 250 | const auto savedPrecision = os.precision(2); |
8ecbe78d | 251 | const auto percent = 100.0 * completed / goal; |
9fa45f86 | 252 | os << percent << "% (" << completed << " out of " << goal << ")"; |
70ac5b29 | 253 | (void)os.precision(savedPrecision); |
8ecbe78d EB |
254 | } else if (!completed && !goal) { |
255 | os << "nothing to do"; | |
256 | } else { | |
257 | // unknown (i.e. negative) or buggy (i.e. zero when completed != 0) goal | |
258 | os << completed; | |
259 | } | |
260 | } | |
261 | ||
e2851fe7 | 262 | bool |
3254023f | 263 | storeRebuildLoadEntry(int fd, int diskIndex, MemBuf &buf, StoreRebuildData &) |
e2851fe7 AR |
264 | { |
265 | if (fd < 0) | |
266 | return false; | |
267 | ||
aa1a691e | 268 | assert(buf.hasSpace()); // caller must allocate |
e2851fe7 | 269 | |
aa1a691e | 270 | const int len = FD_READ_METHOD(fd, buf.space(), buf.spaceSize()); |
5db6bf73 | 271 | ++ statCounter.syscalls.disk.reads; |
aa1a691e AR |
272 | if (len < 0) { |
273 | const int xerrno = errno; | |
28edca61 | 274 | debugs(47, DBG_IMPORTANT, "WARNING: cache_dir[" << diskIndex << "]: " << |
9199139f | 275 | "Ignoring cached entry after meta data read failure: " << xstrerr(xerrno)); |
e2851fe7 AR |
276 | return false; |
277 | } | |
278 | ||
aa1a691e AR |
279 | buf.appended(len); |
280 | return true; | |
281 | } | |
282 | ||
283 | bool | |
284 | storeRebuildParseEntry(MemBuf &buf, StoreEntry &tmpe, cache_key *key, | |
3254023f | 285 | StoreRebuildData &stats, |
aa1a691e AR |
286 | uint64_t expectedSize) |
287 | { | |
d448e1eb EB |
288 | uint64_t swap_hdr_len = 0; |
289 | ||
290 | tmpe.key = nullptr; | |
e2851fe7 | 291 | |
4c2f8b72 | 292 | try { |
d448e1eb EB |
293 | swap_hdr_len = Store::UnpackIndexSwapMeta(buf, tmpe, key); |
294 | } catch (...) { | |
295 | debugs(47, Important(65), "WARNING: Indexer ignores a cache_dir entry: " << CurrentException); | |
e2851fe7 AR |
296 | return false; |
297 | } | |
298 | ||
aa1a691e AR |
299 | // TODO: consume parsed metadata? |
300 | ||
539283df | 301 | debugs(47,7, "successful swap meta unpacking; swap_file_sz=" << tmpe.swap_file_sz); |
e2851fe7 | 302 | |
d448e1eb | 303 | if (!tmpe.key) { |
28edca61 | 304 | debugs(47, DBG_IMPORTANT, "WARNING: Ignoring keyless cache entry"); |
e2851fe7 AR |
305 | return false; |
306 | } | |
307 | ||
e2851fe7 AR |
308 | /* check sizes */ |
309 | ||
310 | if (expectedSize > 0) { | |
311 | if (tmpe.swap_file_sz == 0) { | |
312 | tmpe.swap_file_sz = expectedSize; | |
313 | } else if (tmpe.swap_file_sz == (uint64_t)(expectedSize - swap_hdr_len)) { | |
314 | tmpe.swap_file_sz = expectedSize; | |
315 | } else if (tmpe.swap_file_sz != expectedSize) { | |
28edca61 AR |
316 | debugs(47, DBG_IMPORTANT, "WARNING: Ignoring cache entry due to a " << |
317 | "SIZE MISMATCH " << tmpe.swap_file_sz << "!=" << expectedSize); | |
e2851fe7 AR |
318 | return false; |
319 | } | |
9199139f | 320 | } else if (tmpe.swap_file_sz <= 0) { |
52dce2fe AR |
321 | // if caller cannot handle unknown sizes, it must check after the call. |
322 | debugs(47, 7, "unknown size: " << tmpe); | |
e2851fe7 AR |
323 | } |
324 | ||
325 | if (EBIT_TEST(tmpe.flags, KEY_PRIVATE)) { | |
3254023f | 326 | ++ stats.badflags; |
e2851fe7 AR |
327 | return false; |
328 | } | |
329 | ||
330 | return true; | |
331 | } | |
332 |