diff options
author | Mark Salyzyn | 2015-11-06 14:26:52 -0600 |
---|---|---|
committer | Mark Salyzyn | 2015-11-19 15:14:16 -0600 |
commit | 2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9 (patch) | |
tree | ef9d05a98bc0eb3fe698089c0701e1db503ced29 /liblog/log_is_loggable.c | |
parent | 9f903687011c195154b0c69c02e6aaa35c867242 (diff) | |
download | platform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.tar.gz platform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.tar.xz platform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.zip |
liblog: resolve deadlocks
Although ever present, an increased regression introduced with
commit b6bee33182cedea49199eb2252b3f3b442899c6d (liblog: logd:
support logd.timestamp = monotonic).
A signal handler can interrupt in locked context, if log is written
in the signal handler, we are in deadlock. To reduce the contention
and chances for this problem separate out timestamp lock from is
loggable lock to reduce contention situations. Provide a best-guess
response if lock would fail in timestamp path.
Use a common lock() inline within each module, with a comment speaking
to the issues surrounding calling a function that has a mutex within
a signal handler.
ToDo: Hold off signals temporarily in mainline, restart when unblock.
Can not use pthread_sigmask(SIG_BLOCK,,) as it breaks AtCmd.
Signed-off-by: Mark Salyzyn <salyzyn@google.com>
Bug: 25563384
Change-Id: I47e2c87c988c3e359eb9eef129c6a3a08e9eedef
Diffstat (limited to 'liblog/log_is_loggable.c')
-rw-r--r-- | liblog/log_is_loggable.c | 67 |
1 files changed, 46 insertions, 21 deletions
diff --git a/liblog/log_is_loggable.c b/liblog/log_is_loggable.c index 814d96d09..e128edbd8 100644 --- a/liblog/log_is_loggable.c +++ b/liblog/log_is_loggable.c | |||
@@ -23,6 +23,22 @@ | |||
23 | 23 | ||
24 | #include <android/log.h> | 24 | #include <android/log.h> |
25 | 25 | ||
26 | static pthread_mutex_t lock_loggable = PTHREAD_MUTEX_INITIALIZER; | ||
27 | |||
28 | static void lock() | ||
29 | { | ||
30 | /* | ||
31 | * If we trigger a signal handler in the middle of locked activity and the | ||
32 | * signal handler logs a message, we could get into a deadlock state. | ||
33 | */ | ||
34 | pthread_mutex_lock(&lock_loggable); | ||
35 | } | ||
36 | |||
37 | static void unlock() | ||
38 | { | ||
39 | pthread_mutex_unlock(&lock_loggable); | ||
40 | } | ||
41 | |||
26 | struct cache { | 42 | struct cache { |
27 | const prop_info *pinfo; | 43 | const prop_info *pinfo; |
28 | uint32_t serial; | 44 | uint32_t serial; |
@@ -49,9 +65,7 @@ static void refresh_cache(struct cache *cache, const char *key) | |||
49 | cache->c = buf[0]; | 65 | cache->c = buf[0]; |
50 | } | 66 | } |
51 | 67 | ||
52 | static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER; | 68 | static int __android_log_level(const char *tag, int default_prio) |
53 | |||
54 | static int __android_log_level(const char *tag, int def) | ||
55 | { | 69 | { |
56 | /* sizeof() is used on this array below */ | 70 | /* sizeof() is used on this array below */ |
57 | static const char log_namespace[] = "persist.log.tag."; | 71 | static const char log_namespace[] = "persist.log.tag."; |
@@ -86,7 +100,7 @@ static int __android_log_level(const char *tag, int def) | |||
86 | 100 | ||
87 | strcpy(key, log_namespace); | 101 | strcpy(key, log_namespace); |
88 | 102 | ||
89 | pthread_mutex_lock(&lock); | 103 | lock(); |
90 | 104 | ||
91 | current_global_serial = __system_property_area_serial(); | 105 | current_global_serial = __system_property_area_serial(); |
92 | 106 | ||
@@ -156,7 +170,7 @@ static int __android_log_level(const char *tag, int def) | |||
156 | 170 | ||
157 | global_serial = current_global_serial; | 171 | global_serial = current_global_serial; |
158 | 172 | ||
159 | pthread_mutex_unlock(&lock); | 173 | unlock(); |
160 | 174 | ||
161 | switch (toupper(c)) { | 175 | switch (toupper(c)) { |
162 | case 'V': return ANDROID_LOG_VERBOSE; | 176 | case 'V': return ANDROID_LOG_VERBOSE; |
@@ -168,36 +182,47 @@ static int __android_log_level(const char *tag, int def) | |||
168 | case 'A': return ANDROID_LOG_FATAL; | 182 | case 'A': return ANDROID_LOG_FATAL; |
169 | case 'S': return -1; /* ANDROID_LOG_SUPPRESS */ | 183 | case 'S': return -1; /* ANDROID_LOG_SUPPRESS */ |
170 | } | 184 | } |
171 | return def; | 185 | return default_prio; |
172 | } | 186 | } |
173 | 187 | ||
174 | int __android_log_is_loggable(int prio, const char *tag, int def) | 188 | int __android_log_is_loggable(int prio, const char *tag, int default_prio) |
175 | { | 189 | { |
176 | int logLevel = __android_log_level(tag, def); | 190 | int logLevel = __android_log_level(tag, default_prio); |
177 | return logLevel >= 0 && prio >= logLevel; | 191 | return logLevel >= 0 && prio >= logLevel; |
178 | } | 192 | } |
179 | 193 | ||
194 | /* | ||
195 | * Timestamp state generally remains constant, since a change is | ||
196 | * rare, we can accept a trylock failure gracefully. Use a separate | ||
197 | * lock from is_loggable to keep contention down b/25563384. | ||
198 | */ | ||
199 | static pthread_mutex_t lock_timestamp = PTHREAD_MUTEX_INITIALIZER; | ||
200 | |||
180 | char android_log_timestamp() | 201 | char android_log_timestamp() |
181 | { | 202 | { |
182 | static struct cache r_time_cache = { NULL, -1, 0 }; | 203 | static struct cache r_time_cache = { NULL, -1, 0 }; |
183 | static struct cache p_time_cache = { NULL, -1, 0 }; | 204 | static struct cache p_time_cache = { NULL, -1, 0 }; |
184 | static uint32_t serial; | ||
185 | uint32_t current_serial; | ||
186 | char retval; | 205 | char retval; |
187 | 206 | ||
188 | pthread_mutex_lock(&lock); | 207 | if (pthread_mutex_trylock(&lock_timestamp)) { |
208 | /* We are willing to accept some race in this context */ | ||
209 | if (!(retval = p_time_cache.c)) { | ||
210 | retval = r_time_cache.c; | ||
211 | } | ||
212 | } else { | ||
213 | static uint32_t serial; | ||
214 | uint32_t current_serial = __system_property_area_serial(); | ||
215 | if (current_serial != serial) { | ||
216 | refresh_cache(&r_time_cache, "ro.logd.timestamp"); | ||
217 | refresh_cache(&p_time_cache, "persist.logd.timestamp"); | ||
218 | serial = current_serial; | ||
219 | } | ||
220 | if (!(retval = p_time_cache.c)) { | ||
221 | retval = r_time_cache.c; | ||
222 | } | ||
189 | 223 | ||
190 | current_serial = __system_property_area_serial(); | 224 | pthread_mutex_unlock(&lock_timestamp); |
191 | if (current_serial != serial) { | ||
192 | refresh_cache(&r_time_cache, "ro.logd.timestamp"); | ||
193 | refresh_cache(&p_time_cache, "persist.logd.timestamp"); | ||
194 | serial = current_serial; | ||
195 | } | 225 | } |
196 | if (!(retval = p_time_cache.c)) { | ||
197 | retval = r_time_cache.c; | ||
198 | } | ||
199 | |||
200 | pthread_mutex_unlock(&lock); | ||
201 | 226 | ||
202 | return tolower(retval ?: 'r'); | 227 | return tolower(retval ?: 'r'); |
203 | } | 228 | } |