store_rebuild.cc
Go to the documentation of this file.
1 /*
2  * Copyright (C) 1996-2020 The Squid Software Foundation and contributors
3  *
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.
7  */
8 
9 /* DEBUG: section 20 Store Rebuild Routines */
10 
11 #include "squid.h"
12 #include "event.h"
13 #include "globals.h"
14 #include "md5.h"
15 #include "SquidConfig.h"
16 #include "SquidTime.h"
17 #include "StatCounters.h"
18 #include "Store.h"
19 #include "store/Disk.h"
20 #include "store_digest.h"
21 #include "store_key_md5.h"
22 #include "store_rebuild.h"
23 #include "StoreSearch.h"
24 // for tvSubDsec() which should be in SquidTime.h
25 #include "util.h"
26 
27 #include <cerrno>
28 
30 
31 static void storeCleanup(void *);
32 
33 // TODO: Either convert to Progress or replace with StoreRebuildData.
34 // TODO: Handle unknown totals (UFS cache_dir that lost swap.state) correctly.
35 typedef struct {
36  /* total number of "swap.state" entries that will be read */
37  int total;
38  /* number of entries read so far */
39  int scanned;
41 
43 
44 void
45 StoreRebuildData::updateStartTime(const timeval &dirStartTime)
46 {
47  startTime = started() ? std::min(startTime, dirStartTime) : dirStartTime;
48 }
49 
50 static int
52 {
53  SwapDir *SD = dynamic_cast<SwapDir *>(INDEXSD(e->swap_dirn));
54  return (SD->doubleCheck(*e));
55 }
56 
57 static void
58 storeCleanup(void *)
59 {
60  static int store_errors = 0;
61  static StoreSearchPointer currentSearch;
62  static int validated = 0;
63  static int seen = 0;
64 
65  if (currentSearch == NULL || currentSearch->isDone())
66  currentSearch = Store::Root().search();
67 
68  size_t statCount = 500;
69 
70  // TODO: Avoid the loop (and ENTRY_VALIDATED) unless opt_store_doublecheck.
71  while (statCount-- && !currentSearch->isDone() && currentSearch->next()) {
72  StoreEntry *e;
73 
74  e = currentSearch->currentItem();
75 
76  ++seen;
77 
79  continue;
80 
81  /*
82  * Calling StoreEntry->release() has no effect because we're
83  * still in 'store_rebuilding' state
84  */
85  if (!e->hasDisk())
86  continue;
87 
90  ++store_errors;
91 
93 
94  /*
95  * Only set the file bit if we know its a valid entry
96  * otherwise, set it in the validation procedure
97  */
98 
99  if ((++validated & 0x3FFFF) == 0)
100  /* TODO format the int with with a stream operator */
101  debugs(20, DBG_IMPORTANT, " " << validated << " Entries Validated so far.");
102  }
103 
104  if (currentSearch->isDone()) {
105  debugs(20, 2, "Seen: " << seen << " entries");
106  debugs(20, DBG_IMPORTANT, " Completed Validation Procedure");
107  debugs(20, DBG_IMPORTANT, " Validated " << validated << " Entries");
108  debugs(20, DBG_IMPORTANT, " store_swap_size = " << Store::Root().currentSize() / 1024.0 << " KB");
111 
112  if (opt_store_doublecheck && store_errors) {
113  fatalf("Quitting after finding %d cache index inconsistencies. " \
114  "Removing cache index will force its slow rebuild. " \
115  "Removing -S will let Squid start with an inconsistent " \
116  "cache index (at your own risk).\n", store_errors);
117  }
118 
119  if (store_digest)
121 
122  currentSearch = NULL;
123  } else
124  eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
125 }
126 
127 /* meta data recreated from disk image in swap directory */
128 void
129 
131 {
132  if (dc) {
133  counts.objcount += dc->objcount;
134  counts.expcount += dc->expcount;
135  counts.scancount += dc->scancount;
136  counts.clashcount += dc->clashcount;
137  counts.dupcount += dc->dupcount;
138  counts.cancelcount += dc->cancelcount;
139  counts.invalid += dc->invalid;
140  counts.badflags += dc->badflags;
141  counts.bad_log_op += dc->bad_log_op;
142  counts.zero_object_sz += dc->zero_object_sz;
143  counts.validations += dc->validations;
144  counts.updateStartTime(dc->startTime);
145  }
146  // else the caller was not responsible for indexing its cache_dir
147 
150 
151  /*
152  * When store_dirs_rebuilding == 1, it means we are done reading
153  * or scanning all cache_dirs. Now report the stats and start
154  * the validation (storeCleanup()) thread.
155  */
156 
158  return;
159 
160  const auto dt = tvSubDsec(counts.startTime, current_time);
161 
162  debugs(20, DBG_IMPORTANT, "Finished rebuilding storage from disk.");
163  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.scancount << " Entries scanned");
164  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.invalid << " Invalid entries.");
165  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.badflags << " With invalid flags.");
166  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.objcount << " Objects loaded.");
167  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.expcount << " Objects expired.");
168  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.cancelcount << " Objects cancelled.");
169  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.dupcount << " Duplicate URLs purged.");
170  debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.clashcount << " Swapfile clashes avoided.");
171  debugs(20, DBG_IMPORTANT, " Took "<< std::setw(3)<< std::setprecision(2) << dt << " seconds ("<< std::setw(6) <<
172  ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec).");
173  debugs(20, DBG_IMPORTANT, "Beginning Validation Procedure");
174 
175  eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
176 
178 
180 }
181 
182 /*
183  * this is ugly. We don't actually start any rebuild threads here,
184  * but only initialize counters, etc. The rebuild threads are
185  * actually started by the filesystem "fooDirInit" function.
186  */
187 void
189 {
190  counts = StoreRebuildData(); // reset counters
191  /*
192  * Note: store_dirs_rebuilding is initialized to 1.
193  *
194  * When we parse the configuration and construct each swap dir,
195  * the construction of that raises the rebuild count.
196  *
197  * This prevents us from trying to write clean logs until we
198  * finished rebuilding - including after a reconfiguration that opens an
199  * existing swapdir. The corresponding decrement * occurs in
200  * storeCleanup(), when it is finished.
201  */
203  sizeof(store_rebuild_progress));
204 }
205 
206 /*
207  * A fs-specific rebuild procedure periodically reports its
208  * progress.
209  */
210 void
211 storeRebuildProgress(int sd_index, int total, int sofar)
212 {
213  static time_t last_report = 0;
214  // TODO: Switch to int64_t and fix handling of unknown totals.
215  double n = 0.0;
216  double d = 0.0;
217 
218  if (sd_index < 0)
219  return;
220 
221  if (sd_index >= Config.cacheSwap.n_configured)
222  return;
223 
224  if (NULL == RebuildProgress)
225  return;
226 
227  RebuildProgress[sd_index].total = total;
228 
229  RebuildProgress[sd_index].scanned = sofar;
230 
231  if (squid_curtime - last_report < 15)
232  return;
233 
234  for (sd_index = 0; sd_index < Config.cacheSwap.n_configured; ++sd_index) {
235  n += (double) RebuildProgress[sd_index].scanned;
236  d += (double) RebuildProgress[sd_index].total;
237  }
238 
239  debugs(20, DBG_IMPORTANT, "Indexing cache entries: " << Progress(n, d));
240  last_report = squid_curtime;
241 }
242 
243 void
244 Progress::print(std::ostream &os) const
245 {
246  if (goal > 0) {
247  const auto percent = 100.0 * completed / goal;
248  os << std::setprecision(2) << percent << "% (" <<
249  completed << " out of " << goal << ")";
250  } else if (!completed && !goal) {
251  os << "nothing to do";
252  } else {
253  // unknown (i.e. negative) or buggy (i.e. zero when completed != 0) goal
254  os << completed;
255  }
256 }
257 
258 #include "fde.h"
259 #include "Generic.h"
260 #include "StoreMeta.h"
261 #include "StoreMetaUnpacker.h"
262 
263 struct InitStoreEntry : public unary_function<StoreMeta, void> {
264  InitStoreEntry(StoreEntry *anEntry, cache_key *aKey):what(anEntry),index(aKey) {}
265 
266  void operator()(StoreMeta const &x) {
267  switch (x.getType()) {
268 
269  case STORE_META_KEY:
271  memcpy(index, x.value, SQUID_MD5_DIGEST_LENGTH);
272  break;
273 
274  case STORE_META_STD:
275  struct old_metahdr {
276  time_t timestamp;
277  time_t lastref;
278  time_t expires;
279  time_t lastmod;
280  size_t swap_file_sz;
281  uint16_t refcount;
282  uint16_t flags;
283  } *tmp;
284  tmp = (struct old_metahdr *)x.value;
286  what->timestamp = tmp->timestamp;
287  what->lastref = tmp->lastref;
288  what->expires = tmp->expires;
289  what->lastModified(tmp->lastmod);
290  what->swap_file_sz = tmp->swap_file_sz;
291  what->refcount = tmp->refcount;
292  what->flags = tmp->flags;
293  break;
294 
295  case STORE_META_STD_LFS:
297  memcpy(&what->timestamp, x.value, STORE_HDR_METASIZE);
298  break;
299 
300  default:
301  break;
302  }
303  }
304 
307 };
308 
309 bool
311 {
312  if (fd < 0)
313  return false;
314 
315  assert(buf.hasSpace()); // caller must allocate
316 
317  const int len = FD_READ_METHOD(fd, buf.space(), buf.spaceSize());
318  ++ statCounter.syscalls.disk.reads;
319  if (len < 0) {
320  const int xerrno = errno;
321  debugs(47, DBG_IMPORTANT, "WARNING: cache_dir[" << diskIndex << "]: " <<
322  "Ignoring cached entry after meta data read failure: " << xstrerr(xerrno));
323  return false;
324  }
325 
326  buf.appended(len);
327  return true;
328 }
329 
330 bool
333  uint64_t expectedSize)
334 {
335  int swap_hdr_len = 0;
336  StoreMetaUnpacker aBuilder(buf.content(), buf.contentSize(), &swap_hdr_len);
337  if (aBuilder.isBufferZero()) {
338  debugs(47,5, HERE << "skipping empty record.");
339  return false;
340  }
341 
342  StoreMeta *tlv_list = nullptr;
343  try {
344  tlv_list = aBuilder.createStoreMeta();
345  } catch (const std::exception &e) {
346  debugs(47, DBG_IMPORTANT, "WARNING: Ignoring store entry because " << e.what());
347  return false;
348  }
349  assert(tlv_list);
350 
351  // TODO: consume parsed metadata?
352 
353  debugs(47,7, "successful swap meta unpacking; swap_file_sz=" << tmpe.swap_file_sz);
354  memset(key, '\0', SQUID_MD5_DIGEST_LENGTH);
355 
356  InitStoreEntry visitor(&tmpe, key);
357  for_each(*tlv_list, visitor);
358  storeSwapTLVFree(tlv_list);
359  tlv_list = NULL;
360 
361  if (storeKeyNull(key)) {
362  debugs(47, DBG_IMPORTANT, "WARNING: Ignoring keyless cache entry");
363  return false;
364  }
365 
366  tmpe.key = key;
367  /* check sizes */
368 
369  if (expectedSize > 0) {
370  if (tmpe.swap_file_sz == 0) {
371  tmpe.swap_file_sz = expectedSize;
372  } else if (tmpe.swap_file_sz == (uint64_t)(expectedSize - swap_hdr_len)) {
373  tmpe.swap_file_sz = expectedSize;
374  } else if (tmpe.swap_file_sz != expectedSize) {
375  debugs(47, DBG_IMPORTANT, "WARNING: Ignoring cache entry due to a " <<
376  "SIZE MISMATCH " << tmpe.swap_file_sz << "!=" << expectedSize);
377  return false;
378  }
379  } else if (tmpe.swap_file_sz <= 0) {
380  // if caller cannot handle unknown sizes, it must check after the call.
381  debugs(47, 7, "unknown size: " << tmpe);
382  }
383 
384  if (EBIT_TEST(tmpe.flags, KEY_PRIVATE)) {
385  ++ stats.badflags;
386  return false;
387  }
388 
389  return true;
390 }
391 
const char * xstrerr(int error)
Definition: xstrerror.cc:83
void storeRebuildProgress(int sd_index, int total, int sofar)
virtual bool doubleCheck(StoreEntry &)
Definition: Disk.cc:46
class Ping::pingStats_ stats
void * xcalloc(size_t n, size_t sz)
Definition: xalloc.cc:72
#define INDEXSD(i)
Definition: SquidConfig.h:71
int64_t completed
the number of finished work steps
Definition: store_rebuild.h:55
time_t timestamp
Definition: Store.h:216
@ STORE_META_STD
Definition: StoreMeta.h:83
int64_t goal
the known total number of work steps (or negative)
Definition: store_rebuild.h:56
manages a single cache_dir
Definition: Disk.h:21
unsigned char cache_key
Store key.
Definition: forward.h:29
#define EBIT_SET(flag, bit)
Definition: defines.h:105
int opt_store_doublecheck
bool storeRebuildParseEntry(MemBuf &buf, StoreEntry &tmpe, cache_key *key, StoreRebuildData &stats, uint64_t expectedSize)
parses entry buffer and validates entry metadata; fills e on success
SQUIDCEXTERN double tvSubDsec(struct timeval, struct timeval)
Definition: util.c:46
InitStoreEntry(StoreEntry *anEntry, cache_key *aKey)
@ STORE_META_STD_LFS
Definition: StoreMeta.h:102
@ KEY_PRIVATE
Definition: enums.h:102
static int storeCleanupDoubleCheck(StoreEntry *e)
void updateStartTime(const timeval &dirStartTime)
maintain earliest initiation time across multiple indexing cache_dirs
cache_dir(s) indexing statistics
Definition: store_rebuild.h:19
uint16_t flags
Definition: Store.h:224
time_t expires
Definition: Store.h:218
Store::DiskConfig cacheSwap
Definition: SquidConfig.h:427
#define DBG_IMPORTANT
Definition: Debug.h:46
void storeRebuildComplete(StoreRebuildData *dc)
#define STORE_HDR_METASIZE_OLD
Definition: defines.h:173
#define SQUID_MD5_DIGEST_LENGTH
Definition: md5.h:66
#define NULL
Definition: types.h:166
static void storeCleanup(void *)
struct StatCounters::@137::@141 disk
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Debug.h:128
@ ENTRY_VALIDATED
Definition: enums.h:113
struct StatCounters::@137 syscalls
uint16_t refcount
Definition: Store.h:223
bool hasDisk(const sdirno dirn=-1, const sfileno filen=-1) const
Definition: store.cc:1990
sdirno swap_dirn
Definition: Store.h:230
Definition: MemBuf.h:23
#define EBIT_TEST(flag, bit)
Definition: defines.h:107
std::ostream & HERE(std::ostream &s)
Definition: Debug.h:157
#define STORE_HDR_METASIZE
Definition: defines.h:172
timeval startTime
absolute time when the rebuild was initiated
Definition: store_rebuild.h:42
StoreMeta * createStoreMeta()
#define assert(EX)
Definition: assert.h:19
bool storeRebuildLoadEntry(int fd, int diskIndex, MemBuf &buf, StoreRebuildData &)
loads entry from disk; fills supplied memory buffer on success
void storeDigestNoteStoreReady(void)
virtual void next(void(callback)(void *cbdata), void *cbdata)=0
void fatalf(const char *fmt,...)
Definition: fatal.cc:68
int length
Definition: StoreMeta.h:133
virtual bool isDone() const =0
virtual StoreEntry * currentItem()=0
StoreSearch * search()
Definition: Controller.cc:215
static store_rebuild_progress * RebuildProgress
static int store_dirs_rebuilding
the number of cache_dirs being rebuilt; TODO: move to Disks::Rebuilding
Definition: Controller.h:139
time_t squid_curtime
Definition: stub_time.cc:17
#define xfree
int FD_READ_METHOD(int fd, char *buf, int len)
Definition: fde.h:194
void print(std::ostream &os) const
brief progress report suitable for level-0/1 debugging
advancement of work that consists of (usually known number) of similar steps
Definition: store_rebuild.h:46
void * value
Definition: StoreMeta.h:134
int storeKeyNull(const cache_key *key)
virtual char getType() const =0
struct timeval current_time
Definition: stub_time.cc:15
bool started() const
whether we have worked on indexing this(these) cache_dir(s) before
Definition: store_rebuild.h:26
int64_t validations
the number of validated cache entries, slots
Definition: store_rebuild.h:41
void storeSwapTLVFree(tlv *n)
StoreEntry * what
static StoreRebuildData counts
bool isBufferZero()
useful for meta stored in pre-initialized (with zeros) db files
void storeRebuildStart(void)
uint64_t swap_file_sz
Definition: Store.h:222
CacheDigest * store_digest
int unsigned int const char *desc STUB void int len
Definition: stub_fd.cc:20
cache_key * index
void lastModified(const time_t when)
Definition: Store.h:168
void operator()(StoreMeta const &x)
#define STORE_META_KEY
Definition: defines.h:165
T & for_each(L const &head, T &visitor)
Definition: Generic.h:23
const A & min(A const &lhs, A const &rhs)
time_t lastref
Definition: Store.h:217
void const char * buf
Definition: stub_helper.cc:16
void eventAdd(const char *name, EVH *func, void *arg, double when, int weight, bool cbdata)
Definition: event.cc:109
class SquidConfig Config
Definition: SquidConfig.cc:12
StatCounters statCounter
Definition: StatCounters.cc:12
Controller & Root()
safely access controller singleton
Definition: Controller.cc:938

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors