LogBuffer.cpp revision ab4b7308ecd8a425cdeb3e289fcfeda0e08085be 
1/*
2 * Copyright (C) 2012-2014 The Android Open Source Project
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 <ctype.h>
18#include <stdio.h>
19#include <stdlib.h>
20#include <string.h>
21#include <sys/user.h>
22#include <time.h>
23#include <unistd.h>
24
25#include <cutils/properties.h>
26#include <log/logger.h>
27
28#include "LogBuffer.h"
29#include "LogReader.h"
30#include "LogStatistics.h"
31#include "LogWhiteBlackList.h"
32
33// Default
34#define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here?
35#define log_buffer_size(id) mMaxSize[id]
36#define LOG_BUFFER_MIN_SIZE (64 * 1024UL)
37#define LOG_BUFFER_MAX_SIZE (256 * 1024 * 1024UL)
38
39static bool valid_size(unsigned long value) {
40    if ((value < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < value)) {
41        return false;
42    }
43
44    long pages = sysconf(_SC_PHYS_PAGES);
45    if (pages < 1) {
46        return true;
47    }
48
49    long pagesize = sysconf(_SC_PAGESIZE);
50    if (pagesize <= 1) {
51        pagesize = PAGE_SIZE;
52    }
53
54    // maximum memory impact a somewhat arbitrary ~3%
55    pages = (pages + 31) / 32;
56    unsigned long maximum = pages * pagesize;
57
58    if ((maximum < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < maximum)) {
59        return true;
60    }
61
62    return value <= maximum;
63}
64
65static unsigned long property_get_size(const char *key) {
66    char property[PROPERTY_VALUE_MAX];
67    property_get(key, property, "");
68
69    char *cp;
70    unsigned long value = strtoul(property, &cp, 10);
71
72    switch(*cp) {
73    case 'm':
74    case 'M':
75        value *= 1024;
76    /* FALLTHRU */
77    case 'k':
78    case 'K':
79        value *= 1024;
80    /* FALLTHRU */
81    case '\0':
82        break;
83
84    default:
85        value = 0;
86    }
87
88    if (!valid_size(value)) {
89        value = 0;
90    }
91
92    return value;
93}
94
95LogBuffer::LogBuffer(LastLogTimes *times)
96        : mTimes(*times) {
97    pthread_mutex_init(&mLogElementsLock, NULL);
98    dgram_qlen_statistics = false;
99
100    static const char global_tuneable[] = "persist.logd.size"; // Settings App
101    static const char global_default[] = "ro.logd.size";       // BoardConfig.mk
102
103    unsigned long default_size = property_get_size(global_tuneable);
104    if (!default_size) {
105        default_size = property_get_size(global_default);
106    }
107
108    log_id_for_each(i) {
109        char key[PROP_NAME_MAX];
110
111        snprintf(key, sizeof(key), "%s.%s",
112                 global_tuneable, android_log_id_to_name(i));
113        unsigned long property_size = property_get_size(key);
114
115        if (!property_size) {
116            snprintf(key, sizeof(key), "%s.%s",
117                     global_default, android_log_id_to_name(i));
118            property_size = property_get_size(key);
119        }
120
121        if (!property_size) {
122            property_size = default_size;
123        }
124
125        if (!property_size) {
126            property_size = LOG_BUFFER_SIZE;
127        }
128
129        if (setSize(i, property_size)) {
130            setSize(i, LOG_BUFFER_MIN_SIZE);
131        }
132    }
133}
134
135void LogBuffer::log(log_id_t log_id, log_time realtime,
136                    uid_t uid, pid_t pid, pid_t tid,
137                    const char *msg, unsigned short len) {
138    if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
139        return;
140    }
141    LogBufferElement *elem = new LogBufferElement(log_id, realtime,
142                                                  uid, pid, tid, msg, len);
143
144    pthread_mutex_lock(&mLogElementsLock);
145
146    // Insert elements in time sorted order if possible
147    //  NB: if end is region locked, place element at end of list
148    LogBufferElementCollection::iterator it = mLogElements.end();
149    LogBufferElementCollection::iterator last = it;
150    while (--it != mLogElements.begin()) {
151        if ((*it)->getRealTime() <= realtime) {
152            // halves the peak performance, use with caution
153            if (dgram_qlen_statistics) {
154                LogBufferElementCollection::iterator ib = it;
155                unsigned short buckets, num = 1;
156                for (unsigned short i = 0; (buckets = stats.dgram_qlen(i)); ++i) {
157                    buckets -= num;
158                    num += buckets;
159                    while (buckets && (--ib != mLogElements.begin())) {
160                        --buckets;
161                    }
162                    if (buckets) {
163                        break;
164                    }
165                    stats.recordDiff(
166                        elem->getRealTime() - (*ib)->getRealTime(), i);
167                }
168            }
169            break;
170        }
171        last = it;
172    }
173
174    if (last == mLogElements.end()) {
175        mLogElements.push_back(elem);
176    } else {
177        log_time end = log_time::EPOCH;
178        bool end_set = false;
179        bool end_always = false;
180
181        LogTimeEntry::lock();
182
183        LastLogTimes::iterator t = mTimes.begin();
184        while(t != mTimes.end()) {
185            LogTimeEntry *entry = (*t);
186            if (entry->owned_Locked()) {
187                if (!entry->mNonBlock) {
188                    end_always = true;
189                    break;
190                }
191                if (!end_set || (end <= entry->mEnd)) {
192                    end = entry->mEnd;
193                    end_set = true;
194                }
195            }
196            t++;
197        }
198
199        if (end_always
200                || (end_set && (end >= (*last)->getMonotonicTime()))) {
201            mLogElements.push_back(elem);
202        } else {
203            mLogElements.insert(last,elem);
204        }
205
206        LogTimeEntry::unlock();
207    }
208
209    stats.add(len, log_id, uid, pid);
210    maybePrune(log_id);
211    pthread_mutex_unlock(&mLogElementsLock);
212}
213
214// If we're using more than 256K of memory for log entries, prune
215// at least 10% of the log entries.
216//
217// mLogElementsLock must be held when this function is called.
218void LogBuffer::maybePrune(log_id_t id) {
219    size_t sizes = stats.sizes(id);
220    if (sizes > log_buffer_size(id)) {
221        size_t sizeOver90Percent = sizes - ((log_buffer_size(id) * 9) / 10);
222        size_t elements = stats.elements(id);
223        unsigned long pruneRows = elements * sizeOver90Percent / sizes;
224        elements /= 10;
225        if (pruneRows <= elements) {
226            pruneRows = elements;
227        }
228        prune(id, pruneRows);
229    }
230}
231
232// prune "pruneRows" of type "id" from the buffer.
233//
234// mLogElementsLock must be held when this function is called.
235void LogBuffer::prune(log_id_t id, unsigned long pruneRows) {
236    LogTimeEntry *oldest = NULL;
237
238    LogTimeEntry::lock();
239
240    // Region locked?
241    LastLogTimes::iterator t = mTimes.begin();
242    while(t != mTimes.end()) {
243        LogTimeEntry *entry = (*t);
244        if (entry->owned_Locked()
245                && (!oldest || (oldest->mStart > entry->mStart))) {
246            oldest = entry;
247        }
248        t++;
249    }
250
251    LogBufferElementCollection::iterator it;
252
253    // prune by worst offender by uid
254    while (pruneRows > 0) {
255        // recalculate the worst offender on every batched pass
256        uid_t worst = (uid_t) -1;
257        size_t worst_sizes = 0;
258        size_t second_worst_sizes = 0;
259
260        if ((id != LOG_ID_CRASH) && mPrune.worstUidEnabled()) {
261            LidStatistics &l = stats.id(id);
262            l.sort();
263            UidStatisticsCollection::iterator iu = l.begin();
264            if (iu != l.end()) {
265                UidStatistics *u = *iu;
266                worst = u->getUid();
267                worst_sizes = u->sizes();
268                if (++iu != l.end()) {
269                    second_worst_sizes = (*iu)->sizes();
270                }
271            }
272        }
273
274        bool kick = false;
275        for(it = mLogElements.begin(); it != mLogElements.end();) {
276            LogBufferElement *e = *it;
277
278            if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
279                break;
280            }
281
282            if (e->getLogId() != id) {
283                ++it;
284                continue;
285            }
286
287            uid_t uid = e->getUid();
288
289            if (uid == worst) {
290                it = mLogElements.erase(it);
291                unsigned short len = e->getMsgLen();
292                stats.subtract(len, id, worst, e->getPid());
293                delete e;
294                kick = true;
295                pruneRows--;
296                if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) {
297                    break;
298                }
299                worst_sizes -= len;
300            } else if (mPrune.naughty(e)) { // BlackListed
301                it = mLogElements.erase(it);
302                stats.subtract(e->getMsgLen(), id, uid, e->getPid());
303                delete e;
304                pruneRows--;
305                if (pruneRows == 0) {
306                    break;
307                }
308            } else {
309                ++it;
310            }
311        }
312
313        if (!kick || !mPrune.worstUidEnabled()) {
314            break; // the following loop will ask bad clients to skip/drop
315        }
316    }
317
318    bool whitelist = false;
319    it = mLogElements.begin();
320    while((pruneRows > 0) && (it != mLogElements.end())) {
321        LogBufferElement *e = *it;
322        if (e->getLogId() == id) {
323            if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
324                if (!whitelist) {
325                    if (stats.sizes(id) > (2 * log_buffer_size(id))) {
326                        // kick a misbehaving log reader client off the island
327                        oldest->release_Locked();
328                    } else {
329                        oldest->triggerSkip_Locked(pruneRows);
330                    }
331                }
332                break;
333            }
334
335            if (mPrune.nice(e)) { // WhiteListed
336                whitelist = true;
337                it++;
338                continue;
339            }
340
341            it = mLogElements.erase(it);
342            stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
343            delete e;
344            pruneRows--;
345        } else {
346            it++;
347        }
348    }
349
350    if (whitelist && (pruneRows > 0)) {
351        it = mLogElements.begin();
352        while((it != mLogElements.end()) && (pruneRows > 0)) {
353            LogBufferElement *e = *it;
354            if (e->getLogId() == id) {
355                if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
356                    if (stats.sizes(id) > (2 * log_buffer_size(id))) {
357                        // kick a misbehaving log reader client off the island
358                        oldest->release_Locked();
359                    } else {
360                        oldest->triggerSkip_Locked(pruneRows);
361                    }
362                    break;
363                }
364                it = mLogElements.erase(it);
365                stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
366                delete e;
367                pruneRows--;
368            } else {
369                it++;
370            }
371        }
372    }
373
374    LogTimeEntry::unlock();
375}
376
377// clear all rows of type "id" from the buffer.
378void LogBuffer::clear(log_id_t id) {
379    pthread_mutex_lock(&mLogElementsLock);
380    prune(id, ULONG_MAX);
381    pthread_mutex_unlock(&mLogElementsLock);
382}
383
384// get the used space associated with "id".
385unsigned long LogBuffer::getSizeUsed(log_id_t id) {
386    pthread_mutex_lock(&mLogElementsLock);
387    size_t retval = stats.sizes(id);
388    pthread_mutex_unlock(&mLogElementsLock);
389    return retval;
390}
391
392// set the total space allocated to "id"
393int LogBuffer::setSize(log_id_t id, unsigned long size) {
394    // Reasonable limits ...
395    if (!valid_size(size)) {
396        return -1;
397    }
398    pthread_mutex_lock(&mLogElementsLock);
399    log_buffer_size(id) = size;
400    pthread_mutex_unlock(&mLogElementsLock);
401    return 0;
402}
403
404// get the total space allocated to "id"
405unsigned long LogBuffer::getSize(log_id_t id) {
406    pthread_mutex_lock(&mLogElementsLock);
407    size_t retval = log_buffer_size(id);
408    pthread_mutex_unlock(&mLogElementsLock);
409    return retval;
410}
411
412log_time LogBuffer::flushTo(
413        SocketClient *reader, const log_time start, bool privileged,
414        bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
415    LogBufferElementCollection::iterator it;
416    log_time max = start;
417    uid_t uid = reader->getUid();
418
419    pthread_mutex_lock(&mLogElementsLock);
420    for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
421        LogBufferElement *element = *it;
422
423        if (!privileged && (element->getUid() != uid)) {
424            continue;
425        }
426
427        if (element->getMonotonicTime() <= start) {
428            continue;
429        }
430
431        // NB: calling out to another object with mLogElementsLock held (safe)
432        if (filter && !(*filter)(element, arg)) {
433            continue;
434        }
435
436        pthread_mutex_unlock(&mLogElementsLock);
437
438        // range locking in LastLogTimes looks after us
439        max = element->flushTo(reader);
440
441        if (max == element->FLUSH_ERROR) {
442            return max;
443        }
444
445        pthread_mutex_lock(&mLogElementsLock);
446    }
447    pthread_mutex_unlock(&mLogElementsLock);
448
449    return max;
450}
451
452void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
453    log_time oldest(CLOCK_MONOTONIC);
454
455    pthread_mutex_lock(&mLogElementsLock);
456
457    // Find oldest element in the log(s)
458    LogBufferElementCollection::iterator it;
459    for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
460        LogBufferElement *element = *it;
461
462        if ((logMask & (1 << element->getLogId()))) {
463            oldest = element->getMonotonicTime();
464            break;
465        }
466    }
467
468    stats.format(strp, uid, logMask, oldest);
469
470    pthread_mutex_unlock(&mLogElementsLock);
471}
472