Add logging of various important graphics events

There are 16 events logged in the event log:
SF_APP_DEQUEUE_BEFORE
SF_APP_DEQUEUE_AFTER
SF_APP_LOCK_BEFORE
SF_APP_LOCK_AFTER
SF_APP_QUEUE

SF_REPAINT
SF_COMPOSITION_COMPLETE
SF_UNLOCK_CLIENTS
SF_SWAP_BUFFERS
SF_REPAINT_DONE

SF_FB_POST_BEFORE
SF_FB_POST_AFTER
SF_FB_DEQUEUE_BEFORE
SF_FB_DEQUEUE_AFTER
SF_FB_LOCK_BEFORE
SF_FB_LOCK_AFTER

all events log the buffer conserned and a timestamp in microseconds.

by default the logging is not enabled, to turn it on:
adb shell service call SurfaceFlinger 1006 i31 1
adb shell setprop debug.graphic_log 1

The effect is immediate in SurfaceFlinger, but applications need to be
restarted.

Change-Id: Ifc2e31f7aed072d9a7dede20ff2ce59231edbec1
This commit is contained in:
Mathias Agopian 2010-09-13 22:57:58 -07:00
parent 0e152daec3
commit 35b48d10bc
9 changed files with 233 additions and 6 deletions

View File

@ -56,6 +56,9 @@ public:
status_t setUpdateRectangle(const Rect& updateRect); status_t setUpdateRectangle(const Rect& updateRect);
status_t compositionComplete(); status_t compositionComplete();
// for debugging only
int getCurrentBufferIndex() const;
private: private:
friend class LightRefBase<FramebufferNativeWindow>; friend class LightRefBase<FramebufferNativeWindow>;
~FramebufferNativeWindow(); // this class cannot be overloaded ~FramebufferNativeWindow(); // this class cannot be overloaded
@ -77,6 +80,7 @@ private:
int32_t mNumBuffers; int32_t mNumBuffers;
int32_t mNumFreeBuffers; int32_t mNumFreeBuffers;
int32_t mBufferHead; int32_t mBufferHead;
int32_t mCurrentBufferIndex;
bool mUpdateOnDemand; bool mUpdateOnDemand;
}; };

70
include/ui/GraphicLog.h Normal file
View File

@ -0,0 +1,70 @@
/*
* Copyright (C) 2010 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.
*/
#ifndef _UI_GRAPHIC_LOG_H
#define _UI_GRAPHIC_LOG_H
#include <utils/Singleton.h>
#include <cutils/compiler.h>
namespace android {
class GraphicLog : public Singleton<GraphicLog>
{
int32_t mEnabled;
static void logImpl(int32_t tag, int32_t buffer);
static void logImpl(int32_t tag, int32_t identity, int32_t buffer);
public:
enum {
SF_APP_DEQUEUE_BEFORE = 60000,
SF_APP_DEQUEUE_AFTER = 60001,
SF_APP_LOCK_BEFORE = 60002,
SF_APP_LOCK_AFTER = 60003,
SF_APP_QUEUE = 60004,
SF_REPAINT = 60005,
SF_COMPOSITION_COMPLETE = 60006,
SF_UNLOCK_CLIENTS = 60007,
SF_SWAP_BUFFERS = 60008,
SF_REPAINT_DONE = 60009,
SF_FB_POST_BEFORE = 60010,
SF_FB_POST_AFTER = 60011,
SF_FB_DEQUEUE_BEFORE = 60012,
SF_FB_DEQUEUE_AFTER = 60013,
SF_FB_LOCK_BEFORE = 60014,
SF_FB_LOCK_AFTER = 60015,
};
inline void log(int32_t tag, int32_t buffer) {
if (CC_UNLIKELY(mEnabled))
logImpl(tag, buffer);
}
inline void log(int32_t tag, int32_t identity, int32_t buffer) {
if (CC_UNLIKELY(mEnabled))
logImpl(tag, identity, buffer);
}
GraphicLog();
void setEnabled(bool enable);
};
}
#endif // _UI_GRAPHIC_LOG_H

View File

