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