cfm: Improve logging.
[openvswitch] / lib / coverage.c
1 /*
2  * Copyright (c) 2009, 2010, 2011, 2012 Nicira, Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at:
7  *
8  *     http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16
17 #include <config.h>
18 #include "coverage.h"
19 #include <inttypes.h>
20 #include <stdlib.h>
21 #include "dynamic-string.h"
22 #include "hash.h"
23 #include "svec.h"
24 #include "timeval.h"
25 #include "unixctl.h"
26 #include "util.h"
27 #include "vlog.h"
28
29 VLOG_DEFINE_THIS_MODULE(coverage);
30
31 /* The coverage counters. */
32 #if USE_LINKER_SECTIONS
33 extern struct coverage_counter *__start_coverage[];
34 extern struct coverage_counter *__stop_coverage[];
35 #define coverage_counters __start_coverage
36 #define n_coverage_counters  (__stop_coverage - __start_coverage)
37 #else  /* !USE_LINKER_SECTIONS */
38 #define COVERAGE_COUNTER(NAME) COVERAGE_DEFINE__(NAME);
39 #include "coverage.def"
40 #undef COVERAGE_COUNTER
41
42 struct coverage_counter *coverage_counters[] = {
43 #define COVERAGE_COUNTER(NAME) &counter_##NAME,
44 #include "coverage.def"
45 #undef COVERAGE_COUNTER
46 };
47 #define n_coverage_counters ARRAY_SIZE(coverage_counters)
48 #endif  /* !USE_LINKER_SECTIONS */
49
50 static unsigned int epoch;
51
52 static void coverage_read(struct svec *);
53
54 static void
55 coverage_unixctl_show(struct unixctl_conn *conn, int argc OVS_UNUSED,
56                      const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED)
57 {
58     struct svec lines;
59     char *reply;
60
61     svec_init(&lines);
62     coverage_read(&lines);
63     reply = svec_join(&lines, "\n", "\n");
64     unixctl_command_reply(conn, reply);
65     free(reply);
66     svec_destroy(&lines);
67 }
68
69 void
70 coverage_init(void)
71 {
72     unixctl_command_register("coverage/show", "", 0, 0,
73                              coverage_unixctl_show, NULL);
74 }
75
76 /* Sorts coverage counters in descending order by count, within equal counts
77  * alphabetically by name. */
78 static int
79 compare_coverage_counters(const void *a_, const void *b_)
80 {
81     const struct coverage_counter *const *ap = a_;
82     const struct coverage_counter *const *bp = b_;
83     const struct coverage_counter *a = *ap;
84     const struct coverage_counter *b = *bp;
85     if (a->count != b->count) {
86         return a->count < b->count ? 1 : -1;
87     } else {
88         return strcmp(a->name, b->name);
89     }
90 }
91
92 static uint32_t
93 coverage_hash(void)
94 {
95     struct coverage_counter **c;
96     uint32_t hash = 0;
97     int n_groups, i;
98
99     /* Sort coverage counters into groups with equal counts. */
100     c = xmalloc(n_coverage_counters * sizeof *c);
101     for (i = 0; i < n_coverage_counters; i++) {
102         c[i] = coverage_counters[i];
103     }
104     qsort(c, n_coverage_counters, sizeof *c, compare_coverage_counters);
105
106     /* Hash the names in each group along with the rank. */
107     n_groups = 0;
108     for (i = 0; i < n_coverage_counters; ) {
109         int j;
110
111         if (!c[i]->count) {
112             break;
113         }
114         n_groups++;
115         hash = hash_int(i, hash);
116         for (j = i; j < n_coverage_counters; j++) {
117             if (c[j]->count != c[i]->count) {
118                 break;
119             }
120             hash = hash_string(c[j]->name, hash);
121         }
122         i = j;
123     }
124
125     free(c);
126
127     return hash_int(n_groups, hash);
128 }
129
130 static bool
131 coverage_hit(uint32_t hash)
132 {
133     enum { HIT_BITS = 1024, BITS_PER_WORD = 32 };
134     static uint32_t hit[HIT_BITS / BITS_PER_WORD];
135     BUILD_ASSERT_DECL(IS_POW2(HIT_BITS));
136
137     static long long int next_clear = LLONG_MIN;
138
139     unsigned int bit_index = hash & (HIT_BITS - 1);
140     unsigned int word_index = bit_index / BITS_PER_WORD;
141     unsigned int word_mask = 1u << (bit_index % BITS_PER_WORD);
142
143     /* Expire coverage hash suppression once a day. */
144     if (time_msec() >= next_clear) {
145         memset(hit, 0, sizeof hit);
146         next_clear = time_msec() + 60 * 60 * 24 * 1000LL;
147     }
148
149     if (hit[word_index] & word_mask) {
150         return true;
151     } else {
152         hit[word_index] |= word_mask;
153         return false;
154     }
155 }
156
157 /* Logs the coverage counters, unless a similar set of events has already been
158  * logged.
159  *
160  * This function logs at log level VLL_INFO.  Use care before adjusting this
161  * level, because depending on its configuration, syslogd can write changes
162  * synchronously, which can cause the coverage messages to take several seconds
163  * to write. */
164 void
165 coverage_log(void)
166 {
167     static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 3);
168
169     if (!VLOG_DROP_INFO(&rl)) {
170         uint32_t hash = coverage_hash();
171         if (coverage_hit(hash)) {
172             VLOG_INFO("Skipping details of duplicate event coverage for "
173                       "hash=%08"PRIx32" in epoch %u", hash, epoch);
174         } else {
175             struct svec lines;
176             const char *line;
177             size_t i;
178
179             svec_init(&lines);
180             coverage_read(&lines);
181             SVEC_FOR_EACH (i, line, &lines) {
182                 VLOG_INFO("%s", line);
183             }
184             svec_destroy(&lines);
185         }
186     }
187 }
188
189 static void
190 coverage_read_counter(struct svec *lines, const struct coverage_counter *c)
191 {
192     svec_add_nocopy(lines, xasprintf("%-24s %5u / %9llu",
193                                      c->name, c->count, c->count + c->total));
194 }
195
196 /* Adds coverage counter information to 'lines'. */
197 static void
198 coverage_read(struct svec *lines)
199 {
200     size_t n_never_hit;
201     uint32_t hash;
202     size_t i;
203
204     hash = coverage_hash();
205
206     n_never_hit = 0;
207     svec_add_nocopy(lines, xasprintf("Event coverage (epoch %u/entire run), "
208                                      "hash=%08"PRIx32":", epoch, hash));
209     for (i = 0; i < n_coverage_counters; i++) {
210         struct coverage_counter *c = coverage_counters[i];
211         if (c->count) {
212             coverage_read_counter(lines, c);
213         }
214     }
215     for (i = 0; i < n_coverage_counters; i++) {
216         struct coverage_counter *c = coverage_counters[i];
217         if (!c->count) {
218             if (c->total) {
219                 coverage_read_counter(lines, c);
220             } else {
221                 n_never_hit++;
222             }
223         }
224     }
225     svec_add_nocopy(lines, xasprintf("%zu events never hit", n_never_hit));
226 }
227
228 /* Advances to the next epoch of coverage, resetting all the counters to 0. */
229 void
230 coverage_clear(void)
231 {
232     size_t i;
233
234     epoch++;
235     for (i = 0; i < n_coverage_counters; i++) {
236         struct coverage_counter *c = coverage_counters[i];
237         c->total += c->count;
238         c->count = 0;
239     }
240 }