@ -32,6 +32,7 @@
#include <ui/DisplayInfo.h> #include <ui/DisplayInfo.h>
#include <ui/GraphicBuffer.h> #include <ui/GraphicBuffer.h>
#include <ui/GraphicBufferMapper.h> #include <ui/GraphicBufferMapper.h>
#include <ui/GraphicLog.h>
#include <ui/Rect.h> #include <ui/Rect.h>
#include <surfaceflinger/Surface.h> #include <surfaceflinger/Surface.h>
@ -568,7 +569,13 @@ int Surface::dequeueBuffer(android_native_buffer_t** buffer)
if (err != NO_ERROR) if (err != NO_ERROR)
return err; return err;
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_APP_DEQUEUE_BEFORE, mIdentity, -1);
ssize_t bufIdx = mSharedBufferClient->dequeue(); ssize_t bufIdx = mSharedBufferClient->dequeue();
logger.log(GraphicLog::SF_APP_DEQUEUE_AFTER, mIdentity, bufIdx);
if (bufIdx < 0) { if (bufIdx < 0) {
LOGE("error dequeuing a buffer (%s)", strerror(bufIdx)); LOGE("error dequeuing a buffer (%s)", strerror(bufIdx));
return bufIdx; return bufIdx;
@ -617,13 +624,20 @@ int Surface::lockBuffer(android_native_buffer_t* buffer)
return err; return err;
int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer)); int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer));
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_APP_LOCK_BEFORE, mIdentity, bufIdx);
err = mSharedBufferClient->lock(bufIdx); err = mSharedBufferClient->lock(bufIdx);
logger.log(GraphicLog::SF_APP_LOCK_AFTER, mIdentity, bufIdx);
LOGE_IF(err, "error locking buffer %d (%s)", bufIdx, strerror(-err)); LOGE_IF(err, "error locking buffer %d (%s)", bufIdx, strerror(-err));
return err; return err;
} }
int Surface::queueBuffer(android_native_buffer_t* buffer) int Surface::queueBuffer(android_native_buffer_t* buffer)
{ {
status_t err = validate(); status_t err = validate();
if (err != NO_ERROR) if (err != NO_ERROR)
return err; return err;
@ -633,6 +647,9 @@ int Surface::queueBuffer(android_native_buffer_t* buffer)
} }
int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer)); int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer));
GraphicLog::getInstance().log(GraphicLog::SF_APP_QUEUE, mIdentity, bufIdx);
mSharedBufferClient->setTransform(bufIdx, mNextBufferTransform); mSharedBufferClient->setTransform(bufIdx, mNextBufferTransform);
mSharedBufferClient->setCrop(bufIdx, mNextBufferCrop); mSharedBufferClient->setCrop(bufIdx, mNextBufferCrop);
mSharedBufferClient->setDirtyRegion(bufIdx, mDirtyRegion); mSharedBufferClient->setDirtyRegion(bufIdx, mDirtyRegion);

View File

@ -9,6 +9,7 @@ LOCAL_SRC_FILES:= \
GraphicBuffer.cpp \ GraphicBuffer.cpp \
GraphicBufferAllocator.cpp \ GraphicBufferAllocator.cpp \
GraphicBufferMapper.cpp \ GraphicBufferMapper.cpp \
GraphicLog.cpp \
KeyLayoutMap.cpp \ KeyLayoutMap.cpp \
KeyCharacterMap.cpp \ KeyCharacterMap.cpp \
Input.cpp \ Input.cpp \

View File

@ -29,6 +29,7 @@
#include <ui/Rect.h> #include <ui/Rect.h>
#include <ui/FramebufferNativeWindow.h> #include <ui/FramebufferNativeWindow.h>
#include <ui/GraphicLog.h>
#include <EGL/egl.h> #include <EGL/egl.h>
@ -174,6 +175,14 @@ int FramebufferNativeWindow::setSwapInterval(
return fb->setSwapInterval(fb, interval); return fb->setSwapInterval(fb, interval);
} }
// only for debugging / logging
int FramebufferNativeWindow::getCurrentBufferIndex() const
{
Mutex::Autolock _l(mutex);
const int index = mCurrentBufferIndex;
return index;
}
int FramebufferNativeWindow::dequeueBuffer(ANativeWindow* window, int FramebufferNativeWindow::dequeueBuffer(ANativeWindow* window,
android_native_buffer_t** buffer) android_native_buffer_t** buffer)
{ {
@ -181,18 +190,24 @@ int FramebufferNativeWindow::dequeueBuffer(ANativeWindow* window,
Mutex::Autolock _l(self->mutex); Mutex::Autolock _l(self->mutex);
framebuffer_device_t* fb = self->fbDev; framebuffer_device_t* fb = self->fbDev;
int index = self->mBufferHead++;
if (self->mBufferHead >= self->mNumBuffers)
self->mBufferHead = 0;
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_FB_DEQUEUE_BEFORE, index);
// wait for a free buffer // wait for a free buffer
while (!self->mNumFreeBuffers) { while (!self->mNumFreeBuffers) {
self->mCondition.wait(self->mutex); self->mCondition.wait(self->mutex);
} }
// get this buffer // get this buffer
self->mNumFreeBuffers--; self->mNumFreeBuffers--;
int index = self->mBufferHead++; self->mCurrentBufferIndex = index;
if (self->mBufferHead >= self->mNumBuffers)
self->mBufferHead = 0;
*buffer = self->buffers[index].get(); *buffer = self->buffers[index].get();
logger.log(GraphicLog::SF_FB_DEQUEUE_AFTER, index);
return 0; return 0;
} }
@ -202,11 +217,17 @@ int FramebufferNativeWindow::lockBuffer(ANativeWindow* window,
FramebufferNativeWindow* self = getSelf(window); FramebufferNativeWindow* self = getSelf(window);
Mutex::Autolock _l(self->mutex); Mutex::Autolock _l(self->mutex);
const int index = self->mCurrentBufferIndex;
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_FB_LOCK_BEFORE, index);
// wait that the buffer we're locking is not front anymore // wait that the buffer we're locking is not front anymore
while (self->front == buffer) { while (self->front == buffer) {
self->mCondition.wait(self->mutex); self->mCondition.wait(self->mutex);
} }
logger.log(GraphicLog::SF_FB_LOCK_AFTER, index);
return NO_ERROR; return NO_ERROR;
} }
@ -217,7 +238,15 @@ int FramebufferNativeWindow::queueBuffer(ANativeWindow* window,
Mutex::Autolock _l(self->mutex); Mutex::Autolock _l(self->mutex);
framebuffer_device_t* fb = self->fbDev; framebuffer_device_t* fb = self->fbDev;
buffer_handle_t handle = static_cast<NativeBuffer*>(buffer)->handle; buffer_handle_t handle = static_cast<NativeBuffer*>(buffer)->handle;
const int index = self->mCurrentBufferIndex;
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_FB_POST_BEFORE, index);
int res = fb->post(fb, handle); int res = fb->post(fb, handle);
logger.log(GraphicLog::SF_FB_POST_AFTER, index);
self->front = static_cast<NativeBuffer*>(buffer); self->front = static_cast<NativeBuffer*>(buffer);
self->mNumFreeBuffers++; self->mNumFreeBuffers++;
self->mCondition.broadcast(); self->mCondition.broadcast();

84
libs/ui/GraphicLog.cpp Normal file
View File

@ -0,0 +1,84 @@
/*
* Copyright (C) 2010 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.
*/
#include <stdlib.h>
#include <unistd.h>
#include <cutils/log.h>
#include <cutils/properties.h>
#include <utils/Endian.h>
#include <utils/Timers.h>
#include <ui/GraphicLog.h>
namespace android {
ANDROID_SINGLETON_STATIC_INSTANCE(GraphicLog)
static inline
void writeInt32(uint8_t* base, size_t& pos, int32_t value) {
int32_t v = htole32(value);
base[pos] = EVENT_TYPE_INT;
memcpy(&base[pos+1], &v, sizeof(int32_t));
pos += 1+sizeof(int32_t);
}
static inline
void writeInt64(uint8_t* base, size_t& pos, int64_t value) {
int64_t v = htole64(value);
base[pos] = EVENT_TYPE_LONG;
memcpy(&base[pos+1], &v, sizeof(int64_t));
pos += 1+sizeof(int64_t);
}
void GraphicLog::logImpl(int32_t tag, int32_t buffer)
{
uint8_t scratch[2 + 2 + sizeof(int32_t) + sizeof(int64_t)];
size_t pos = 0;
scratch[pos++] = EVENT_TYPE_LIST;
scratch[pos++] = 2;
writeInt32(scratch, pos, buffer);
writeInt64(scratch, pos, ns2ms( systemTime( SYSTEM_TIME_MONOTONIC ) ));
android_bWriteLog(tag, scratch, sizeof(scratch));
}
void GraphicLog::logImpl(int32_t tag, int32_t identity, int32_t buffer)
{
uint8_t scratch[2 + 3 + sizeof(int32_t) + sizeof(int32_t) + sizeof(int64_t)];
size_t pos = 0;
scratch[pos++] = EVENT_TYPE_LIST;
scratch[pos++] = 3;
writeInt32(scratch, pos, buffer);
writeInt32(scratch, pos, identity);
writeInt64(scratch, pos, ns2ms( systemTime( SYSTEM_TIME_MONOTONIC ) ));
android_bWriteLog(tag, scratch, sizeof(scratch));
}
GraphicLog::GraphicLog()
: mEnabled(0)
{
char property[PROPERTY_VALUE_MAX];
if (property_get("debug.graphic_log", property, NULL) > 0) {
mEnabled = atoi(property);
}
}
void GraphicLog::setEnabled(bool enable)
{
mEnabled = enable;
}
}

