TS-2515: Add stats for stripe wrap and cache sync.

CHANGES

@@ -1,6 +1,8 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache Traffic Server 5.3.0
 
+  *) [TS-2515] Add statistics for stripe wrap and cache sync.
+
   *) [TS-2721] add more hook support for atscppapi.
 
   *) [TS-3413] High CPU utiliziation when processing HTTP/2 traffic.

doc/reference/commands/traffic_line.en.rst

@@ -256,6 +256,27 @@ proxy.process.ssl.cipher.user_agent.{CIPHERNAME}
     proxy.process.ssl.cipher.user_agent.ECDHE-ECDSA-AES256-SHA384 0
     ...
 
+Cache Statistics
+======================
+
+Cache statistics come in two varieties, global and per cache volume. These will be listed here in the global form. To get a
+cache volume statistic add `.volume_#` to the name after `cache` where `#` is 1-based index of the volume in :file:`storage.config`.
+For example the statistic `proxy.process.cache.sync.bytes` is a global statistic. The value for the third cache volume is
+`proxy.process.cache.volume_3.sync.bytes`.
+
+proxy.process.cache.sync.bytes
+   The total number of bytes written to disk to synchronize the cache directory.
+
+proxy.process.cache.sync.time
+   The total time, in nanoseconds, during which the cache directory was being written to disk.
+
+proxy.process.cache.sync.count
+   The number of times a cache directory sync has been done.
+
+proxy.process.cache.wrap_count
+   The number of times a cache stripe has cycled. Each stripe is a circular buffer and this is incremented each time the
+   write cursor is reset to the start of the stripe.
+
 Examples
 ========
 

iocore/cache/Cache.cc

@@ -3472,6 +3472,10 @@ register_cache_stats(RecRawStatBlock *rsb, const char *prefix)
   REG_INT("hdr_marshal_bytes", cache_hdr_marshal_bytes_stat);
   REG_INT("gc_bytes_evacuated", cache_gc_bytes_evacuated_stat);
   REG_INT("gc_frags_evacuated", cache_gc_frags_evacuated_stat);
+  REG_INT("wrap_count", cache_directory_wrap_stat);
+  REG_INT("sync.count", cache_directory_sync_count_stat);
+  REG_INT("sync.bytes", cache_directory_sync_bytes_stat);
+  REG_INT("sync.time", cache_directory_sync_time_stat);
 }
 
 

iocore/cache/CacheDir.cc

@@ -1114,8 +1114,8 @@ CacheSync::mainEvent(int event, Event *e)
   }
 
 Lrestart:
