Resurrect verbose binder logging
Updated the command name lists, and masked off the additional bits in
the command word when doing the name lookup.
Made descriptor values easier to grep for and consistent with kernel
output (i.e. decimal rather than hex). Attempt to show transaction
descriptors as such (they're in a union with a pointer).
Also, the writeLines() function in Static was using a no-op
logging call to write an iovec. It looks like all callers are using
N=1, so I just added a log for the first string.
Bug 5155269
Change-Id: I417b8d77da3eb6ee1d2069ba94047210f75738bc
diff --git a/IPCThreadState.cpp b/IPCThreadState.cpp
index 392193b..5ccf87f 100644
--- a/IPCThreadState.cpp
+++ b/IPCThreadState.cpp
@@ -78,12 +78,8 @@
// conditionals don't get stripped... but that is probably what we want.
#if !LOG_NDEBUG
static const char *kReturnStrings[] = {
-#if 1 /* TODO: error update strings */
- "unknown",
-#else
+ "BR_ERROR",
"BR_OK",
- "BR_TIMEOUT",
- "BR_WAKEUP",
"BR_TRANSACTION",
"BR_REPLY",
"BR_ACQUIRE_RESULT",
@@ -94,25 +90,19 @@
"BR_RELEASE",
"BR_DECREFS",
"BR_ATTEMPT_ACQUIRE",
- "BR_EVENT_OCCURRED",
"BR_NOOP",
"BR_SPAWN_LOOPER",
"BR_FINISHED",
"BR_DEAD_BINDER",
- "BR_CLEAR_DEATH_NOTIFICATION_DONE"
-#endif
+ "BR_CLEAR_DEATH_NOTIFICATION_DONE",
+ "BR_FAILED_REPLY"
};
static const char *kCommandStrings[] = {
-#if 1 /* TODO: error update strings */
- "unknown",
-#else
- "BC_NOOP",
"BC_TRANSACTION",
"BC_REPLY",
"BC_ACQUIRE_RESULT",
"BC_FREE_BUFFER",
- "BC_TRANSACTION_COMPLETE",
"BC_INCREFS",
"BC_ACQUIRE",
"BC_RELEASE",
@@ -120,18 +110,12 @@
"BC_INCREFS_DONE",
"BC_ACQUIRE_DONE",
"BC_ATTEMPT_ACQUIRE",
- "BC_RETRIEVE_ROOT_OBJECT",
- "BC_SET_THREAD_ENTRY",
"BC_REGISTER_LOOPER",
"BC_ENTER_LOOPER",
"BC_EXIT_LOOPER",
- "BC_SYNC",
- "BC_STOP_PROCESS",
- "BC_STOP_SELF",
"BC_REQUEST_DEATH_NOTIFICATION",
"BC_CLEAR_DEATH_NOTIFICATION",
"BC_DEAD_BINDER_DONE"
-#endif
};
static const char* getReturnString(size_t idx)
@@ -154,30 +138,36 @@
{
const binder_transaction_data* btd =
(const binder_transaction_data*)data;
- out << "target=" << btd->target.ptr << " (cookie " << btd->cookie << ")" << endl
+ if (btd->target.handle < 1024) {
+ /* want to print descriptors in decimal; guess based on value */
+ out << "target.desc=" << btd->target.handle;
+ } else {
+ out << "target.ptr=" << btd->target.ptr;
+ }
+ out << " (cookie " << btd->cookie << ")" << endl
<< "code=" << TypeCode(btd->code) << ", flags=" << (void*)btd->flags << endl
<< "data=" << btd->data.ptr.buffer << " (" << (void*)btd->data_size
<< " bytes)" << endl
<< "offsets=" << btd->data.ptr.offsets << " (" << (void*)btd->offsets_size
- << " bytes)" << endl;
+ << " bytes)";
return btd+1;
}
static const void* printReturnCommand(TextOutput& out, const void* _cmd)
{
- static const int32_t N = sizeof(kReturnStrings)/sizeof(kReturnStrings[0]);
-
+ static const size_t N = sizeof(kReturnStrings)/sizeof(kReturnStrings[0]);
const int32_t* cmd = (const int32_t*)_cmd;
int32_t code = *cmd++;
- if (code == BR_ERROR) {
+ size_t cmdIndex = code & 0xff;
+ if (code == (int32_t) BR_ERROR) {
out << "BR_ERROR: " << (void*)(*cmd++) << endl;
return cmd;
- } else if (code < 0 || code >= N) {
+ } else if (cmdIndex >= N) {
out << "Unknown reply: " << code << endl;
return cmd;
}
+ out << kReturnStrings[cmdIndex];
- out << kReturnStrings[code];
switch (code) {
case BR_TRANSACTION:
case BR_REPLY: {
@@ -213,6 +203,11 @@
const int32_t c = *cmd++;
out << ": death cookie " << (void*)c;
} break;
+
+ default:
+ // no details to show for: BR_OK, BR_DEAD_REPLY,
+ // BR_TRANSACTION_COMPLETE, BR_FINISHED
+ break;
}
out << endl;
@@ -221,16 +216,17 @@
static const void* printCommand(TextOutput& out, const void* _cmd)
{
- static const int32_t N = sizeof(kCommandStrings)/sizeof(kCommandStrings[0]);
-
+ static const size_t N = sizeof(kCommandStrings)/sizeof(kCommandStrings[0]);
const int32_t* cmd = (const int32_t*)_cmd;
int32_t code = *cmd++;
- if (code < 0 || code >= N) {
+ size_t cmdIndex = code & 0xff;
+
+ if (cmdIndex >= N) {
out << "Unknown command: " << code << endl;
return cmd;
}
-
- out << kCommandStrings[code];
+ out << kCommandStrings[cmdIndex];
+
switch (code) {
case BC_TRANSACTION:
case BC_REPLY: {
@@ -254,7 +250,7 @@
case BC_RELEASE:
case BC_DECREFS: {
const int32_t d = *cmd++;
- out << ": descriptor=" << (void*)d;
+ out << ": desc=" << d;
} break;
case BC_INCREFS_DONE:
@@ -267,7 +263,7 @@
case BC_ATTEMPT_ACQUIRE: {
const int32_t p = *cmd++;
const int32_t d = *cmd++;
- out << ": decriptor=" << (void*)d << ", pri=" << p;
+ out << ": desc=" << d << ", pri=" << p;
} break;
case BC_REQUEST_DEATH_NOTIFICATION:
@@ -281,6 +277,11 @@
const int32_t c = *cmd++;
out << ": death cookie " << (void*)c;
} break;
+
+ default:
+ // no details to show for: BC_REGISTER_LOOPER, BC_ENTER_LOOPER,
+ // BC_EXIT_LOOPER
+ break;
}
out << endl;
@@ -592,6 +593,7 @@
status_t IPCThreadState::attemptIncStrongHandle(int32_t handle)
{
+ LOG_REMOTEREFS("IPCThreadState::attemptIncStrongHandle(%d)\n", handle);
mOut.writeInt32(BC_ATTEMPT_ACQUIRE);
mOut.writeInt32(0); // xxx was thread priority
mOut.writeInt32(handle);
@@ -772,7 +774,7 @@
} else {
bwr.read_size = 0;
}
-
+
IF_LOG_COMMANDS() {
TextOutput::Bundle _b(alog);
if (outAvail != 0) {
@@ -789,7 +791,7 @@
// Return immediately if there is nothing to do.
if ((bwr.write_size == 0) && (bwr.read_size == 0)) return NO_ERROR;
-
+
bwr.write_consumed = 0;
bwr.read_consumed = 0;
status_t err;
@@ -809,7 +811,7 @@
alog << "Finished read/write, write size = " << mOut.dataSize() << endl;
}
} while (err == -EINTR);
-
+
IF_LOG_COMMANDS() {
alog << "Our err: " << (void*)err << ", write consumed: "
<< bwr.write_consumed << " (of " << mOut.dataSize()