1/*
2 * Copyright (C) 2013 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#define LOG_TAG "NBLog"
18//#define LOG_NDEBUG 0
19
20#include <stdarg.h>
21#include <stdint.h>
22#include <stdio.h>
23#include <string.h>
24#include <time.h>
25#include <new>
26#include <cutils/atomic.h>
27#include <media/nbaio/NBLog.h>
28#include <utils/Log.h>
29
30namespace android {
31
32int NBLog::Entry::readAt(size_t offset) const
33{
34    // FIXME This is too slow, despite the name it is used during writing
35    if (offset == 0)
36        return mEvent;
37    else if (offset == 1)
38        return mLength;
39    else if (offset < (size_t) (mLength + 2))
40        return ((char *) mData)[offset - 2];
41    else if (offset == (size_t) (mLength + 2))
42        return mLength;
43    else
44        return 0;
45}
46
47// ---------------------------------------------------------------------------
48
49#if 0   // FIXME see note in NBLog.h
50NBLog::Timeline::Timeline(size_t size, void *shared)
51    : mSize(roundup(size)), mOwn(shared == NULL),
52      mShared((Shared *) (mOwn ? new char[sharedSize(size)] : shared))
53{
54    new (mShared) Shared;
55}
56
57NBLog::Timeline::~Timeline()
58{
59    mShared->~Shared();
60    if (mOwn) {
61        delete[] (char *) mShared;
62    }
63}
64#endif
65
66/*static*/
67size_t NBLog::Timeline::sharedSize(size_t size)
68{
69    return sizeof(Shared) + roundup(size);
70}
71
72// ---------------------------------------------------------------------------
73
74NBLog::Writer::Writer()
75    : mSize(0), mShared(NULL), mRear(0), mEnabled(false)
76{
77}
78
79NBLog::Writer::Writer(size_t size, void *shared)
80    : mSize(roundup(size)), mShared((Shared *) shared), mRear(0), mEnabled(mShared != NULL)
81{
82}
83
84NBLog::Writer::Writer(size_t size, const sp<IMemory>& iMemory)
85    : mSize(roundup(size)), mShared(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL),
86      mIMemory(iMemory), mRear(0), mEnabled(mShared != NULL)
87{
88}
89
90void NBLog::Writer::log(const char *string)
91{
92    if (!mEnabled) {
93        return;
94    }
95    size_t length = strlen(string);
96    if (length > 255) {
97        length = 255;
98    }
99    log(EVENT_STRING, string, length);
100}
101
102void NBLog::Writer::logf(const char *fmt, ...)
103{
104    if (!mEnabled) {
105        return;
106    }
107    va_list ap;
108    va_start(ap, fmt);
109    Writer::logvf(fmt, ap);     // the Writer:: is needed to avoid virtual dispatch for LockedWriter
110    va_end(ap);
111}
112
113void NBLog::Writer::logvf(const char *fmt, va_list ap)
114{
115    if (!mEnabled) {
116        return;
117    }
118    char buffer[256];
119    int length = vsnprintf(buffer, sizeof(buffer), fmt, ap);
120    if (length >= (int) sizeof(buffer)) {
121        length = sizeof(buffer) - 1;
122        // NUL termination is not required
123        // buffer[length] = '\0';
124    }
125    if (length >= 0) {
126        log(EVENT_STRING, buffer, length);
127    }
128}
129
130void NBLog::Writer::logTimestamp()
131{
132    if (!mEnabled) {
133        return;
134    }
135    struct timespec ts;
136    if (!clock_gettime(CLOCK_MONOTONIC, &ts)) {
137        log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec));
138    }
139}
140
141void NBLog::Writer::logTimestamp(const struct timespec& ts)
142{
143    if (!mEnabled) {
144        return;
145    }
146    log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec));
147}
148
149void NBLog::Writer::log(Event event, const void *data, size_t length)
150{
151    if (!mEnabled) {
152        return;
153    }
154    if (data == NULL || length > 255) {
155        return;
156    }
157    switch (event) {
158    case EVENT_STRING:
159    case EVENT_TIMESTAMP:
160        break;
161    case EVENT_RESERVED:
162    default:
163        return;
164    }
165    Entry entry(event, data, length);
166    log(&entry, true /*trusted*/);
167}
168
169void NBLog::Writer::log(const NBLog::Entry *entry, bool trusted)
170{
171    if (!mEnabled) {
172        return;
173    }
174    if (!trusted) {
175        log(entry->mEvent, entry->mData, entry->mLength);
176        return;
177    }
178    size_t rear = mRear & (mSize - 1);
179    size_t written = mSize - rear;      // written = number of bytes that have been written so far
180    size_t need = entry->mLength + 3;   // mEvent, mLength, data[length], mLength
181                                        // need = number of bytes remaining to write
182    if (written > need) {
183        written = need;
184    }
185    size_t i;
186    // FIXME optimize this using memcpy for the data part of the Entry.
187    // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy.
188    for (i = 0; i < written; ++i) {
189        mShared->mBuffer[rear + i] = entry->readAt(i);
190    }
191    if (rear + written == mSize && (need -= written) > 0)  {
192        for (i = 0; i < need; ++i) {
193            mShared->mBuffer[i] = entry->readAt(written + i);
194        }
195        written += need;
196    }
197    android_atomic_release_store(mRear += written, &mShared->mRear);
198}
199
200bool NBLog::Writer::isEnabled() const
201{
202    return mEnabled;
203}
204
205bool NBLog::Writer::setEnabled(bool enabled)
206{
207    bool old = mEnabled;
208    mEnabled = enabled && mShared != NULL;
209    return old;
210}
211
212// ---------------------------------------------------------------------------
213
214NBLog::LockedWriter::LockedWriter()
215    : Writer()
216{
217}
218
219NBLog::LockedWriter::LockedWriter(size_t size, void *shared)
220    : Writer(size, shared)
221{
222}
223
224void NBLog::LockedWriter::log(const char *string)
225{
226    Mutex::Autolock _l(mLock);
227    Writer::log(string);
228}
229
230void NBLog::LockedWriter::logf(const char *fmt, ...)
231{
232    // FIXME should not take the lock until after formatting is done
233    Mutex::Autolock _l(mLock);
234    va_list ap;
235    va_start(ap, fmt);
236    Writer::logvf(fmt, ap);
237    va_end(ap);
238}
239
240void NBLog::LockedWriter::logvf(const char *fmt, va_list ap)
241{
242    // FIXME should not take the lock until after formatting is done
243    Mutex::Autolock _l(mLock);
244    Writer::logvf(fmt, ap);
245}
246
247void NBLog::LockedWriter::logTimestamp()
248{
249    // FIXME should not take the lock until after the clock_gettime() syscall
250    Mutex::Autolock _l(mLock);
251    Writer::logTimestamp();
252}
253
254void NBLog::LockedWriter::logTimestamp(const struct timespec& ts)
255{
256    Mutex::Autolock _l(mLock);
257    Writer::logTimestamp(ts);
258}
259
260bool NBLog::LockedWriter::isEnabled() const
261{
262    Mutex::Autolock _l(mLock);
263    return Writer::isEnabled();
264}
265
266bool NBLog::LockedWriter::setEnabled(bool enabled)
267{
268    Mutex::Autolock _l(mLock);
269    return Writer::setEnabled(enabled);
270}
271
272// ---------------------------------------------------------------------------
273
274NBLog::Reader::Reader(size_t size, const void *shared)
275    : mSize(roundup(size)), mShared((const Shared *) shared), mFront(0)
276{
277}
278
279NBLog::Reader::Reader(size_t size, const sp<IMemory>& iMemory)
280    : mSize(roundup(size)), mShared(iMemory != 0 ? (const Shared *) iMemory->pointer() : NULL),
281      mIMemory(iMemory), mFront(0)
282{
283}
284
285void NBLog::Reader::dump(int fd, size_t indent)
286{
287    int32_t rear = android_atomic_acquire_load(&mShared->mRear);
288    size_t avail = rear - mFront;
289    if (avail == 0) {
290        return;
291    }
292    size_t lost = 0;
293    if (avail > mSize) {
294        lost = avail - mSize;
295        mFront += lost;
296        avail = mSize;
297    }
298    size_t remaining = avail;       // remaining = number of bytes left to read
299    size_t front = mFront & (mSize - 1);
300    size_t read = mSize - front;    // read = number of bytes that have been read so far
301    if (read > remaining) {
302        read = remaining;
303    }
304    // make a copy to avoid race condition with writer
305    uint8_t *copy = new uint8_t[avail];
306    // copy first part of circular buffer up until the wraparound point
307    memcpy(copy, &mShared->mBuffer[front], read);
308    if (front + read == mSize) {
309        if ((remaining -= read) > 0) {
310            // copy second part of circular buffer starting at beginning
311            memcpy(&copy[read], mShared->mBuffer, remaining);
312            read += remaining;
313            // remaining = 0 but not necessary
314        }
315    }
316    mFront += read;
317    size_t i = avail;
318    Event event;
319    size_t length;
320    struct timespec ts;
321    time_t maxSec = -1;
322    while (i >= 3) {
323        length = copy[i - 1];
324        if (length + 3 > i || copy[i - length - 2] != length) {
325            break;
326        }
327        event = (Event) copy[i - length - 3];
328        if (event == EVENT_TIMESTAMP) {
329            if (length != sizeof(struct timespec)) {
330                // corrupt
331                break;
332            }
333            memcpy(&ts, &copy[i - length - 1], sizeof(struct timespec));
334            if (ts.tv_sec > maxSec) {
335                maxSec = ts.tv_sec;
336            }
337        }
338        i -= length + 3;
339    }
340    if (i > 0) {
341        lost += i;
342        if (fd >= 0) {
343            fdprintf(fd, "%*swarning: lost %u bytes worth of events\n", indent, "", lost);
344        } else {
345            ALOGI("%*swarning: lost %u bytes worth of events\n", indent, "", lost);
346        }
347    }
348    size_t width = 1;
349    while (maxSec >= 10) {
350        ++width;
351        maxSec /= 10;
352    }
353    char prefix[32];
354    if (maxSec >= 0) {
355        snprintf(prefix, sizeof(prefix), "[%*s] ", width + 4, "");
356    } else {
357        prefix[0] = '\0';
358    }
359    while (i < avail) {
360        event = (Event) copy[i];
361        length = copy[i + 1];
362        const void *data = &copy[i + 2];
363        size_t advance = length + 3;
364        switch (event) {
365        case EVENT_STRING:
366            if (fd >= 0) {
367                fdprintf(fd, "%*s%s%.*s\n", indent, "", prefix, length, (const char *) data);
368            } else {
369                ALOGI("%*s%s%.*s", indent, "", prefix, length, (const char *) data);
370            } break;
371        case EVENT_TIMESTAMP: {
372            // already checked that length == sizeof(struct timespec);
373            memcpy(&ts, data, sizeof(struct timespec));
374            long prevNsec = ts.tv_nsec;
375            long deltaMin = LONG_MAX;
376            long deltaMax = -1;
377            long deltaTotal = 0;
378            size_t j = i;
379            for (;;) {
380                j += sizeof(struct timespec) + 3;
381                if (j >= avail || (Event) copy[j] != EVENT_TIMESTAMP) {
382                    break;
383                }
384                struct timespec tsNext;
385                memcpy(&tsNext, &copy[j + 2], sizeof(struct timespec));
386                if (tsNext.tv_sec != ts.tv_sec) {
387                    break;
388                }
389                long delta = tsNext.tv_nsec - prevNsec;
390                if (delta < 0) {
391                    break;
392                }
393                if (delta < deltaMin) {
394                    deltaMin = delta;
395                }
396                if (delta > deltaMax) {
397                    deltaMax = delta;
398                }
399                deltaTotal += delta;
400                prevNsec = tsNext.tv_nsec;
401            }
402            size_t n = (j - i) / (sizeof(struct timespec) + 3);
403            if (n >= kSquashTimestamp) {
404                if (fd >= 0) {
405                    fdprintf(fd, "%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "",
406                            (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000),
407                            (int) ((ts.tv_nsec + deltaTotal) / 1000000),
408                            (int) (deltaMin / 1000000), (int) (deltaMax / 1000000));
409                } else {
410                    ALOGI("%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "",
411                            (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000),
412                            (int) ((ts.tv_nsec + deltaTotal) / 1000000),
413                            (int) (deltaMin / 1000000), (int) (deltaMax / 1000000));
414                }
415                i = j;
416                advance = 0;
417                break;
418            }
419            if (fd >= 0) {
420                fdprintf(fd, "%*s[%d.%03d]\n", indent, "", (int) ts.tv_sec,
421                        (int) (ts.tv_nsec / 1000000));
422            } else {
423                ALOGI("%*s[%d.%03d]", indent, "", (int) ts.tv_sec,
424                        (int) (ts.tv_nsec / 1000000));
425            }
426            } break;
427        case EVENT_RESERVED:
428        default:
429            if (fd >= 0) {
430                fdprintf(fd, "%*s%swarning: unknown event %d\n", indent, "", prefix, event);
431            } else {
432                ALOGI("%*s%swarning: unknown event %d", indent, "", prefix, event);
433            }
434            break;
435        }
436        i += advance;
437    }
438    // FIXME it would be more efficient to put a char mCopy[256] as a member variable of the dumper
439    delete[] copy;
440}
441
442bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const
443{
444    return iMemory.get() == mIMemory.get();
445}
446
447}   // namespace android
448