Thu Mar 14 21:36:30 UTC 2013 Phil Mesnier <mesnier_p@ociweb.com>

8 files changed, 241 insertions, 19 deletions

diff --git a/TAO/ChangeLog_Asynch_ImR b/TAO/ChangeLog_Asynch_ImR
index a7f9739345d..b1d50608e83 100644
--- a/TAO/ChangeLog_Asynch_ImR
+++ b/TAO/ChangeLog_Asynch_ImR
@@ -1,3 +1,20 @@
+Thu Mar 14 21:36:30 UTC 2013  Phil Mesnier  <mesnier_p@ociweb.com>
+
+        * orbsvcs/ImplRepo_Service/AsyncStartupWaiter_i.cpp:
+        * orbsvcs/ImplRepo_Service/ImR_Locator_i.cpp:
+
+          Some syntactic clean up and apply a fix for a memory leak Kevin applied to
+          the trunk.
+
+        * utils/logWalker/HostProcess.cpp:
+        * utils/logWalker/Invocation.h:
+        * utils/logWalker/Invocation.cpp:
+        * utils/logWalker/Thread.h:
+        * utils/logWalker/Thread.cpp:
+
+          Add a new type of by-thread output that highlights nested upcalls and the
+          processing impact of delaying action on replies.
+
 Mon Mar 11 16:31:08 UTC 2013  Phil Mesnier  <mesnier_p@ociweb.com>
 
         * orbsvcs/ImplRepo_Service/ImR_Locator_i.h:
diff --git a/TAO/orbsvcs/ImplRepo_Service/AsyncStartupWaiter_i.cpp b/TAO/orbsvcs/ImplRepo_Service/AsyncStartupWaiter_i.cpp
index cca2a7a9807..19bc12e4162 100644
--- a/TAO/orbsvcs/ImplRepo_Service/AsyncStartupWaiter_i.cpp
+++ b/TAO/orbsvcs/ImplRepo_Service/AsyncStartupWaiter_i.cpp
@@ -77,7 +77,8 @@ AsyncStartupWaiter_i::send_response (ImplementationRepository::AMH_AsyncStartupW
 }
 
 void
-AsyncStartupWaiter_i::unblock_one (const char* name, const char* partial_ior, const char* ior, bool queue) {
+AsyncStartupWaiter_i::unblock_one (const char* name, const char* partial_ior, const char* ior, bool queue)
+{
   ImplementationRepository::AMH_AsyncStartupWaiterResponseHandler_var rh = get_one_waiter(name);
   if (! CORBA::is_nil(rh.in ()))
     {
@@ -102,7 +103,8 @@ AsyncStartupWaiter_i::unblock_one (const char* name, const char* partial_ior, co
 }
 
 void
-AsyncStartupWaiter_i::unblock_all (const char* name) {
+AsyncStartupWaiter_i::unblock_all (const char* name)
+{
   RHList tmp;
 
   get_all_waiters (name, tmp);
diff --git a/TAO/orbsvcs/ImplRepo_Service/ImR_Locator_i.cpp b/TAO/orbsvcs/ImplRepo_Service/ImR_Locator_i.cpp
index 46d8785bf70..8dfa7737424 100644
--- a/TAO/orbsvcs/ImplRepo_Service/ImR_Locator_i.cpp
+++ b/TAO/orbsvcs/ImplRepo_Service/ImR_Locator_i.cpp
@@ -303,8 +303,6 @@ ImR_Locator_i::fini (void)
       if (debug_ > 1)
         ACE_DEBUG ((LM_DEBUG, ACE_TEXT ("ImR: Shutting down...\n")));
 
-      this->repository_.release();
-
       this->root_poa_->destroy (1, 1);
 
       this->orb_->destroy ();
diff --git a/TAO/utils/logWalker/HostProcess.cpp b/TAO/utils/logWalker/HostProcess.cpp
index 486911f4a8c..e8adc928c89 100644
--- a/TAO/utils/logWalker/HostProcess.cpp
+++ b/TAO/utils/logWalker/HostProcess.cpp
@@ -283,6 +283,8 @@ HostProcess::dump_thread_invocations (ostream &strm)
       t_iter.next(thr);
       thr->dump_invocations (strm);
       strm << endl;
+      thr->dump_incidents (strm);
+      strm << endl;
     }
 }
 
diff --git a/TAO/utils/logWalker/Invocation.cpp b/TAO/utils/logWalker/Invocation.cpp
index a7a67bf03d8..25bd4d1da29 100644
--- a/TAO/utils/logWalker/Invocation.cpp
+++ b/TAO/utils/logWalker/Invocation.cpp
@@ -20,7 +20,10 @@ Invocation::Invocation (PeerProcess *peer, Thread *thr, size_t rid)
    peer_(peer),
    req_id_(rid),
    target_(0),
-   handle_(thr->active_handle())
+   handle_(thr->active_handle()),
+   finish_reported_(false),
+   req_level_ (0),
+   repl_level_ (0)
 {
 }
 
@@ -179,11 +182,11 @@ Invocation::handle (void) const
 bool
 Invocation::contains (size_t line)
 {
-  if (this->req_octets_ == 0 || this->repl_octets_ == 0)
+  if (this->req_octets_ == 0 || this->is_oneway())
     return false;
   return
     line > this->req_octets_->log_posn() &&
-    line < this->repl_octets_->log_posn();
+    (this->repl_octets_ == 0 || line < this->repl_octets_->log_posn());
 }
 
 size_t
@@ -192,6 +195,12 @@ Invocation::req_line (void)
   return this->req_octets_ == 0 ? 0 : this->req_octets_->log_posn();
 }
 
+size_t
+Invocation::repl_line (void)
+{
+  return this->repl_octets_ == 0 ? 0 : this->repl_octets_->log_posn();
+}
+
 void
 Invocation::new_line (ostream &strm, int indent, int offset, bool add_nl, bool show_indent)
 {
@@ -200,19 +209,125 @@ Invocation::new_line (ostream &strm, int indent, int offset, bool add_nl, bool s
       strm << "\n";
     }
 
-  if (indent > 9)
+  int steps = indent / 20;
+  int extra = indent % 20;
+
+  if (steps > 1)
     {
       if (show_indent)
-        strm << "[indent " << indent << "] ---> ";
+        {
+          strm << "[indent " << steps * 20 << "] --->";
+          extra += (indent > 99) ? 5 : 4;
+        }
       else
-        strm << "                   ";
+        {
+          extra += 20;
+        }
     }
   else
     {
-      indent += offset;
-      while (indent-- > 0)
-        strm << "  ";
+      extra += (steps * 20);
+    }
+
+  extra += offset;
+  while (extra-- > 0)
+    strm << " ";
+}
+
+void
+Invocation::dump_start_line (ostream &strm, size_t indent)
+{
+  if (this->req_octets_ == 0)
+    return;
+  this->req_level_ = indent;
+  strm << setw(7) << this->req_octets_->log_posn() << " " << setw(0);
+
+  const char *opname = "";
+  const char *dir_1 = "sent to ";
+  const char *dir_2 = " in ";
+
+  if (this->req_octets_ != 0)
+    {
+      opname = this->req_octets_->operation();
+      if (this->req_octets_->sending())
+        {
+          dir_1 = "recv for ";
+          dir_2 = " from ";
+        }
     }
+
+  this->new_line (strm, indent, 0, false, true);
+
+  strm << "start request ";
+
+  if (opname == 0 || opname[0] == 0)
+    opname = "<no operation>";
+
+  strm << dir_1;
+  if (this->target_ == 0)
+    strm << "<unknown object>" ;
+  else
+    strm << this->target_->name();
+  strm << dir_2 << this->peer_->id() << ", req " << this->req_id_;
+  strm << " [" << opname << "]";
+  if (this->is_oneway())
+    strm << " oneway";
+  else if (this->repl_octets_ == 0)
+    strm << " <no reply found>";
+  strm << endl;
+}
+
+void
+Invocation::dump_finish_line (ostream &strm, size_t indent)
+{
+  bool is_popped = this->repl_level_ > 0 && indent == this->req_level_;
+
+  if (!is_popped && (this->finish_reported_ || this->is_oneway() || this->repl_octets_ == 0))
+    return;
+
+  if (!this->finish_reported_)
+    {
+      this->repl_level_ = indent;
+    }
+
+  this->finish_reported_ = true;
+
+  strm << setw(7) << this->repl_octets_->log_posn() << " " << setw(0);
+
+  const char *opname = "";
+  const char *dir_2 = " in ";
+
+  if (this->req_octets_ != 0)
+    {
+      opname = this->req_octets_->operation();
+      if (this->req_octets_->sending())
+        {
+          dir_2 = " from ";
+        }
+    }
+
+  if (opname == 0 || opname[0] == 0)
+    {
+      opname = "<no operation>";
+    }
+
+  this->new_line (strm, indent, 0, false, true);
+
+  strm << "reply for " << this->peer_->id() << ", req " << this->req_id_;
+  strm << " [" << opname << "]";
+  if (is_popped)
+    {
+      strm << " (reply received at " << this->repl_level_ << " evaluated)";
+    }
+  else
+    {
+      if (indent != this->req_level_)
+        {
+          strm << " (req at level " << this->req_level_ << " reply at " << indent << ")";
+        }
+    }
+
+  strm << endl;
 }
 
 void
diff --git a/TAO/utils/logWalker/Invocation.h b/TAO/utils/logWalker/Invocation.h
index dae1e15c823..278b30d7dec 100644
--- a/TAO/utils/logWalker/Invocation.h
+++ b/TAO/utils/logWalker/Invocation.h
@@ -76,6 +76,7 @@ public:
 
   bool contains (size_t line);
   size_t req_line (void);
+  size_t repl_line (void);
 
   void add_notify_incident (const ACE_CString &text, size_t offset);
   Thread *waiter (void) const;
@@ -83,6 +84,8 @@ public:
 
   void new_line (ostream &strm, int indent, int offset,  bool add_nl, bool show_indent);
   void dump_detail (ostream &strm, size_t indent, Dump_Mode mode, bool show_handle);
+  void dump_start_line (ostream &strm, size_t indent);
+  void dump_finish_line (ostream &strm, size_t indent);
   void dump_special_details (ostream &strm, size_t indent, const char *opname);
 
 private:
@@ -95,6 +98,9 @@ private:
   size_t req_id_;
   PeerObject *target_;
   long handle_;
+  bool finish_reported_;
+  size_t req_level_;
+  size_t repl_level_;
 };
 
 #endif // LOG_WALKER_INVOCATION_H
diff --git a/TAO/utils/logWalker/Thread.cpp b/TAO/utils/logWalker/Thread.cpp
index cb19431f45d..3bd7f206ef4 100644
--- a/TAO/utils/logWalker/Thread.cpp
+++ b/TAO/utils/logWalker/Thread.cpp
@@ -6,6 +6,7 @@
 #include "GIOP_Buffer.h"
 #include "ace/OS_NS_stdio.h"
 #include <stack>
+#include <deque>
 
 Thread::Thread (long tid, const char *alias, size_t offset)
   : id_(tid),
@@ -223,13 +224,13 @@ Thread::current_invocation (void) const
 }
 
 void
