bluesky/debug.c

   1 /* Blue Sky: File Systems in the Cloud
   2  *
   3  * Copyright (C) 2009  The Regents of the University of California
   4  * Written by Michael Vrable <mvrable@cs.ucsd.edu>
   5  *
   6  * Redistribution and use in source and binary forms, with or without
   7  * modification, are permitted provided that the following conditions
   8  * are met:
   9  * 1. Redistributions of source code must retain the above copyright
  10  *    notice, this list of conditions and the following disclaimer.
  11  * 2. Redistributions in binary form must reproduce the above copyright
  12  *    notice, this list of conditions and the following disclaimer in the
  13  *    documentation and/or other materials provided with the distribution.
  14  * 3. Neither the name of the University nor the names of its contributors
  15  *    may be used to endorse or promote products derived from this software
  16  *    without specific prior written permission.
  17  *
  18  * THIS SOFTWARE IS PROVIDED BY THE REGENTS AND CONTRIBUTORS ``AS IS'' AND
  19  * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
  20  * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
  21  * ARE DISCLAIMED.  IN NO EVENT SHALL THE REGENTS OR CONTRIBUTORS BE LIABLE
  22  * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
  23  * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
  24  * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
  25  * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
  26  * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
  27  * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  28  * SUCH DAMAGE.
  29  */
  30
  31 #include <stdint.h>
  32 #include <stdlib.h>
  33 #include <inttypes.h>
  34 #include <glib.h>
  35 #include <string.h>
  36
  37 #include "bluesky-private.h"
  38
  39 /* Debugging support for BlueSky. */
  40
  41 static void inode_dump(gpointer key, gpointer value, gpointer user_data)
  42 {
  43     BlueSkyInode *inode = (BlueSkyInode *)value;
  44
  45     g_print("Inode %"PRIu64":\n", inode->inum);
  46
  47     gboolean locked = TRUE;
  48     if (g_mutex_trylock(inode->lock)) {
  49         locked = FALSE;
  50         g_mutex_unlock(inode->lock);
  51     }
  52     g_print("    Locked: %c   Refcount: %d\n",
  53             locked ? 'T' : 'F', inode->refcount);
  54
  55     g_print("    Type: %d   Mode: %o\n", inode->type, inode->mode);
  56     g_print("    change_count = %"PRIu64", change_commit = %"PRIu64", "
  57             "change_cloud = %"PRIu64"\n",
  58             inode->change_count, inode->change_commit, inode->change_cloud);
  59 }
  60
  61 static void cloudlog_dump(gpointer key, gpointer value, gpointer user_data)
  62 {
  63     BlueSkyCloudLog *log = (BlueSkyCloudLog *)value;
  64
  65     for (int i = 0; i < sizeof(BlueSkyCloudID); i++) {
  66         g_print("%02x", (uint8_t)(log->id.bytes[i]));
  67     }
  68     g_print(": refs=%d ty=%d inode=%"PRIu64" locs=%x log@(%d,%d) cloud@(%d,%d,%d)\n",
  69             log->refcount,
  70             log->type, log->inum,
  71             log->location_flags | (log->data != NULL ? 0x100 : 0),
  72             log->log_seq, log->log_offset, log->location.directory,
  73             log->location.sequence, log->location.offset);
  74 }
  75
  76 static void cache_dump(gpointer key, gpointer value, gpointer user_data)
  77 {
  78     BlueSkyCacheFile *cache = (BlueSkyCacheFile *)value;
  79
  80     int64_t age = bluesky_get_current_time() - cache->atime;
  81     g_print("%s addr=%p mapcount=%d refcount=%d atime_age=%f",
  82             cache->filename, cache->addr, cache->mapcount, cache->refcount,
  83             age / 1e6);
  84     if (cache->fetching)
  85         g_print(" (fetching)");
  86     g_print("\n");
  87 }
  88
  89
  90 void inode_map_dump(GSequence *inode_map)
  91 {
  92     GSequenceIter *i, *j;
  93
  94     g_print("\nInode map dump:\n");
  95     for (i = g_sequence_get_begin_iter(inode_map);
  96          !g_sequence_iter_is_end(i); i = g_sequence_iter_next(i))
  97     {
  98         InodeMapRange *range = (InodeMapRange *)g_sequence_get(i);
  99
 100         g_print("  Range [%"PRIu64", %"PRIu64"]\n", range->start, range->end);
 101
 102         for (j = g_sequence_get_begin_iter(range->map_entries);
 103              !g_sequence_iter_is_end(j); j = g_sequence_iter_next(j))
 104         {
 105             InodeMapEntry *entry = (InodeMapEntry *)g_sequence_get(j);
 106             BlueSkyCloudLog *item = entry->item;
 107             if (item != NULL) {
 108                 char *id = bluesky_cloudlog_id_to_string(item->id);
 109                 g_print("    Entry %"PRIu64" id=%s\n", entry->inum, id);
 110                 g_free(id);
 111             } else {
 112                 g_print("    Entry %"PRIu64" not available\n", entry->inum);
 113             }
 114         }
 115     }
 116 }
 117 /* Dump a summary of filesystem state as it is cached in memory. */
 118 void bluesky_debug_dump(BlueSkyFS *fs)
 119 {
 120     g_print("\n*** DEBUG DUMP FOR FILESYSTEM %s ***\n", fs->name);
 121     g_print("Dirty blocks: %d\n", g_atomic_int_get(&fs->cache_dirty));
 122     g_print("Cached inodes: %u\tNext inode: %"PRIu64"\n",
 123             g_hash_table_size(fs->inodes), fs->next_inum);
 124     g_print("Cloudlog cache: %d dirty, %d writeback, %d journal, %d cloud\n",
 125             g_atomic_int_get(&fs->cache_log_dirty),
 126             g_atomic_int_get(&fs->cache_log_writeback),
 127             g_atomic_int_get(&fs->cache_log_journal),
 128             g_atomic_int_get(&fs->cache_log_cloud));
 129
 130     GList *item;
 131     g_print("Unsynced inode list:");
 132     for (item = fs->unlogged_list.next; item != NULL; item = item->next) {
 133         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
 134     }
 135     g_print("\n");
 136     g_print("Dirty inode LRU list:");
 137     for (item = fs->dirty_list.next; item != NULL; item = item->next) {
 138         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
 139     }
 140     g_print("\n");
 141     g_print("Accessed inode LRU list:");
 142     for (item = fs->accessed_list.next; item != NULL; item = item->next) {
 143         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
 144     }
 145     g_print("\n");
 146
 147     g_hash_table_foreach(fs->inodes, inode_dump, fs);
 148
 149     g_print("\nLog Objects:\n");
 150     g_hash_table_foreach(fs->locations, cloudlog_dump, fs);
 151
 152     g_print("\nJournal/Cache Files:\n");
 153     g_hash_table_foreach(fs->log->mmap_cache, cache_dump, fs);
 154     g_print("\n");
 155
 156     g_mutex_lock(fs->lock);
 157     inode_map_dump(fs->inode_map);
 158     g_mutex_unlock(fs->lock);
 159 }
 160
 161 /* Statistics counters: for operation counts, bytes transferred, etc. */
 162 static GStaticMutex stats_lock = G_STATIC_MUTEX_INIT;
 163 static GList *stats_list = NULL;
 164
 165 struct bluesky_stats *bluesky_stats_new(const char *name)
 166 {
 167     struct bluesky_stats *stats = g_new0(struct bluesky_stats, 1);
 168     stats->name = name;
 169     g_static_mutex_lock(&stats_lock);
 170     stats_list = g_list_append(stats_list, stats);
 171     g_static_mutex_unlock(&stats_lock);
 172     return stats;
 173 }
 174
 175 void bluesky_stats_add(struct bluesky_stats *stats, int64_t value)
 176 {
 177     __sync_fetch_and_add(&stats->count, (int64_t)1);
 178     __sync_fetch_and_add(&stats->sum, value);
 179 }
 180
 181 void bluesky_stats_dump_all()
 182 {
 183     g_static_mutex_lock(&stats_lock);
 184     for (GList *item = stats_list; item != NULL; item = item->next) {
 185         struct bluesky_stats *stats = (struct bluesky_stats *)item->data;
 186         g_print("%s: count=%"PRIi64" sum=%"PRIi64"\n",
 187                 stats->name, stats->count, stats->sum);
 188     }
 189     g_static_mutex_unlock(&stats_lock);
 190 }
 191
 192 static void periodic_stats_dumper(FILE *f)
 193 {
 194     const int64_t interval = 10 * 1000000000ULL;
 195     bluesky_time_hires timestamp = bluesky_now_hires();
 196     bluesky_time_hires next_timestamp = timestamp;
 197
 198     while (TRUE) {
 199         g_static_mutex_lock(&stats_lock);
 200         timestamp = bluesky_now_hires();
 201         fprintf(f, "********\ntime=%f\n\n", timestamp / 1e9);
 202         for (GList *item = stats_list; item != NULL; item = item->next) {
 203             struct bluesky_stats *stats = (struct bluesky_stats *)item->data;
 204             fprintf(f, "%s: count=%"PRIi64" sum=%"PRIi64"\n",
 205                     stats->name, stats->count, stats->sum);
 206         }
 207         g_static_mutex_unlock(&stats_lock);
 208         fflush(f);
 209
 210         /* Wait until ten seconds from the last timestamp, with a few extra
 211          * checks for sanity (always try to wait some amount of time in the
 212          * range [0, 20] seconds). */
 213         timestamp = bluesky_now_hires();
 214         next_timestamp += interval;
 215         if (next_timestamp < timestamp) {
 216             next_timestamp = timestamp;
 217             continue;
 218         }
 219         if (next_timestamp - timestamp > 2 * interval) {
 220             next_timestamp = timestamp + interval;
 221         }
 222
 223         struct timespec delay;
 224         delay.tv_sec = (next_timestamp - timestamp) / 1000000000;
 225         delay.tv_nsec = (next_timestamp - timestamp) % 1000000000;
 226         nanosleep(&delay, NULL);
 227     }
 228 }
 229
 230 /* Start a background thread that will periodically dump statistics counters to
 231  * he specified file every ten seconds. */
 232 void bluesky_stats_run_periodic_dump(FILE *f)
 233 {
 234     g_thread_create((GThreadFunc)periodic_stats_dumper, f, FALSE, NULL);
 235 }