src/test_cache_digest.cc

   1
   2 /*
   3  * $Id$
   4  *
   5  * AUTHOR: Alex Rousskov
   6  *
   7  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   8  * ----------------------------------------------------------
   9  *
  10  *  Squid is the result of efforts by numerous individuals from
  11  *  the Internet community; see the CONTRIBUTORS file for full
  12  *  details.   Many organizations have provided support for Squid's
  13  *  development; see the SPONSORS file for full details.  Squid is
  14  *  Copyrighted (C) 2001 by the Regents of the University of
  15  *  California; see the COPYRIGHT file for full details.  Squid
  16  *  incorporates software developed and/or copyrighted by other
  17  *  sources; see the CREDITS file for full details.
  18  *
  19  *  This program is free software; you can redistribute it and/or modify
  20  *  it under the terms of the GNU General Public License as published by
  21  *  the Free Software Foundation; either version 2 of the License, or
  22  *  (at your option) any later version.
  23  *
  24  *  This program is distributed in the hope that it will be useful,
  25  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  26  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  27  *  GNU General Public License for more details.
  28  *
  29  *  You should have received a copy of the GNU General Public License
  30  *  along with this program; if not, write to the Free Software
  31  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  32  *
  33  */
  34
  35 /*
  36  * Test-suite for playing with cache digests
  37  */
  38
  39 #include "squid-old.h"
  40
  41 typedef struct {
  42     int query_count;
  43     int true_hit_count;
  44     int true_miss_count;
  45     int false_hit_count;
  46     int false_miss_count;
  47 } CacheQueryStats;
  48
  49 typedef struct _Cache Cache;
  50
  51 struct _Cache {
  52     const char *name;
  53     hash_table *hash;
  54     CacheDigest *digest;
  55     Cache *peer;
  56     CacheQueryStats qstats;
  57     int count;                  /* #currently cached entries */
  58     int req_count;              /* #requests to this cache */
  59     int bad_add_count;          /* #duplicate adds */
  60     int bad_del_count;          /* #dels with no prior add */
  61 };
  62
  63
  64 typedef struct _CacheEntry {
  65     const cache_key *key;
  66
  67     struct _CacheEntry *next;
  68     unsigned char key_arr[SQUID_MD5_DIGEST_LENGTH];
  69     /* storeSwapLogData s; */
  70 } CacheEntry;
  71
  72 /* parsed access log entry */
  73
  74 typedef struct {
  75     cache_key key[SQUID_MD5_DIGEST_LENGTH];
  76     time_t timestamp;
  77     short int use_icp;          /* true/false */
  78 } RawAccessLogEntry;
  79
  80 typedef enum {
  81     frError = -2, frMore = -1, frEof = 0, frOk = 1
  82 } fr_result;
  83
  84 typedef struct _FileIterator FileIterator;
  85 typedef fr_result(*FI_READER) (FileIterator * fi);
  86
  87 struct _FileIterator {
  88     const char *fname;
  89     FILE *file;
  90     time_t inner_time;          /* timestamp of the current entry */
  91     time_t time_offset;         /* to adjust time set by reader */
  92     int line_count;             /* number of lines scanned */
  93     int bad_line_count;         /* number of parsing errors */
  94     int time_warp_count;        /* number of out-of-order entries in the file */
  95     FI_READER reader;           /* reads next entry and updates inner_time */
  96     void *entry;                /* buffer for the current entry, freed with xfree() */
  97 };
  98
  99 /* globals */
 100 static time_t cur_time = -1;    /* timestamp of the current log entry */
 101
 102 /* copied from url.c */
 103 const char *RequestMethodStr[] = {
 104     "NONE",
 105     "GET",
 106     "POST",
 107     "PUT",
 108     "HEAD",
 109     "CONNECT",
 110     "TRACE",
 111     "PURGE"
 112 };
 113
 114 /* copied from url.c */
 115 static HttpRequestMethod
 116 methodStrToId(const char *s)
 117 {
 118     if (strcasecmp(s, "GET") == 0) {
 119         return METHOD_GET;
 120     } else if (strcasecmp(s, "POST") == 0) {
 121         return METHOD_POST;
 122     } else if (strcasecmp(s, "PUT") == 0) {
 123         return METHOD_PUT;
 124     } else if (strcasecmp(s, "HEAD") == 0) {
 125         return METHOD_HEAD;
 126     } else if (strcasecmp(s, "CONNECT") == 0) {
 127         return METHOD_CONNECT;
 128     } else if (strcasecmp(s, "TRACE") == 0) {
 129         return METHOD_TRACE;
 130     } else if (strcasecmp(s, "PURGE") == 0) {
 131         return METHOD_PURGE;
 132     }
 133
 134     return METHOD_NONE;
 135 }
 136
 137 /* FileIterator */
 138
 139 static void fileIteratorAdvance(FileIterator * fi);
 140
 141 static FileIterator *
 142 fileIteratorCreate(const char *fname, FI_READER reader)
 143 {
 144     FileIterator *fi = (FileIterator *)xcalloc(1, sizeof(FileIterator));
 145     assert(fname && reader);
 146     fi->fname = fname;
 147     fi->reader = reader;
 148     fi->file = fopen(fname, "r");
 149
 150     if (!fi->file) {
 151         fprintf(stderr, "cannot open %s: %s\n", fname, strerror(errno));
 152         return NULL;
 153     } else
 154         fprintf(stderr, "opened %s\n", fname);
 155
 156     fileIteratorAdvance(fi);
 157
 158     return fi;
 159 }
 160
 161 static void
 162 fileIteratorDestroy(FileIterator * fi)
 163 {
 164     assert(fi);
 165
 166     if (fi->file) {
 167         fclose(fi->file);
 168         fprintf(stderr, "closed %s\n", fi->fname);
 169     }
 170
 171     xfree(fi->entry);
 172     xfree(fi);
 173 }
 174
 175 static void
 176 fileIteratorSetCurTime(FileIterator * fi, time_t ct)
 177 {
 178     assert(fi);
 179     assert(fi->inner_time > 0);
 180     fi->time_offset = ct - fi->inner_time;
 181 }
 182
 183 static void
 184 fileIteratorAdvance(FileIterator * fi)
 185 {
 186     int res;
 187     assert(fi);
 188
 189     do {
 190         const time_t last_time = fi->inner_time;
 191         fi->inner_time = -1;
 192         res = fi->reader(fi);
 193         ++ fi->line_count;
 194
 195         if (fi->inner_time < 0)
 196             fi->inner_time = last_time;
 197         else
 198             fi->inner_time += fi->time_offset;
 199
 200         if (res == frError)
 201             ++ fi->bad_line_count;
 202         else if (res == frEof) {
 203             fprintf(stderr, "exhausted %s (%d entries) at %s",
 204                     fi->fname, fi->line_count, ctime(&fi->inner_time));
 205             fi->inner_time = -1;
 206         } else if (fi->inner_time < last_time) {
 207             assert(last_time >= 0);
 208             ++ fi->time_warp_count;
 209             fi->inner_time = last_time;
 210         }
 211
 212         /* report progress */
 213         if (!(fi->line_count % 50000))
 214             fprintf(stderr, "%s scanned %d K entries (%d bad) at %s",
 215                     fi->fname, fi->line_count / 1000, fi->bad_line_count,
 216                     ctime(&fi->inner_time));
 217     } while (res < 0);
 218 }
 219
 220 /* CacheEntry */
 221
 222 static CacheEntry *
 223 cacheEntryCreate(const storeSwapLogData * s)
 224 {
 225     CacheEntry *e = (CacheEntry *)xcalloc(1, sizeof(CacheEntry));
 226     assert(s);
 227     /* e->s = *s; */
 228     memcpy(e->key_arr, s->key, SQUID_MD5_DIGEST_LENGTH);
 229     e->key = &e->key_arr[0];
 230     return e;
 231 }
 232
 233 static void
 234 cacheEntryDestroy(CacheEntry * e)
 235 {
 236     assert(e);
 237     xfree(e);
 238 }
 239
 240
 241 /* Cache */
 242
 243 static Cache *
 244 cacheCreate(const char *name)
 245 {
 246     Cache *c;
 247     assert(name && strlen(name));
 248     c = (Cache *)xcalloc(1, sizeof(Cache));
 249     c->name = name;
 250     c->hash = hash_create(storeKeyHashCmp, (int)2e6, storeKeyHashHash);
 251     return c;
 252 }
 253
 254 static void
 255 cacheDestroy(Cache * cache)
 256 {
 257     CacheEntry *e = NULL;
 258     hash_table *hash;
 259     assert(cache);
 260     hash = cache->hash;
 261     /* destroy hash table contents */
 262     hash_first(hash);
 263
 264     while ((e = (CacheEntry *)hash_next(hash))) {
 265         hash_remove_link(hash, (hash_link *) e);
 266         cacheEntryDestroy(e);
 267     }
 268
 269     /* destroy the hash table itself */
 270     hashFreeMemory(hash);
 271
 272     if (cache->digest)
 273         cacheDigestDestroy(cache->digest);
 274
 275     xfree(cache);
 276 }
 277
 278 /* re-digests currently hashed entries */
 279 static void
 280 cacheResetDigest(Cache * cache)
 281 {
 282     CacheEntry *e = NULL;
 283     hash_table *hash;
 284
 285     struct timeval t_start, t_end;
 286
 287     assert(cache);
 288     fprintf(stderr, "%s: init-ing digest with %d entries\n", cache->name, cache->count);
 289
 290     if (cache->digest)
 291         cacheDigestDestroy(cache->digest);
 292
 293     hash = cache->hash;
 294
 295     cache->digest = cacheDigestCreate(cache->count + 1, 6);
 296
 297     if (!cache->count)
 298         return;
 299
 300     gettimeofday(&t_start, NULL);
 301
 302     hash_first(hash);
 303
 304     while ((e = (CacheEntry *)hash_next(hash))) {
 305         cacheDigestAdd(cache->digest, e->key);
 306     }
 307
 308     gettimeofday(&t_end, NULL);
 309     assert(cache->digest->count == cache->count);
 310     fprintf(stderr, "%s: init-ed  digest with %d entries\n",
 311             cache->name, cache->digest->count);
 312     fprintf(stderr, "%s: init took: %f sec, %f sec/M\n",
 313             cache->name,
 314             tvSubDsec(t_start, t_end),
 315             (double) 1e6 * tvSubDsec(t_start, t_end) / cache->count);
 316     /* check how long it takes to traverse the hash */
 317     gettimeofday(&t_start, NULL);
 318     hash_first(hash);
 319
 320     for (e = (CacheEntry *)hash_next(hash); e; e = (CacheEntry *)hash_next(hash)) {}
 321
 322     gettimeofday(&t_end, NULL);
 323     fprintf(stderr, "%s: hash scan took: %f sec, %f sec/M\n",
 324             cache->name,
 325             tvSubDsec(t_start, t_end),
 326             (double) 1e6 * tvSubDsec(t_start, t_end) / cache->count);
 327 }
 328
 329 static void
 330 cacheQueryPeer(Cache * cache, const cache_key * key)
 331 {
 332     const int peer_has_it = hash_lookup(cache->peer->hash, key) != NULL;
 333     const int we_think_we_have_it = cacheDigestTest(cache->digest, key);
 334
 335     ++ cache->qstats.query_count;
 336
 337     if (peer_has_it) {
 338         if (we_think_we_have_it)
 339             ++ cache->qstats.true_hit_count;
 340         else
 341             ++ cache->qstats.false_miss_count;
 342     } else {
 343         if (we_think_we_have_it)
 344             ++ cache->qstats.false_hit_count;
 345         else
 346             ++ cache->qstats.true_miss_count;
 347     }
 348 }
 349
 350 static void
 351 cacheQueryReport(Cache * cache, CacheQueryStats * stats)
 352 {
 353     fprintf(stdout, "%s: peer queries: %d (%d%%)\n",
 354             cache->name,
 355             stats->query_count, xpercentInt(stats->query_count, cache->req_count)
 356            );
 357     fprintf(stdout, "%s: t-hit: %d (%d%%) t-miss: %d (%d%%) t-*: %d (%d%%)\n",
 358             cache->name,
 359             stats->true_hit_count, xpercentInt(stats->true_hit_count, stats->query_count),
 360             stats->true_miss_count, xpercentInt(stats->true_miss_count, stats->query_count),
 361             stats->true_hit_count + stats->true_miss_count,
 362             xpercentInt(stats->true_hit_count + stats->true_miss_count, stats->query_count)
 363            );
 364     fprintf(stdout, "%s: f-hit: %d (%d%%) f-miss: %d (%d%%) f-*: %d (%d%%)\n",
 365             cache->name,
 366             stats->false_hit_count, xpercentInt(stats->false_hit_count, stats->query_count),
 367             stats->false_miss_count, xpercentInt(stats->false_miss_count, stats->query_count),
 368             stats->false_hit_count + stats->false_miss_count,
 369             xpercentInt(stats->false_hit_count + stats->false_miss_count, stats->query_count)
 370            );
 371 }
 372
 373 static void
 374 cacheReport(Cache * cache)
 375 {
 376     fprintf(stdout, "%s: entries: %d reqs: %d bad-add: %d bad-del: %d\n",
 377             cache->name, cache->count, cache->req_count,
 378             cache->bad_add_count, cache->bad_del_count);
 379
 380 }
 381
 382 static void
 383 cacheFetch(Cache * cache, const RawAccessLogEntry * e)
 384 {
 385     assert(e);
 386     ++ cache->req_count;
 387
 388     if (e->use_icp)
 389         cacheQueryPeer(cache, e->key);
 390 }
 391
 392 static fr_result
 393 swapStateReader(FileIterator * fi)
 394 {
 395     storeSwapLogData *entry;
 396
 397     if (!fi->entry)
 398         fi->entry = xcalloc(1, sizeof(storeSwapLogData));
 399
 400     entry = (storeSwapLogData *)fi->entry;
 401
 402     if (fread(entry, sizeof(*entry), 1, fi->file) != 1)
 403         return frEof;
 404
 405     fi->inner_time = entry->lastref;
 406
 407     if (entry->op != SWAP_LOG_ADD && entry->op != SWAP_LOG_DEL) {
 408         fprintf(stderr, "%s:%d: unknown swap log action\n", fi->fname, fi->line_count);
 409         exit(-3);
 410     }
 411
 412     return frOk;
 413 }
 414
 415 static fr_result
 416 accessLogReader(FileIterator * fi)
 417 {
 418     static char buf[4096];
 419     RawAccessLogEntry *entry;
 420     char *url;
 421     char *method;
 422     HttpRequestMethod method_id = METHOD_NONE;
 423     char *hier = NULL;
 424
 425     assert(fi);
 426
 427     if (!fi->entry)
 428         fi->entry = xcalloc(1, sizeof(RawAccessLogEntry));
 429     else
 430         memset(fi->entry, 0, sizeof(RawAccessLogEntry));
 431
 432     entry = (RawAccessLogEntry*)fi->entry;
 433
 434     if (!fgets(buf, sizeof(buf), fi->file))
 435         return frEof;           /* eof */
 436
 437     entry->timestamp = fi->inner_time = (time_t) atoi(buf);
 438
 439     url = strstr(buf, "://");
 440
 441     hier = url ? strstr(url, " - ") : NULL;
 442
 443     if (!url || !hier) {
 444         /*fprintf(stderr, "%s:%d: strange access log entry '%s'\n",
 445          * fname, scanned_count, buf); */
 446         return frError;
 447     }
 448
 449     method = url;
 450
 451     while (!xisdigit(*method)) {
 452         if (*method == ' ')
 453             *method = '\0';
 454
 455         --method;
 456     }
 457
 458     method += 2;
 459     method_id = methodStrToId(method);
 460
 461     if (method_id == METHOD_NONE) {
 462         /*fprintf(stderr, "%s:%d: invalid method %s in '%s'\n",
 463          * fname, scanned_count, method, buf); */
 464         return frError;
 465     }
 466
 467     while (*url)
 468         --url;
 469
 470     ++url;
 471
 472     *hier = '\0';
 473
 474     hier += 3;
 475
 476     *strchr(hier, '/') = '\0';
 477
 478     /*fprintf(stdout, "%s:%d: %s %s %s\n",
 479      * fname, count, method, url, hier); */
 480     entry->use_icp = strcmp(hier, "NONE");
 481
 482     /* no ICP lookup for these status codes */
 483     /*      strcmp(hier, "NONE") &&
 484      * strcmp(hier, "DIRECT") &&
 485      * strcmp(hier, "FIREWALL_IP_DIRECT") &&
 486      * strcmp(hier, "LOCAL_IP_DIRECT") &&
 487      * strcmp(hier, "NO_DIRECT_FAIL") &&
 488      * strcmp(hier, "NO_PARENT_DIRECT") &&
 489      * strcmp(hier, "SINGLE_PARENT") &&
 490      * strcmp(hier, "PASSTHROUGH_PARENT") &&
 491      * strcmp(hier, "SSL_PARENT_MISS") &&
 492      * strcmp(hier, "DEFAULT_PARENT");
 493      */
 494     memcpy(entry->key, storeKeyPublic(url, method_id), sizeof(entry->key));
 495
 496     /*fprintf(stdout, "%s:%d: %s %s %s %s\n",
 497      * fname, count, method, storeKeyText(entry->key), url, hier); */
 498     return frOk;
 499 }
 500
 501
 502 static void
 503 cachePurge(Cache * cache, storeSwapLogData * s, int update_digest)
 504 {
 505     CacheEntry *olde = (CacheEntry *) hash_lookup(cache->hash, s->key);
 506
 507     if (!olde) {
 508         ++ cache->bad_del_count;
 509     } else {
 510         assert(cache->count);
 511         hash_remove_link(cache->hash, (hash_link *) olde);
 512
 513         if (update_digest)
 514             cacheDigestDel(cache->digest, s->key);
 515
 516         cacheEntryDestroy(olde);
 517
 518         -- cache->count;
 519     }
 520 }
 521
 522 static void
 523 cacheStore(Cache * cache, storeSwapLogData * s, int update_digest)
 524 {
 525     CacheEntry *olde = (CacheEntry *) hash_lookup(cache->hash, s->key);
 526
 527     if (olde) {
 528         ++ cache->bad_add_count;
 529     } else {
 530         CacheEntry *e = cacheEntryCreate(s);
 531         hash_join(cache->hash, (hash_link *)&e->key);
 532         ++ cache->count;
 533
 534         if (update_digest)
 535             cacheDigestAdd(cache->digest, e->key);
 536     }
 537 }
 538
 539 static void
 540 cacheUpdateStore(Cache * cache, storeSwapLogData * s, int update_digest)
 541 {
 542     switch (s->op) {
 543
 544     case SWAP_LOG_ADD:
 545         cacheStore(cache, s, update_digest);
 546         break;
 547
 548     case SWAP_LOG_DEL:
 549         cachePurge(cache, s, update_digest);
 550         break;
 551
 552     default:
 553         assert(0);
 554     }
 555 }
 556
 557 static int
 558 usage(const char *prg_name)
 559 {
 560     fprintf(stderr, "usage: %s <access_log> <swap_state> ...\n",
 561             prg_name);
 562     return -1;
 563 }
 564
 565 int
 566 main(int argc, char *argv[])
 567 {
 568     FileIterator **fis = NULL;
 569     const int fi_count = argc - 1;
 570     int active_fi_count = 0;
 571     time_t ready_time;
 572     Cache *them, *us;
 573     int i;
 574
 575     if (argc < 3)
 576         return usage(argv[0]);
 577
 578     them = cacheCreate("them");
 579
 580     us = cacheCreate("us");
 581
 582     them->peer = us;
 583
 584     us->peer = them;
 585
 586     fis = (FileIterator **)xcalloc(fi_count, sizeof(FileIterator *));
 587
 588     /* init iterators with files */
 589     fis[0] = fileIteratorCreate(argv[1], accessLogReader);
 590
 591     for (i = 2; i < argc; ++i)
 592         fis[i - 1] = fileIteratorCreate(argv[i], swapStateReader);
 593
 594     /* check that all files were found */
 595     for (i = 0; i < fi_count; ++i)
 596         if (!fis[i])
 597             return -2;
 598
 599     /* read prefix to get start-up contents of the peer cache */
 600     ready_time = -1;
 601
 602     for (i = 1; i < fi_count; ++i) {
 603         FileIterator *fi = fis[i];
 604
 605         while (fi->inner_time > 0) {
 606             if (((storeSwapLogData *) fi->entry)->op == SWAP_LOG_DEL) {
 607                 cachePurge(them, (storeSwapLogData *)fi->entry, 0);
 608
 609                 if (ready_time < 0)
 610                     ready_time = fi->inner_time;
 611             } else {
 612                 if (ready_time > 0 && fi->inner_time > ready_time)
 613                     break;
 614
 615                 cacheStore(them, (storeSwapLogData *)fi->entry, 0);
 616             }
 617
 618             fileIteratorAdvance(fi);
 619         }
 620     }
 621
 622     /* digest peer cache content */
 623     cacheResetDigest(them);
 624
 625     us->digest = cacheDigestClone(them->digest);        /* @netw@ */
 626
 627     /* shift the time in access log to match ready_time */
 628     fileIteratorSetCurTime(fis[0], ready_time);
 629
 630     /* iterate, use the iterator with the smallest positive inner_time */
 631     cur_time = -1;
 632
 633     do {
 634         int next_i = -1;
 635         time_t next_time = -1;
 636         active_fi_count = 0;
 637
 638         for (i = 0; i < fi_count; ++i) {
 639             if (fis[i]->inner_time >= 0) {
 640                 if (!active_fi_count || fis[i]->inner_time < next_time) {
 641                     next_i = i;
 642                     next_time = fis[i]->inner_time;
 643                 }
 644
 645                 ++active_fi_count;
 646             }
 647         }
 648
 649         if (next_i >= 0) {
 650             cur_time = next_time;
 651             /*fprintf(stderr, "%2d time: %d %s", next_i, (int)cur_time, ctime(&cur_time)); */
 652
 653             if (next_i == 0)
 654                 cacheFetch(us, (RawAccessLogEntry *)fis[next_i]->entry);
 655             else
 656                 cacheUpdateStore(them, (storeSwapLogData *)fis[next_i]->entry, 1);
 657
 658             fileIteratorAdvance(fis[next_i]);
 659         }
 660     } while (active_fi_count);
 661
 662     /* report */
 663     cacheReport(them);
 664
 665     cacheReport(us);
 666
 667     cacheQueryReport(us, &us->qstats);
 668
 669     /* clean */
 670     for (i = 0; i < argc - 1; ++i) {
 671         fileIteratorDestroy(fis[i]);
 672     }
 673
 674     xfree(fis);
 675     cacheDestroy(them);
 676     cacheDestroy(us);
 677     return 0;
 678 }