test_cache_digest.cc
Go to the documentation of this file.
1/*
2 * Copyright (C) 1996-2022 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/*
10 * Test-suite for playing with cache digests
11 */
12
13#include "squid.h"
14#include "CacheDigest.h"
15#include "store_key_md5.h"
16
17#include <cerrno>
18
19typedef struct {
26
27typedef struct _Cache Cache;
28
29struct _Cache {
30 const char *name;
35 int count; /* #currently cached entries */
36 int req_count; /* #requests to this cache */
37 int bad_add_count; /* #duplicate adds */
38 int bad_del_count; /* #dels with no prior add */
39};
40
41typedef struct _CacheEntry {
42 const cache_key *key;
43
46 /* storeSwapLogData s; */
48
49/* parsed access log entry */
50
51typedef struct {
53 time_t timestamp;
54 short int use_icp; /* true/false */
56
57typedef enum {
58 frError = -2, frMore = -1, frEof = 0, frOk = 1
60
63
65 const char *fname;
66 FILE *file;
67 time_t inner_time; /* timestamp of the current entry */
68 time_t time_offset; /* to adjust time set by reader */
69 int line_count; /* number of lines scanned */
70 int bad_line_count; /* number of parsing errors */
71 int time_warp_count; /* number of out-of-order entries in the file */
72 FI_READER reader; /* reads next entry and updates inner_time */
73 void *entry; /* buffer for the current entry, freed with xfree() */
74};
75
76/* globals */
77static time_t cur_time = -1; /* timestamp of the current log entry */
78
79/* copied from url.c */
81methodStrToId(const char *s)
82{
83 if (strcasecmp(s, "GET") == 0) {
84 return METHOD_GET;
85 } else if (strcasecmp(s, "POST") == 0) {
86 return METHOD_POST;
87 } else if (strcasecmp(s, "PUT") == 0) {
88 return METHOD_PUT;
89 } else if (strcasecmp(s, "HEAD") == 0) {
90 return METHOD_HEAD;
91 } else if (strcasecmp(s, "CONNECT") == 0) {
92 return METHOD_CONNECT;
93 } else if (strcasecmp(s, "TRACE") == 0) {
94 return METHOD_TRACE;
95 } else if (strcasecmp(s, "PURGE") == 0) {
96 return METHOD_PURGE;
97 }
98
99 return METHOD_NONE;
100}
101
102/* FileIterator */
103
104static void fileIteratorAdvance(FileIterator * fi);
105
106static FileIterator *
107fileIteratorCreate(const char *fname, FI_READER reader)
108{
109 FileIterator *fi = (FileIterator *)xcalloc(1, sizeof(FileIterator));
110 assert(fname && reader);
111 fi->fname = fname;
112 fi->reader = reader;
113 fi->file = fopen(fname, "r");
114
115 if (!fi->file) {
116 fprintf(stderr, "cannot open %s: %s\n", fname, strerror(errno));
117 return NULL;
118 } else
119 fprintf(stderr, "opened %s\n", fname);
120
122
123 return fi;
124}
125
126static void
128{
129 assert(fi);
130
131 if (fi->file) {
132 fclose(fi->file);
133 fprintf(stderr, "closed %s\n", fi->fname);
134 }
135
136 xfree(fi->entry);
137 xfree(fi);
138}
139
140static void
142{
143 assert(fi);
144 assert(fi->inner_time > 0);
145 fi->time_offset = ct - fi->inner_time;
146}
147
148static void
150{
151 int res;
152 assert(fi);
153
154 do {
155 const time_t last_time = fi->inner_time;
156 fi->inner_time = -1;
157 res = fi->reader(fi);
158 ++ fi->line_count;
159
160 if (fi->inner_time < 0)
161 fi->inner_time = last_time;
162 else
163 fi->inner_time += fi->time_offset;
164
165 if (res == frError)
166 ++ fi->bad_line_count;
167 else if (res == frEof) {
168 fprintf(stderr, "exhausted %s (%d entries) at %s",
169 fi->fname, fi->line_count, ctime(&fi->inner_time));
170 fi->inner_time = -1;
171 } else if (fi->inner_time < last_time) {
172 assert(last_time >= 0);
173 ++ fi->time_warp_count;
174 fi->inner_time = last_time;
175 }
176
177 /* report progress */
178 if (!(fi->line_count % 50000))
179 fprintf(stderr, "%s scanned %d K entries (%d bad) at %s",
180 fi->fname, fi->line_count / 1000, fi->bad_line_count,
181 ctime(&fi->inner_time));
182 } while (res < 0);
183}
184
185/* CacheEntry */
186
187static CacheEntry *
188cacheEntryCreate(const storeSwapLogData * s)
189{
190 CacheEntry *e = (CacheEntry *)xcalloc(1, sizeof(CacheEntry));
191 assert(s);
192 /* e->s = *s; */
193 memcpy(e->key_arr, s->key, SQUID_MD5_DIGEST_LENGTH);
194 e->key = &e->key_arr[0];
195 return e;
196}
197
198static void
200{
201 assert(e);
202 xfree(e);
203}
204
205/* Cache */
206
207static Cache *
208cacheCreate(const char *name)
209{
210 Cache *c;
211 assert(name && strlen(name));
212 c = (Cache *)xcalloc(1, sizeof(Cache));
213 c->name = name;
215 return c;
216}
217
218static void
220{
221 CacheEntry *e = NULL;
223 assert(cache);
224 hash = cache->hash;
225 /* destroy hash table contents */
227
228 while ((e = (CacheEntry *)hash_next(hash))) {
231 }
232
233 /* destroy the hash table itself */
235
236 delete cache->digest;
237 xfree(cache);
238}
239
240/* re-digests currently hashed entries */
241static void
243{
244 CacheEntry *e = NULL;
246
247 struct timeval t_start, t_end;
248
249 assert(cache);
250 fprintf(stderr, "%s: init-ing digest with %d entries\n", cache->name, cache->count);
251
252 hash = cache->hash;
253
254 delete cache->digest;
255 cache->digest = new CacheDigest(cache->count + 1, 6);
256
257 if (!cache->count)
258 return;
259
260 gettimeofday(&t_start, NULL);
261
263
264 while ((e = (CacheEntry *)hash_next(hash))) {
265 cache->digest->add(e->key);
266 }
267
268 gettimeofday(&t_end, NULL);
269 assert(cache->digest->count == cache->count);
270 fprintf(stderr, "%s: init-ed digest with %d entries\n",
271 cache->name, cache->digest->count);
272 fprintf(stderr, "%s: init took: %f sec, %f sec/M\n",
273 cache->name,
274 tvSubDsec(t_start, t_end),
275 (double) 1e6 * tvSubDsec(t_start, t_end) / cache->count);
276 /* check how long it takes to traverse the hash */
277 gettimeofday(&t_start, NULL);
279
280 for (e = (CacheEntry *)hash_next(hash); e; e = (CacheEntry *)hash_next(hash)) {}
281
282 gettimeofday(&t_end, NULL);
283 fprintf(stderr, "%s: hash scan took: %f sec, %f sec/M\n",
284 cache->name,
285 tvSubDsec(t_start, t_end),
286 (double) 1e6 * tvSubDsec(t_start, t_end) / cache->count);
287}
288
289static void
290cacheQueryPeer(Cache * cache, const cache_key * key)
291{
292 const int peer_has_it = hash_lookup(cache->peer->hash, key) != NULL;
293 const int we_think_we_have_it = cache->digest->test(key);
294
295 ++ cache->qstats.query_count;
296
297 if (peer_has_it) {
298 if (we_think_we_have_it)
299 ++ cache->qstats.true_hit_count;
300 else
301 ++ cache->qstats.false_miss_count;
302 } else {
303 if (we_think_we_have_it)
304 ++ cache->qstats.false_hit_count;
305 else
306 ++ cache->qstats.true_miss_count;
307 }
308}
309
310static void
312{
313 fprintf(stdout, "%s: peer queries: %d (%d%%)\n",
314 cache->name,
315 stats->query_count, xpercentInt(stats->query_count, cache->req_count)
316 );
317 fprintf(stdout, "%s: t-hit: %d (%d%%) t-miss: %d (%d%%) t-*: %d (%d%%)\n",
318 cache->name,
319 stats->true_hit_count, xpercentInt(stats->true_hit_count, stats->query_count),
320 stats->true_miss_count, xpercentInt(stats->true_miss_count, stats->query_count),
321 stats->true_hit_count + stats->true_miss_count,
322 xpercentInt(stats->true_hit_count + stats->true_miss_count, stats->query_count)
323 );
324 fprintf(stdout, "%s: f-hit: %d (%d%%) f-miss: %d (%d%%) f-*: %d (%d%%)\n",
325 cache->name,
326 stats->false_hit_count, xpercentInt(stats->false_hit_count, stats->query_count),
327 stats->false_miss_count, xpercentInt(stats->false_miss_count, stats->query_count),
328 stats->false_hit_count + stats->false_miss_count,
329 xpercentInt(stats->false_hit_count + stats->false_miss_count, stats->query_count)
330 );
331}
332
333static void
335{
336 fprintf(stdout, "%s: entries: %d reqs: %d bad-add: %d bad-del: %d\n",
337 cache->name, cache->count, cache->req_count,
338 cache->bad_add_count, cache->bad_del_count);
339
340}
341
342static void
344{
345 assert(e);
346 ++ cache->req_count;
347
348 if (e->use_icp)
349 cacheQueryPeer(cache, e->key);
350}
351
352static fr_result
354{
355 storeSwapLogData *entry;
356
357 if (!fi->entry)
358 fi->entry = xcalloc(1, sizeof(storeSwapLogData));
359
360 entry = (storeSwapLogData *)fi->entry;
361
362 if (fread(entry, sizeof(*entry), 1, fi->file) != 1)
363 return frEof;
364
365 fi->inner_time = entry->lastref;
366
367 if (entry->op != SWAP_LOG_ADD && entry->op != SWAP_LOG_DEL) {
368 fprintf(stderr, "%s:%d: unknown swap log action\n", fi->fname, fi->line_count);
369 exit(-3);
370 }
371
372 return frOk;
373}
374
375static fr_result
377{
378 static char buf[4096];
379 RawAccessLogEntry *entry;
380 char *url;
381 char *method;
382 HttpRequestMethod method_id = METHOD_NONE;
383 char *hier = NULL;
384
385 assert(fi);
386
387 if (!fi->entry)
388 fi->entry = xcalloc(1, sizeof(RawAccessLogEntry));
389 else
390 memset(fi->entry, 0, sizeof(RawAccessLogEntry));
391
392 entry = (RawAccessLogEntry*)fi->entry;
393
394 if (!fgets(buf, sizeof(buf), fi->file))
395 return frEof; /* eof */
396
397 entry->timestamp = fi->inner_time = (time_t) atoi(buf);
398
399 url = strstr(buf, "://");
400
401 hier = url ? strstr(url, " - ") : NULL;
402
403 if (!url || !hier) {
404 /*fprintf(stderr, "%s:%d: strange access log entry '%s'\n",
405 * fname, scanned_count, buf); */
406 return frError;
407 }
408
409 method = url;
410
411 while (!xisdigit(*method)) {
412 if (*method == ' ')
413 *method = '\0';
414
415 --method;
416 }
417
418 method += 2;
419 method_id = methodStrToId(method);
420
421 if (method_id == METHOD_NONE) {
422 /*fprintf(stderr, "%s:%d: invalid method %s in '%s'\n",
423 * fname, scanned_count, method, buf); */
424 return frError;
425 }
426
427 while (*url)
428 --url;
429
430 ++url;
431
432 *hier = '\0';
433
434 hier += 3;
435
436 *strchr(hier, '/') = '\0';
437
438 /*fprintf(stdout, "%s:%d: %s %s %s\n",
439 * fname, count, method, url, hier); */
440 entry->use_icp = strcmp(hier, "NONE");
441
442 /* no ICP lookup for these status codes */
443 /* strcmp(hier, "NONE") &&
444 * strcmp(hier, "DIRECT") &&
445 * strcmp(hier, "FIREWALL_IP_DIRECT") &&
446 * strcmp(hier, "LOCAL_IP_DIRECT") &&
447 * strcmp(hier, "NO_DIRECT_FAIL") &&
448 * strcmp(hier, "NO_PARENT_DIRECT") &&
449 * strcmp(hier, "SINGLE_PARENT") &&
450 * strcmp(hier, "PASSTHROUGH_PARENT") &&
451 * strcmp(hier, "SSL_PARENT_MISS") &&
452 * strcmp(hier, "DEFAULT_PARENT");
453 */
454 memcpy(entry->key, storeKeyPublic(url, method_id), sizeof(entry->key));
455
456 /*fprintf(stdout, "%s:%d: %s %s %s %s\n",
457 * fname, count, method, storeKeyText(entry->key), url, hier); */
458 return frOk;
459}
460
461static void
462cachePurge(Cache * cache, storeSwapLogData * s, int update_digest)
463{
464 CacheEntry *olde = (CacheEntry *) hash_lookup(cache->hash, s->key);
465
466 if (!olde) {
467 ++ cache->bad_del_count;
468 } else {
469 assert(cache->count);
470 hash_remove_link(cache->hash, (hash_link *) olde);
471
472 if (update_digest)
473 cache->digest->remove(s->key);
474
475 cacheEntryDestroy(olde);
476
477 -- cache->count;
478 }
479}
480
481static void
482cacheStore(Cache * cache, storeSwapLogData * s, int update_digest)
483{
484 CacheEntry *olde = (CacheEntry *) hash_lookup(cache->hash, s->key);
485
486 if (olde) {
487 ++ cache->bad_add_count;
488 } else {
490 hash_join(cache->hash, (hash_link *)&e->key);
491 ++ cache->count;
492
493 if (update_digest)
494 cache->digest->add(e->key);
495 }
496}
497
498static void
499cacheUpdateStore(Cache * cache, storeSwapLogData * s, int update_digest)
500{
501 switch (s->op) {
502
503 case SWAP_LOG_ADD:
504 cacheStore(cache, s, update_digest);
505 break;
506
507 case SWAP_LOG_DEL:
508 cachePurge(cache, s, update_digest);
509 break;
510
511 default:
512 assert(0);
513 }
514}
515
516static int
517usage(const char *prg_name)
518{
519 fprintf(stderr, "usage: %s <access_log> <swap_state> ...\n",
520 prg_name);
521 return EXIT_FAILURE;
522}
523
524int
525main(int argc, char *argv[])
526{
527 FileIterator **fis = NULL;
528 const int fi_count = argc - 1;
529 int active_fi_count = 0;
530 time_t ready_time;
531 Cache *them, *us;
532 int i;
533
534 if (argc < 3)
535 return usage(argv[0]);
536
537 them = cacheCreate("them");
538
539 us = cacheCreate("us");
540
541 them->peer = us;
542
543 us->peer = them;
544
545 fis = (FileIterator **)xcalloc(fi_count, sizeof(FileIterator *));
546
547 /* init iterators with files */
548 fis[0] = fileIteratorCreate(argv[1], accessLogReader);
549
550 for (i = 2; i < argc; ++i)
551 fis[i - 1] = fileIteratorCreate(argv[i], swapStateReader);
552
553 /* check that all files were found */
554 for (i = 0; i < fi_count; ++i)
555 if (!fis[i])
556 return -2;
557
558 /* read prefix to get start-up contents of the peer cache */
559 ready_time = -1;
560
561 for (i = 1; i < fi_count; ++i) {
562 FileIterator *fi = fis[i];
563
564 while (fi->inner_time > 0) {
565 if (((storeSwapLogData *) fi->entry)->op == SWAP_LOG_DEL) {
566 cachePurge(them, (storeSwapLogData *)fi->entry, 0);
567
568 if (ready_time < 0)
569 ready_time = fi->inner_time;
570 } else {
571 if (ready_time > 0 && fi->inner_time > ready_time)
572 break;
573
574 cacheStore(them, (storeSwapLogData *)fi->entry, 0);
575 }
576
578 }
579 }
580
581 /* digest peer cache content */
582 cacheResetDigest(them);
583
584 us->digest = them->digest->clone();
585
586 /* shift the time in access log to match ready_time */
587 fileIteratorSetCurTime(fis[0], ready_time);
588
589 /* iterate, use the iterator with the smallest positive inner_time */
590 cur_time = -1;
591
592 do {
593 int next_i = -1;
594 time_t next_time = -1;
595 active_fi_count = 0;
596
597 for (i = 0; i < fi_count; ++i) {
598 if (fis[i]->inner_time >= 0) {
599 if (!active_fi_count || fis[i]->inner_time < next_time) {
600 next_i = i;
601 next_time = fis[i]->inner_time;
602 }
603
604 ++active_fi_count;
605 }
606 }
607
608 if (next_i >= 0) {
609 cur_time = next_time;
610 /*fprintf(stderr, "%2d time: %d %s", next_i, (int)cur_time, ctime(&cur_time)); */
611
612 if (next_i == 0)
613 cacheFetch(us, (RawAccessLogEntry *)fis[next_i]->entry);
614 else
615 cacheUpdateStore(them, (storeSwapLogData *)fis[next_i]->entry, 1);
616
617 fileIteratorAdvance(fis[next_i]);
618 }
619 } while (active_fi_count);
620
621 /* report */
622 cacheReport(them);
623
624 cacheReport(us);
625
626 cacheQueryReport(us, &us->qstats);
627
628 /* clean */
629 for (i = 0; i < argc - 1; ++i) {
630 fileIteratorDestroy(fis[i]);
631 }
632
633 xfree(fis);
634 cacheDestroy(them);
635 cacheDestroy(us);
636 return EXIT_SUCCESS;
637}
638
#define assert(EX)
Definition: assert.h:19
uint64_t count
Definition: CacheDigest.h:55
void add(const cache_key *key)
Definition: CacheDigest.cc:107
CacheDigest * clone() const
produce a new identical copy of the digest object
Definition: CacheDigest.cc:68
void remove(const cache_key *key)
Definition: CacheDigest.cc:140
SQUIDCEXTERN hash_table * hash_create(HASHCMP *, int, HASHHASH *)
Definition: hash.cc:108
SQUIDCEXTERN void hash_join(hash_table *, hash_link *)
Definition: hash.cc:131
SQUIDCEXTERN void hash_first(hash_table *)
Definition: hash.cc:172
SQUIDCEXTERN void hashFreeMemory(hash_table *)
Definition: hash.cc:268
SQUIDCEXTERN hash_link * hash_next(hash_table *)
Definition: hash.cc:188
SQUIDCEXTERN void hash_remove_link(hash_table *, hash_link *)
Definition: hash.cc:220
SQUIDCEXTERN hash_link * hash_lookup(hash_table *, const void *)
Definition: hash.cc:146
#define SQUID_MD5_DIGEST_LENGTH
Definition: md5.h:66
@ METHOD_TRACE
Definition: MethodType.h:30
@ METHOD_NONE
Definition: MethodType.h:22
@ METHOD_PUT
Definition: MethodType.h:27
@ METHOD_POST
Definition: MethodType.h:26
@ METHOD_CONNECT
Definition: MethodType.h:29
@ METHOD_GET
Definition: MethodType.h:25
@ METHOD_PURGE
Definition: MethodType.h:92
@ METHOD_HEAD
Definition: MethodType.h:28
class Ping::pingStats_ stats
#define xfree
unsigned char cache_key
Store key.
Definition: forward.h:29
const cache_key * storeKeyPublic(const char *url, const HttpRequestMethod &method, const KeyScope keyScope)
HASHHASH storeKeyHashHash
HASHCMP storeKeyHashCmp
char * strerror(int ern)
Definition: strerror.c:22
cache_key key[SQUID_MD5_DIGEST_LENGTH]
struct _CacheEntry * next
unsigned char key_arr[SQUID_MD5_DIGEST_LENGTH]
const cache_key * key
CacheQueryStats qstats
Cache * peer
const char * name
CacheDigest * digest
hash_table * hash
const char * fname
@ SWAP_LOG_DEL
Definition: swap_log_op.h:15
@ SWAP_LOG_ADD
Definition: swap_log_op.h:14
static int usage(const char *prg_name)
int main(int argc, char *argv[])
static void cacheDestroy(Cache *cache)
static void cacheQueryPeer(Cache *cache, const cache_key *key)
static void cacheQueryReport(Cache *cache, CacheQueryStats *stats)
static void fileIteratorSetCurTime(FileIterator *fi, time_t ct)
static void cacheFetch(Cache *cache, const RawAccessLogEntry *e)
static time_t cur_time
static void fileIteratorAdvance(FileIterator *fi)
static void cacheUpdateStore(Cache *cache, storeSwapLogData *s, int update_digest)
static void cacheEntryDestroy(CacheEntry *e)
static FileIterator * fileIteratorCreate(const char *fname, FI_READER reader)
static CacheEntry * cacheEntryCreate(const storeSwapLogData *s)
struct _CacheEntry CacheEntry
static Cache * cacheCreate(const char *name)
@ frOk
@ frEof
@ frMore
@ frError
static HttpRequestMethod methodStrToId(const char *s)
static fr_result swapStateReader(FileIterator *fi)
static void cacheStore(Cache *cache, storeSwapLogData *s, int update_digest)
static void cacheResetDigest(Cache *cache)
static void cacheReport(Cache *cache)
static void cachePurge(Cache *cache, storeSwapLogData *s, int update_digest)
static void fileIteratorDestroy(FileIterator *fi)
static fr_result accessLogReader(FileIterator *fi)
fr_result(* FI_READER)(FileIterator *fi)
static hash_table * hash
Definition: text_backend.cc:41
double tvSubDsec(struct timeval t1, struct timeval t2)
Definition: gadgets.cc:44
#define NULL
Definition: types.h:166
SQUIDCEXTERN int xpercentInt(double part, double whole)
Definition: util.c:46
void * xcalloc(size_t n, size_t sz)
Definition: xalloc.cc:71
#define xisdigit(x)
Definition: xis.h:20

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors