/* * Copyright (C) 2017 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ // Non-blocking event logger intended for safe communication between processes via shared memory #ifndef ANDROID_MEDIA_NBLOG_H #define ANDROID_MEDIA_NBLOG_H #include <deque> #include <map> #include <set> #include <vector> #include <audio_utils/fifo.h> #include <binder/IMemory.h> #include <media/nblog/PerformanceAnalysis.h> #include <media/nblog/ReportPerformance.h> #include <utils/Mutex.h> #include <utils/threads.h> namespace android { class String8; class NBLog { public: using log_hash_t = ReportPerformance::log_hash_t; // FIXME Everything needed for client (writer API and registration) should be isolated // from the rest of the implementation. class Writer; class Reader; enum Event : uint8_t { EVENT_RESERVED, EVENT_STRING, // ASCII string, not NUL-terminated // TODO: make timestamp optional EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC) EVENT_INTEGER, // integer value entry EVENT_FLOAT, // floating point value entry EVENT_PID, // process ID and process name EVENT_AUTHOR, // author index (present in merged logs) tracks entry's // original log EVENT_START_FMT, // logFormat start event: entry includes format string, // following entries contain format arguments EVENT_HASH, // unique HASH of log origin, originates from hash of file name // and line number EVENT_HISTOGRAM_ENTRY_TS, // single datum for timestamp histogram EVENT_AUDIO_STATE, // audio on/off event: logged on FastMixer::onStateChange call EVENT_END_FMT, // end of logFormat argument list EVENT_UPPER_BOUND, // to check for invalid events }; private: // --------------------------------------------------------------------------- // API for handling format entry operations // a formatted entry has the following structure: // * START_FMT entry, containing the format string // * TIMESTAMP entry // * HASH entry // * author entry of the thread that generated it (optional, present in merged log) // * format arg1 // * format arg2 // * ... // * END_FMT entry // entry representation in memory struct entry { const uint8_t type; const uint8_t length; const uint8_t data[0]; }; // entry tail representation (after data) struct ending { uint8_t length; uint8_t next[0]; }; // entry iterator class EntryIterator { public: EntryIterator(); explicit EntryIterator(const uint8_t *entry); EntryIterator(const EntryIterator &other); // dereference underlying entry const entry& operator*() const; const entry* operator->() const; // advance to next entry EntryIterator& operator++(); // ++i // back to previous entry EntryIterator& operator--(); // --i EntryIterator next() const; EntryIterator prev() const; bool operator!=(const EntryIterator &other) const; int operator-(const EntryIterator &other) const; bool hasConsistentLength() const; void copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const; void copyData(uint8_t *dst) const; template<typename T> inline const T& payload() { return *reinterpret_cast<const T *>(ptr + offsetof(entry, data)); } inline operator const uint8_t*() const { return ptr; } private: const uint8_t *ptr; }; class AbstractEntry { public: // Entry starting in the given pointer explicit AbstractEntry(const uint8_t *entry); virtual ~AbstractEntry() {} // build concrete entry of appropriate class from pointer static std::unique_ptr<AbstractEntry> buildEntry(const uint8_t *ptr); // get format entry timestamp virtual int64_t timestamp() const = 0; // get format entry's unique id virtual log_hash_t hash() const = 0; // entry's author index (-1 if none present) // a Merger has a vector of Readers, author simply points to the index of the // Reader that originated the entry // TODO consider changing to uint32_t virtual int author() const = 0; // copy entry, adding author before timestamp, returns iterator to end of entry virtual EntryIterator copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const = 0; protected: // copies ordinary entry from src to dst, and returns length of entry // size_t copyEntry(audio_utils_fifo_writer *dst, const iterator &it); const uint8_t *mEntry; }; class FormatEntry : public AbstractEntry { public: // explicit FormatEntry(const EntryIterator &it); explicit FormatEntry(const uint8_t *ptr) : AbstractEntry(ptr) {} virtual ~FormatEntry() {} EntryIterator begin() const; // Entry's format string const char* formatString() const; // Enrty's format string length size_t formatStringLength() const; // Format arguments (excluding format string, timestamp and author) EntryIterator args() const; // get format entry timestamp virtual int64_t timestamp() const override; // get format entry's unique id virtual log_hash_t hash() const override; // entry's author index (-1 if none present) // a Merger has a vector of Readers, author simply points to the index of the // Reader that originated the entry virtual int author() const override; // copy entry, adding author before timestamp, returns size of original entry virtual EntryIterator copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const override; }; class HistogramEntry : public AbstractEntry { public: explicit HistogramEntry(const uint8_t *ptr) : AbstractEntry(ptr) { } virtual ~HistogramEntry() {} virtual int64_t timestamp() const override; virtual log_hash_t hash() const override; virtual int author() const override; virtual EntryIterator copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const override; }; // --------------------------------------------------------------------------- // representation of a single log entry in private memory struct Entry { Entry(Event event, const void *data, size_t length) : mEvent(event), mLength(length), mData(data) { } /*virtual*/ ~Entry() { } // used during writing to format Entry information as follows: // [type][length][data ... ][length] int copyEntryDataAt(size_t offset) const; private: friend class Writer; Event mEvent; // event type uint8_t mLength; // length of additional data, 0 <= mLength <= kMaxLength const void *mData; // event type-specific data static const size_t kMaxLength = 255; public: // mEvent, mLength, mData[...], duplicate mLength static const size_t kOverhead = sizeof(entry) + sizeof(ending); // endind length of previous entry static const ssize_t kPreviousLengthOffset = - sizeof(ending) + offsetof(ending, length); }; struct HistTsEntry { log_hash_t hash; int64_t ts; }; //TODO __attribute__((packed)); struct HistTsEntryWithAuthor { log_hash_t hash; int64_t ts; int author; }; //TODO __attribute__((packed)); struct HistIntEntry { log_hash_t hash; int value; }; //TODO __attribute__((packed)); // representation of a single log entry in shared memory // byte[0] mEvent // byte[1] mLength // byte[2] mData[0] // ... // byte[2+i] mData[i] // ... // byte[2+mLength-1] mData[mLength-1] // byte[2+mLength] duplicate copy of mLength to permit reverse scan // byte[3+mLength] start of next log entry static void appendInt(String8 *body, const void *data); static void appendFloat(String8 *body, const void *data); static void appendPID(String8 *body, const void *data, size_t length); static void appendTimestamp(String8 *body, const void *data); static size_t fmtEntryLength(const uint8_t *data); static String8 bufferDump(const uint8_t *buffer, size_t size); static String8 bufferDump(const EntryIterator &it); public: // Located in shared memory, must be POD. // Exactly one process must explicitly call the constructor or use placement new. // Since this is a POD, the destructor is empty and unnecessary to call it explicitly. struct Shared { Shared() /* mRear initialized via default constructor */ { } /*virtual*/ ~Shared() { } audio_utils_fifo_index mRear; // index one byte past the end of most recent Entry char mBuffer[0]; // circular buffer for entries }; public: // --------------------------------------------------------------------------- // FIXME Timeline was intended to wrap Writer and Reader, but isn't actually used yet. // For now it is just a namespace for sharedSize(). class Timeline : public RefBase { public: #if 0 Timeline(size_t size, void *shared = NULL); virtual ~Timeline(); #endif // Input parameter 'size' is the desired size of the timeline in byte units. // Returns the size rounded up to a power-of-2, plus the constant size overhead for indices. static size_t sharedSize(size_t size); #if 0 private: friend class Writer; friend class Reader; const size_t mSize; // circular buffer size in bytes, must be a power of 2 bool mOwn; // whether I own the memory at mShared Shared* const mShared; // pointer to shared memory #endif }; // --------------------------------------------------------------------------- // Writer is thread-safe with respect to Reader, but not with respect to multiple threads // calling Writer methods. If you need multi-thread safety for writing, use LockedWriter. class Writer : public RefBase { public: Writer(); // dummy nop implementation without shared memory // Input parameter 'size' is the desired size of the timeline in byte units. // The size of the shared memory must be at least Timeline::sharedSize(size). Writer(void *shared, size_t size); Writer(const sp<IMemory>& iMemory, size_t size); virtual ~Writer(); // FIXME needs comments, and some should be private virtual void log(const char *string); virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3))); virtual void logvf(const char *fmt, va_list ap); virtual void logTimestamp(); virtual void logTimestamp(const int64_t ts); virtual void logInteger(const int x); virtual void logFloat(const float x); virtual void logPID(); virtual void logFormat(const char *fmt, log_hash_t hash, ...); virtual void logVFormat(const char *fmt, log_hash_t hash, va_list ap); virtual void logStart(const char *fmt); virtual void logEnd(); virtual void logHash(log_hash_t hash); virtual void logEventHistTs(Event event, log_hash_t hash); virtual bool isEnabled() const; // return value for all of these is the previous isEnabled() virtual bool setEnabled(bool enabled); // but won't enable if no shared memory bool enable() { return setEnabled(true); } bool disable() { return setEnabled(false); } sp<IMemory> getIMemory() const { return mIMemory; } private: // 0 <= length <= kMaxLength // writes a single Entry to the FIFO void log(Event event, const void *data, size_t length); // checks validity of an event before calling log above this one void log(const Entry *entry, bool trusted = false); Shared* const mShared; // raw pointer to shared memory sp<IMemory> mIMemory; // ref-counted version, initialized in constructor // and then const audio_utils_fifo * const mFifo; // FIFO itself, non-NULL // unless constructor fails audio_utils_fifo_writer * const mFifoWriter; // used to write to FIFO, non-NULL // unless dummy constructor used bool mEnabled; // whether to actually log // cached pid and process name to use in %p format specifier // total tag length is mPidTagSize and process name is not zero terminated char *mPidTag; size_t mPidTagSize; }; // --------------------------------------------------------------------------- // Similar to Writer, but safe for multiple threads to call concurrently class LockedWriter : public Writer { public: LockedWriter(); LockedWriter(void *shared, size_t size); virtual void log(const char *string); virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3))); virtual void logvf(const char *fmt, va_list ap); virtual void logTimestamp(); virtual void logTimestamp(const int64_t ts); virtual void logInteger(const int x); virtual void logFloat(const float x); virtual void logPID(); virtual void logStart(const char *fmt); virtual void logEnd(); virtual void logHash(log_hash_t hash); virtual bool isEnabled() const; virtual bool setEnabled(bool enabled); private: mutable Mutex mLock; }; // --------------------------------------------------------------------------- class Reader : public RefBase { public: // A snapshot of a readers buffer // This is raw data. No analysis has been done on it class Snapshot { public: Snapshot() : mData(NULL), mLost(0) {} Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {} ~Snapshot() { delete[] mData; } // copy of the buffer uint8_t *data() const { return mData; } // amount of data lost (given by audio_utils_fifo_reader) size_t lost() const { return mLost; } // iterator to beginning of readable segment of snapshot // data between begin and end has valid entries EntryIterator begin() { return mBegin; } // iterator to end of readable segment of snapshot EntryIterator end() { return mEnd; } private: friend class MergeReader; friend class Reader; uint8_t *mData; size_t mLost; EntryIterator mBegin; EntryIterator mEnd; }; // Input parameter 'size' is the desired size of the timeline in byte units. // The size of the shared memory must be at least Timeline::sharedSize(size). Reader(const void *shared, size_t size); Reader(const sp<IMemory>& iMemory, size_t size); virtual ~Reader(); // get snapshot of readers fifo buffer, effectively consuming the buffer std::unique_ptr<Snapshot> getSnapshot(); bool isIMemory(const sp<IMemory>& iMemory) const; protected: // print a summary of the performance to the console void dumpLine(const String8& timestamp, String8& body); EntryIterator handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body); int mFd; // file descriptor int mIndent; // indentation level int mLost; // bytes of data lost before buffer was read private: static const std::set<Event> startingTypes; static const std::set<Event> endingTypes; // declared as const because audio_utils_fifo() constructor sp<IMemory> mIMemory; // ref-counted version, assigned only in constructor /*const*/ Shared* const mShared; // raw pointer to shared memory, actually const but not audio_utils_fifo * const mFifo; // FIFO itself, // non-NULL unless constructor fails audio_utils_fifo_reader * const mFifoReader; // used to read from FIFO, // non-NULL unless constructor fails // Searches for the last entry of type <type> in the range [front, back) // back has to be entry-aligned. Returns nullptr if none enconuntered. static const uint8_t *findLastEntryOfTypes(const uint8_t *front, const uint8_t *back, const std::set<Event> &types); // dummy method for handling absent author entry virtual void handleAuthor(const AbstractEntry& /*fmtEntry*/, String8* /*body*/) {} }; // Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name class NamedReader { public: NamedReader() { mName[0] = '\0'; } // for Vector NamedReader(const sp<NBLog::Reader>& reader, const char *name) : mReader(reader) { strlcpy(mName, name, sizeof(mName)); } ~NamedReader() { } const sp<NBLog::Reader>& reader() const { return mReader; } const char* name() const { return mName; } private: sp<NBLog::Reader> mReader; static const size_t kMaxName = 32; char mName[kMaxName]; }; // --------------------------------------------------------------------------- // This class is used to read data from each thread's individual FIFO in shared memory // and write it to a single FIFO in local memory. class Merger : public RefBase { public: Merger(const void *shared, size_t size); virtual ~Merger() {} void addReader(const NamedReader &reader); // TODO add removeReader void merge(); // FIXME This is returning a reference to a shared variable that needs a lock const std::vector<NamedReader>& getNamedReaders() const; private: // vector of the readers the merger is supposed to merge from. // every reader reads from a writer's buffer // FIXME Needs to be protected by a lock std::vector<NamedReader> mNamedReaders; Shared * const mShared; // raw pointer to shared memory std::unique_ptr<audio_utils_fifo> mFifo; // FIFO itself std::unique_ptr<audio_utils_fifo_writer> mFifoWriter; // used to write to FIFO }; // This class has a pointer to the FIFO in local memory which stores the merged // data collected by NBLog::Merger from all NamedReaders. It is used to process // this data and write the result to PerformanceAnalysis. class MergeReader : public Reader { public: MergeReader(const void *shared, size_t size, Merger &merger); void dump(int fd, int indent = 0); // process a particular snapshot of the reader void getAndProcessSnapshot(Snapshot & snap); // call getSnapshot of the content of the reader's buffer and process the data void getAndProcessSnapshot(); private: // FIXME Needs to be protected by a lock, // because even though our use of it is read-only there may be asynchronous updates const std::vector<NamedReader>& mNamedReaders; // analyzes, compresses and stores the merged data // contains a separate instance for every author (thread), and for every source file // location within each author ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis; // handle author entry by looking up the author's name and appending it to the body // returns number of bytes read from fmtEntry void handleAuthor(const AbstractEntry &fmtEntry, String8 *body); }; // MergeThread is a thread that contains a Merger. It works as a retriggerable one-shot: // when triggered, it awakes for a lapse of time, during which it periodically merges; if // retriggered, the timeout is reset. // The thread is triggered on AudioFlinger binder activity. class MergeThread : public Thread { public: MergeThread(Merger &merger, MergeReader &mergeReader); virtual ~MergeThread() override; // Reset timeout and activate thread to merge periodically if it's idle void wakeup(); // Set timeout period until the merging thread goes idle again void setTimeoutUs(int time); private: virtual bool threadLoop() override; // the merger who actually does the work of merging the logs Merger& mMerger; // the mergereader used to process data merged by mMerger MergeReader& mMergeReader; // mutex for the condition variable Mutex mMutex; // condition variable to activate merging on timeout >= 0 Condition mCond; // time left until the thread blocks again (in microseconds) int mTimeoutUs; // merging period when the thread is awake static const int kThreadSleepPeriodUs = 1000000 /*1s*/; // initial timeout value when triggered static const int kThreadWakeupPeriodUs = 3000000 /*3s*/; }; }; // class NBLog // TODO put somewhere else static inline int64_t get_monotonic_ns() { timespec ts; if (clock_gettime(CLOCK_MONOTONIC, &ts) == 0) { return (uint64_t) ts.tv_sec * 1000 * 1000 * 1000 + ts.tv_nsec; } return 0; // should not happen. } } // namespace android #endif // ANDROID_MEDIA_NBLOG_H