From 444f2675728dde36378beb8e67a94f86ebf1ca46 Mon Sep 17 00:00:00 2001 From: Aravind Akella Date: Thu, 7 May 2015 12:40:52 -0700 Subject: [PATCH] Improve logging in SensorService dump output. Maintain a per sensor circular buffer of last 10 sensor_events and the wall clock time at which each event is received. Change-Id: Ia50c825ab5a7aaf0932ce7dce7ac8b9be7071e77 --- services/sensorservice/SensorDevice.cpp | 2 +- services/sensorservice/SensorService.cpp | 373 ++++++++++++++--------- services/sensorservice/SensorService.h | 51 +++- 3 files changed, 283 insertions(+), 143 deletions(-) diff --git a/services/sensorservice/SensorDevice.cpp b/services/sensorservice/SensorDevice.cpp index 3bcbd5834..7c829f495 100644 --- a/services/sensorservice/SensorDevice.cpp +++ b/services/sensorservice/SensorDevice.cpp @@ -79,7 +79,7 @@ void SensorDevice::dump(String8& result) sensor_t const* list; ssize_t count = mSensorModule->get_sensors_list(mSensorModule, &list); - result.appendFormat("halVersion %d\n", getHalDeviceVersion()); + result.appendFormat("halVersion 0x%08x\n", getHalDeviceVersion()); result.appendFormat("%d h/w sensors:\n", int(count)); Mutex::Autolock _l(mLock); diff --git a/services/sensorservice/SensorService.cpp b/services/sensorservice/SensorService.cpp index c8dc6eccf..3d985dceb 100644 --- a/services/sensorservice/SensorService.cpp +++ b/services/sensorservice/SensorService.cpp @@ -213,7 +213,7 @@ Sensor SensorService::registerSensor(SensorInterface* s) // add to our handle->SensorInterface mapping mSensorMap.add(sensor.getHandle(), s); // create an entry in the mLastEventSeen array - mLastEventSeen.add(sensor.getHandle(), event); + mLastEventSeen.add(sensor.getHandle(), NULL); return sensor; } @@ -239,13 +239,21 @@ status_t SensorService::dump(int fd, const Vector& args) "can't dump SensorService from pid=%d, uid=%d\n", IPCThreadState::self()->getCallingPid(), IPCThreadState::self()->getCallingUid()); - } else if (args.size() > 0) { + } else { if (args.size() > 1) { return INVALID_OPERATION; } Mutex::Autolock _l(mLock); SensorDevice& dev(SensorDevice::getInstance()); - if (args[0] == String16("restrict") && mCurrentOperatingMode == NORMAL) { + if (args.size() == 1 && args[0] == String16("restrict")) { + // If already in restricted mode. Ignore. + if (mCurrentOperatingMode == RESTRICTED) { + return status_t(NO_ERROR); + } + // If in any mode other than normal, ignore. + if (mCurrentOperatingMode != NORMAL) { + return INVALID_OPERATION; + } mCurrentOperatingMode = RESTRICTED; dev.disableAllSensors(); // Clear all pending flush connections for all active sensors. If one of the active @@ -254,132 +262,107 @@ status_t SensorService::dump(int fd, const Vector& args) for (size_t i=0 ; i< mActiveSensors.size(); ++i) { mActiveSensors.valueAt(i)->clearAllPendingFlushConnections(); } - } else if (args[0] == String16("enable") && mCurrentOperatingMode == RESTRICTED) { - mCurrentOperatingMode = NORMAL; - dev.enableAllSensors(); - } - return status_t(NO_ERROR); - } else { - Mutex::Autolock _l(mLock); - result.append("Sensor List:\n"); - for (size_t i=0 ; i 0) { + result.appendFormat("minRate=%.2fHz | ", 1e6f / s.getMaxDelay()); + } else { + result.appendFormat("maxDelay=%dus |", s.getMaxDelay()); + } + + if (s.getMinDelay() > 0) { + result.appendFormat("maxRate=%.2fHz | ", 1e6f / s.getMinDelay()); + } else { + result.appendFormat("minDelay=%dus |", s.getMinDelay()); + } + + if (s.getFifoMaxEventCount() > 0) { + result.appendFormat("FifoMax=%d events | ", + s.getFifoMaxEventCount()); + } else { + result.append("no batching | "); + } + + if (s.isWakeUpSensor()) { + result.appendFormat("wakeUp | "); + } else { + result.appendFormat("non-wakeUp | "); + } + + const CircularBuffer* buf = mLastEventSeen.valueFor(s.getHandle()); + if (buf != NULL && s.getRequiredPermission().isEmpty()) { + buf->printBuffer(result); + } else { + result.append("last=<> \n"); + } + result.append("\n"); + } + SensorFusion::getInstance().dump(result); + SensorDevice::getInstance().dump(result); + + result.append("Active sensors:\n"); + for (size_t i=0 ; igetNumConnections()); } - if (s.getMaxDelay() > 0) { - result.appendFormat("minRate=%.2fHz | ", 1e6f / s.getMaxDelay()); - } else { - result.appendFormat("maxDelay=%dus |", s.getMaxDelay()); + result.appendFormat("Socket Buffer size = %d events\n", + mSocketBufferSize/sizeof(sensors_event_t)); + result.appendFormat("WakeLock Status: %s \n", mWakeLockAcquired ? "acquired" : "not held"); + result.appendFormat("Mode :"); + switch(mCurrentOperatingMode) { + case NORMAL: + result.appendFormat(" NORMAL\n"); + break; + case RESTRICTED: + result.appendFormat(" RESTRICTED\n"); + break; + case DATA_INJECTION: + result.appendFormat(" DATA_INJECTION\n"); } + result.appendFormat("%zd active connections\n", mActiveConnections.size()); - if (s.getMinDelay() > 0) { - result.appendFormat("maxRate=%.2fHz | ", 1e6f / s.getMinDelay()); - } else { - result.appendFormat("minDelay=%dus |", s.getMinDelay()); - } - - if (s.getFifoMaxEventCount() > 0) { - result.appendFormat("FifoMax=%d events | ", - s.getFifoMaxEventCount()); - } else { - result.append("no batching | "); - } - - if (s.isWakeUpSensor()) { - result.appendFormat("wakeUp | "); - } else { - result.appendFormat("non-wakeUp | "); - } - - switch (s.getType()) { - case SENSOR_TYPE_ROTATION_VECTOR: - case SENSOR_TYPE_GEOMAGNETIC_ROTATION_VECTOR: - result.appendFormat( - "last=<%5.1f,%5.1f,%5.1f,%5.1f,%5.1f, %" PRId64 ">\n", - e.data[0], e.data[1], e.data[2], e.data[3], e.data[4], e.timestamp); - break; - case SENSOR_TYPE_MAGNETIC_FIELD_UNCALIBRATED: - case SENSOR_TYPE_GYROSCOPE_UNCALIBRATED: - result.appendFormat( - "last=<%5.1f,%5.1f,%5.1f,%5.1f,%5.1f,%5.1f, %" PRId64 ">\n", - e.data[0], e.data[1], e.data[2], e.data[3], e.data[4], e.data[5], - e.timestamp); - break; - case SENSOR_TYPE_GAME_ROTATION_VECTOR: - result.appendFormat( - "last=<%5.1f,%5.1f,%5.1f,%5.1f, %" PRId64 ">\n", - e.data[0], e.data[1], e.data[2], e.data[3], e.timestamp); - break; - case SENSOR_TYPE_SIGNIFICANT_MOTION: - case SENSOR_TYPE_STEP_DETECTOR: - result.appendFormat( "last=<%f %" PRId64 ">\n", e.data[0], e.timestamp); - break; - case SENSOR_TYPE_STEP_COUNTER: - result.appendFormat( "last=<%" PRIu64 ", %" PRId64 ">\n", e.u64.step_counter, - e.timestamp); - break; - default: - // default to 3 values - result.appendFormat( - "last=<%5.1f,%5.1f,%5.1f, %" PRId64 ">\n", - e.data[0], e.data[1], e.data[2], e.timestamp); - break; - } - result.append("\n"); - } - SensorFusion::getInstance().dump(result); - SensorDevice::getInstance().dump(result); - - result.append("Active sensors:\n"); - for (size_t i=0 ; igetNumConnections()); - } - - result.appendFormat("Socket Buffer size = %d events\n", - mSocketBufferSize/sizeof(sensors_event_t)); - result.appendFormat("WakeLock Status: %s \n", mWakeLockAcquired ? "acquired" : "not held"); - result.appendFormat("Mode :"); - switch(mCurrentOperatingMode) { - case NORMAL: - result.appendFormat(" NORMAL\n"); - break; - case RESTRICTED: - result.appendFormat(" RESTRICTED\n"); - break; - case DATA_INJECTION: - result.appendFormat(" DATA_INJECTION\n"); - } - result.appendFormat("%zd active connections\n", mActiveConnections.size()); - - for (size_t i=0 ; i < mActiveConnections.size() ; i++) { - sp connection(mActiveConnections[i].promote()); - if (connection != 0) { - result.appendFormat("Connection Number: %zu \n", i); - connection->dump(result); + for (size_t i=0 ; i < mActiveConnections.size() ; i++) { + sp connection(mActiveConnections[i].promote()); + if (connection != 0) { + result.appendFormat("Connection Number: %zu \n", i); + connection->dump(result); + } } } } @@ -609,19 +592,15 @@ bool SensorService::SensorEventAckReceiver::threadLoop() { void SensorService::recordLastValueLocked( const sensors_event_t* buffer, size_t count) { - const sensors_event_t* last = NULL; for (size_t i = 0; i < count; i++) { - const sensors_event_t* event = &buffer[i]; - if (event->type != SENSOR_TYPE_META_DATA) { - if (last && event->sensor != last->sensor) { - mLastEventSeen.editValueFor(last->sensor) = *last; + if (buffer[i].type != SENSOR_TYPE_META_DATA) { + CircularBuffer* &circular_buf = mLastEventSeen.editValueFor(buffer[i].sensor); + if (circular_buf == NULL) { + circular_buf = new CircularBuffer(buffer[i].type); } - last = event; + circular_buf->addEvent(buffer[i]); } } - if (last) { - mLastEventSeen.editValueFor(last->sensor) = *last; - } } void SensorService::sortEventBuffer(sensors_event_t* buffer, size_t count) @@ -836,14 +815,24 @@ status_t SensorService::enable(const sp& connection, if (sensor->getSensor().getReportingMode() == AREPORTING_MODE_ON_CHANGE) { // NOTE: The wake_up flag of this event may get set to // WAKE_UP_SENSOR_EVENT_NEEDS_ACK if this is a wake_up event. - sensors_event_t& event(mLastEventSeen.editValueFor(handle)); - if (event.version == sizeof(sensors_event_t)) { - if (isWakeUpSensorEvent(event) && !mWakeLockAcquired) { - setWakeLockAcquiredLocked(true); - } - connection->sendEvents(&event, 1, NULL); - if (!connection->needsWakeLock() && mWakeLockAcquired) { - checkWakeLockStateLocked(); + CircularBuffer *circular_buf = mLastEventSeen.valueFor(handle); + if (circular_buf) { + sensors_event_t event; + memset(&event, 0, sizeof(event)); + // It is unlikely that this buffer is empty as the sensor is already active. + // One possible corner case may be two applications activating an on-change + // sensor at the same time. + if(circular_buf->populateLastEvent(&event)) { + event.sensor = handle; + if (event.version == sizeof(sensors_event_t)) { + if (isWakeUpSensorEvent(event) && !mWakeLockAcquired) { + setWakeLockAcquiredLocked(true); + } + connection->sendEvents(&event, 1, NULL); + if (!connection->needsWakeLock() && mWakeLockAcquired) { + checkWakeLockStateLocked(); + } + } } } } @@ -1081,6 +1070,29 @@ bool SensorService::isWhiteListedPackage(const String8& packageName) { return (packageName.find(".cts.") != -1); } +int SensorService::getNumEventsForSensorType(int sensor_event_type) { + switch (sensor_event_type) { + case SENSOR_TYPE_ROTATION_VECTOR: + case SENSOR_TYPE_GEOMAGNETIC_ROTATION_VECTOR: + return 5; + + case SENSOR_TYPE_MAGNETIC_FIELD_UNCALIBRATED: + case SENSOR_TYPE_GYROSCOPE_UNCALIBRATED: + return 6; + + case SENSOR_TYPE_GAME_ROTATION_VECTOR: + return 4; + + case SENSOR_TYPE_SIGNIFICANT_MOTION: + case SENSOR_TYPE_STEP_DETECTOR: + case SENSOR_TYPE_STEP_COUNTER: + return 1; + + default: + return 3; + } +} + // --------------------------------------------------------------------------- SensorService::SensorRecord::SensorRecord( const sp& connection) @@ -1141,6 +1153,85 @@ void SensorService::SensorRecord::clearAllPendingFlushConnections() { mPendingFlushConnections.clear(); } +// -------------------------------------------------------------------------- +SensorService::CircularBuffer::CircularBuffer(int sensor_event_type) { + mNextInd = 0; + mTrimmedSensorEventArr = new TrimmedSensorEvent *[CIRCULAR_BUF_SIZE]; + mSensorType = sensor_event_type; + const int numData = SensorService::getNumEventsForSensorType(mSensorType); + for (int i = 0; i < CIRCULAR_BUF_SIZE; ++i) { + mTrimmedSensorEventArr[i] = new TrimmedSensorEvent(numData, mSensorType); + } +} + +void SensorService::CircularBuffer::addEvent(const sensors_event_t& sensor_event) { + TrimmedSensorEvent *curr_event = mTrimmedSensorEventArr[mNextInd]; + curr_event->mTimestamp = sensor_event.timestamp; + if (mSensorType == SENSOR_TYPE_STEP_COUNTER) { + curr_event->mStepCounter = sensor_event.u64.step_counter; + } else { + memcpy(curr_event->mData, sensor_event.data, + sizeof(float) * SensorService::getNumEventsForSensorType(mSensorType)); + } + time_t rawtime = time(NULL); + struct tm * timeinfo = localtime(&rawtime); + curr_event->mHour = timeinfo->tm_hour; + curr_event->mMin = timeinfo->tm_min; + curr_event->mSec = timeinfo->tm_sec; + mNextInd = (mNextInd + 1) % CIRCULAR_BUF_SIZE; +} + +void SensorService::CircularBuffer::printBuffer(String8& result) const { + const int numData = SensorService::getNumEventsForSensorType(mSensorType); + int i = mNextInd, eventNum = 1; + result.appendFormat("last %d events = < ", CIRCULAR_BUF_SIZE); + do { + if (mTrimmedSensorEventArr[i]->mTimestamp == -1) { + // Sentinel, ignore. + i = (i + 1) % CIRCULAR_BUF_SIZE; + continue; + } + result.appendFormat("%d) ", eventNum++); + if (mSensorType == SENSOR_TYPE_STEP_COUNTER) { + result.appendFormat("%llu,", mTrimmedSensorEventArr[i]->mStepCounter); + } else { + for (int j = 0; j < numData; ++j) { + result.appendFormat("%5.1f,", mTrimmedSensorEventArr[i]->mData[j]); + } + } + result.appendFormat("%lld %02d:%02d:%02d ", mTrimmedSensorEventArr[i]->mTimestamp, + mTrimmedSensorEventArr[i]->mHour, mTrimmedSensorEventArr[i]->mMin, + mTrimmedSensorEventArr[i]->mSec); + i = (i + 1) % CIRCULAR_BUF_SIZE; + } while (i != mNextInd); + result.appendFormat(">\n"); +} + +bool SensorService::CircularBuffer::populateLastEvent(sensors_event_t *event) { + int lastEventInd = (mNextInd - 1 + CIRCULAR_BUF_SIZE) % CIRCULAR_BUF_SIZE; + // Check if the buffer is empty. + if (mTrimmedSensorEventArr[lastEventInd]->mTimestamp == -1) { + return false; + } + event->version = sizeof(sensors_event_t); + event->type = mSensorType; + event->timestamp = mTrimmedSensorEventArr[lastEventInd]->mTimestamp; + if (mSensorType == SENSOR_TYPE_STEP_COUNTER) { + event->u64.step_counter = mTrimmedSensorEventArr[lastEventInd]->mStepCounter; + } else { + memcpy(event->data, mTrimmedSensorEventArr[lastEventInd]->mData, + sizeof(float) * SensorService::getNumEventsForSensorType(mSensorType)); + } + return true; +} + +SensorService::CircularBuffer::~CircularBuffer() { + for (int i = 0; i < CIRCULAR_BUF_SIZE; ++i) { + delete mTrimmedSensorEventArr[i]; + } + delete [] mTrimmedSensorEventArr; +} + // --------------------------------------------------------------------------- SensorService::SensorEventConnection::SensorEventConnection( diff --git a/services/sensorservice/SensorService.h b/services/sensorservice/SensorService.h index 4d34471ac..8a254b953 100644 --- a/services/sensorservice/SensorService.h +++ b/services/sensorservice/SensorService.h @@ -53,6 +53,8 @@ // For older HALs which don't support batching, use a smaller socket buffer size. #define SOCKET_BUFFER_SIZE_NON_BATCHED 4 * 1024 +#define CIRCULAR_BUF_SIZE 10 + struct sensors_poll_device_t; struct sensors_module_t; @@ -257,6 +259,53 @@ class SensorService : SensorEventAckReceiver(const sp& service): mService(service) {} }; + // sensor_event_t with only the data and the timestamp. + struct TrimmedSensorEvent { + union { + float *mData; + uint64_t mStepCounter; + }; + // Timestamp from the sensor_event. + int64_t mTimestamp; + // HH:MM:SS local time at which this sensor event is read at SensorService. Useful + // for debugging. + int32_t mHour, mMin, mSec; + + TrimmedSensorEvent(int numData, int sensorType) { + mTimestamp = -1; + if (sensorType == SENSOR_TYPE_STEP_COUNTER) { + mStepCounter = 0; + } else { + mData = new float[numData]; + for (int i = 0; i < numData; ++i) { + mData[i] = -1.0; + } + } + mHour = mMin = mSec = 0; + } + + ~TrimmedSensorEvent() { + delete [] mData; + } + }; + + // A circular buffer of TrimmedSensorEvents. The size of this buffer is typically 10. The + // last N events generated from the sensor are stored in this buffer. The buffer is NOT + // cleared when the sensor unregisters and as a result one may see very old data in the + // dumpsys output but this is WAI. + class CircularBuffer { + int mNextInd; + int mSensorType; + TrimmedSensorEvent ** mTrimmedSensorEventArr; + public: + CircularBuffer(int sensor_event_type); + void addEvent(const sensors_event_t& sensor_event); + void printBuffer(String8& buffer) const; + bool populateLastEvent(sensors_event_t *event); + ~CircularBuffer(); + }; + + static int getNumEventsForSensorType(int sensor_event_type); String8 getSensorName(int handle) const; bool isVirtualSensor(int handle) const; Sensor getSensorFromHandle(int handle) const; @@ -335,7 +384,7 @@ class SensorService : Mode mCurrentOperatingMode; // The size of this vector is constant, only the items are mutable - KeyedVector mLastEventSeen; + KeyedVector mLastEventSeen; public: void cleanupConnection(SensorEventConnection* connection);