View File

@ -296,6 +296,10 @@ status_t DisplayHardware::compositionComplete() const {
return mNativeWindow->compositionComplete(); return mNativeWindow->compositionComplete();
} }
int DisplayHardware::getCurrentBufferIndex() const {
return mNativeWindow->getCurrentBufferIndex();
}
void DisplayHardware::flip(const Region& dirty) const void DisplayHardware::flip(const Region& dirty) const
{ {
checkGLErrors(); checkGLErrors();

View File

@ -87,6 +87,9 @@ public:
return Rect(mWidth, mHeight); return Rect(mWidth, mHeight);
} }
// only for debugging
int getCurrentBufferIndex() const;
private: private:
void init(uint32_t displayIndex) __attribute__((noinline)); void init(uint32_t displayIndex) __attribute__((noinline));
void fini() __attribute__((noinline)); void fini() __attribute__((noinline));

View File

@ -38,6 +38,7 @@
#include <utils/StopWatch.h> #include <utils/StopWatch.h>
#include <ui/GraphicBufferAllocator.h> #include <ui/GraphicBufferAllocator.h>
#include <ui/GraphicLog.h>
#include <ui/PixelFormat.h> #include <ui/PixelFormat.h>
#include <pixelflinger/pixelflinger.h> #include <pixelflinger/pixelflinger.h>
@ -371,15 +372,25 @@ bool SurfaceFlinger::threadLoop()
const DisplayHardware& hw(graphicPlane(0).displayHardware()); const DisplayHardware& hw(graphicPlane(0).displayHardware());
if (LIKELY(hw.canDraw() && !isFrozen())) { if (LIKELY(hw.canDraw() && !isFrozen())) {
// repaint the framebuffer (if needed) // repaint the framebuffer (if needed)
const int index = hw.getCurrentBufferIndex();
GraphicLog& logger(GraphicLog::getInstance());
logger.log(GraphicLog::SF_REPAINT, index);
handleRepaint(); handleRepaint();
// inform the h/w that we're done compositing // inform the h/w that we're done compositing
logger.log(GraphicLog::SF_COMPOSITION_COMPLETE, index);
hw.compositionComplete(); hw.compositionComplete();
// release the clients before we flip ('cause flip might block) // release the clients before we flip ('cause flip might block)
logger.log(GraphicLog::SF_UNLOCK_CLIENTS, index);
unlockClients(); unlockClients();
logger.log(GraphicLog::SF_SWAP_BUFFERS, index);
postFramebuffer(); postFramebuffer();
logger.log(GraphicLog::SF_REPAINT_DONE, index);
} else { } else {
// pretend we did the post // pretend we did the post
unlockClients(); unlockClients();
@ -1470,8 +1481,7 @@ status_t SurfaceFlinger::onTransact(
int n; int n;
switch (code) { switch (code) {
case 1000: // SHOW_CPU, NOT SUPPORTED ANYMORE case 1000: // SHOW_CPU, NOT SUPPORTED ANYMORE
return NO_ERROR; case 1001: // SHOW_FPS, NOT SUPPORTED ANYMORE
case 1001: // SHOW_FPS, NOT SUPPORTED ANYMORE
return NO_ERROR; return NO_ERROR;
case 1002: // SHOW_UPDATES case 1002: // SHOW_UPDATES
n = data.readInt32(); n = data.readInt32();
@ -1492,6 +1502,11 @@ status_t SurfaceFlinger::onTransact(
setTransactionFlags(eTransactionNeeded|eTraversalNeeded); setTransactionFlags(eTransactionNeeded|eTraversalNeeded);
return NO_ERROR; return NO_ERROR;
} }
case 1006:{ // enable/disable GraphicLog
int enabled = data.readInt32();
GraphicLog::getInstance().setEnabled(enabled);
return NO_ERROR;
}
case 1007: // set mFreezeCount case 1007: // set mFreezeCount
mFreezeCount = data.readInt32(); mFreezeCount = data.readInt32();
mFreezeDisplayTime = 0; mFreezeDisplayTime = 0;