-  if (vol >= gnvol) {
-    vol = 0;
+  if (vol_idx >= gnvol) {
+    vol_idx = 0;
     if (buf) {
       ats_memalign_free(buf);
       buf = 0;
@@ -1128,32 +1128,38 @@ CacheSync::mainEvent(int event, Event *e)
       trigger = eventProcessor.schedule_in(this, HRTIME_SECONDS(cache_config_dir_sync_frequency));
     return EVENT_CONT;
   }
+
+  Vol* vol = gvol[vol_idx]; // must be named "vol" to make STAT macros work.
+
   if (event == AIO_EVENT_DONE) {
     // AIO Thread
     if (io.aio_result != (int64_t)io.aiocb.aio_nbytes) {
-      Warning("vol write error during directory sync '%s'", gvol[vol]->hash_text.get());
+      Warning("vol write error during directory sync '%s'", gvol[vol_idx]->hash_text.get());
       event = EVENT_NONE;
       goto Ldone;
     }
+    CACHE_SUM_DYN_STAT(cache_directory_sync_bytes_stat, io.aio_result);
+
     trigger = eventProcessor.schedule_in(this, SYNC_DELAY);
     return EVENT_CONT;
   }
   {
-    CACHE_TRY_LOCK(lock, gvol[vol]->mutex, mutex->thread_holding);
+    CACHE_TRY_LOCK(lock, gvol[vol_idx]->mutex, mutex->thread_holding);
     if (!lock.is_locked()) {
       trigger = eventProcessor.schedule_in(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay));
       return EVENT_CONT;
     }
-    Vol *d = gvol[vol];
+
+    if (!vol->dir_sync_in_progress) start_time = ink_get_hrtime();
 
     // recompute hit_evacuate_window
-    d->hit_evacuate_window = (d->data_blocks * cache_config_hit_evacuate_percent) / 100;
+    vol->hit_evacuate_window = (vol->data_blocks * cache_config_hit_evacuate_percent) / 100;
 
-    if (DISK_BAD(d->disk))
+    if (DISK_BAD(vol->disk))
       goto Ldone;
 
     int headerlen = ROUND_TO_STORE_BLOCK(sizeof(VolHeaderFooter));
-    size_t dirlen = vol_dirlen(d);
+    size_t dirlen = vol_dirlen(vol);
     if (!writepos) {
       // start
       Debug("cache_dir_sync", "sync started");
@@ -1163,73 +1169,76 @@ CacheSync::mainEvent(int event, Event *e)
          than necessary.
          The dirty bit it set in dir_insert, dir_overwrite and dir_delete_entry
        */
-      if (!d->header->dirty) {
-        Debug("cache_dir_sync", "Dir %s not dirty", d->hash_text.get());
+      if (!vol->header->dirty) {
+        Debug("cache_dir_sync", "Dir %s not dirty", vol->hash_text.get());
         goto Ldone;
       }
-      if (d->is_io_in_progress() || d->agg_buf_pos) {
-        Debug("cache_dir_sync", "Dir %s: waiting for agg buffer", d->hash_text.get());
-        d->dir_sync_waiting = 1;
-        if (!d->is_io_in_progress())
-          d->aggWrite(EVENT_IMMEDIATE, 0);
+      if (vol->is_io_in_progress() || vol->agg_buf_pos) {
+        Debug("cache_dir_sync", "Dir %s: waiting for agg buffer", vol->hash_text.get());
+        vol->dir_sync_waiting = 1;
+        if (!vol->is_io_in_progress())
+          vol->aggWrite(EVENT_IMMEDIATE, 0);
 #if TS_USE_INTERIM_CACHE == 1
-        for (int i = 0; i < d->num_interim_vols; i++) {
-          if (!d->interim_vols[i].is_io_in_progress()) {
-            d->interim_vols[i].sync = true;
-            d->interim_vols[i].aggWrite(EVENT_IMMEDIATE, 0);
+        for (int i = 0; i < vol->num_interim_vols; i++) {
+          if (!vol->interim_vols[i].is_io_in_progress()) {
+            vol->interim_vols[i].sync = true;
+            vol->interim_vols[i].aggWrite(EVENT_IMMEDIATE, 0);
           }
         }
 #endif
         return EVENT_CONT;
       }
-      Debug("cache_dir_sync", "pos: %" PRIu64 " Dir %s dirty...syncing to disk", d->header->write_pos, d->hash_text.get());
-      d->header->dirty = 0;
+      Debug("cache_dir_sync", "pos: %" PRIu64 " Dir %s dirty...syncing to disk", vol->header->write_pos, vol->hash_text.get());
+      vol->header->dirty = 0;
       if (buflen < dirlen) {
         if (buf)
           ats_memalign_free(buf);
         buf = (char *)ats_memalign(ats_pagesize(), dirlen);
         buflen = dirlen;
       }
-      d->header->sync_serial++;
-      d->footer->sync_serial = d->header->sync_serial;
+      vol->header->sync_serial++;
+      vol->footer->sync_serial = vol->header->sync_serial;
 #if TS_USE_INTERIM_CACHE == 1
-      for (int j = 0; j < d->num_interim_vols; j++) {
-          d->interim_vols[j].header->sync_serial = d->header->sync_serial;
+      for (int j = 0; j < vol->num_interim_vols; j++) {
+          vol->interim_vols[j].header->sync_serial = vol->header->sync_serial;
       }
 #endif
       CHECK_DIR(d);
-      memcpy(buf, d->raw_dir, dirlen);
-      d->dir_sync_in_progress = 1;
+      memcpy(buf, vol->raw_dir, dirlen);
+      vol->dir_sync_in_progress = 1;
     }
-    size_t B = d->header->sync_serial & 1;
-    off_t start = d->skip + (B ? dirlen : 0);
+    size_t B = vol->header->sync_serial & 1;
+    off_t start = vol->skip + (B ? dirlen : 0);
 
     if (!writepos) {
       // write header
-      aio_write(d->fd, buf + writepos, headerlen, start + writepos);
+      aio_write(vol->fd, buf + writepos, headerlen, start + writepos);
       writepos += headerlen;
     } else if (writepos < (off_t)dirlen - headerlen) {
       // write part of body
       int l = SYNC_MAX_WRITE;
       if (writepos + l > (off_t)dirlen - headerlen)
         l = dirlen - headerlen - writepos;
-      aio_write(d->fd, buf + writepos, l, start + writepos);
+      aio_write(vol->fd, buf + writepos, l, start + writepos);
       writepos += l;
     } else if (writepos < (off_t)dirlen) {
       ink_assert(writepos == (off_t)dirlen - headerlen);
       // write footer
-      aio_write(d->fd, buf + writepos, headerlen, start + writepos);
+      aio_write(vol->fd, buf + writepos, headerlen, start + writepos);
       writepos += headerlen;
     } else {
-      d->dir_sync_in_progress = 0;
+      vol->dir_sync_in_progress = 0;
+      CACHE_INCREMENT_DYN_STAT(cache_directory_sync_count_stat);
+      CACHE_SUM_DYN_STAT(cache_directory_sync_time_stat, ink_get_hrtime() - start_time);
+      start_time = 0;
       goto Ldone;
     }
     return EVENT_CONT;
   }
 Ldone:
   // done
   writepos = 0;
-  vol++;
+  ++vol_idx;
   goto Lrestart;
 }
 

iocore/cache/CacheWrite.cc

@@ -949,6 +949,10 @@ Vol::agg_wrap()
   header->agg_pos = header->write_pos;
   dir_lookaside_cleanup(this);
   dir_clean_vol(this);
+  {
+    Vol* vol = this;
+    CACHE_INCREMENT_DYN_STAT(cache_directory_wrap_stat);
+  }
   periodic_scan();
 }
 

iocore/cache/P_CacheDir.h

@@ -297,16 +297,17 @@ struct OpenDir: public Continuation
 
 struct CacheSync: public Continuation
 {
-  int vol;
+  int vol_idx;
   char *buf;
   size_t buflen;
   off_t writepos;
   AIOCallbackInternal io;
   Event *trigger;
+  ink_hrtime start_time;
   int mainEvent(int event, Event *e);
   void aio_write(int fd, char *b, int n, off_t o);
 
-  CacheSync():Continuation(new_ProxyMutex()), vol(0), buf(0), buflen(0), writepos(0), trigger(0)
+ CacheSync():Continuation(new_ProxyMutex()), vol_idx(0), buf(0), buflen(0), writepos(0), trigger(0), start_time(0)
   {
     SET_HANDLER(&CacheSync::mainEvent);
   }

iocore/cache/P_CacheInternal.h

@@ -160,6 +160,10 @@ enum
   cache_hdr_vector_marshal_stat,
   cache_hdr_marshal_stat,
   cache_hdr_marshal_bytes_stat,
+  cache_directory_wrap_stat,
+  cache_directory_sync_count_stat,
+  cache_directory_sync_time_stat,
+  cache_directory_sync_bytes_stat,
   cache_stat_count
 };