• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 // Copyright 2015-2019 Espressif Systems (Shanghai) PTE LTD
2 //
3 // Licensed under the Apache License, Version 2.0 (the "License");
4 // you may not use this file except in compliance with the License.
5 // You may obtain a copy of the License at
6 //
7 //     http://www.apache.org/licenses/LICENSE-2.0
8 //
9 // Unless required by applicable law or agreed to in writing, software
10 // distributed under the License is distributed on an "AS IS" BASIS,
11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 // See the License for the specific language governing permissions and
13 // limitations under the License.
14 
15 /*
16  * Log library implementation notes.
17  *
18  * Log library stores all tags provided to esp_log_level_set as a linked
19  * list. See uncached_tag_entry_t structure.
20  *
21  * To avoid looking up log level for given tag each time message is
22  * printed, this library caches pointers to tags. Because the suggested
23  * way of creating tags uses one 'TAG' constant per file, this caching
24  * should be effective. Cache is a binary min-heap of cached_tag_entry_t
25  * items, ordering is done on 'generation' member. In this context,
26  * generation is an integer which is incremented each time an operation
27  * with cache is performed. When cache is full, new item is inserted in
28  * place of an oldest item (that is, with smallest 'generation' value).
29  * After that, bubble-down operation is performed to fix ordering in the
30  * min-heap.
31  *
32  * The potential problem with wrap-around of cache generation counter is
33  * ignored for now. This will happen if someone happens to output more
34  * than 4 billion log entries, at which point wrap-around will not be
35  * the biggest problem.
36  *
37  */
38 
39 #include <stdbool.h>
40 #include <stdarg.h>
41 #include <string.h>
42 #include <stdlib.h>
43 #include <stdio.h>
44 #include <assert.h>
45 #include "esp_log.h"
46 #include "esp_log_private.h"
47 
48 #ifndef NDEBUG
49 // Enable built-in checks in queue.h in debug builds
50 #define INVARIANTS
51 // Enable consistency checks and cache statistics in this file.
52 #define LOG_BUILTIN_CHECKS
53 #endif
54 
55 #include "sys/queue.h"
56 
57 // Number of tags to be cached. Must be 2**n - 1, n >= 2.
58 #define TAG_CACHE_SIZE 31
59 
60 typedef struct {
61     const char *tag;
62     uint32_t level : 3;
63     uint32_t generation : 29;
64 } cached_tag_entry_t;
65 
66 typedef struct uncached_tag_entry_ {
67     SLIST_ENTRY(uncached_tag_entry_) entries;
68     uint8_t level;  // esp_log_level_t as uint8_t
69     char tag[0];    // beginning of a zero-terminated string
70 } uncached_tag_entry_t;
71 
72 static esp_log_level_t s_log_default_level = ESP_LOG_VERBOSE;
73 static SLIST_HEAD(log_tags_head, uncached_tag_entry_) s_log_tags = SLIST_HEAD_INITIALIZER(s_log_tags);
74 static cached_tag_entry_t s_log_cache[TAG_CACHE_SIZE];
75 static uint32_t s_log_cache_max_generation = 0;
76 static uint32_t s_log_cache_entry_count = 0;
77 static vprintf_like_t s_log_print_func = &vprintf;
78 
79 #ifdef LOG_BUILTIN_CHECKS
80 static uint32_t s_log_cache_misses = 0;
81 #endif
82 
83 
84 static inline bool get_cached_log_level(const char *tag, esp_log_level_t *level);
85 static inline bool get_uncached_log_level(const char *tag, esp_log_level_t *level);
86 static inline void add_to_cache(const char *tag, esp_log_level_t level);
87 static void heap_bubble_down(int index);
88 static inline void heap_swap(int i, int j);
89 static inline bool should_output(esp_log_level_t level_for_message, esp_log_level_t level_for_tag);
90 static inline void clear_log_level_list(void);
91 
92 #if 0
93 vprintf_like_t esp_log_set_vprintf(vprintf_like_t func)
94 {
95     esp_log_impl_lock();
96     vprintf_like_t orig_func = s_log_print_func;
97     s_log_print_func = func;
98     esp_log_impl_unlock();
99     return orig_func;
100 }
101 #endif
102 
esp_log_level_set(const char * tag,esp_log_level_t level)103 void esp_log_level_set(const char *tag, esp_log_level_t level)
104 {
105     esp_log_impl_lock();
106 
107     // for wildcard tag, remove all linked list items and clear the cache
108     if (strcmp(tag, "*") == 0) {
109         s_log_default_level = level;
110         clear_log_level_list();
111         esp_log_impl_unlock();
112         return;
113     }
114 
115     // search for existing tag
116     uncached_tag_entry_t *it = NULL;
117     SLIST_FOREACH(it, &s_log_tags, entries) {
118         if (strcmp(it->tag, tag) == 0) {
119             // one tag in the linked list matched, update the level
120             it->level = level;
121             // quit with it != NULL
122             break;
123         }
124     }
125     // no existing tag, append new one
126     if (it == NULL) {
127         // allocate new linked list entry and append it to the head of the list
128         size_t tag_len = strlen(tag) + 1;
129         size_t entry_size = offsetof(uncached_tag_entry_t, tag) + tag_len;
130         uncached_tag_entry_t *new_entry = (uncached_tag_entry_t *) malloc(entry_size);
131         if (!new_entry) {
132             esp_log_impl_unlock();
133             return;
134         }
135         new_entry->level = (uint8_t) level;
136         strlcpy(new_entry->tag, tag, tag_len);
137         SLIST_INSERT_HEAD(&s_log_tags, new_entry, entries);
138     }
139 
140     // search in the cache and update the entry it if exists
141     for (uint32_t i = 0; i < s_log_cache_entry_count; ++i) {
142 #ifdef LOG_BUILTIN_CHECKS
143         assert(i == 0 || s_log_cache[(i - 1) / 2].generation < s_log_cache[i].generation);
144 #endif
145         if (strcmp(s_log_cache[i].tag, tag) == 0) {
146             s_log_cache[i].level = level;
147             break;
148         }
149     }
150     esp_log_impl_unlock();
151 }
152 
clear_log_level_list(void)153 void clear_log_level_list(void)
154 {
155     uncached_tag_entry_t *it;
156     while ((it = SLIST_FIRST(&s_log_tags)) != NULL) {
157         SLIST_REMOVE_HEAD(&s_log_tags, entries);
158         free(it);
159     }
160     s_log_cache_entry_count = 0;
161     s_log_cache_max_generation = 0;
162 #ifdef LOG_BUILTIN_CHECKS
163     s_log_cache_misses = 0;
164 #endif
165 }
166 
esp_log_writev(esp_log_level_t level,const char * tag,const char * format,va_list args)167 void esp_log_writev(esp_log_level_t level,
168                    const char *tag,
169                    const char *format,
170                    va_list args)
171 {
172     if (!esp_log_impl_lock_timeout()) {
173         return;
174     }
175     esp_log_level_t level_for_tag;
176     // Look for the tag in cache first, then in the linked list of all tags
177     if (!get_cached_log_level(tag, &level_for_tag)) {
178         if (!get_uncached_log_level(tag, &level_for_tag)) {
179             level_for_tag = s_log_default_level;
180         }
181         add_to_cache(tag, level_for_tag);
182 #ifdef LOG_BUILTIN_CHECKS
183         ++s_log_cache_misses;
184 #endif
185     }
186     esp_log_impl_unlock();
187     if (!should_output(level, level_for_tag)) {
188         return;
189     }
190 
191     (*s_log_print_func)(format, args);
192 
193 }
194 
esp_log_write(esp_log_level_t level,const char * tag,const char * format,...)195 void esp_log_write(esp_log_level_t level,
196                    const char *tag,
197                    const char *format, ...)
198 {
199     va_list list;
200     va_start(list, format);
201     esp_log_writev(level, tag, format, list);
202     va_end(list);
203 }
204 
get_cached_log_level(const char * tag,esp_log_level_t * level)205 static inline bool get_cached_log_level(const char *tag, esp_log_level_t *level)
206 {
207     // Look for `tag` in cache
208     uint32_t i;
209     for (i = 0; i < s_log_cache_entry_count; ++i) {
210 #ifdef LOG_BUILTIN_CHECKS
211         assert(i == 0 || s_log_cache[(i - 1) / 2].generation < s_log_cache[i].generation);
212 #endif
213         if (s_log_cache[i].tag == tag) {
214             break;
215         }
216     }
217     if (i == s_log_cache_entry_count) { // Not found in cache
218         return false;
219     }
220     // Return level from cache
221     *level = (esp_log_level_t) s_log_cache[i].level;
222     // If cache has been filled, start taking ordering into account
223     // (other options are: dynamically resize cache, add "dummy" entries
224     //  to the cache; this option was chosen because code is much simpler,
225     //  and the unfair behavior of cache will show it self at most once, when
226     //  it has just been filled)
227     if (s_log_cache_entry_count == TAG_CACHE_SIZE) {
228         // Update item generation
229         s_log_cache[i].generation = s_log_cache_max_generation++;
230         // Restore heap ordering
231         heap_bubble_down(i);
232     }
233     return true;
234 }
235 
add_to_cache(const char * tag,esp_log_level_t level)236 static inline void add_to_cache(const char *tag, esp_log_level_t level)
237 {
238     uint32_t generation = s_log_cache_max_generation++;
239     // First consider the case when cache is not filled yet.
240     // In this case, just add new entry at the end.
241     // This happens to satisfy binary min-heap ordering.
242     if (s_log_cache_entry_count < TAG_CACHE_SIZE) {
243         s_log_cache[s_log_cache_entry_count] = (cached_tag_entry_t) {
244             .generation = generation,
245             .level = level,
246             .tag = tag
247         };
248         ++s_log_cache_entry_count;
249         return;
250     }
251 
252     // Cache is full, so we replace the oldest entry (which is at index 0
253     // because this is a min-heap) with the new one, and do bubble-down
254     // operation to restore min-heap ordering.
255     s_log_cache[0] = (cached_tag_entry_t) {
256         .tag = tag,
257         .level = level,
258         .generation = generation
259     };
260     heap_bubble_down(0);
261 }
262 
get_uncached_log_level(const char * tag,esp_log_level_t * level)263 static inline bool get_uncached_log_level(const char *tag, esp_log_level_t *level)
264 {
265     // Walk the linked list of all tags and see if given tag is present in the list.
266     // This is slow because tags are compared as strings.
267     uncached_tag_entry_t *it;
268     SLIST_FOREACH(it, &s_log_tags, entries) {
269         if (strcmp(tag, it->tag) == 0) {
270             *level = it->level;
271             return true;
272         }
273     }
274     return false;
275 }
276 
should_output(esp_log_level_t level_for_message,esp_log_level_t level_for_tag)277 static inline bool should_output(esp_log_level_t level_for_message, esp_log_level_t level_for_tag)
278 {
279     return level_for_message <= level_for_tag;
280 }
281 
heap_bubble_down(int index)282 static void heap_bubble_down(int index)
283 {
284     while (index < TAG_CACHE_SIZE / 2) {
285         int left_index = index * 2 + 1;
286         int right_index = left_index + 1;
287         int next = (s_log_cache[left_index].generation < s_log_cache[right_index].generation) ? left_index : right_index;
288         heap_swap(index, next);
289         index = next;
290     }
291 }
292 
heap_swap(int i,int j)293 static inline void heap_swap(int i, int j)
294 {
295     cached_tag_entry_t tmp = s_log_cache[i];
296     s_log_cache[i] = s_log_cache[j];
297     s_log_cache[j] = tmp;
298 }
299