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