-Thread::dump_detail (ostream &strm) const
+Thread::dump_detail (ostream &strm)
 {
   strm << "   " << this->alias_ << " tid = 0x" << hex << this->id_
        << "\tfirst line " << dec << this->first_line_ << "\t"
        << this->server_encounters_ << " requests sent "
        << this->client_encounters_ << " requests received";
-  if (nested_ > 0)
+  if (this->count_nesting () > 0)
     strm <<", with " << this->nested_ << " nested upcalls, max depth "
          << this->max_depth_;
   strm << endl;
@@ -241,6 +242,7 @@ Thread::get_summary (long &sent_reqs,
                      size_t &sent_size,
                      size_t &recv_size)
 {
+
   for (ACE_DLList_Iterator <Invocation> i(this->invocations_);
        !i.done();
        i.advance())
@@ -264,7 +266,7 @@ void
 Thread::dump_invocations (ostream &strm)
 {
   size_t total_request_bytes = 0;
-  strm << "   " << this->alias_ << " handled " << this->invocations_.size()
+  strm << this->alias_ << " handled " << this->invocations_.size()
        << " invocations" << endl;
 
   std::stack<Invocation *> nested;
@@ -272,14 +274,17 @@ Thread::dump_invocations (ostream &strm)
        !i.done();
        i.advance())
     {
-      Invocation *inv;
+      Invocation *inv = 0;
       i.next(inv);
       size_t level = 0;
+
       while (!nested.empty ())
         {
           if (nested.top()->contains (inv->req_line ()))
             {
               level = nested.size();
+              if (level > this->nested_)
+                this->nested_ = level;
               break;
             }
           nested.pop();
@@ -291,3 +296,76 @@ Thread::dump_invocations (ostream &strm)
     }
   strm << "total request octet count: " << total_request_bytes;
 }
+
+void
+Thread::dump_incidents (ostream &strm)
+{
+  if (this->nested_ == 0)
+    return;
+  strm << "\n" << this->alias_  << " handled " << this->invocations_.size()
+       << " invocations with a max nesting level of " << this->nested_ << endl;
+
+  std::deque<Invocation *> nested_queue;
+  for (ACE_DLList_Iterator <Invocation> i (this->invocations_);
+       !i.done();
+       i.advance())
+    {
+      Invocation *inv = 0;
+      i.next(inv);
+      size_t level = nested_queue.size();
+
+      while (!nested_queue.empty ())
+        {
+          Invocation *prev = nested_queue.back ();
+          if (prev->contains (inv->req_line ()))
+            {
+              break;
+            }
+          nested_queue.pop_back ();
+          level--;
+          prev->dump_finish_line (strm, level);
+        }
+      if (nested_queue.size() > 1)
+        {
+          size_t inv_line = inv->req_line ();
+          for (std::deque<Invocation *>::iterator j = nested_queue.begin ();
+               j != nested_queue.end ();
+               j++)
+            {
+              if ((*j)->repl_line () < inv_line)
+                {
+                  (*j)->dump_finish_line (strm, level);
+                }
+            }
+        }
+      nested_queue.push_back (inv);
+      inv->dump_start_line (strm, level);
+    }
+}
+
+size_t
+Thread::count_nesting (void)
+{
+  std::stack<Invocation *> nested;
+  for (ACE_DLList_Iterator <Invocation> i (this->invocations_);
+       !i.done();
+       i.advance())
+    {
+      Invocation *inv = 0;
+      i.next(inv);
+      size_t level = 0;
+      while (!nested.empty ())
+        {
+          level = nested.size();
+          if (level > this->nested_)
+            this->nested_ = level;
+          if (nested.top()->contains (inv->req_line ()))
+            {
+              break;
+            }
+          nested.pop ();
+        }
+      nested.push (inv);
+    }
+  return this->nested_;
+}
diff --git a/TAO/utils/logWalker/Thread.h b/TAO/utils/logWalker/Thread.h
index 9e5da0fec12..180bd1bfc43 100644
--- a/TAO/utils/logWalker/Thread.h
+++ b/TAO/utils/logWalker/Thread.h
@@ -37,8 +37,10 @@ public:
   void exit_wait (PeerProcess *, size_t linenum);
   GIOP_Buffer *giop_target (void);
   void set_giop_target (GIOP_Buffer *buffer);
-  void dump_detail (ostream &strm) const;
+  void dump_detail (ostream &strm);
   void dump_invocations (ostream &strm);
+  void dump_incidents (ostream &strm);
+
   void get_summary (long &sent_reqs, long &recv_reqs, size_t &sent_size, size_t &recv_size);
 
   void push_new_connection (PeerProcess *pp);
@@ -54,13 +56,15 @@ public:
   void swap_target (void);
   bool has_dup (void);
 
+  size_t count_nesting (void);
+
 private:
   long id_;
   ACE_CString alias_;
   size_t max_depth_;
   long client_encounters_;
   long server_encounters_;
-  long nested_;
+  size_t nested_;
   PeerProcessStack pending_;
   PeerProcess *incoming_;
   PeerProcessStack new_connection_;