am 5bce6668: am 15027de7: Added new logging messages and updated event logs with plugin execution time

Merge commit '5bce666850444bb87efe0be67046e7648ff15e67'

* commit '5bce666850444bb87efe0be67046e7648ff15e67':
  Added new logging messages and updated event logs with plugin execution time

3 files changed, 36 insertions, 16 deletions

diff --git a/WebKit/android/plugins/PluginDebugAndroid.cpp b/WebKit/android/plugins/PluginDebugAndroid.cpp
index 3f1db2d..f8a3c50 100644
--- a/WebKit/android/plugins/PluginDebugAndroid.cpp
+++ b/WebKit/android/plugins/PluginDebugAndroid.cpp
@@ -59,7 +59,7 @@ void anp_logPlugin(const char format[], ...) {
     va_end(args);
 }
 
-void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
+void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal, int elapsedTime) {
 
     switch(evt->eventType) {
 
@@ -69,8 +69,8 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
 
         case kKey_ANPEventType:
             if(evt->data.key.action < ARRAY_COUNT(inputActions)) {
-                anp_logPlugin("%p EVENT::KEY[%d] action=%s code=%d vcode=%d unichar=%d repeat=%d mods=%x",
-                        npp, returnVal, inputActions[evt->data.key.action],
+                anp_logPlugin("%p EVENT::KEY[%d] time=%d action=%s code=%d vcode=%d unichar=%d repeat=%d mods=%x",
+                        npp, returnVal, elapsedTime, inputActions[evt->data.key.action],
                         evt->data.key.nativeCode, evt->data.key.virtualCode,
                         evt->data.key.unichar, evt->data.key.repeatCount,
                         evt->data.key.modifiers);
@@ -81,8 +81,8 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
 
         case kMouse_ANPEventType:
             if(evt->data.mouse.action < ARRAY_COUNT(inputActions)) {
-                anp_logPlugin("%p EVENT::MOUSE[%d] action=%s [%d %d]", npp,
-                        returnVal, inputActions[evt->data.mouse.action],
+                anp_logPlugin("%p EVENT::MOUSE[%d] time=%d action=%s [%d %d]", npp,
+                        returnVal, elapsedTime, inputActions[evt->data.mouse.action],
                         evt->data.touch.x, evt->data.touch.y);
             } else {
                 anp_logPlugin("%p EVENT::MOUSE[%d] unknown action", npp, returnVal);
@@ -91,8 +91,8 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
 
         case kTouch_ANPEventType:
             if(evt->data.touch.action < ARRAY_COUNT(inputActions)) {
-                anp_logPlugin("%p EVENT::TOUCH[%d] action=%s [%d %d]", npp,
-                        returnVal, inputActions[evt->data.touch.action],
+                anp_logPlugin("%p EVENT::TOUCH[%d] time=%d action=%s [%d %d]", npp,
+                        returnVal,  elapsedTime,inputActions[evt->data.touch.action],
                         evt->data.touch.x, evt->data.touch.y);
             } else {
                 anp_logPlugin("%p EVENT::TOUCH[%d] unknown action", npp, returnVal);
@@ -101,8 +101,8 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
 
         case kDraw_ANPEventType:
             if (evt->data.draw.model == kBitmap_ANPDrawingModel) {
-                anp_logPlugin("%p EVENT::DRAW bitmap format=%d clip=[%d,%d,%d,%d]",
-                        npp, evt->data.draw.data.bitmap.format,
+                anp_logPlugin("%p EVENT::DRAW bitmap time=%d format=%d clip=[%d,%d,%d,%d]",
+                        npp, elapsedTime, evt->data.draw.data.bitmap.format,
                         evt->data.draw.clip.left, evt->data.draw.clip.top,
                         evt->data.draw.clip.right, evt->data.draw.clip.bottom);
             } else {
@@ -112,7 +112,7 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
 
         case kLifecycle_ANPEventType:
             if(evt->data.lifecycle.action < ARRAY_COUNT(lifecycleActions)) {
-                anp_logPlugin("%p EVENT::LIFECYCLE %s", npp,
+                anp_logPlugin("%p EVENT::LIFECYCLE time=%d action=%s", npp, elapsedTime,
                         lifecycleActions[evt->data.lifecycle.action]);
             } else {
                 anp_logPlugin("%p EVENT::LIFECYCLE unknown action", npp);
@@ -120,7 +120,7 @@ void anp_logPluginEvent(void* npp, const ANPEvent* evt, int16 returnVal) {
             break;
 
         case kCustom_ANPEventType:
-            anp_logPlugin("%p EVENT::CUSTOM", npp);
+            anp_logPlugin("%p EVENT::CUSTOM time=%d", npp, elapsedTime);
             break;
 
         default:
diff --git a/WebKit/android/plugins/PluginDebugAndroid.h b/WebKit/android/plugins/PluginDebugAndroid.h
index 24944cb..92092d5 100644
--- a/WebKit/android/plugins/PluginDebugAndroid.h
+++ b/WebKit/android/plugins/PluginDebugAndroid.h
@@ -1,5 +1,5 @@
 /*
- * Copyright 2008, The Android Open Source Project
+ * Copyright 2010, The Android Open Source Project
  *
  * Redistribution and use in source and binary forms, with or without
  * modification, are permitted provided that the following conditions
@@ -37,14 +37,22 @@
 
 #if PLUGIN_DEBUG_GLOBAL || defined(PLUGIN_DEBUG_LOCAL)
 # define PLUGIN_LOG(FORMAT, ARGS...) do { anp_logPlugin(FORMAT, ## ARGS); } while(0)
-# define PLUGIN_LOG_EVENT(NPP, EVT, RET) do { anp_logPluginEvent(NPP, EVT, RET); } while(0)
+# define PLUGIN_LOG_EVENT(NPP, EVT, RET, TIME) do { anp_logPluginEvent(NPP, EVT, RET, TIME); } while(0)
 
+/* Logs the given character array and optional arguments. All log entries use
+   the DEBUG priority and use the same "webkit_plugin" log tag.
+ */
 void anp_logPlugin(const char format[], ...);
-void anp_logPluginEvent(void* npp, const ANPEvent* event, int16 returnVal);
+/* Logs a user readable description of a plugin event. The relevant contents of
+   each event are logged, as well as the value returned by the plugin instance
+   and how long the instance took to process the event (in milliseconds).
+ */
+void anp_logPluginEvent(void* npp, const ANPEvent* event, int16 returnVal, int elapsedTime);
 
 #else
 # define PLUGIN_LOG(A, B...)    do { } while(0)
-# define PLUGIN_LOG_EVENT(NPP, EVENT) do { } while(0)
+# define PLUGIN_LOG_EVENT(NPP, EVT, RET, TIME) do { } while(0)
+
 #endif
 
 #endif // defined(PLUGIN_DEBUG_ANDROID_H__)
diff --git a/WebKit/android/plugins/PluginWidgetAndroid.cpp b/WebKit/android/plugins/PluginWidgetAndroid.cpp
index 06dfa39..690c1a4 100644
--- a/WebKit/android/plugins/PluginWidgetAndroid.cpp
+++ b/WebKit/android/plugins/PluginWidgetAndroid.cpp
@@ -40,11 +40,13 @@
 #include "SkANP.h"
 #include "SkFlipPixelRef.h"
 #include "SkString.h"
+#include "SkTime.h"
 #include "WebViewCore.h"
 #include "android_graphics.h"
 #include <JNIUtility.h>
 
 #define PLUGIN_DEBUG_LOCAL 0 // controls the printing of log messages
+#define DEBUG_EVENTS 0 // logs event contents, return value, and processing time
 #define DEBUG_VISIBLE_RECTS 1 // temporary debug printfs and fixes
 
 // this include statement must follow the declaration of PLUGIN_DEBUG_LOCAL
@@ -70,6 +72,7 @@ PluginWidgetAndroid::PluginWidgetAndroid(WebCore::PluginView* view)
 }
 
 PluginWidgetAndroid::~PluginWidgetAndroid() {
+    PLUGIN_LOG("%p Deleting Plugin", m_pluginView->instance());
     m_acceptEvents = false;
     if (m_core) {
         m_core->removePlugin(this);
@@ -94,6 +97,7 @@ void PluginWidgetAndroid::init(android::WebViewCore* core) {
     m_core = core;
     m_core->addPlugin(this);
     m_acceptEvents = true;
+    PLUGIN_LOG("%p Initialized Plugin", m_pluginView->instance());
 }
 
 static SkBitmap::Config computeConfig(bool isTransparent) {
@@ -242,11 +246,19 @@ int16 PluginWidgetAndroid::sendEvent(const ANPEvent& evt) {
             m_hasFocus = true;
         }
 
+#if DEBUG_EVENTS
+        SkMSec startTime = SkTime::GetMSecs();
+#endif
+
         // make a localCopy since the actual plugin may not respect its constness,
         // and so we don't want our caller to have its param modified
         ANPEvent localCopy = evt;
         int16 result = pkg->pluginFuncs()->event(instance, &localCopy);
-        PLUGIN_LOG_EVENT(instance, &evt, result);
+
+#if DEBUG_EVENTS
+        SkMSec endTime = SkTime::GetMSecs();
+        PLUGIN_LOG_EVENT(instance, &evt, result, endTime - startTime);
+#endif
 
         // if the plugin is losing focus then delay the update of our state
         // until after we notify the plugin and allow them to perform actions