Enhanced debugging output to print also the thread ID.

git-svn-id: file:///srv/svn/repos/haiku/trunk/current@10676 a95241bf-73f2-0310-859d-f6bbb57e9c96
This commit is contained in:
Ingo Weinhold
2005-01-12 03:13:52 +00:00
parent e9bd14d444
commit c5c962d426
+55 -55
View File
@@ -37,8 +37,8 @@
// debugging // debugging
//#define DBG(x) x //#define DBG(x) x
#define DBG(x) #define DBG(x) ;
#define OUT printf #define PRINT(x) DBG({ printf("[%6ld] ", find_thread(NULL)); printf x; })
// Standard Includes ----------------------------------------------------------- // Standard Includes -----------------------------------------------------------
#include <stdio.h> #include <stdio.h>
@@ -262,7 +262,7 @@ status_t BLooper::PostMessage(BMessage* message, BHandler* handler,
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::DispatchMessage(BMessage* message, BHandler* handler) void BLooper::DispatchMessage(BMessage* message, BHandler* handler)
{ {
DBG(OUT("BLooper::DispatchMessage(%.4s)\n", (char*)&message->what)); PRINT(("BLooper::DispatchMessage(%.4s)\n", (char*)&message->what));
/** /**
@note Initially, DispatchMessage() was locking the looper, calling the @note Initially, DispatchMessage() was locking the looper, calling the
filtering API, determining whether to use fPreferred or not, and filtering API, determining whether to use fPreferred or not, and
@@ -311,7 +311,7 @@ DBG(OUT("BLooper::DispatchMessage(%.4s)\n", (char*)&message->what));
break; break;
} }
} }
DBG(OUT("BLooper::DispatchMessage() done\n")); PRINT(("BLooper::DispatchMessage() done\n"));
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::MessageReceived(BMessage* msg) void BLooper::MessageReceived(BMessage* msg)
@@ -515,7 +515,7 @@ thread_id BLooper::Run()
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::Quit() void BLooper::Quit()
{ {
DBG(OUT("BLooper::Quit()\n")); PRINT(("BLooper::Quit()\n"));
if (!IsLocked()) if (!IsLocked())
{ {
const char* name = Name(); const char* name = Name();
@@ -534,24 +534,24 @@ DBG(OUT("BLooper::Quit()\n"));
return; return;
} }
DBG(OUT(" is locked\n")); PRINT((" is locked\n"));
if (!fRunCalled) if (!fRunCalled)
{ {
DBG(OUT(" Run() has not been called yet\n")); PRINT((" Run() has not been called yet\n"));
fTerminating = true; fTerminating = true;
delete this; delete this;
} }
else if (find_thread(NULL) == fTaskID) else if (find_thread(NULL) == fTaskID)
{ {
DBG(OUT(" We are the looper thread\n")); PRINT((" We are the looper thread\n"));
fTerminating = true; fTerminating = true;
delete this; delete this;
exit_thread(0); exit_thread(0);
} }
else else
{ {
DBG(OUT(" Run() has already been called and we are not the looper thread\n")); PRINT((" Run() has already been called and we are not the looper thread\n"));
// As with sem in _Lock(), we need to cache this here in case the looper // As with sem in _Lock(), we need to cache this here in case the looper
// disappears before we get to the wait_for_thread() below // disappears before we get to the wait_for_thread() below
thread_id tid = Thread(); thread_id tid = Thread();
@@ -572,13 +572,13 @@ DBG(OUT(" Run() has already been called and we are not the looper thread\n"));
// when Quit() was invoked from another thread. Makes a nice proof that // when Quit() was invoked from another thread. Makes a nice proof that
// this is how it's handled, too. // this is how it's handled, too.
status_t err; status_t err;
DBG(OUT(" PostMessage(_QUIT_)...\n")); PRINT((" PostMessage(_QUIT_)...\n"));
// err = PostMessage(_QUIT_); // err = PostMessage(_QUIT_);
BMessage message(_QUIT_); BMessage message(_QUIT_);
message.AddInt32("testfield", 42); message.AddInt32("testfield", 42);
err = PostMessage(&message); err = PostMessage(&message);
DBG(OUT(" ... done: %lx\n", err)); PRINT((" ... done: %lx\n", err));
// There's a possibility that PostMessage() will return B_WOULD_BLOCK // There's a possibility that PostMessage() will return B_WOULD_BLOCK
// because the port is full, so we'll wait a bit and re-post until // because the port is full, so we'll wait a bit and re-post until
@@ -595,11 +595,11 @@ DBG(OUT(" ... done: %lx\n", err));
int32 temp; int32 temp;
do do
{ {
DBG(OUT(" wait_for_thread(%ld)...\n", tid)); PRINT((" wait_for_thread(%ld)...\n", tid));
err = wait_for_thread(tid, &temp); err = wait_for_thread(tid, &temp);
} while (err == B_INTERRUPTED); } while (err == B_INTERRUPTED);
} }
DBG(OUT("BLooper::Quit() done\n")); PRINT(("BLooper::Quit() done\n"));
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
bool BLooper::QuitRequested() bool BLooper::QuitRequested()
@@ -615,13 +615,13 @@ bool BLooper::Lock()
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::Unlock() void BLooper::Unlock()
{ {
DBG(OUT("BLooper::Unlock()\n")); PRINT(("BLooper::Unlock()\n"));
// Make sure we're locked to begin with // Make sure we're locked to begin with
AssertLocked(); AssertLocked();
// Decrement fOwnerCount // Decrement fOwnerCount
--fOwnerCount; --fOwnerCount;
DBG(OUT(" fOwnerCount now: %ld\n", fOwnerCount)); PRINT((" fOwnerCount now: %ld\n", fOwnerCount));
// Check to see if the owner still wants a lock // Check to see if the owner still wants a lock
if (fOwnerCount == 0) if (fOwnerCount == 0)
{ {
@@ -630,7 +630,7 @@ DBG(OUT(" fOwnerCount now: %ld\n", fOwnerCount));
// Decrement requested lock count (using fAtomicCount for this) // Decrement requested lock count (using fAtomicCount for this)
/* int32 atomicCount =*/ atomic_add(&fAtomicCount, -1); /* int32 atomicCount =*/ atomic_add(&fAtomicCount, -1);
DBG(OUT(" fAtomicCount now: %ld\n", fAtomicCount)); PRINT((" fAtomicCount now: %ld\n", fAtomicCount));
// Check if anyone is waiting for a lock // Check if anyone is waiting for a lock
// bonefish: Currently _Lock() always acquires the semaphore. // bonefish: Currently _Lock() always acquires the semaphore.
@@ -640,7 +640,7 @@ DBG(OUT(" fAtomicCount now: %ld\n", fAtomicCount));
release_sem(fLockSem); release_sem(fLockSem);
} }
} }
DBG(OUT("BLooper::Unlock() done\n")); PRINT(("BLooper::Unlock() done\n"));
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
bool BLooper::IsLocked() const bool BLooper::IsLocked() const
@@ -1002,7 +1002,7 @@ status_t BLooper::_PostMessage(BMessage* msg, BHandler* handler,
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
status_t BLooper::_Lock(BLooper* loop, port_id port, bigtime_t timeout) status_t BLooper::_Lock(BLooper* loop, port_id port, bigtime_t timeout)
{ {
DBG(OUT("BLooper::_Lock(%p, %lx)\n", loop, port)); PRINT(("BLooper::_Lock(%p, %lx)\n", loop, port));
/** /**
@note The assumption I'm under here is that since we can get the port of @note The assumption I'm under here is that since we can get the port of
the BLooper directly from the BLooper itself, the port parameter is the BLooper directly from the BLooper itself, the port parameter is
@@ -1028,7 +1028,7 @@ DBG(OUT("BLooper::_Lock(%p, %lx)\n", loop, port));
// Check params (loop, port) // Check params (loop, port)
if (!loop && port < 0) if (!loop && port < 0)
{ {
DBG(OUT("BLooper::_Lock() done 1\n")); PRINT(("BLooper::_Lock() done 1\n"));
return B_BAD_VALUE; return B_BAD_VALUE;
} }
@@ -1049,7 +1049,7 @@ DBG(OUT("BLooper::_Lock() done 1\n"));
{ {
// If we can't lock, the semaphore is probably // If we can't lock, the semaphore is probably
// gone, which leaves us in no-man's land // gone, which leaves us in no-man's land
DBG(OUT("BLooper::_Lock() done 2\n")); PRINT(("BLooper::_Lock() done 2\n"));
return B_BAD_VALUE; return B_BAD_VALUE;
} }
@@ -1059,7 +1059,7 @@ DBG(OUT("BLooper::_Lock() done 2\n"));
loop = LooperForPort(port); loop = LooperForPort(port);
if (!loop) if (!loop)
{ {
DBG(OUT("BLooper::_Lock() done 3\n")); PRINT(("BLooper::_Lock() done 3\n"));
return B_BAD_VALUE; return B_BAD_VALUE;
} }
} }
@@ -1068,7 +1068,7 @@ DBG(OUT("BLooper::_Lock() done 3\n"));
// Check looper validity // Check looper validity
if (!IsLooperValid(loop)) if (!IsLooperValid(loop))
{ {
DBG(OUT("BLooper::_Lock() done 4\n")); PRINT(("BLooper::_Lock() done 4\n"));
return B_BAD_VALUE; return B_BAD_VALUE;
} }
} }
@@ -1080,7 +1080,7 @@ DBG(OUT("BLooper::_Lock() done 4\n"));
{ {
// Bump fOwnerCount // Bump fOwnerCount
++loop->fOwnerCount; ++loop->fOwnerCount;
DBG(OUT("BLooper::_Lock() done 5: fOwnerCount: %ld\n", loop->fOwnerCount)); PRINT(("BLooper::_Lock() done 5: fOwnerCount: %ld\n", loop->fOwnerCount));
return B_OK; return B_OK;
} }
@@ -1091,7 +1091,7 @@ DBG(OUT("BLooper::_Lock() done 5: fOwnerCount: %ld\n", loop->fOwnerCount));
// Validate the semaphore // Validate the semaphore
if (sem < 0) if (sem < 0)
{ {
DBG(OUT("BLooper::_Lock() done 6\n")); PRINT(("BLooper::_Lock() done 6\n"));
return B_BAD_VALUE; return B_BAD_VALUE;
} }
@@ -1125,7 +1125,7 @@ DBG(OUT("BLooper::_Lock() done 6\n"));
loop->fOwnerCount = 1; loop->fOwnerCount = 1;
} }
DBG(OUT("BLooper::_Lock() done: %lx\n", err)); PRINT(("BLooper::_Lock() done: %lx\n", err));
return err; return err;
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
@@ -1189,18 +1189,18 @@ void BLooper::_AddMessagePriv(BMessage* msg)
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
status_t BLooper::_task0_(void* arg) status_t BLooper::_task0_(void* arg)
{ {
DBG(OUT("LOOPER: _task0_()\n")); PRINT(("LOOPER: _task0_()\n"));
BLooper* obj = (BLooper*)arg; BLooper* obj = (BLooper*)arg;
DBG(OUT("LOOPER: locking looper...\n")); PRINT(("LOOPER: locking looper...\n"));
if (obj->Lock()) if (obj->Lock())
{ {
DBG(OUT("LOOPER: looper locked\n")); PRINT(("LOOPER: looper locked\n"));
obj->task_looper(); obj->task_looper();
delete obj; delete obj;
} }
DBG(OUT("LOOPER: _task0_() done: thread %ld\n", find_thread(NULL))); PRINT(("LOOPER: _task0_() done: thread %ld\n", find_thread(NULL)));
return B_OK; return B_OK;
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
@@ -1208,7 +1208,7 @@ DBG(OUT("LOOPER: _task0_() done: thread %ld\n", find_thread(NULL)));
void * void *
BLooper::ReadRawFromPort(int32 *msgCode, bigtime_t timeout) BLooper::ReadRawFromPort(int32 *msgCode, bigtime_t timeout)
{ {
DBG(OUT("BLooper::ReadRawFromPort()\n")); PRINT(("BLooper::ReadRawFromPort()\n"));
int8 *msgBuffer = NULL; int8 *msgBuffer = NULL;
ssize_t bufferSize; ssize_t bufferSize;
@@ -1217,7 +1217,7 @@ BLooper::ReadRawFromPort(int32 *msgCode, bigtime_t timeout)
} while (bufferSize == B_INTERRUPTED); } while (bufferSize == B_INTERRUPTED);
if (bufferSize < B_OK) { if (bufferSize < B_OK) {
DBG(OUT("BLooper::ReadRawFromPort(): failed: %ld\n", bufferSize)); PRINT(("BLooper::ReadRawFromPort(): failed: %ld\n", bufferSize));
return NULL; return NULL;
} }
@@ -1227,22 +1227,22 @@ BLooper::ReadRawFromPort(int32 *msgCode, bigtime_t timeout)
// we don't want to wait again here, since that can only mean // we don't want to wait again here, since that can only mean
// that someone else has read our message and our bufferSize // that someone else has read our message and our bufferSize
// is now probably wrong // is now probably wrong
DBG(OUT("read_port()...\n")); PRINT(("read_port()...\n"));
bufferSize = read_port_etc(fMsgPort, msgCode, msgBuffer, bufferSize, bufferSize = read_port_etc(fMsgPort, msgCode, msgBuffer, bufferSize,
B_RELATIVE_TIMEOUT, 0); B_RELATIVE_TIMEOUT, 0);
if (bufferSize < B_OK) { if (bufferSize < B_OK) {
delete[] msgBuffer; delete[] msgBuffer;
return NULL; return NULL;
} }
DBG(OUT("BLooper::ReadRawFromPort() read: %.4s\n", (char *)msgCode)); PRINT(("BLooper::ReadRawFromPort() read: %.4s\n", (char *)msgCode));
DBG(OUT("BLooper::ReadRawFromPort() done: %p\n", msgBuffer)); PRINT(("BLooper::ReadRawFromPort() done: %p\n", msgBuffer));
return msgBuffer; return msgBuffer;
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
BMessage* BLooper::ReadMessageFromPort(bigtime_t tout) BMessage* BLooper::ReadMessageFromPort(bigtime_t tout)
{ {
DBG(OUT("BLooper::ReadMessageFromPort()\n")); PRINT(("BLooper::ReadMessageFromPort()\n"));
int32 msgcode; int32 msgcode;
BMessage* bmsg; BMessage* bmsg;
@@ -1255,32 +1255,32 @@ DBG(OUT("BLooper::ReadMessageFromPort()\n"));
delete[] (int8*)msgbuffer; delete[] (int8*)msgbuffer;
} }
DBG(OUT("BLooper::ReadMessageFromPort() done: %p\n", bmsg)); PRINT(("BLooper::ReadMessageFromPort() done: %p\n", bmsg));
return bmsg; return bmsg;
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
BMessage* BLooper::ConvertToMessage(void* raw, int32 code) BMessage* BLooper::ConvertToMessage(void* raw, int32 code)
{ {
DBG(OUT("BLooper::ConvertToMessage()\n")); PRINT(("BLooper::ConvertToMessage()\n"));
BMessage* bmsg = new BMessage(code); BMessage* bmsg = new BMessage(code);
if (raw != NULL) if (raw != NULL)
{ {
if (bmsg->Unflatten((const char*)raw) != B_OK) if (bmsg->Unflatten((const char*)raw) != B_OK)
{ {
DBG(OUT("BLooper::ConvertToMessage(): unflattening message failed\n")); PRINT(("BLooper::ConvertToMessage(): unflattening message failed\n"));
delete bmsg; delete bmsg;
bmsg = NULL; bmsg = NULL;
} }
} }
DBG(OUT("BLooper::ConvertToMessage(): %p\n", bmsg)); PRINT(("BLooper::ConvertToMessage(): %p\n", bmsg));
return bmsg; return bmsg;
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::task_looper() void BLooper::task_looper()
{ {
DBG(OUT("BLooper::task_looper()\n")); PRINT(("BLooper::task_looper()\n"));
// Check that looper is locked (should be) // Check that looper is locked (should be)
AssertLocked(); AssertLocked();
// Unlock the looper // Unlock the looper
@@ -1289,22 +1289,22 @@ DBG(OUT("BLooper::task_looper()\n"));
// loop: As long as we are not terminating. // loop: As long as we are not terminating.
while (!fTerminating) while (!fTerminating)
{ {
DBG(OUT("LOOPER: outer loop\n")); PRINT(("LOOPER: outer loop\n"));
// TODO: timeout determination algo // TODO: timeout determination algo
// Read from message port (how do we determine what the timeout is?) // Read from message port (how do we determine what the timeout is?)
DBG(OUT("LOOPER: MessageFromPort()...\n")); PRINT(("LOOPER: MessageFromPort()...\n"));
BMessage* msg = MessageFromPort(); BMessage* msg = MessageFromPort();
DBG(OUT("LOOPER: ...done\n")); PRINT(("LOOPER: ...done\n"));
// Did we get a message? // Did we get a message?
if (msg) if (msg)
{ {
DBG(OUT("LOOPER: got message\n")); PRINT(("LOOPER: got message\n"));
// Add to queue // Add to queue
fQueue->AddMessage(msg); fQueue->AddMessage(msg);
} }
else else
DBG(OUT("LOOPER: got no message\n")); PRINT(("LOOPER: got no message\n"));
// Get message count from port // Get message count from port
int32 msgCount = port_count(fMsgPort); int32 msgCount = port_count(fMsgPort);
@@ -1325,7 +1325,7 @@ DBG(OUT("LOOPER: got no message\n"));
bool dispatchNextMessage = true; bool dispatchNextMessage = true;
while (!fTerminating && dispatchNextMessage) while (!fTerminating && dispatchNextMessage)
{ {
DBG(OUT("LOOPER: inner loop\n")); PRINT(("LOOPER: inner loop\n"));
// Get next message from queue (assign to fLastMessage) // Get next message from queue (assign to fLastMessage)
fLastMessage = fQueue->NextMessage(); fLastMessage = fQueue->NextMessage();
@@ -1339,7 +1339,7 @@ DBG(OUT("LOOPER: inner loop\n"));
} }
else else
{ {
DBG(OUT("LOOPER: fLastMessage: 0x%lx: %.4s\n", fLastMessage->what, PRINT(("LOOPER: fLastMessage: 0x%lx: %.4s\n", fLastMessage->what,
(char*)&fLastMessage->what)); (char*)&fLastMessage->what));
DBG(fLastMessage->PrintToStream()); DBG(fLastMessage->PrintToStream());
// Get the target handler // Get the target handler
@@ -1348,12 +1348,12 @@ DBG(fLastMessage->PrintToStream());
BHandler* handler; BHandler* handler;
if (_use_preferred_target_(fLastMessage)) if (_use_preferred_target_(fLastMessage))
{ {
DBG(OUT("LOOPER: use preferred target\n")); PRINT(("LOOPER: use preferred target\n"));
handler = fPreferred; handler = fPreferred;
} }
else else
{ {
DBG(OUT("LOOPER: don't use preferred target\n")); PRINT(("LOOPER: don't use preferred target\n"));
/** /**
@note Here is where all the token stuff starts to @note Here is where all the token stuff starts to
make sense. How, exactly, do we determine make sense. How, exactly, do we determine
@@ -1362,16 +1362,16 @@ DBG(OUT("LOOPER: don't use preferred target\n"));
Amazingly, we happen to have a global mapping Amazingly, we happen to have a global mapping
of BHandler pointers to int32s! of BHandler pointers to int32s!
*/ */
DBG(OUT("LOOPER: use: %ld\n", _get_message_target_(fLastMessage))); PRINT(("LOOPER: use: %ld\n", _get_message_target_(fLastMessage)));
gDefaultTokens.GetToken(_get_message_target_(fLastMessage), gDefaultTokens.GetToken(_get_message_target_(fLastMessage),
B_HANDLER_TOKEN, B_HANDLER_TOKEN,
(void**)&handler); (void**)&handler);
DBG(OUT("LOOPER: handler: %p, this: %p\n", handler, this)); PRINT(("LOOPER: handler: %p, this: %p\n", handler, this));
} }
if (!handler) if (!handler)
{ {
DBG(OUT("LOOPER: no target handler, use this\n")); PRINT(("LOOPER: no target handler, use this\n"));
handler = this; handler = this;
} }
@@ -1387,14 +1387,14 @@ DBG(OUT("LOOPER: no target handler, use this\n"));
} }
else else
{ {
DBG(OUT("LOOPER: no scripting message\n")); PRINT(("LOOPER: no scripting message\n"));
} }
if (handler) if (handler)
{ {
// Do filtering // Do filtering
handler = top_level_filter(fLastMessage, handler); handler = top_level_filter(fLastMessage, handler);
DBG(OUT("LOOPER: top_level_filter(): %p\n", handler)); PRINT(("LOOPER: top_level_filter(): %p\n", handler));
if (handler && handler->Looper() == this) if (handler && handler->Looper() == this)
{ {
DispatchMessage(fLastMessage, handler); DispatchMessage(fLastMessage, handler);
@@ -1420,7 +1420,7 @@ DBG(OUT("LOOPER: top_level_filter(): %p\n", handler));
} }
} }
} }
DBG(OUT("BLooper::task_looper() done\n")); PRINT(("BLooper::task_looper() done\n"));
} }
//------------------------------------------------------------------------------ //------------------------------------------------------------------------------
void BLooper::do_quit_requested(BMessage* msg) void BLooper::do_quit_requested(BMessage* msg)