Reduce verbosity
[bluesky.git] / 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  * TODO: Licensing
7  */
8
9 #include <stdint.h>
10 #include <stdlib.h>
11 #include <inttypes.h>
12 #include <glib.h>
13 #include <string.h>
14
15 #include "bluesky-private.h"
16
17 /* Debugging support for BlueSky. */
18
19 static void inode_dump(gpointer key, gpointer value, gpointer user_data)
20 {
21     BlueSkyInode *inode = (BlueSkyInode *)value;
22
23     g_print("Inode %"PRIu64":\n", inode->inum);
24
25     gboolean locked = TRUE;
26     if (g_mutex_trylock(inode->lock)) {
27         locked = FALSE;
28         g_mutex_unlock(inode->lock);
29     }
30     g_print("    Locked: %c   Refcount: %d\n",
31             locked ? 'T' : 'F', inode->refcount);
32
33     g_print("    Type: %d   Mode: %o\n", inode->type, inode->mode);
34     g_print("    change_count = %"PRIu64", change_commit = %"PRIu64", "
35             "change_cloud = %"PRIu64"\n",
36             inode->change_count, inode->change_commit, inode->change_cloud);
37 }
38
39 static void cloudlog_dump(gpointer key, gpointer value, gpointer user_data)
40 {
41     BlueSkyCloudLog *log = (BlueSkyCloudLog *)value;
42
43     for (int i = 0; i < sizeof(BlueSkyCloudID); i++) {
44         g_print("%02x", (uint8_t)(log->id.bytes[i]));
45     }
46     g_print(": refs=%d ty=%d inode=%"PRIu64" locs=%x log@(%d,%d) cloud@(%d,%d,%d)\n",
47             log->refcount,
48             log->type, log->inum,
49             log->location_flags | (log->data != NULL ? 0x100 : 0),
50             log->log_seq, log->log_offset, log->location.directory,
51             log->location.sequence, log->location.offset);
52 }
53
54 static void cache_dump(gpointer key, gpointer value, gpointer user_data)
55 {
56     BlueSkyCacheFile *cache = (BlueSkyCacheFile *)value;
57
58     int64_t age = bluesky_get_current_time() - cache->atime;
59     g_print("%s addr=%p mapcount=%d refcount=%d atime_age=%f",
60             cache->filename, cache->addr, cache->mapcount, cache->refcount,
61             age / 1e6);
62     if (cache->fetching)
63         g_print(" (fetching)");
64     g_print("\n");
65 }
66
67
68 void inode_map_dump(GSequence *inode_map)
69 {
70     GSequenceIter *i, *j;
71
72     g_print("\nInode map dump:\n");
73     for (i = g_sequence_get_begin_iter(inode_map);
74          !g_sequence_iter_is_end(i); i = g_sequence_iter_next(i))
75     {
76         InodeMapRange *range = (InodeMapRange *)g_sequence_get(i);
77
78         g_print("  Range [%"PRIu64", %"PRIu64"]\n", range->start, range->end);
79
80         for (j = g_sequence_get_begin_iter(range->map_entries);
81              !g_sequence_iter_is_end(j); j = g_sequence_iter_next(j))
82         {
83             InodeMapEntry *entry = (InodeMapEntry *)g_sequence_get(j);
84             BlueSkyCloudLog *item = entry->item;
85             if (item != NULL) {
86                 char *id = bluesky_cloudlog_id_to_string(item->id);
87                 g_print("    Entry %"PRIu64" id=%s\n", entry->inum, id);
88                 g_free(id);
89             } else {
90                 g_print("    Entry %"PRIu64" not available\n", entry->inum);
91             }
92         }
93     }
94 }
95 /* Dump a summary of filesystem state as it is cached in memory. */
96 void bluesky_debug_dump(BlueSkyFS *fs)
97 {
98     g_print("\n*** DEBUG DUMP FOR FILESYSTEM %s ***\n", fs->name);
99     g_print("Dirty blocks: %d\n", g_atomic_int_get(&fs->cache_dirty));
100     g_print("Cached inodes: %u\tNext inode: %"PRIu64"\n",
101             g_hash_table_size(fs->inodes), fs->next_inum);
102     g_print("Cloudlog cache: %d dirty, %d writeback, %d journal, %d cloud\n",
103             g_atomic_int_get(&fs->cache_log_dirty),
104             g_atomic_int_get(&fs->cache_log_writeback),
105             g_atomic_int_get(&fs->cache_log_journal),
106             g_atomic_int_get(&fs->cache_log_cloud));
107
108     GList *item;
109     g_print("Unsynced inode list:");
110     for (item = fs->unlogged_list.next; item != NULL; item = item->next) {
111         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
112     }
113     g_print("\n");
114     g_print("Dirty inode LRU list:");
115     for (item = fs->dirty_list.next; item != NULL; item = item->next) {
116         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
117     }
118     g_print("\n");
119     g_print("Accessed inode LRU list:");
120     for (item = fs->accessed_list.next; item != NULL; item = item->next) {
121         g_print(" %"PRIu64";", ((BlueSkyInode *)item->data)->inum);
122     }
123     g_print("\n");
124
125     g_hash_table_foreach(fs->inodes, inode_dump, fs);
126
127     g_print("\nLog Objects:\n");
128     g_hash_table_foreach(fs->locations, cloudlog_dump, fs);
129
130     g_print("\nJournal/Cache Files:\n");
131     g_hash_table_foreach(fs->log->mmap_cache, cache_dump, fs);
132     g_print("\n");
133
134     g_mutex_lock(fs->lock);
135     inode_map_dump(fs->inode_map);
136     g_mutex_unlock(fs->lock);
137 }
138
139 /* Statistics counters: for operation counts, bytes transferred, etc. */
140 static GStaticMutex stats_lock = G_STATIC_MUTEX_INIT;
141 static GList *stats_list = NULL;
142
143 struct bluesky_stats *bluesky_stats_new(const char *name)
144 {
145     struct bluesky_stats *stats = g_new0(struct bluesky_stats, 1);
146     stats->name = name;
147     g_static_mutex_lock(&stats_lock);
148     stats_list = g_list_append(stats_list, stats);
149     g_static_mutex_unlock(&stats_lock);
150     return stats;
151 }
152
153 void bluesky_stats_add(struct bluesky_stats *stats, int64_t value)
154 {
155     __sync_fetch_and_add(&stats->count, (int64_t)1);
156     __sync_fetch_and_add(&stats->sum, value);
157 }
158
159 void bluesky_stats_dump_all()
160 {
161     g_static_mutex_lock(&stats_lock);
162     for (GList *item = stats_list; item != NULL; item = item->next) {
163         struct bluesky_stats *stats = (struct bluesky_stats *)item->data;
164         g_print("%s: count=%"PRIi64" sum=%"PRIi64"\n",
165                 stats->name, stats->count, stats->sum);
166     }
167     g_static_mutex_unlock(&stats_lock);
168 }
169
170 static void periodic_stats_dumper(FILE *f)
171 {
172     const int64_t interval = 10 * 1000000000ULL;
173     bluesky_time_hires timestamp = bluesky_now_hires();
174     bluesky_time_hires next_timestamp = timestamp;
175
176     while (TRUE) {
177         g_static_mutex_lock(&stats_lock);
178         timestamp = bluesky_now_hires();
179         fprintf(f, "********\ntime=%f\n\n", timestamp / 1e9);
180         for (GList *item = stats_list; item != NULL; item = item->next) {
181             struct bluesky_stats *stats = (struct bluesky_stats *)item->data;
182             fprintf(f, "%s: count=%"PRIi64" sum=%"PRIi64"\n",
183                     stats->name, stats->count, stats->sum);
184         }
185         g_static_mutex_unlock(&stats_lock);
186         fflush(f);
187
188         /* Wait until ten seconds from the last timestamp, with a few extra
189          * checks for sanity (always try to wait some amount of time in the
190          * range [0, 20] seconds). */
191         timestamp = bluesky_now_hires();
192         next_timestamp += interval;
193         if (next_timestamp < timestamp) {
194             next_timestamp = timestamp;
195             continue;
196         }
197         if (next_timestamp - timestamp > 2 * interval) {
198             next_timestamp = timestamp + interval;
199         }
200
201         struct timespec delay;
202         delay.tv_sec = (next_timestamp - timestamp) / 1000000000;
203         delay.tv_nsec = (next_timestamp - timestamp) % 1000000000;
204         nanosleep(&delay, NULL);
205     }
206 }
207
208 /* Start a background thread that will periodically dump statistics counters to
209  * he specified file every ten seconds. */
210 void bluesky_stats_run_periodic_dump(FILE *f)
211 {
212     g_thread_create((GThreadFunc)periodic_stats_dumper, f, FALSE, NULL);
213 }