diff options
author | Phil Mesnier <mesnier_p@ociweb.com> | 2009-06-09 22:42:09 +0000 |
---|---|---|
committer | Phil Mesnier <mesnier_p@ociweb.com> | 2009-06-09 22:42:09 +0000 |
commit | bb1b776a28e0b6b0ee2cacad23fd3d830a790350 (patch) | |
tree | 9187496014d9c25f308daa9b9e7369ad92197c6c | |
parent | 18c7ea6c6dbfbc0a146ddaedeb4bc108c11e7565 (diff) | |
download | ATCD-bb1b776a28e0b6b0ee2cacad23fd3d830a790350.tar.gz |
Tue Jun 9 22:26:07 UTC 2009 Phil Mesnier <mesnier_p@ociweb.com>
* utils/README:
* utils/logWalker:
* NEWS:
Adding a new utility for parsing TAO debug log files.
-rw-r--r-- | TAO/ChangeLog | 8 | ||||
-rw-r--r-- | TAO/NEWS | 5 | ||||
-rw-r--r-- | TAO/utils/README | 3 | ||||
-rw-r--r-- | TAO/utils/logWalker/HostProcess.cpp | 281 | ||||
-rw-r--r-- | TAO/utils/logWalker/HostProcess.h | 61 | ||||
-rw-r--r-- | TAO/utils/logWalker/Invocation.cpp | 580 | ||||
-rw-r--r-- | TAO/utils/logWalker/Invocation.h | 131 | ||||
-rw-r--r-- | TAO/utils/logWalker/Log.cpp | 486 | ||||
-rw-r--r-- | TAO/utils/logWalker/Log.h | 50 | ||||
-rw-r--r-- | TAO/utils/logWalker/PeerObject.cpp | 47 | ||||
-rw-r--r-- | TAO/utils/logWalker/PeerObject.h | 38 | ||||
-rw-r--r-- | TAO/utils/logWalker/PeerProcess.cpp | 243 | ||||
-rw-r--r-- | TAO/utils/logWalker/PeerProcess.h | 73 | ||||
-rw-r--r-- | TAO/utils/logWalker/README | 118 | ||||
-rw-r--r-- | TAO/utils/logWalker/Session.cpp | 175 | ||||
-rw-r--r-- | TAO/utils/logWalker/Session.h | 44 | ||||
-rw-r--r-- | TAO/utils/logWalker/Thread.cpp | 133 | ||||
-rw-r--r-- | TAO/utils/logWalker/Thread.h | 50 | ||||
-rw-r--r-- | TAO/utils/logWalker/hello.mft | 4 | ||||
-rw-r--r-- | TAO/utils/logWalker/helloClient.log | 86 | ||||
-rw-r--r-- | TAO/utils/logWalker/helloServer.log | 80 | ||||
-rw-r--r-- | TAO/utils/logWalker/logWalker.cpp | 143 | ||||
-rw-r--r-- | TAO/utils/logWalker/logWalker.mpc | 6 |
23 files changed, 2845 insertions, 0 deletions
diff --git a/TAO/ChangeLog b/TAO/ChangeLog index 17e5f21759d..18f8b78108c 100644 --- a/TAO/ChangeLog +++ b/TAO/ChangeLog @@ -1,3 +1,11 @@ +Tue Jun 9 22:26:07 UTC 2009 Phil Mesnier <mesnier_p@ociweb.com> + + * utils/README: + * utils/logWalker: + * NEWS: + + Adding a new utility for parsing TAO debug log files. + Tue Jun 9 22:04:49 UTC 2009 William R. Otte <wotte@dre.vanderbilt.edu> * TAO_IDL/contrib/mcpp/internal.H: @@ -22,6 +22,11 @@ USER VISIBLE CHANGES BETWEEN TAO-1.6.9 and TAO-1.7.0 . Updated ZIOP to match the OMG Beta 2 specification +. Added a new utility, tao_logWalker, see utils/logWalker for details. + This tool analises a collection of log files containing output of + TAO running with -ORBDebuglevel 10, and generates a report showing + process, thread and invocation summaries. + USER VISIBLE CHANGES BETWEEN TAO-1.6.8 and TAO-1.6.9 ==================================================== diff --git a/TAO/utils/README b/TAO/utils/README index 712cfaf67a9..4dba0ab072f 100644 --- a/TAO/utils/README +++ b/TAO/utils/README @@ -9,6 +9,9 @@ with TAO. . IOR-parser -- The "ior-parser" utility is similar to catior, i.e,. parses IORs generated by ORBs. + . logWalker -- A way to make sense of large, complicated + TAO debug output logs. + . nslist -- This utility lists the current entries in the Naming Service in a nicely formatter manner. diff --git a/TAO/utils/logWalker/HostProcess.cpp b/TAO/utils/logWalker/HostProcess.cpp new file mode 100644 index 00000000000..27a979e1bf8 --- /dev/null +++ b/TAO/utils/logWalker/HostProcess.cpp @@ -0,0 +1,281 @@ +// $Id$ + +#include "HostProcess.h" +#include "Invocation.h" +#include "PeerProcess.h" +#include "Thread.h" + +#include "ace/OS_NS_stdio.h" + +HostProcess::HostProcess (const ACE_CString &src, long pid) + : pid_(pid), + logfile_name_(src), + closed_handles_(0) +{ +} + +HostProcess::~HostProcess (void) +{ + for (AddrList::ITERATOR i(this->endpoints_); + !i.done(); + i++) + { + delete reinterpret_cast<ACE_CString *>(i.next()->item_); + } + for (ThreadList::ITERATOR i(this->threads_); + !i.done(); + i++) + { + delete reinterpret_cast<Thread *>(i.next()->item_); + } + for (PeerProcs::ITERATOR i = clients_.begin(); i != clients_.end(); i++) + { + PeerProcs::ENTRY *entry; + if (i.next(entry) == 0) + break; + delete entry->item(); + } + for (PeerProcs::ITERATOR i = servers_.begin(); i != servers_.end(); i++) + { + PeerProcs::ENTRY *entry; + if (i.next(entry) == 0) + break; + delete entry->item(); + } +} + +void +HostProcess::proc_name (const ACE_CString &name) +{ + this->proc_name_ = name; +} + +const ACE_CString& +HostProcess::proc_name (void) const +{ + return this->proc_name_; +} + +Thread * +HostProcess::find_thread (long tid) +{ + Thread *thr; + for (ACE_DLList_Iterator<Thread> i(threads_); + !i.done(); + i.advance()) + { + i.next(thr); + if (thr->id() == tid) + return thr; + } + char alias[20]; + ACE_OS::sprintf (alias,"Thread[%d]",this->threads_.size() + 1); + thr = new Thread (tid, alias); + threads_.insert_tail (thr); + return thr; +} + +PeerProcess * +HostProcess::find_peer (long handle) +{ + PeerProcess *pp = 0; + if (this->clients_.find(handle,pp) != 0) + this->servers_.find(handle,pp); + return pp; +} + +long +HostProcess::pid (void) const +{ + return this->pid_; +} + +bool +HostProcess::has_endpoint (ACE_CString& addr) +{ + ACE_CString *a; + for (ACE_DLList_Iterator<ACE_CString> i(this->endpoints_); + !i.done(); + i.advance()) + { + i.next(a); + if (*a == addr) + return true; + } + return false; +} + +void +HostProcess::add_endpoint(ACE_CString &addr) +{ + this->endpoints_.insert_tail(new ACE_CString (addr)); +} + +void +HostProcess::add_peer(PeerProcess *peer, bool as_client) +{ + peer->set_owner (this); + PeerProcess *existing = this->find_peer(peer->handle()); + if (existing != 0) + { + ACE_DEBUG ((LM_DEBUG, + "add_peer, found existing for %d, is_closed = %d\n", + peer->handle(), existing->is_closed())); + } + PeerProcs *list = as_client ? &clients_ : &servers_; + long handle = peer->handle(); + list->bind (handle, peer); +} + +void +HostProcess::close_peer (long handle, size_t offset) +{ + PeerProcess *pp = 0; + --this->closed_handles_; + if (this->clients_.unbind(handle,pp) == 0) + { + pp->close (offset); + this->clients_.bind (this->closed_handles_, pp); + } + else if (this->servers_.unbind(handle,pp) == 0) + { + pp->close (offset); + this->servers_.bind (this->closed_handles_, pp); + } + return; +} + +void +HostProcess::dump_summary (ostream &strm) +{ + strm << "Host process " << this->proc_name_ << " pid(" << this->pid_ << ") from logfile " << this->logfile_name_ << endl; + size_t num = this->endpoints_.size(); + if (num > 0) + { + strm << " listening on "; + size_t count = 0; + for (ACE_DLList_Iterator <ACE_CString> t_iter (this->endpoints_); + !t_iter.done(); + t_iter.advance()) + { + ACE_CString *ep; + t_iter.next(ep); + strm << ep->c_str(); + if (++count < num) + strm << ", "; + } + strm << endl; + } + + strm << " " << threads_.size() << " threads"; + if (clients_.current_size() > 0) + strm << ", client to " << clients_.current_size(); + if (servers_.current_size() > 0) + strm << ", server to " << servers_.current_size(); + strm << endl; +} + +void +HostProcess::dump_ident (ostream &strm, const char *message) +{ + strm <<"\nHost process "; + if (this->proc_name_.length()) + strm << this->proc_name_; + strm << " pid (" << this->pid_ << ") " << message << endl; +} + +void +HostProcess::dump_thread_detail (ostream &strm) +{ + this->dump_ident (strm, " thread details:"); + for (ACE_DLList_Iterator <Thread> t_iter (this->threads_); + !t_iter.done(); + t_iter.advance()) + { + Thread *thr; + t_iter.next(thr); + thr->dump_detail (strm); + } +} + +void +HostProcess::dump_thread_invocations (ostream &strm) +{ + this->dump_ident (strm, " invocations by thread:"); + for (ACE_DLList_Iterator <Thread> t_iter (this->threads_); + !t_iter.done(); + t_iter.advance()) + { + Thread *thr; + t_iter.next(thr); + thr->dump_invocations (strm); + } +} + +void +HostProcess::dump_detail_list(ostream &strm, PeerProcs &list, int mode, Session *session) +{ + bool first = true; + for (PeerProcs::ITERATOR i = list.begin(); i !=list.end(); i++) + { + PeerProcs::ENTRY *entry; + if (i.next(entry) == 0) + break; + if (entry->item() == 0) + break; + switch (mode) + { + case 0: + entry->item()->dump_summary (strm); + break; + case 1: + entry->item()->dump_object_detail (strm); + strm << endl; + break; + case 2: + if (!first) + this->dump_ident (strm,"Invocations continued"); + entry->item()->dump_invocation_detail (strm); + strm << endl; + break; + case 3: + entry->item()->match_hosts (session); + break; + } + first = false; + } +} + +void +HostProcess::dump_peer_detail (ostream &strm) +{ + this->dump_ident (strm, " peer processes:"); + strm << this->clients_.current_size() << " clients" << endl; + this->dump_detail_list(strm, this->clients_, 0); + strm << this->servers_.current_size() << " servers" << endl; + this->dump_detail_list(strm, this->servers_, 0); +} + +void +HostProcess::dump_object_detail (ostream &strm) +{ + this->dump_ident (strm, " peer objects: "); + this->dump_detail_list(strm, this->clients_, 1); + this->dump_detail_list(strm, this->servers_, 1); +} + +void +HostProcess::dump_invocation_detail(ostream &strm) +{ + this->dump_ident (strm, " invocations: "); + this->dump_detail_list(strm, this->clients_, 2); + this->dump_detail_list(strm, this->servers_, 2); + this->dump_ident (strm, " end invocation report"); +} + +void +HostProcess::reconcile_peers (Session *session) +{ + this->dump_detail_list(cout, this->clients_, 3, session); + this->dump_detail_list(cout, this->servers_, 3, session); +} diff --git a/TAO/utils/logWalker/HostProcess.h b/TAO/utils/logWalker/HostProcess.h new file mode 100644 index 00000000000..014a0754f86 --- /dev/null +++ b/TAO/utils/logWalker/HostProcess.h @@ -0,0 +1,61 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_HOST_PROCESS_H +#define LOG_WALKER_HOST_PROCESS_H +#include "ace/SString.h" +#include "ace/Synch.h" +#include "ace/Containers.h" +#include "ace/Hash_Map_Manager.h" +#include "Invocation.h" +#include "PeerProcess.h" + +class Session; +class Thread; + +typedef ACE_DLList<Thread> ThreadList; +typedef ACE_DLList<ACE_CString> AddrList; +typedef ACE_Hash_Map_Manager<long, PeerProcess *, ACE_Null_Mutex> PeerProcs; + +class HostProcess +{ +public: + HostProcess (const ACE_CString &src, long pid); + ~HostProcess (void); + void proc_name (const ACE_CString &name); + const ACE_CString &proc_name (void) const; + Thread * find_thread (long tid); + long pid (void) const; + bool has_endpoint (ACE_CString& addr); + void add_endpoint (ACE_CString& addr); + void add_peer (PeerProcess *peer, bool as_client); + PeerProcess *find_peer (long handle); + void close_peer (long handle, size_t offset); + + void dump_ident (ostream &strm, const char *extra); + void dump_summary (ostream &strm); + void dump_thread_detail (ostream &strm); + void dump_thread_invocations (ostream &strm); + void dump_peer_detail (ostream &strm); + void dump_object_detail (ostream &strm); + void dump_invocation_detail (ostream &strm); + + void reconcile_peers (Session *session); + +private: + void dump_detail_list (ostream &strm, PeerProcs &list, int mode, Session * session = 0); + + long pid_; + ACE_CString logfile_name_; + ACE_CString proc_name_; + AddrList endpoints_; + ThreadList threads_; + PeerProcs clients_; + PeerProcs servers_; + // PeerProcs closed_; + long closed_handles_; +}; + +#endif // LOG_WALKER_HOST_PROCESS_H diff --git a/TAO/utils/logWalker/Invocation.cpp b/TAO/utils/logWalker/Invocation.cpp new file mode 100644 index 00000000000..0467cbe9054 --- /dev/null +++ b/TAO/utils/logWalker/Invocation.cpp @@ -0,0 +1,580 @@ +// $Id$ + +#include "Invocation.h" +#include "PeerProcess.h" +#include "PeerObject.h" +#include "Session.h" +#include "HostProcess.h" +#include "Thread.h" + +#include "ace/OS_NS_string.h" +#include "ace/CDR_Stream.h" +#include "ace/Log_Msg.h" +#include <stdio.h> + +static const char *size_leadin_1_5 = "GIOP v1.2 msg, "; +static const char *size_leadin_1_6 = "GIOP message v1.2, "; +static const char *size_leadin = 0; +static size_t leadin_len = 0; +static const size_t giop_header_len = 12; + +// GIOP 1.2 header: 12 bytes +// Magic: 4 +// ver: 2 +// flags: 1 // bo +// type: 1 // req/repl/lf/excp +// len: 4 +// +// Request 1.2 header: +// req_id: 4 +// flags: 1 +// RESVD: 3 +// Address disposition: 4 +// target: <4 len, + len> [0-3 pad] +// opname: <4 len, + len> + +static const size_t target_offset = giop_header_len + 12; +// 12 = req_id + flags + RESVD + addr disp. + +Invocation::GIOP_Buffer::GIOP_Buffer(const char *text, + size_t offset, + Thread *thread, + Invocation *owner) + : preamble_(text), + log_offset_(offset), + thr_(thread), + time_(0), + expected_req_id_(0), + expected_size_(0), + expected_type_(0), + size_(0), + wr_pos_ (0), + octets_ (0), + owner_ (owner), + buffer_lost_ (false), + sending_(false) +{ + const char *size_str = ACE_OS::strstr(text, size_leadin) + leadin_len; + const char *id = size_str == 0 ? 0 : ACE_OS::strchr(size_str, '[') + 1; + this->sending_ = ACE_OS::strstr(text,"send") ? 0 : 1; + this->expected_type_ = ACE_OS::strstr(text,"Request") ? 0 : 1; + this->expected_size_ = ACE_OS::strtol(size_str, 0,10) + giop_header_len; + this->expected_req_id_ = ACE_OS::strtol(id, 0, 10); + const char *time_tok = ACE_OS::strchr (text,'@'); + if (time_tok != 0) + { + char timebuf[30]; + ACE_OS::strncpy(timebuf, text, (time_tok - text)); + timebuf[time_tok - text] = 0; + char *hms = ACE_OS::strchr (timebuf,' '); + if (hms != 0) + hms = ACE_OS::strchr (hms + 1, ' '); + if (hms != 0) + { + int hr, min, sec, msec; + ::sscanf (hms+1,"%d:%d:%d.%d", &hr, &min, &sec, &msec); + this->time_ = (hr * 3600 + min *60 + sec) * 1000 + msec; + } + } +} + +void +Invocation::GIOP_Buffer::owner (Invocation *owner) +{ + this->owner_ = owner; +} + +Invocation * +Invocation::GIOP_Buffer::owner (void) +{ + return this->owner_; +} + +void +Invocation::GIOP_Buffer::init_buf (const char *text) +{ + // GIOP message - HEXDUMP + const char * size_str = ACE_OS::strstr(text,"HEXDUMP ") + 8; + this->size_ = ACE_OS::strtol(size_str, 0,10); + size_str = ACE_OS::strstr(text,"showing first "); + if (size_str != 0) + { + size_str += 14; + this->size_ = ACE_OS::strtol(size_str, 0, 10); + } + this->octets_ = new char [this->size_]; + ACE_OS::memset(this->octets_,this->size_,0); + this->wr_pos_ = this->octets_; +} + +Invocation::GIOP_Buffer::~GIOP_Buffer(void) +{ + delete [] this->octets_; +} + +int +Invocation::GIOP_Buffer::add_octets(const char *text) +{ + if (this->octets_ == 0) + { + this->init_buf(text); + return 0; + } + + const char *c = text; + char *err; + for (int count = 0; count < 16 && this->cur_size() < this->size_; count++) + { + if (count == 8) + ++c; + int o = ::strtol(c, &err, 16); + if (err == c || *err == 0) + return -1; + *this->wr_pos_++ = o; + c = err+1; + } + size_t cs = this->cur_size(); + return cs == this->size_ ? -1 : cs / 16; +} + +bool +Invocation::GIOP_Buffer::sending (void) const +{ + return this->sending_; +} + +bool +Invocation::GIOP_Buffer::is_full(void) const +{ + return this->size_ > 0 && this->cur_size() == this->size_; +} + +char +Invocation::GIOP_Buffer::type (void) const +{ + if (this->octets_ == 0) + return 127; + return this->octets_[7]; +} + +char +Invocation::GIOP_Buffer::expected_type (void) const +{ + return this->expected_type_; +} + +bool +Invocation::GIOP_Buffer::is_oneway(void) const +{ + if (this->octets_ == 0) + { + return false; + } + char mtype = this->octets_[7]; + if (mtype != 0) //GIOP_REQUEST + return false; + char flag = this->octets_[16]; // GIOP 1.2 request_header.response_flags + return (flag & 1) == 0; +} + +size_t +Invocation::GIOP_Buffer::log_posn (void) const +{ + return this->log_offset_; +} + +const Thread * +Invocation::GIOP_Buffer::thread (void) const +{ + return this->thr_; +} + +time_t +Invocation::GIOP_Buffer::time (void) const +{ + return this->time_; +} + +const ACE_CString & +Invocation::GIOP_Buffer::preamble(void) const +{ + return this->preamble_; +} + +size_t +Invocation::GIOP_Buffer::expected_size (void) const +{ + return this->expected_size_; +} + +size_t +Invocation::GIOP_Buffer::size(void) const +{ + return this->size_; +} + +size_t +Invocation::GIOP_Buffer::expected_req_id(void) const +{ + return this->expected_req_id_; +} + +size_t +Invocation::GIOP_Buffer::actual_req_id(void) const +{ + if (this->octets_ == 0) + return 0; + char vmaj = this->octets_[4]; + char vmin = this->octets_[5]; + char bo = this->octets_[6]; + + ACE_InputCDR cdr(this->octets_+giop_header_len, + this->cur_size() - giop_header_len, + bo, vmaj, vmin); + size_t rid; + cdr >> rid; + return rid; +} + +size_t +Invocation::GIOP_Buffer::cur_size(void) const +{ + return this->wr_pos_ - this->octets_; +} + +const char * +Invocation::GIOP_Buffer::target_oid(size_t &len) const +{ + if (this->octets_ == 0) + { + return 0; + } + char mtype = this->octets_[7]; + if (mtype != 0) //GIOP_REQUEST + return 0; + + char vmaj = this->octets_[4]; + char vmin = this->octets_[5]; + char bo = this->octets_[6]; + ACE_InputCDR cdr(this->octets_ + target_offset, + this->cur_size() - target_offset, + bo, vmaj, vmin); + cdr >> len; + if (target_offset + len > this->cur_size()) + { + len = 0; + return 0; + } + return this->octets_ + target_offset + 4; +} + +const char * +Invocation::GIOP_Buffer::operation(void) const +{ + if (octets_ == 0) + return 0; + + char mtype = this->octets_[7]; + if (mtype != 0) //GIOP_REQUEST + return 0; + + char vmaj = this->octets_[4]; + char vmin = this->octets_[5]; + char bo = this->octets_[6]; + ACE_InputCDR cdr(this->octets_ + target_offset, + this->cur_size() - target_offset, + bo, vmaj, vmin); + ACE_CDR::Long tgt_size; + cdr.read_long(tgt_size); + if (target_offset + tgt_size > this->cur_size()) + return 0; + cdr.skip_bytes(tgt_size); + cdr.read_long(tgt_size); + size_t offset = cdr.rd_ptr() - this->octets_; + if (offset + tgt_size > this->cur_size()) + return 0; + return this->octets_ + offset; +} + +bool +Invocation::GIOP_Buffer::validate (void) const +{ + return this->expected_req_id_ == this->actual_req_id() && + this->expected_type_ == this->type(); +} + +bool +Invocation::GIOP_Buffer::matches (Invocation::GIOP_Buffer *other) const +{ + return this->expected_req_id_ == other->actual_req_id() && + this->expected_type_ == other->type() && + this->expected_size_ == other->size(); +} + +void +Invocation::GIOP_Buffer::reset (void) +{ + this->octets_ = 0; + this->wr_pos_ = 0; + this->size_ = 0; + this->buffer_lost_ = true; +} + +void +Invocation::GIOP_Buffer::transfer_from (GIOP_Buffer *other) +{ + delete this->octets_; + this->octets_ = other->octets_; + this->wr_pos_ = other->wr_pos_; + this->size_ = other->size_; + other->reset(); +} + + +//---------------------------------------------------------------------------- + + +Invocation::Invocation (PeerProcess *peer, size_t rid) + :req_octets_(0), + repl_octets_(0), + peer_(peer), + req_id_(rid), + target_(0), + child_(0), + sibling_(0), + dumped_(false) +{ + if (size_leadin == 0) + { + size_leadin = Session::tao_version() == 150 ? + size_leadin_1_5 : size_leadin_1_6; + leadin_len = ACE_OS::strlen(size_leadin); + } +} + +Invocation::~Invocation (void) +{ + delete this->req_octets_; + delete this->repl_octets_; +} + +bool +Invocation::init (const char * text, size_t offset, Thread *thread) +{ + const char *size_str = ACE_OS::strstr(text, size_leadin); + const char *id = size_str == 0 ? 0 : ACE_OS::strchr(size_str, '['); + if (size_str == 0 || id == 0) + { + ACE_ERROR ((LM_ERROR, + "Not a request preamble:\n '%s'\n", + text)); + return false; + } + + + if( ACE_OS::strstr(text,"Request") == 0) + this->repl_octets_ = new GIOP_Buffer(text, offset, thread, this); + else + this->req_octets_ = new GIOP_Buffer(text, offset, thread, this); + return true; +} + +bool +Invocation::is_oneway(void) const +{ + return this->req_octets_ == 0 ? false : this->req_octets_->is_oneway(); +} + +void +Invocation::set_target (const char *oid, size_t oid_len) +{ + PeerObject *tgt = this->peer_->object_for (oid, oid_len); + if (tgt == 0) + return; + + if (this->target_ == 0) + { + this->target_ = tgt; + this->target_->add_invocation (this); + } +} + +bool +Invocation::message_complete (void) +{ + if (this->is_oneway()) + { + if (this->req_octets_ == 0 || !this->req_octets_->is_full()) + return false; + } + else + if (this->repl_octets_ == 0 || !this->repl_octets_->is_full()) + return false; + + return true; +} + +Invocation::GIOP_Buffer * +Invocation::octets (bool request) +{ + return request ? this->req_octets_ : this->repl_octets_ ; +} + +Invocation::GIOP_Buffer * +Invocation::give_octets (bool request) +{ + GIOP_Buffer *result = request ? this->req_octets_ : this->repl_octets_ ; + + if (request) + this->req_octets_ = 0; + else + this->repl_octets_ = 0; + return result; +} + +void +Invocation::set_octets (bool request, GIOP_Buffer *octets) +{ + if (request) + { + if (this->req_octets_ != 0) + { + return; + } + this->req_octets_ = octets; + } + else + { + if (this->repl_octets_ != 0) + { + return; + } + this->repl_octets_ = octets; + } + octets->owner(this); +} + +size_t +Invocation::request_id (void) const +{ + return this->req_octets_ == 0 ? this->req_id_ : this->req_octets_->expected_req_id(); +} + +size_t +Invocation::expected_size (void) const +{ + if (repl_octets_ != 0) + return repl_octets_->expected_size(); + return req_octets_->expected_size(); +} + + +void +Invocation::add_child(Invocation *child) +{ + if (this->child_ == 0) + this->child_ = child; + else + this->child_->add_sibling(child); +} + +void +Invocation::add_sibling(Invocation *sibling) +{ + if (this->sibling_ == 0) + this->sibling_ = sibling; + else + this->sibling_->add_sibling(sibling); +} + +Invocation * +Invocation::child(void) +{ + return this->child_; +} + +Invocation * +Invocation::sibling(void) +{ + return this->sibling_; +} + +void +Invocation::dump_detail (ostream &strm, int indent) +{ + if (this->dumped_) + return; + this->dumped_ = true; + const char *opname = ""; + const char *dir_1 = " to "; + const char *dir_2 = " in "; + + if (this->req_octets_ != 0) + { + opname = this->req_octets_->operation(); + if (this->req_octets_->sending()) + { + dir_1 = " for "; + dir_2 = " from "; + } + } + + for (int ind = 0; ind < indent; ind++) + strm << " "; + + if (opname == 0) + opname = "<no operation>"; + + strm << " " << this->req_id_ << dir_1; + if (this->target_ == 0) + strm << "<unknown object>" ; + else + strm << this->target_->name(); + strm << dir_2 << this->peer_->id() + << " [" << opname << "]\t"; + time_t req_time = 0; + time_t rep_time = 0; + long delta = 0; + if (!this->is_oneway() && this->req_octets_ != 0) + { + req_time = this->req_octets_->time(); + if (this->repl_octets_ != 0) + { + rep_time = this->repl_octets_->time(); + delta = this->repl_octets_->log_posn() - this->req_octets_->log_posn(); + } + } + if (req_time != 0 && rep_time != 0) + strm << " took " << (rep_time - req_time) << " ms"; + + if (this->req_octets_ != 0) + { + strm << " Request, line " << this->req_octets_->log_posn(); +// #if defined (SHOW_THREAD_ID) + strm << " " << this->req_octets_->thread()->alias(); +// #endif + } + else + strm << " <no request found>"; + if (this->is_oneway()) + strm << " oneway"; + else + { + if (this->repl_octets_ != 0) + { + strm << " Reply, line " << this->repl_octets_->log_posn(); +#if defined (SHOW_THREAD_ID) + strm << " " << this->repl_octets_->thread()->alias(); +#endif + } + else + strm << " <no reply found>"; + } + if (delta > 0) + strm << " log offset = " << delta; + strm << endl; + if (this->child_ != 0) + child_->dump_detail(strm, indent+1); + if (this->sibling_ != 0) + sibling_->dump_detail (strm, indent); +} diff --git a/TAO/utils/logWalker/Invocation.h b/TAO/utils/logWalker/Invocation.h new file mode 100644 index 00000000000..d6c79853cda --- /dev/null +++ b/TAO/utils/logWalker/Invocation.h @@ -0,0 +1,131 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_INVOCATION_H +#define LOG_WALKER_INVOCATION_H + +#include <stdlib.h> +#include "ace/SString.h" + +class PeerProcess; +class PeerObject; +class Thread; + +// Invocation holds the buffer contents for a request/response pair. +// This could be originating in this process, or in the peer process. +// +// The trigger for finding a new outgoing invocation is "Muxed_TMS[%d]" +// following that the process/thread will perform a dump_msg. +// +// The trigger for finding a new incoming invocation is +// "Transport[%d]::process_parsed_messages, entering (missing data == 0)" +// which could indicate a new request or reply, depending on the context +// in which the peer connection is made. +// +// It is possible that two or more threads may call dump_msg +// concurrently and thus have the preamble and body printed out of +// order. The HEXDUMP always reports a buffer size including the 12 +// byte GIOP header. Also, the first line of the text contains header +// data which can be compared to the expected request ID. + +class Invocation +{ +public: + class GIOP_Buffer + { + public: + GIOP_Buffer (const char *text, size_t offset, Thread *thread, Invocation *owner = 0); + ~GIOP_Buffer (void); + void owner (Invocation *); + Invocation *owner (void); + void init_buf (const char *text); + int add_octets(const char *text); + char type (void) const; + char expected_type (void) const; + bool sending (void) const; + bool is_oneway (void) const; + bool is_full (void) const; + size_t log_posn (void) const; + const Thread *thread (void) const; + time_t time (void) const; + + const ACE_CString &preamble(void) const; + size_t expected_req_id(void) const; + size_t actual_req_id(void) const; + size_t expected_size (void) const; + size_t size (void) const; + size_t cur_size(void) const; + const char * target_oid (size_t &len) const; + const char * operation (void) const; + bool validate (void) const; + bool matches (GIOP_Buffer *other) const; + void reset (void); + void transfer_from (GIOP_Buffer *other); + + private: + ACE_CString preamble_; + size_t log_offset_; + Thread *thr_; + time_t time_; + size_t expected_req_id_; + size_t expected_size_; + char expected_type_; + size_t size_; + char * wr_pos_; + char * octets_; + Invocation *owner_; + bool buffer_lost_; + bool sending_; + }; + + // initialize a new instance, with the initial request text line and offeset + Invocation (PeerProcess *peer, size_t req_id = 0); + bool init ( const char * text, size_t offset, Thread *thr); + ~Invocation (void); + + // return true if the invocation was a oneway + bool is_oneway(void) const; + + void set_target (const char *oid, size_t oid_len); + + // return true if the request is a oneway and has all its octets, or + // if it also has all its reply octets. The side-effect of this call + // is to obtain the target reference from the request buffer and associate + // it with the peer process. + bool message_complete (void); + + size_t request_id (void) const; + + // returns the size parsed from either the request or reply preamble + // which can be used to match a HEXDUMP b + size_t expected_size (void) const; + + void set_octets (bool request, GIOP_Buffer *octets); + GIOP_Buffer *octets (bool request); + GIOP_Buffer *give_octets (bool request); + + void dump_detail (ostream &strm, int indent); + + void add_child(Invocation *child); + void add_sibling(Invocation *sibling); + + Invocation *child(void); + Invocation *sibling(void); + +private: + GIOP_Buffer *req_octets_; + GIOP_Buffer *repl_octets_; + + PeerProcess *peer_; + size_t req_id_; + PeerObject *target_; + + Invocation *child_; + Invocation *sibling_; + + bool dumped_; +}; + +#endif // LOG_WALKER_INVOCATION_H diff --git a/TAO/utils/logWalker/Log.cpp b/TAO/utils/logWalker/Log.cpp new file mode 100644 index 00000000000..ef103e7a00d --- /dev/null +++ b/TAO/utils/logWalker/Log.cpp @@ -0,0 +1,486 @@ +// $Id$ + +#include "Log.h" +#include "Invocation.h" +#include "PeerProcess.h" +#include "HostProcess.h" +#include "Session.h" +#include "Thread.h" + +#include "ace/Mem_Map.h" + +Log::Log (Session &session) + : session_(session), + dump_target_(0) +{ +} + +Log::~Log (void) +{ +} + +bool +Log::init (ACE_TCHAR *filename, const char *alias) +{ + this->origin_ = ACE_TEXT_ALWAYS_CHAR (filename); + this->alias_ = alias; + + ACE_Mem_Map mapped_file; + int result = mapped_file.map(filename); + if (result == -1) + return false; + + size_t mapsize = mapped_file.size(); + char *base = reinterpret_cast<char *>(mapped_file.addr()); + if (mapsize == 0 || base == 0) + { + mapped_file.close(); + return false; + } + + size_t remainder = mapsize; + size_t linelen = 0; + char *line; + size_t maxline = 1000; + char *buffer = new char[maxline]; + size_t line_pos = 1; + while ((line = ACE_OS::strchr(base,'\n')) != 0) + { + linelen = line - base; + if (linelen >= maxline) + { + delete [] buffer; + buffer = 0; + maxline = linelen + 100; + buffer = new char[maxline]; + } + ACE_OS::strncpy(buffer,base,linelen); + buffer[linelen] = 0; + this->parse_line (buffer, line_pos); + base = line+1; + ++line_pos; + remainder -= linelen; + if (remainder < 1) + break; + } + + delete [] buffer; + + mapped_file.close(); + + return true; +} + +bool +Log::get_pid_tid (long &pid, long &tid, char *line) +{ + const char * p = ACE_OS::strstr (line, "TAO ("); + char * t = 0; + if (p == 0) + return false; + + pid = ACE_OS::strtol(p+5,&t,10); + tid = ACE_OS::strtol(t+1,0,10); + return true; +} + +HostProcess * +Log::get_host (long pid) +{ + HostProcess *hp = 0; + if (pid == 0) + return 0; + for (ACE_DLList_Iterator<HostProcess> i (this->procs_); + !i.done(); + i.advance()) + { + i.next(hp); + if (hp->pid() == pid) + return hp; + } + hp = this->session_.find_process(pid); + if (hp != 0) + return hp; + + size_t numprocs = this->procs_.size(); + hp = new HostProcess (this->origin_,pid); + this->procs_.insert_tail(hp); + if (this->alias_.length() > 0) + { + switch (numprocs) + { + case 0: + hp->proc_name(alias_); + break; + case 1: + { + ACE_CString a2 = alias_ + "_1"; + HostProcess *first; + if (this->procs_.get(first) == 0) + first->proc_name(a2); + } + //fallthru + default: + { + char ext[10]; + ACE_OS::sprintf(ext,"_%d",numprocs+1); + ACE_CString a2 = alias_ + ext; + hp->proc_name(a2); + } + } + } + this->session_.add_process(hp); + return hp; +} + +void +Log::parse_line (char *line, size_t offset) +{ + // first, is it a client connection to a new peer? + // next is it a server connection to a new peer? + // is it a new request or reply? + // a GIOP hex dump? + + static const char * exprs[] = { + "make_connection, new connected", + "Handler::open, IIOP connection to peer", + "GIOP_Message_Base::dump_msg,", + "GIOP message - HEXDUMP", + "open_i, listening on:", + "Muxed_TMS[", // initiating new request + "process_parsed_messages", // server side new incoming + "wait_for_event", + "::cleanup_queue, byte_count", + "close_connection_eh", + "IIOP_Connector::begin_connection, to ", + "IIOP_Connection_Handler::open, The local addr is", + "opened as TAO_SERVER_ROLE", + //connection to peer closed. + 0 + }; + + if (this->dump_target_ != 0) + { + int pos = this->dump_target_->add_octets(line); + if (pos == 1) // need to validate target + { + if (!this->dump_target_->validate()) + { + for (ACE_DLList_Iterator<Thread> t_iter(this->giop_waiters_); + !t_iter.done(); + t_iter.advance()) + { + Thread *th = 0; + t_iter.next(th); + Invocation::GIOP_Buffer *new_target = th->giop_target(); + if (new_target == 0 || new_target == this->dump_target_) + continue; + if (new_target->matches (this->dump_target_)) + { + new_target->transfer_from (this->dump_target_); + this->dump_target_ = new_target; + th->exit_wait(th->incoming(), offset); + t_iter.remove(); + break; + } + } + } + else + { + for (ACE_DLList_Iterator<Thread> t_iter(this->giop_waiters_); + !t_iter.done(); + t_iter.advance()) + { + Thread *th = 0; + t_iter.next(th); + if (this->dump_target_ == th->giop_target()) + { + th->exit_wait(th->incoming(), offset); + t_iter.remove(); + break; + } + } + } + } + else if (pos == -1) // done + { + Invocation *inv = this->dump_target_->owner(); + if (inv != 0) + { + size_t len = 0; + const char *oid = this->dump_target_->target_oid(len); + if (oid != 0) + inv->set_target (oid, len); + } + + this->dump_target_ = 0; + } + return; + } + + int i = 0; + for (; exprs[i] != 0; i++) + { + if (ACE_OS::strstr(line, exprs[i]) != 0) + break; + } + if (exprs[i] == 0) + return; + + long pid = 0; + long tid = 0; + this->get_pid_tid(pid,tid,line); + + HostProcess *hp = this->get_host(pid); + Thread *thr = hp == 0 ? 0 : hp->find_thread (tid); + + switch (i) + { + case 0: //"make_connection, new connected" + {// no longer needed... at least for now. + break; + } + case 1: // "Handler::open, IIOP connection to peer" + { + char *addr = ACE_OS::strchr(line,'<') +1; + char *c = ACE_OS::strchr(addr,'>'); + *c = '\0'; + c = ACE_OS::strstr(c+1,"on "); + long handle = ACE_OS::strtol(c + 3,0,10); + PeerProcess *pp = thr->pending_peer(); + if (pp == 0) + { + ACE_ERROR ((LM_ERROR,"no pending peer for file %s, line %d\n", + this->origin_.c_str(), offset)); + break; + } + if (!pp->is_client()) + { + pp->set_addr(addr,false); + } + thr->pending_peer(0); + pp->handle(handle); + hp->add_peer(pp, pp->is_client()); + break; + } + case 2: //GIOP_Message_Base::dump_msg, + { + int mode = ACE_OS::strstr (line,"send") != 0 ? 0 : 1; + mode += ACE_OS::strstr (line,"Request") != 0 ? 0 : 2; + char *pos = strrchr (line,'['); + long rid = ACE_OS::strtol(pos+1, 0, 10); + PeerProcess *pp = thr->incoming(); + if (pp == 0) + { + ACE_ERROR((LM_ERROR,"dump_msg, could not find pp for incoming\n")); + break; + } + if (mode < 2) + thr->enter_wait(pp); + Invocation::GIOP_Buffer *target = 0; + switch (mode) + { + case 1: { // receiving request + Invocation *inv = pp->new_invocation (rid); + if (inv == 0) + { + ACE_ERROR ((LM_ERROR, + "process %d already has invocation " + "%d, at line %d\n", + pp->handle(), rid, offset)); + break; + } + inv->init (line, offset, thr); + target = inv->octets(true); + break; + } + case 0: // sending request + case 3: { // receiving reply + Invocation *inv = pp->find_invocation(rid); + if (inv == 0) + { + ACE_ERROR ((LM_ERROR,"line %d, could not find existing invocation for req_id %d\n", + offset, rid)); + inv = pp->new_invocation (rid); + } + inv->init (line, offset, thr); + target = inv->octets(mode == 0); + if (mode == 3) + thr->exit_wait(pp, offset); + break; + } + case 2: { // sending reply + target = new Invocation::GIOP_Buffer(line,offset, thr); + break; + } + default:; + } + + thr->set_giop_target (target); + this->giop_waiters_.insert_tail(thr); + break; + } + case 3: // "GIOP message - HEXDUMP" + { + char *pos = ACE_OS::strstr (line,"HEXDUMP"); + pos += 8; + size_t len = ACE_OS::strtol (pos, 0, 10); + for (ACE_DLList_Reverse_Iterator<Thread> t_iter(this->giop_waiters_); + !t_iter.done(); + t_iter.advance()) + { + t_iter.next(thr); + Invocation::GIOP_Buffer *target = thr->giop_target(); + if (target == 0 || target->expected_size() != len || target->size() > 0) + continue; + this->dump_target_ = target; + break; + } + if (this->dump_target_ == 0) + { + ACE_ERROR ((LM_ERROR, + "Could not find a giop waiter for size %d, offset = %d\n", + len, offset)); + } + else + this->dump_target_->init_buf (line); + break; + } + case 4: // "open_i, listening on:" + { + char *addr = ACE_OS::strchr(line,'<') +1; + char *c = ACE_OS::strchr(addr,'>'); + *c = '\0'; + ACE_CString s_addr(addr); + hp->add_endpoint(s_addr); + break; + } + case 5: // "Muxed_TMS" + { + char *hpos = ACE_OS::strchr(line,'['); + long handle = ACE_OS::strtol(hpos+1,0,10); + hpos = ACE_OS::strchr(hpos, '<'); + long req_id = ACE_OS::strtol(hpos+1,0,10); + PeerProcess *pp = hp->find_peer(handle); + if (pp == 0) + { + ACE_ERROR ((LM_ERROR, + "Error parsing %C, line %d, can't find peer " + "for handle %d, text = %s\n", + this->origin_.c_str(), offset, handle, line)); + break; + } + + pp->new_invocation(req_id); + thr->incoming_from (pp); + break; + } + case 6: // "process_parsed_messages" + { + char *hpos = ACE_OS::strchr(line,'['); + long handle = ACE_OS::strtol(hpos+1,0,10); + + PeerProcess *pp = hp->find_peer(handle); + if (pp == 0) + { + ACE_ERROR ((LM_ERROR, + "Error parsing %C, line %d, can't find peer " + "for handle %d, text = %s\n", + this->origin_.c_str(), offset, handle, line)); + break; + } + thr->incoming_from (pp); + break; + } + case 7: // "wait_for_event" + { + // thr->exit_wait()? + break; + } + case 8: // cleanup_queue + { + char *hpos = ACE_OS::strchr(line,'['); + long handle = ACE_OS::strtol(hpos+1,0,10); + PeerProcess *pp = hp->find_peer(handle); + Invocation::GIOP_Buffer *target = thr->giop_target(); + thr->set_giop_target(0); + if (target != 0 && target->owner() == 0) + { + size_t rid = target->actual_req_id(); + char mtype = target->type(); + Invocation *inv = pp->find_invocation(rid); + if (inv == 0) + { + ACE_ERROR ((LM_ERROR, + "Cleanup queue detected at line %d, " + "could not find invocation for rid = %d\n", + offset, rid)); + rid = target->expected_req_id(); + inv = pp->find_invocation (rid); + if (inv == 0) + { + ACE_ERROR ((LM_ERROR, + "Cleanup queue still failed to find rid %d\n", + rid)); + break; + } + thr->exit_wait(pp, offset); + mtype = target->expected_type(); + } + inv->set_octets (mtype == 0, target); + size_t len = 0; + const char *oid = target->target_oid(len); + if (mtype == 0 && len > 0) + inv->set_target (oid, len); + } + break; + } + case 9: // close_connection_eh + { + char *hpos = ACE_OS::strchr(line,'['); + long handle = ACE_OS::strtol(hpos+1,0,10); + hp->close_peer (handle,offset); + break; + } + case 10: // IIOP_Connector::begin_connection + { + char *addr = ACE_OS::strchr(line,'<') +1; + char *c = ACE_OS::strchr(addr,'>'); + *c = '\0'; + thr->pending_peer (new PeerProcess(line,offset,true,addr,0)); + break; + } + case 11: // IIOP_Connection_Handler::open, The local addr is + { + PeerProcess *peer = thr->pending_peer(); + if (peer == 0) + ACE_ERROR((LM_ERROR, "file %s, line %d, no pending client or server\n", + this->origin_.c_str(), offset)); + else + { + char *addr = ACE_OS::strchr(line,'<') +1; + char *c = ACE_OS::strchr(addr,'>'); + *c = '\0'; + peer->set_addr(addr, true); + ACE_CString s_addr(addr); + hp->add_endpoint(s_addr); + } + break; + } + case 12: // opened as TAO_SERVER_ROLE + { + thr->pending_peer (new PeerProcess(line,offset,false,"",0)); + break; + } + default: // future expansion + { + break; + } + } +} + +void +Log::summarize (void) +{ + // todo +} diff --git a/TAO/utils/logWalker/Log.h b/TAO/utils/logWalker/Log.h new file mode 100644 index 00000000000..ce403346afe --- /dev/null +++ b/TAO/utils/logWalker/Log.h @@ -0,0 +1,50 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_LOG_H +#define LOG_WALKER_LOG_H + +#include "ace/Containers.h" +#include "ace/Synch.h" +#include "ace/SString.h" +#include "PeerProcess.h" +#include "HostProcess.h" + +class Session; +class HostProcess; + +typedef ACE_DLList<HostProcess> HostProcesses; +typedef ACE_DLList<PeerProcess> PeerProcesses; + + +class Log +{ +public: + Log (Session &s); + + ~Log(); + + bool init (ACE_TCHAR *filename, const char *alias = ""); + void parse_line (char* line, size_t offset); + + void summarize(void); + + void dump (ostream &strm); + +private: + bool get_pid_tid (long &pid, long &tid, char *line); + HostProcess *get_host (long pid); + + ACE_CString origin_; + ACE_CString alias_; + Session &session_; + HostProcesses procs_; +// PeerProcesses peers_; + Invocation::GIOP_Buffer* dump_target_; + ThreadList giop_waiters_; + +}; + +#endif // LOG_WALKER_LOG_H diff --git a/TAO/utils/logWalker/PeerObject.cpp b/TAO/utils/logWalker/PeerObject.cpp new file mode 100644 index 00000000000..3cf504bcb5e --- /dev/null +++ b/TAO/utils/logWalker/PeerObject.cpp @@ -0,0 +1,47 @@ +// $Id$ + + +#include "PeerObject.h" +#include "Invocation.h" + +PeerObject::PeerObject (long id, const char *name, PeerProcess *parent) + :ident_(id), + name_(name), + parent_(parent) +{ +} + +PeerObject::~PeerObject (void) +{ +} + +ACE_CString & +PeerObject::name (void) +{ + return this->name_; +} + +long +PeerObject::ident (void) +{ + return this->ident_; +} + +void +PeerObject::add_invocation (Invocation *inv) +{ + this->invocations_.enqueue_tail (inv); +} +size_t +PeerObject::num_invocations (void) +{ + return this->invocations_.size(); +} + +void +PeerObject::dump_detail (ostream &strm) +{ + strm << this->ident_ << " has " + << this->invocations_.size() << " invocations" << endl; + +} diff --git a/TAO/utils/logWalker/PeerObject.h b/TAO/utils/logWalker/PeerObject.h new file mode 100644 index 00000000000..7a7be19bd68 --- /dev/null +++ b/TAO/utils/logWalker/PeerObject.h @@ -0,0 +1,38 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_PEER_OBJECT_H +#define LOG_WALKER_PEER_OBJECT_H + +#include "ace/SString.h" +#include "ace/Unbounded_Queue.h" +#include "ace/streams.h" + +class PeerProcess; +class Invocation; + +typedef ACE_Unbounded_Queue<Invocation*> Invocations; +typedef ACE_Unbounded_Queue_Iterator<Invocation*> InvocationIter; + +class PeerObject +{ +public: + PeerObject (long ident, const char *name, PeerProcess *parent); + virtual ~PeerObject (void); + + void add_invocation (Invocation *inv); + void dump_detail (ostream &strm); + size_t num_invocations (void); + long ident (void); + ACE_CString &name (void); + +private: + long ident_; + ACE_CString name_; + PeerProcess *parent_; + Invocations invocations_; +}; + +#endif // LOG_WALKER_PEER_OBJECT_H diff --git a/TAO/utils/logWalker/PeerProcess.cpp b/TAO/utils/logWalker/PeerProcess.cpp new file mode 100644 index 00000000000..b02abd2f637 --- /dev/null +++ b/TAO/utils/logWalker/PeerProcess.cpp @@ -0,0 +1,243 @@ +// $Id$ + +#include "PeerProcess.h" +#include "PeerObject.h" +#include "ace/OS_NS_stdio.h" +#include "ace/ACE.h" +#include "Invocation.h" +#include "HostProcess.h" +#include "Session.h" + +char * +PeerProcess::nextIdent(void) +{ + static int count = 0; + char *ident = new char[15]; + ACE_OS::sprintf (ident,"proc_%d", count++); + return ident; +} + +PeerProcess::PeerProcess (const char *text, + size_t offset, + bool as_client, + const char *target, + long handle) + : owner_ (0), + remote_ (0), + local_addr_(), + remote_addr_(target), + handle_(handle), + client_(as_client), + origin_(text), + origin_offset_ (offset), + closed_offset_ (0), + objects_ () +{ + this->ident_ = PeerProcess::nextIdent(); +} + +PeerProcess::~PeerProcess (void) +{ + delete [] ident_; + while (this->invocations_.size()) + { + Invocation *head = this->invocations_.delete_head(); + delete head; + } + for (PeerObjectTable::ITERATOR i = objects_.begin(); i != objects_.end(); i++) + { + PeerObjectTable::ENTRY *entry; + if (i.next(entry) == 0) + break; + delete entry->item(); + } +} + +void +PeerProcess::set_addr (const char *addr, bool local) +{ + if (local) + this->local_addr_ = addr; + else + this->remote_addr_ = addr; +} + +void +PeerProcess::match_hosts (Session *session) +{ + if (this->remote_addr_.length () > 0) + this->remote_ = session->find_host(this->remote_addr_.c_str()); +} + +void +PeerProcess::handle (long h) +{ + this->handle_ = h; +} + +long +PeerProcess::handle (void) const +{ + return this->handle_; +} + +const char * +PeerProcess::id (void) const +{ + if (this->remote_ != 0) + { + const ACE_CString &pname = this->remote_->proc_name(); + if (pname.length() > 0) + return pname.c_str(); + } + + return this->ident_; +} + +void +PeerProcess::close (size_t offset) +{ + this->closed_offset_ = offset; +} + +bool +PeerProcess::is_closed (void) const +{ + return this->closed_offset_ > 0; +} + +bool +PeerProcess::is_client (void) const +{ + return this->client_; +} + +PeerObject * +PeerProcess::object_for (const char *oid, size_t len) +{ + PeerObject *po; + u_long key = ACE::hash_pjw (oid,len); + int result = objects_.find(key, po); + if (result == -1) + { + long index = static_cast<long>(objects_.current_size()); + char alias[20]; + ACE_OS::sprintf (alias, "obj_%d", index); + po = new PeerObject(index,alias, this); + objects_.bind(key, po); + } + return po; +} + +Invocation * +PeerProcess::new_invocation (size_t req_id) +{ + if (this->find_invocation (req_id) != 0) + return 0; + Invocation *inv = new Invocation (this, req_id); + this->invocations_.insert_tail(inv); + return inv; +} + +Invocation * +PeerProcess::find_invocation (size_t req_id) +{ + Invocation *inv; + for (ACE_DLList_Reverse_Iterator<Invocation> i(this->invocations_); + !i.done(); + i.advance()) + { + i.next(inv); + if (inv->request_id() == req_id) + { + return inv; + } + } + return 0; +} + +Invocation * +PeerProcess::find_invocation_size (size_t len) +{ + Invocation *inv; + for (ACE_DLList_Reverse_Iterator<Invocation> i(this->invocations_); + !i.done(); + i.advance()) + { + i.next(inv); + if (!inv->message_complete() && inv->expected_size() == len) + { + return inv; + } + } + return 0; +} + +void +PeerProcess::set_owner (HostProcess *hp) +{ + this->owner_ = hp; +} + +HostProcess * +PeerProcess::owner (void) +{ + return this->owner_; +} + +void +PeerProcess::dump_summary (ostream &strm) +{ + strm << " peer process " << this->ident_ << " handle[" + << this->handle_ << "] as "; + if (this->client_) + strm << "client on " + << this->local_addr_; + else + strm << " server"; + if (this->remote_) + { + strm << " to " << remote_->proc_name(); + } + else + strm << " to peer at " << this->remote_addr_; + strm << " referenced " << this->objects_.current_size() + << " objects in " << this->invocations_.size() << " invocations"; + if (this->is_closed()) + strm << " closed on line " << this->closed_offset_; + strm << endl; +} + +void +PeerProcess::dump_object_detail (ostream &strm) +{ + strm << this->objects_.current_size() + << " Objects referenced in " << this->ident_ << ":" << endl; + size_t count_inv = 0; + for (PeerObjectTable::ITERATOR i = this->objects_.begin(); + i != this->objects_.end(); + i++) + { + PeerObjectTable::ENTRY *entry; + i.next (entry); + PeerObject *obj = entry->item(); + obj->dump_detail (strm); + count_inv += obj->num_invocations(); + } + strm << "Total of " << count_inv << " invocations " << endl; +} + +void +PeerProcess::dump_invocation_detail (ostream &strm) +{ + strm << "\n " << this->invocations_.size() << " Invocations with " << this->ident_ << ":" << endl; + Invocation *inv = 0; + for (ACE_DLList_Iterator<Invocation> i(this->invocations_); + !i.done(); + i.advance()) + { + i.next(inv); + inv->dump_detail(strm, 0); + } + +} diff --git a/TAO/utils/logWalker/PeerProcess.h b/TAO/utils/logWalker/PeerProcess.h new file mode 100644 index 00000000000..688bbcc9d05 --- /dev/null +++ b/TAO/utils/logWalker/PeerProcess.h @@ -0,0 +1,73 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_PEER_PROCESS_H +#define LOG_WALKER_PEER_PROCESS_H + +#include "ace/SString.h" +#include "ace/Synch.h" +#include "ace/Hash_Map_Manager.h" +#include "ace/Containers.h" +#include "ace/streams.h" + +class PeerObject; +class HostProcess; +class Invocation; +class Session; + +typedef ACE_Hash_Map_Manager<u_long, PeerObject*, ACE_Null_Mutex> PeerObjectTable; +typedef ACE_DLList<Invocation> InvocationList; + +class PeerProcess +{ +public: + static char *nextIdent(void); + PeerProcess (const char *text, + size_t offset, + bool as_client, + const char *target_addr, + long handle_); + ~PeerProcess (void); + void handle (long h); + long handle (void) const; + bool is_client (void) const; + const char * id (void) const; + + void set_owner (HostProcess *host); + HostProcess *owner (void); + + void match_hosts (Session *session); + void set_addr (const char *addr, bool local); + bool match_local (const char *addr) const; + + void close (size_t offset); + bool is_closed (void) const; + + Invocation *new_invocation (size_t req_id); + Invocation *find_invocation (size_t req_id); + Invocation *find_invocation_size (size_t len); + + PeerObject *object_for(const char *oid, size_t len); + + void dump_summary (ostream &strm); + void dump_object_detail (ostream &strm); + void dump_invocation_detail (ostream &strm); + +private: + char *ident_; + HostProcess *owner_; + HostProcess *remote_; + ACE_CString local_addr_; + ACE_CString remote_addr_; + long handle_; + bool client_; + ACE_CString origin_; + size_t origin_offset_; + size_t closed_offset_; + PeerObjectTable objects_; + InvocationList invocations_; +}; + +#endif // LOG_WALKER_PEER_PROCESS_H diff --git a/TAO/utils/logWalker/README b/TAO/utils/logWalker/README new file mode 100644 index 00000000000..4e2bd883ffe --- /dev/null +++ b/TAO/utils/logWalker/README @@ -0,0 +1,118 @@ +$Id$ + +This utility is intended to assist in the analysis of large debug output +files generated with -ORBDebuglevel 10. The utility summarizes thread, +connection, and invocation details for a collection of related processes. + +This is a work in progress. It currently is limited to parsing logs of +IIOP based apps only. + +The executable is installed as $ACE_ROOT/bin/tao_logWalker. + +The command line options are: + + -t <version> where <version> represents a TAO minor version + number, currently only 1.5 and 1.6 are supported. + As variations in logfile output bound to version + are found, this option will expand and may include + micro release numbers as well. Default is 1.6. + + -o <filename> redirects the output to the named file rather than + standard out. + + -p <name=value> allows the tagging of processes participating in + a logged run, but for which no log file exists. The + name in this case is some alias which will appear in + the output, and value is the TCP endpoint used by + the phantom process. + + -a <name=value> allows for substitution of addresses. Some endpoints + may be logged using a hostname, while other instances + may appear as an IP address. This is a simple means + of substituting one for the other to improve the + recognition of a peer process. + + -m <filename> read argument from the named manifest file. For + repeated analysis of may perhaps distributed log files, + use a manifest file to minimize keying in long command + lines. Each line of the file contains one full argument. + + [alias=]logfile provide as many log files as needed. The optional + alias gives a way to assign a useful name to the process + that generated the log output in the file. If many + processes shared a logfile so that their output is + comingled or consecutive, each process instance will be + given an indexed alias such as alias_1, alias_2, etc. + +Below is a sample output resulting from a run of tests/Hello, which can be +reproduced by running: ./tao_logWalker -m hello.mft + + +Session summary report: 2 Processes detected. +Host process HelloServer pid(8447) from logfile helloServer.log + listening on phil.ociweb.com:33152, 10.201.200.173:33152 + 1 threads, server to 1 +Host process HelloClient pid(8448) from logfile helloClient.log + listening on 10.201.200.173:40203 + 1 threads, client to 1 + + + +Session detail threads report: + +Host process HelloServer pid (8447) thread details: + Thread[1] tid = 2147483647 2 encounters + +Host process HelloClient pid (8448) thread details: + Thread[1] tid = 2147483647 2 encounters + + + +Session detail peer process report: + +Host process HelloServer pid (8447) peer processes: +0 clients +1 servers + peer process proc_0 handle[8] as server to HelloClient referenced 1 objects in 2 invocations closed on line 71 + +Host process HelloClient pid (8448) peer processes: +1 clients + peer process proc_1 handle[7] as client on 10.201.200.173:40203 to HelloServer referenced 1 objects in 2 invocations closed on line 77 +0 servers + + + +Session detail object report: + +Host process HelloServer pid (8447) peer objects: +1 Objects referenced in proc_0: +0 has 2 invocations +Total of 2 invocations + + +Host process HelloClient pid (8448) peer objects: +1 Objects referenced in proc_1: +0 has 2 invocations +Total of 2 invocations + + + + +Session detail invocation report: + +Host process HelloServer pid (8447) invocations: + + 2 Invocations with proc_0: + 1 for obj_0 from HelloClient [get_string] Request, line 30 Thread[1] Reply, line 37 log offset = 7 + 2 for obj_0 from HelloClient [shutdown] Request, line 58 Thread[1] oneway + +Host process HelloServer pid (8447) end invocation report + +Host process HelloClient pid (8448) invocations: + + 2 Invocations with proc_1: + 1 to obj_0 in HelloServer [get_string] Request, line 27 Thread[1] Reply, line 49 log offset = 22 + 2 to obj_0 in HelloServer [shutdown] Request, line 62 Thread[1] oneway + +Host process HelloClient pid (8448) end invocation report + diff --git a/TAO/utils/logWalker/Session.cpp b/TAO/utils/logWalker/Session.cpp new file mode 100644 index 00000000000..386f88cf12b --- /dev/null +++ b/TAO/utils/logWalker/Session.cpp @@ -0,0 +1,175 @@ +// $Id$ + +#include "Session.h" +#include "HostProcess.h" +#include "Log.h" +#include "ace/OS_NS_strings.h" +#include "ace/SString.h" + +long +Session::tao_version_ = 160; + +Session::Session (void) +{ + ACE_CString n ("localhost"); + ACE_CString v ("127.0.0.1"); + this->alt_addrs_.bind (n,v); +} + +Session::~Session (void) +{ + for (Processes::iterator i = processes_.begin(); + i != processes_.end(); + i++) + { + delete i->item(); + } +} + +void +Session::set_tao_version (ACE_TCHAR *str) +{ + if (ACE_OS::strncmp(str, ACE_TEXT("1.5"), 3)== 0) + tao_version_ = 150; + else if (ACE_OS::strncmp (str, ACE_TEXT("1.6"), 3) == 0) + tao_version_ = 160; +} + +long +Session::tao_version (void) +{ + return tao_version_; +} + +void +Session::add_process (HostProcess *proc) +{ + if (processes_.bind(proc->pid(),proc) != 0) + ACE_ERROR ((LM_ERROR, + "Session::add_process could not bind pid %d\n", + proc->pid())); +} + +void +Session::alternate_address (const char *addrspec) +{ + const char *equal = ACE_OS::strchr(addrspec,'='); + if (equal == 0) + return; + ACE_CString name (addrspec,(equal - addrspec)); + ACE_CString value (equal+1); + this->alt_addrs_.bind(name,value); +} + +void +Session::default_service (const char *addrspec) +{ + const char *equal = ACE_OS::strchr(addrspec,'='); + if (equal == 0) + return; + ACE_CString name (addrspec,(equal - addrspec)); + ACE_CString endpoint (equal+1); + + static long next_def_pid = 0; + --next_def_pid; + HostProcess *hp = new HostProcess ("defaulted",next_def_pid); + hp->proc_name(name); + hp->add_endpoint (endpoint); + this->processes_.bind(next_def_pid,hp); +} + +HostProcess * +Session::find_process (long pid) +{ + Processes::ENTRY *entry; + if (this->processes_.find(pid,entry) == 0) + return entry->item(); + else + return 0; +} + +HostProcess * +Session::find_host (const char *endpoint) +{ + ACE_CString test(endpoint); + ACE_CString alternate; + if (this->alt_addrs_.find(test,alternate) == 0) + test = alternate; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + break; + if (entry->item()->has_endpoint(test)) + return entry->item(); + } + return 0; +} + +void +Session::dump (ostream &strm) const +{ + // report session metrics + + strm << "Session summary report: " + << this->processes_.current_size() << " Processes detected." << endl; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->dump_summary (strm); + } + + strm << "\n\n\nSession detail threads report: " << endl; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->dump_thread_detail (strm); + } + + strm << "\n\n\nSession detail peer process report: " << endl; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->dump_peer_detail (strm); + } + + strm << "\n\n\nSession detail object report: " << endl; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->dump_object_detail (strm); + } + + strm << "\n\n\nSession detail invocation report: " << endl; + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->dump_invocation_detail (strm); + } +} + + +// iterate over the collection of host processes to associate peer +// processes via endpoints. +void +Session::reconcile (void) +{ + for (Processes::CONST_ITERATOR i (this->processes_); !i.done(); i.advance()) + { + Processes::ENTRY *entry; + if (i.next(entry) == 0) + continue; + entry->item()->reconcile_peers(this); + } + +} diff --git a/TAO/utils/logWalker/Session.h b/TAO/utils/logWalker/Session.h new file mode 100644 index 00000000000..6d30b843192 --- /dev/null +++ b/TAO/utils/logWalker/Session.h @@ -0,0 +1,44 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_SESSION_H +#define LOG_WALKER_SESSION_H + +#include "ace/Hash_Map_Manager.h" +#include "ace/SString.h" +#include "ace/Synch.h" + +class Log; +class HostProcess; + +typedef ACE_Hash_Map_Manager<long, HostProcess *, ACE_Null_Mutex> Processes; +typedef ACE_Hash_Map_Manager<ACE_CString, ACE_CString, ACE_Null_Mutex> AltAddresses; + +class Session +{ +public: + Session (); + + ~Session (void); + + void add_process (HostProcess *proc); + HostProcess *find_process (long pid); + HostProcess *find_host (const char *endpoint); + void reconcile (void); + + static void set_tao_version (ACE_TCHAR *str); + static long tao_version (void); + void alternate_address (const char *string); + void default_service (const char *string); + + void dump (ostream &strm) const; + +private: + Processes processes_; + AltAddresses alt_addrs_; + static long tao_version_; +}; + +#endif // LOG_WALKER_SESSION_H diff --git a/TAO/utils/logWalker/Thread.cpp b/TAO/utils/logWalker/Thread.cpp new file mode 100644 index 00000000000..05f685f3727 --- /dev/null +++ b/TAO/utils/logWalker/Thread.cpp @@ -0,0 +1,133 @@ +// $Id$ + +#include "Thread.h" +#include "Invocation.h" +#include "PeerProcess.h" + +#include "ace/OS_NS_stdio.h" + +Thread::Thread (long tid, const char *alias) + : id_(tid), + alias_ (alias), + max_depth_ (0), + encounters_ (0), + nested_ (0), + pending_(), + incoming_(0), + new_connection_(0), + giop_target_(0) +{ +} + +void +Thread::pending_peer (PeerProcess *pp) +{ + this->new_connection_ = pp; +} + +PeerProcess * +Thread::pending_peer (void) const +{ + return this->new_connection_; +} + +void +Thread::enter_wait (PeerProcess *pp) +{ + this->pending_.push (pp); + this->encounters_++; + if (this->pending_.size() > this->max_depth_) + this->max_depth_ = this->pending_.size(); + if (this->pending_.size() > 1) + this->nested_++; +} + +void +Thread::exit_wait (PeerProcess *pp, size_t linenum) +{ + PeerProcess *old; + if (this->pending_.pop(old) == -1) + return; + while (old != pp) + { + ACE_ERROR ((LM_ERROR, + "Line %d, Ending an invocation to peer %s, but most recent started" + " is to peer %s\n", linenum, pp->id(), old->id())); + // this->pending_.push(old); + if (this->pending_.pop(old) == -1) + return; + } +} + +long +Thread::max_depth (void) const +{ + return this->max_depth_; +} + +long +Thread::encounters (void) const +{ + return this->encounters_; +} + +long +Thread::id (void) const +{ + return this->id_; +} + +const ACE_CString & +Thread::alias (void) const +{ + return this->alias_; +} + +void +Thread::incoming_from (PeerProcess *pp) +{ + this->incoming_ = pp; +} + +PeerProcess * +Thread::incoming (void) const +{ + return this->incoming_; +} + +Invocation::GIOP_Buffer * +Thread::giop_target (void) +{ + return this->giop_target_; +} + +void +Thread::set_giop_target (Invocation::GIOP_Buffer *buffer) +{ + this->giop_target_ = buffer; +} + +void +Thread::dump_detail (ostream &strm) +{ + strm << " " << this->alias_ << " tid = " << this->id_ + << "\t" << this->encounters_ << " encounters"; + if (nested_ > 0) + strm <<", with " << this->nested_ << " nested upcalls, max depth " + << this->max_depth_; + strm << endl; +} + +void +Thread::dump_invocations (ostream &strm) +{ + strm << " " << this->alias_ << " handled " << this->invocations_.size() << " invocations" << endl; + for (ACE_DLList_Iterator <Invocation> i(this->invocations_); + !i.done(); + i.advance()) + { + Invocation *inv; + i.next(inv); + inv->dump_detail (strm,0); + } +} diff --git a/TAO/utils/logWalker/Thread.h b/TAO/utils/logWalker/Thread.h new file mode 100644 index 00000000000..adc92a300c1 --- /dev/null +++ b/TAO/utils/logWalker/Thread.h @@ -0,0 +1,50 @@ +// -*- C++ -*- + +// $Id$ +// + +#ifndef LOG_WALKER_THREAD_H +#define LOG_WALKER_THREAD_H + +#include "ace/SString.h" +#include "ace/Synch.h" +#include "ace/Containers.h" +#include "ace/Hash_Map_Manager.h" +#include "Invocation.h" +#include "PeerProcess.h" + +typedef ACE_Unbounded_Stack<PeerProcess *> UpcallStack; + +class Thread +{ +public: + Thread (long tid, const char *alias); + long max_depth (void) const; + long encounters (void) const; + long id (void) const; + const ACE_CString &alias (void) const; + void incoming_from (PeerProcess *); + PeerProcess *incoming (void) const; + void enter_wait (PeerProcess *); + void exit_wait (PeerProcess *, size_t linenum); + Invocation::GIOP_Buffer *giop_target (void); + void set_giop_target (Invocation::GIOP_Buffer *buffer); + void dump_detail (ostream &strm); + void dump_invocations (ostream &strm); + PeerProcess *pending_peer (void) const; + void pending_peer (PeerProcess *pp); + +private: + long id_; + ACE_CString alias_; + size_t max_depth_; + long encounters_; + long nested_; + UpcallStack pending_; + PeerProcess *incoming_; + PeerProcess *new_connection_; + Invocation::GIOP_Buffer *giop_target_; + InvocationList invocations_; +}; + +#endif // LOG_WALKER_THREAD_H diff --git a/TAO/utils/logWalker/hello.mft b/TAO/utils/logWalker/hello.mft new file mode 100644 index 00000000000..419c8df4940 --- /dev/null +++ b/TAO/utils/logWalker/hello.mft @@ -0,0 +1,4 @@ +-t 1.5 +HelloServer=helloServer.log +HelloClient=helloClient.log + diff --git a/TAO/utils/logWalker/helloClient.log b/TAO/utils/logWalker/helloClient.log new file mode 100644 index 00000000000..d210e29119e --- /dev/null +++ b/TAO/utils/logWalker/helloClient.log @@ -0,0 +1,86 @@ +TAO (8448|139740928042736) Initializing the process-wide services +TAO (8448|139740928042736) Default ORB - global initialization completed. +TAO (8448|139740928042736) Initializing the orb-specific services +TAO (8448|139740928042736) Default_Resource_Factory - unable to create codeset manager. +TAO (8448|139740928042736) ORB_Core: Codeset Manager not available +TAO (8448|139740928042736) Loaded default protocol <IIOP_Factory> +TAO (8448|139740928042736) created new ORB <> +TAO (8448|139740928042736) - Transport_Cache_Manager::fill_set_i: current_size = 0, cache_maximum = 512 +TAO (8448|139740928042736) - Transport_Cache_Manager::purge: Cache size after purging is [0] +TAO (8448|139740928042736) - IIOP_Connector::begin_connection, to <phil.ociweb.com:33152> which should block +TAO (8448|139740928042736) - Transport_Connector::caching connection before wait_for_connection_completion 181029421 = [7732384] +TAO (8448|139740928042736) - Transport_Cache_Manager::bind_i: Transport[7732384] @ hash{181029421} +TAO (8448|139740928042736) - Transport_Cache_Manager::bind_i: Bound Transport[7732384] @ hash:index{181029421:0} state CONNECTING. Cache size is [1] +TAO (8448|139740928042736) - Transport_Connector::wait_for_connection_completion, going to wait for connection completion on transport[7732384] +TAO (8448|139740928042736) - Leader_Follower[7732384]::wait_for_event, (leader) enter reactor event loop +TAO (8448|139740928042736) - IIOP_Connection_Handler::open, The local addr is <10.201.200.173:40203> +TAO (8448|139740928042736) - IIOP_Connection_Handler::open, IIOP connection to peer <10.201.200.173:33152> on 7 +TAO (8448|139740928042736) - Leader_Follower[7732384]::wait_for_event, (leader) exit reactor event loop +TAO (8448|139740928042736) - Transport_Connector::wait_for_connection_completion, transport [7], wait done result = 0 +TAO (8448|139740928042736) - IIOP_Connector::make_connection, new connected connection to <phil.ociweb.com:33152> on Transport[7] +TAO (8448|139740928042736) - Transport[7]::register_handler +TAO (8448|139740928042736) - Transport_Connector::connect, opening Transport[7] in TAO_CLIENT_ROLE +TAO (8448|139740928042736) - Transport_Cache_Manager::is_transport_available:Returns True, Transport[7] state: IDLE_BUT_NOT_PURGABLE connected: yes +TAO (8448|139740928042736) - Transport_Cache_Manager::find_i: Found available Transport[7] @hash:index {181029421:0}( +TAO (8448|139740928042736) - Transport_Connector::connect, got an existing connected Transport[7] in role TAO_CLIENT_ROLE +TAO (8448|139740928042736) - Muxed_TMS[7]::request_id, <1> +TAO (8448|139740928042736) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 64 data bytes, my endian, Type Request[1] +GIOP message - HEXDUMP 76 bytes +47 49 4f 50 01 02 01 00 40 00 00 00 01 00 00 00 GIOP....@....... +03 00 00 00 00 00 00 00 1b 00 00 00 14 01 0f 00 ................ +52 53 54 44 87 2e 4a 13 c9 01 00 00 00 00 00 01 RSTD..J......... +00 00 00 01 00 00 00 00 0b 00 00 00 67 65 74 5f ............get_ +73 74 72 69 6e 67 00 00 00 00 00 00 string...... +TAO (8448|139740928042736) - Transport[7]::cleanup_queue, byte_count = 76 +TAO (8448|139740928042736) - Transport[7]::cleanup_queue, after transfer, bc = 0, all_sent = 1, ml = 0 +TAO (8448|139740928042736) - Transport[7]::drain_queue_helper, byte_count = 76, head_is_empty = 1 +TAO (8448|139740928042736) - Transport[7]::drain_queue_i, helper retval = 1 +TAO (8448|139740928042736) - Transport[7]::make_idle +TAO (8448|139740928042736) - Leader_Follower[7]::wait_for_event, (leader) enter reactor event loop +TAO (8448|139740928042736) - Connection_Handler[7]::handle_input, handle = 7/7 +TAO (8448|139740928042736) - Transport[7]::handle_input +TAO (8448|139740928042736) - Transport[7]::process_queue_head, 0 enqueued +TAO (8448|139740928042736) - Transport[7]::handle_input_parse_data, enter +TAO (8448|139740928042736) - Transport[7]::handle_input_parse_data, read 41 bytes +TAO (8448|139740928042736) - GIOP_Message_State::parse_message_header_i +TAO (8448|139740928042736) - GIOP_Message_State::get_version_info +TAO (8448|139740928042736) - GIOP_Message_State::get_byte_order_info +TAO (8448|139740928042736) - Transport[7]::process_parsed_messages, entering (missing data == 0) +TAO (8448|139740928042736) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 29 data bytes, my endian, Type Reply[1] +GIOP message - HEXDUMP 41 bytes +47 49 4f 50 01 02 01 01 1d 00 00 00 01 00 00 00 GIOP............ +00 00 00 00 00 00 00 00 0d 00 00 00 48 65 6c 6c ............Hell +6f 20 74 68 65 72 65 21 00 o there!. +TAO (8448|139740928042736) - TAO_Muxed_TMS::dispatch_reply, id = 1 +TAO (8448|139740928042736) - Connection_Handler[7]::handle_input, handle = 7/7, retval = 0 +TAO (8448|139740928042736) - Leader_Follower[7]::wait_for_event, (leader) exit reactor event loop +(8448|139740928042736) - string returned <Hello there!> +TAO (8448|139740928042736) - Transport_Cache_Manager::is_transport_available:Returns True, Transport[7] state: IDLE_AND_PURGABLE connected: yes +TAO (8448|139740928042736) - Transport_Cache_Manager::find_i: Found available Transport[7] @hash:index {181029421:0}( +TAO (8448|139740928042736) - Transport_Connector::connect, got an existing connected Transport[7] in role TAO_CLIENT_ROLE +TAO (8448|139740928042736) - Muxed_TMS[7]::request_id, <2> +TAO (8448|139740928042736) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 64 data bytes, my endian, Type Request[2] +GIOP message - HEXDUMP 76 bytes +47 49 4f 50 01 02 01 00 40 00 00 00 02 00 00 00 GIOP....@....... +00 00 00 00 00 00 00 00 1b 00 00 00 14 01 0f 00 ................ +52 53 54 44 87 2e 4a 13 c9 01 00 00 00 00 00 01 RSTD..J......... +00 00 00 01 00 00 00 00 09 00 00 00 73 68 75 74 ............shut +64 6f 77 6e 00 67 00 00 00 00 00 00 down.g...... +TAO (8448|139740928042736) - Transport[7]::send_asynchronous_message_i, trying to send the message (ml = 76) +TAO (8448|139740928042736) - Transport[7]::cleanup_queue, byte_count = 76 +TAO (8448|139740928042736) - Transport[7]::cleanup_queue, after transfer, bc = 0, all_sent = 1, ml = 0 +TAO (8448|139740928042736) - Transport[7]::drain_queue_helper, byte_count = 76, head_is_empty = 1 +TAO (8448|139740928042736) - Transport[7]::drain_queue_i, helper retval = 1 +TAO (8448|139740928042736) - Transport[7]::make_idle +CORBA::ORB::destroy() called on ORB <>. +Destroying ORB <> +TAO (8448|139740928042736) - Connection_Handler[7]::close_connection_eh, purging entry from cache +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, cleaning up complete queue +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, discarded 0 messages, 0 bytes. +TAO (8448|139740928042736) - Connection_Handler[7]::close_connection_eh, removing from the reactor +TAO (8448|139740928042736) - Connection_Handler[7]::close_connection_eh, cancel all timers +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, cleaning up complete queue +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, discarded 0 messages, 0 bytes. +TAO (8448|139740928042736) - Connection_Handler[7]::close_connection_eh +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, cleaning up complete queue +TAO (8448|139740928042736) - Transport[7]::cleanup_queue_i, discarded 0 messages, 0 bytes. diff --git a/TAO/utils/logWalker/helloServer.log b/TAO/utils/logWalker/helloServer.log new file mode 100644 index 00000000000..d4bc2c8c2dc --- /dev/null +++ b/TAO/utils/logWalker/helloServer.log @@ -0,0 +1,80 @@ +TAO (8447|140673593390832) Initializing the process-wide services +TAO (8447|140673593390832) Default ORB - global initialization completed. +TAO (8447|140673593390832) Initializing the orb-specific services +TAO (8447|140673593390832) Default_Resource_Factory - unable to create codeset manager. +TAO (8447|140673593390832) ORB_Core: Codeset Manager not available +TAO (8447|140673593390832) Loaded default protocol <IIOP_Factory> +TAO (8447|140673593390832) created new ORB <> +TAO (8447|140673593390832) - IIOP_Acceptor::open_i, listening on: <phil.ociweb.com:33152> +TAO (8447|140673593390832) - ORB_Core::run, start [run] +TAO (8447|140673593390832) - ORB_Core::run, calling handle_events() +TAO (8447|140673593390832) - Transport_Cache_Manager::fill_set_i: current_size = 0, cache_maximum = 512 +TAO (8447|140673593390832) - Transport_Cache_Manager::purge: Cache size after purging is [0] +TAO (8447|140673593390832) - Concurrency_Strategy::activate_svc_handler, opened as TAO_SERVER_ROLE +TAO (8447|140673593390832) - IIOP_Connection_Handler::open, The local addr is <10.201.200.173:33152> +TAO (8447|140673593390832) - IIOP_Connection_Handler::open, IIOP connection to peer <10.201.200.173:40203> on 8 +TAO (8447|140673593390832) - Transport_Cache_Manager::bind_i: Transport[8] @ hash{181036472} +TAO (8447|140673593390832) - Transport_Cache_Manager::bind_i: Bound Transport[8] @ hash:index{181036472:0} state IDLE_AND_PURGABLE. Cache size is [1] +TAO (8447|140673593390832) - Transport[8]::register_handler +TAO (8447|140673593390832) - ORB_Core::run, handle_events() returns 0 +TAO (8447|140673593390832) - ORB_Core::run, calling handle_events() +TAO (8447|140673593390832) - Connection_Handler[8]::handle_input, handle = 8/8 +TAO (8447|140673593390832) - Transport[8]::handle_input +TAO (8447|140673593390832) - Transport[8]::process_queue_head, 0 enqueued +TAO (8447|140673593390832) - Transport[8]::handle_input_parse_data, enter +TAO (8447|140673593390832) - Transport[8]::handle_input_parse_data, read 76 bytes +TAO (8447|140673593390832) - GIOP_Message_State::parse_message_header_i +TAO (8447|140673593390832) - GIOP_Message_State::get_version_info +TAO (8447|140673593390832) - GIOP_Message_State::get_byte_order_info +TAO (8447|140673593390832) - Transport[8]::process_parsed_messages, entering (missing data == 0) +TAO (8447|140673593390832) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 64 data bytes, my endian, Type Request[1] +GIOP message - HEXDUMP 76 bytes +47 49 4f 50 01 02 01 00 40 00 00 00 01 00 00 00 GIOP....@....... +03 00 00 00 00 00 00 00 1b 00 00 00 14 01 0f 00 ................ +52 53 54 44 87 2e 4a 13 c9 01 00 00 00 00 00 01 RSTD..J......... +00 00 00 01 00 00 00 00 0b 00 00 00 67 65 74 5f ............get_ +73 74 72 69 6e 67 00 00 00 00 00 00 string...... +TAO (8447|140673593390832) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 29 data bytes, my endian, Type Reply[1] +GIOP message - HEXDUMP 41 bytes +47 49 4f 50 01 02 01 01 1d 00 00 00 01 00 00 00 GIOP............ +00 00 00 00 00 00 00 00 0d 00 00 00 48 65 6c 6c ............Hell +6f 20 74 68 65 72 65 21 00 o there!. +TAO (8447|140673593390832) - Transport[8]::cleanup_queue, byte_count = 41 +TAO (8447|140673593390832) - Transport[8]::cleanup_queue, after transfer, bc = 0, all_sent = 1, ml = 0 +TAO (8447|140673593390832) - Transport[8]::drain_queue_helper, byte_count = 41, head_is_empty = 1 +TAO (8447|140673593390832) - Transport[8]::drain_queue_i, helper retval = 1 +TAO (8447|140673593390832) - Connection_Handler[8]::handle_input, handle = 8/8, retval = 0 +TAO (8447|140673593390832) - ORB_Core::run, handle_events() returns 0 +TAO (8447|140673593390832) - ORB_Core::run, calling handle_events() +TAO (8447|140673593390832) - Connection_Handler[8]::handle_input, handle = 8/8 +TAO (8447|140673593390832) - Transport[8]::handle_input +TAO (8447|140673593390832) - Transport[8]::process_queue_head, 0 enqueued +TAO (8447|140673593390832) - Transport[8]::handle_input_parse_data, enter +TAO (8447|140673593390832) - Transport[8]::handle_input_parse_data, read 76 bytes +TAO (8447|140673593390832) - GIOP_Message_State::parse_message_header_i +TAO (8447|140673593390832) - GIOP_Message_State::get_version_info +TAO (8447|140673593390832) - GIOP_Message_State::get_byte_order_info +TAO (8447|140673593390832) - Transport[8]::process_parsed_messages, entering (missing data == 0) +TAO (8447|140673593390832) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 64 data bytes, my endian, Type Request[2] +GIOP message - HEXDUMP 76 bytes +47 49 4f 50 01 02 01 00 40 00 00 00 02 00 00 00 GIOP....@....... +00 00 00 00 00 00 00 00 1b 00 00 00 14 01 0f 00 ................ +52 53 54 44 87 2e 4a 13 c9 01 00 00 00 00 00 01 RSTD..J......... +00 00 00 01 00 00 00 00 09 00 00 00 73 68 75 74 ............shut +64 6f 77 6e 00 67 00 00 00 00 00 00 down.g...... +TAO (8447|140673593390832) - Connection_Handler[8]::handle_input, handle = 8/8, retval = 0 +TAO (8447|140673593390832) - ORB_Core::run, handle_events() returns 0 +TAO (8447|140673593390832) - ORB_Core::run, ends with result = 0 +(8447|140673593390832) server - event loop finished +CORBA::ORB::destroy() called on ORB <>. +Destroying ORB <> +TAO (8447|140673593390832) - Connection_Handler[8]::close_connection_eh, purging entry from cache +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, cleaning up complete queue +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, discarded 0 messages, 0 bytes. +TAO (8447|140673593390832) - Connection_Handler[8]::close_connection_eh, removing from the reactor +TAO (8447|140673593390832) - Connection_Handler[8]::close_connection_eh, cancel all timers +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, cleaning up complete queue +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, discarded 0 messages, 0 bytes. +TAO (8447|140673593390832) - Connection_Handler[8]::close_connection_eh +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, cleaning up complete queue +TAO (8447|140673593390832) - Transport[8]::cleanup_queue_i, discarded 0 messages, 0 bytes. diff --git a/TAO/utils/logWalker/logWalker.cpp b/TAO/utils/logWalker/logWalker.cpp new file mode 100644 index 00000000000..976d9c721c7 --- /dev/null +++ b/TAO/utils/logWalker/logWalker.cpp @@ -0,0 +1,143 @@ +// $Id$ + +// Utility to traverse and simplify verbose log files. +// +// The goal is to take a collection of log files and extract details +// related to connections, objects, and invocations to separate out +// perhaps multiple processes, or at least threads to get a sense of +// invocation lifecycle. +// +// Ideally a collection of files could be used so that invocations +// that traverse many processes could be tracked. + +#include "ace/OS_NS_stdio.h" +#include "ace/Log_Msg.h" +#include "ace/streams.h" +#include "ace/OS_NS_strings.h" +#include "ace/Tokenizer_T.h" + +#include "Invocation.h" +#include "PeerObject.h" +#include "PeerProcess.h" +#include "Session.h" +#include "Log.h" + +ACE_TCHAR *outfile = 0; + +void +parse_manifest (Session &session, ACE_TCHAR *filename) +{ + // get list of logs, aliases, and other config from file + ifstream strm (filename); + if (!strm.is_open()) + { + ACE_DEBUG ((LM_DEBUG,"cannot open manifest file %C\n", filename)); + return; + } + char buffer[500]; + while (!strm.eof()) + { + strm.getline(buffer,500); + if (buffer[0] == '\0' || + buffer[0] == '#') + { + continue; + } + if (buffer[0] == '-') + { + if (buffer[1] == 'o') + { + outfile = new char[ACE_OS::strlen(buffer) - 3]; + ACE_OS::strcpy(buffer+3,outfile); + continue; + } + if (buffer[1] == 't') + { + Session::set_tao_version (buffer+3); + continue; + } + if (buffer[1] == 'a') + { + session.alternate_address(buffer+3); + continue; + } + if (buffer[1] == 'p') + { + session.default_service (buffer+3); + continue; + } + } + if (ACE_OS::strchr(buffer,'=') == 0) + { + ACE_DEBUG ((LM_DEBUG,"Unparsable string: %s\n", + buffer)); + return; + } + ACE_Tokenizer tokens(buffer); + tokens.delimiter_replace('=',0); + char *alias = tokens.next(); + char *filename = tokens.next(); + Log log(session); + log.init(filename,alias); + } +} + +int +ACE_TMAIN (int argc, ACE_TCHAR **argv) +{ + if (argc < 2) + { + ACE_ERROR ((LM_ERROR," At least one log file must be specified\n")); + return 0; + } + Session session; + for (int i = 1; i < argc; i++) + { + if (ACE_OS::strcasecmp (argv[i], "-o") == 0) + { + outfile = argv[++i]; + continue; + } + if (ACE_OS::strcasecmp (argv[i], "-m") == 0) + { + parse_manifest (session, argv[++i]); + continue; + } + if (ACE_OS::strcasecmp (argv[i], "-t") == 0) + { + Session::set_tao_version (argv[++i]); + continue; + } + if (ACE_OS::strcasecmp (argv[i], "-a") == 0) + { + session.alternate_address (argv[++i]); + continue; + } + if (ACE_OS::strcasecmp (argv[i], "-p") == 0) + { + session.default_service (argv[++i]); + continue; + } + + Log log(session); + ACE_DEBUG ((LM_DEBUG,"Parsing file %s\n", argv[i])); + if (log.init(argv[i]) == 0) + { + ACE_ERROR ((LM_ERROR, + "Could not parse log file %s\n", argv[i])); + continue; + } + + } + + session.reconcile(); + ostream *strm; + if (outfile == 0) + strm = &cout; + else + strm = new ofstream(outfile); + + session.dump(*strm); + + return 0; +} diff --git a/TAO/utils/logWalker/logWalker.mpc b/TAO/utils/logWalker/logWalker.mpc new file mode 100644 index 00000000000..aea3fd29078 --- /dev/null +++ b/TAO/utils/logWalker/logWalker.mpc @@ -0,0 +1,6 @@ +// -*- mpc -*- + +project : aceexe { + exename = tao_logWalker + install = $(ACE_ROOT)/bin +} |