Add relative (to earliest parsed) time on thread invocation reports

11 files changed, 132 insertions, 55 deletions

diff --git a/TAO/utils/logWalker/GIOP_Buffer.cpp b/TAO/utils/logWalker/GIOP_Buffer.cpp
index 051f9474c2a..fdf08f63fc7 100644
--- a/TAO/utils/logWalker/GIOP_Buffer.cpp
+++ b/TAO/utils/logWalker/GIOP_Buffer.cpp
@@ -111,7 +111,7 @@ GIOP_Buffer::GIOP_Buffer(void)
     preamble_(),
     log_offset_(0),
     thr_(0),
-    time_(0),
+    time_(),
     expected_req_id_(0),
     expected_size_(0),
     expected_type_(0),
@@ -144,7 +144,7 @@ GIOP_Buffer::GIOP_Buffer(const char *text,
     preamble_(text),
     log_offset_(offset),
     thr_(thread),
-    time_(0),
+    time_(ACE_Time_Value::zero),
     expected_req_id_(0),
     expected_size_(0),
     expected_type_(0),
@@ -178,20 +178,6 @@ GIOP_Buffer::GIOP_Buffer(const char *text,
     }
   this->sending_ = ACE_OS::strstr(text,"send") ? 0 : 1;
   this->expected_type_ = ACE_OS::strstr(text,"Request") ? 0 : 1;
-  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)
-        {
-          int hr, min, sec, msec;
-          ::sscanf (hms-2,"%d:%d:%d.%d", &hr, &min, &sec, &msec);
-          this->time_ = (hr * 3600 + min *60 + sec) * 1000 + msec;
-        }
-    }
 }
 
 void
@@ -350,12 +336,18 @@ GIOP_Buffer::thread (void)
   return this->thr_;
 }
 
-time_t
+const ACE_Time_Value &
 GIOP_Buffer::time (void) const
 {
   return this->time_;
 }
 
+void
+GIOP_Buffer::time (const ACE_Time_Value &t)
+{
+  this->time_ = t;
+}
+
 const ACE_CString &
 GIOP_Buffer::preamble (void) const
 {
diff --git a/TAO/utils/logWalker/GIOP_Buffer.h b/TAO/utils/logWalker/GIOP_Buffer.h
index 03d74e8c9be..46209b1bc74 100644
--- a/TAO/utils/logWalker/GIOP_Buffer.h
+++ b/TAO/utils/logWalker/GIOP_Buffer.h
@@ -59,7 +59,9 @@ public:
   bool is_full (void) const;
   size_t log_posn (void) const;
   Thread *thread (void);
-  time_t time (void) const;
+
+  const ACE_Time_Value & time (void) const;
+  void time (const ACE_Time_Value &);
 
   const ACE_CString &preamble(void) const;
   size_t expected_req_id(void) const;
@@ -90,7 +92,7 @@ private:
   ACE_CString preamble_;
   size_t log_offset_;
   Thread *thr_;
-  time_t time_;
+  ACE_Time_Value time_;
   size_t expected_req_id_;
   size_t expected_size_;
   char   expected_type_;
diff --git a/TAO/utils/logWalker/HostProcess.cpp b/TAO/utils/logWalker/HostProcess.cpp
index 75423dc6b93..07055375e40 100644
--- a/TAO/utils/logWalker/HostProcess.cpp
+++ b/TAO/utils/logWalker/HostProcess.cpp
@@ -14,7 +14,8 @@ PeerNode::PeerNode (long h, PeerProcess *p)
 
 HostProcess::HostProcess (const ACE_CString &src, long pid)
   : pid_(pid),
-    logfile_name_(src)
+    logfile_name_(src),
+    start_time_ (ACE_Time_Value::zero)
 {
 }
 
@@ -143,6 +144,19 @@ HostProcess::pid (void) const
   return this->pid_;
 }
 
+
+const ACE_Time_Value &
+HostProcess::start_time (void) const
+{
+  return this->start_time_;
+}
+
+void
+HostProcess::start_time (const ACE_Time_Value &start)
+{
+  this->start_time_ = start;
+}
+
 bool
 HostProcess::has_endpoint (const Endpoint& addr, bool listen)
 {
@@ -274,7 +288,7 @@ HostProcess::dump_thread_summary (ostream &strm)
 }
 
 void
-HostProcess::split_thread_invocations (Session *session)
+HostProcess::split_thread_invocations (Session *session, const ACE_Time_Value& start)
 {
   for (ACE_DLList_Iterator <Thread> t_iter (this->threads_);
        !t_iter.done();
@@ -287,13 +301,13 @@ HostProcess::split_thread_invocations (Session *session)
       ostream *strm = session->stream_for (0, this, "threads", fname);
       thr->dump_invocations (*strm);
       *strm << endl;
-      thr->dump_incidents (*strm);
+      thr->dump_incidents (*strm, start);
       *strm << endl;
       delete strm;
     }
 }
 void
-HostProcess::dump_thread_invocations (ostream &strm)
+HostProcess::dump_thread_invocations (ostream &strm, const ACE_Time_Value& start)
 {
   this->dump_ident (strm, "invocations by thread:");
   for (ACE_DLList_Iterator <Thread> t_iter (this->threads_);
@@ -304,7 +318,7 @@ HostProcess::dump_thread_invocations (ostream &strm)
       t_iter.next(thr);
       thr->dump_invocations (strm);
       strm << endl;
-      thr->dump_incidents (strm);
+      thr->dump_incidents (strm, start);
       strm << endl;
     }
 }
diff --git a/TAO/utils/logWalker/HostProcess.h b/TAO/utils/logWalker/HostProcess.h
index 68b6b33b7b4..4ea6a493c0b 100644
--- a/TAO/utils/logWalker/HostProcess.h
+++ b/TAO/utils/logWalker/HostProcess.h
@@ -66,7 +66,10 @@ public:
   // Returns the process id.
   long pid (void) const;
 
-  // returns true if the supplied endpoint has been visited before. This
+  const ACE_Time_Value &start_time (void) const;
+  void start_time (const ACE_Time_Value &);
+
+  // Return true if the supplied endpoint has been visited before. This
   // may be either a listen endpoint or a client endpoint used to connect
   // to another peer.
   bool has_endpoint (const Endpoint& addr, bool listen);
@@ -96,8 +99,8 @@ public:
   void dump_ident (ostream &strm, const char *extra);
   void dump_summary (ostream &strm);
   void dump_thread_summary (ostream &strm);
-  void split_thread_invocations (Session *session);
-  void dump_thread_invocations (ostream &strm);
+  void split_thread_invocations (Session *session, const ACE_Time_Value& start);
+  void dump_thread_invocations (ostream &strm, const ACE_Time_Value& start);
   void dump_peer_summary (ostream &strm);
   void dump_object_detail (ostream &strm);
   void split_peer_invocations (Session *session);
@@ -122,6 +125,7 @@ private:
 
   PeerProcs   by_addr_;
   PeerArray   by_handle_;
+  ACE_Time_Value start_time_;
 };
 
 #endif // LOG_WALKER_HOST_PROCESS_H
diff --git a/TAO/utils/logWalker/Invocation.cpp b/TAO/utils/logWalker/Invocation.cpp
index 07d15015809..0a8512e8e0b 100644
--- a/TAO/utils/logWalker/Invocation.cpp
+++ b/TAO/utils/logWalker/Invocation.cpp
@@ -232,13 +232,34 @@ Invocation::new_line (ostream &strm, int indent, int offset, bool add_nl, bool s
 }
 
 void
-Invocation::dump_start_line (ostream &strm, size_t indent)
+Invocation::dump_rel_time (ostream &strm, const ACE_Time_Value &tv, const ACE_Time_Value& start)
+{
+  ACE_Time_Value reltime = tv - start;
+  int hours = reltime.sec() / 3600;
+  int min = (reltime.sec() %3600) / 60;
+  int sec = (reltime.sec() %60);
+
+  char buffer[20];
+  ::snprintf (buffer, 20, "%d:%02d:%02d.%03d",
+              hours, min, sec, reltime.usec()/1000);
+
+  strm << buffer << ' ';
+}
+
+void
+Invocation::dump_start_line (ostream &strm, size_t indent, const ACE_Time_Value& start)
 {
   if (this->req_octets_ == 0)
     return;
   this->req_level_ = indent;
   strm << setw(7) << this->req_octets_->log_posn() << " " << setw(0);
 
+  const ACE_Time_Value &tv = this->req_octets_->time();
+  if (tv != ACE_Time_Value::zero)
+    {
+      dump_rel_time (strm, tv, start);
+    }
+
   const char *opname = "";
   const char *dir_1 = "sent to ";
   const char *dir_2 = " in ";
@@ -275,7 +296,7 @@ Invocation::dump_start_line (ostream &strm, size_t indent)
 }
 
 void
-Invocation::dump_finish_line (ostream &strm, size_t indent)
+Invocation::dump_finish_line (ostream &strm, size_t indent, const ACE_Time_Value& start)
 {
   bool is_popped = this->repl_level_ > 0 && indent == this->req_level_;
 
@@ -288,14 +309,24 @@ Invocation::dump_finish_line (ostream &strm, size_t indent)
     }
 
   this->finish_reported_ = true;
-
   strm << setw(7) << this->repl_octets_->log_posn() << " " << setw(0);
 
   const char *opname = "";
+  const ACE_Time_Value &tv = this->repl_octets_->time();
+  if (tv != ACE_Time_Value::zero)
+    {
+      dump_rel_time (strm, tv, start);
+    }
+
+  const char *dir = "reply from ";
 
   if (this->req_octets_ != 0)
     {
       opname = this->req_octets_->operation();
+      if (this->req_octets_->sending())
+        {
+          dir = "reply to ";
+        }
     }
 
   if (opname == 0 || opname[0] == 0)
@@ -305,7 +336,7 @@ Invocation::dump_finish_line (ostream &strm, size_t indent)
 
   this->new_line (strm, indent, 0, false, true);
 
-  strm << "reply for " << this->peer_->id() << ", req " << this->req_id_;
+  strm << dir << this->peer_->id() << ", req " << this->req_id_;
   strm << " [" << opname << "]";
   if (is_popped)
     {
@@ -359,8 +390,8 @@ Invocation::dump_detail (ostream &strm,
   if (show_handle)
     strm << "(h=" << this->handle_ << ")";
   strm << " [" << opname << "]\t";
-  time_t req_time = 0;
-  time_t rep_time = 0;
+  ACE_Time_Value req_time;
+  ACE_Time_Value rep_time;
   size_t delta = 0;
   if (!this->is_oneway() && this->req_octets_ != 0)
     {
@@ -372,8 +403,8 @@ Invocation::dump_detail (ostream &strm,
             this->req_octets_->log_posn();
         }
     }
-  if (req_time != 0 && rep_time != 0)
-    strm << " took " << (rep_time - req_time) << " ms";
+  if (req_time.msec() != 0 && rep_time.msec() != 0)
+    strm << " took " << (rep_time.msec() - req_time.msec()) << " ms";
 
   if (this->req_octets_ != 0)
     {
diff --git a/TAO/utils/logWalker/Invocation.h b/TAO/utils/logWalker/Invocation.h
index e88292117cb..d1cc33b0b83 100644
--- a/TAO/utils/logWalker/Invocation.h
+++ b/TAO/utils/logWalker/Invocation.h
@@ -83,8 +83,9 @@ 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_rel_time (ostream &strm, const ACE_Time_Value& tv, const ACE_Time_Value& start);
+  void dump_start_line (ostream &strm, size_t indent, const ACE_Time_Value& start);
+  void dump_finish_line (ostream &strm, size_t indent, const ACE_Time_Value& start);
   void dump_special_details (ostream &strm, size_t indent, const char *opname);
 
 private:
diff --git a/TAO/utils/logWalker/Log.cpp b/TAO/utils/logWalker/Log.cpp
index 29526d4fc1f..d5fba18af59 100644
--- a/TAO/utils/logWalker/Log.cpp
+++ b/TAO/utils/logWalker/Log.cpp
@@ -13,6 +13,7 @@ Log::Log (Session &session)
     dump_target_ (0),
     history_ (),
     timestamp_ (),
+    time_ (0,0),
     line_ (0),
     info_ (0),
     offset_ (0),
@@ -103,7 +104,6 @@ Log::get_preamble ()
         }
     }
 
-
   long pid = ACE_OS::strtol(p + 1, &t, 10);
   if (pid == 0)
     return;
@@ -136,6 +136,7 @@ Log::get_preamble ()
       size_t numprocs = this->procs_.size();
       this->hostproc_ = new HostProcess (this->origin_, pid);
       this->procs_.insert_tail(this->hostproc_);
+      this->hostproc_->start_time (this->time_);
       ACE_CString &procname = this->alias_.length() > 0 ?
         this->alias_ : this->origin_;
       switch (numprocs)
@@ -264,6 +265,7 @@ Log::parse_dump_giop_msg_i (void)
       inv->init (this->line_, this->offset_, this->thr_);
       this->thr_->push_invocation (inv);
       target = inv->octets(true);
+      target->time (this->time_);
       if (target == 0)
         {
           ACE_ERROR ((LM_ERROR, "%d: no target octets for new recv reqeust, id = %d\n",
@@ -287,6 +289,7 @@ Log::parse_dump_giop_msg_i (void)
         }
       inv->init (this->line_, this->offset_, this->thr_);
       target = inv->octets(mode == 0);
+      target->time (this->time_);
       if (target == 0 && mode == 3)
         {
           ACE_ERROR ((LM_ERROR,
@@ -300,6 +303,7 @@ Log::parse_dump_giop_msg_i (void)
     }
     case 2: { // sending reply
       target = new GIOP_Buffer(this->line_, this->offset_, this->thr_);
+      target->time (this->time_);
       this->thr_->pop_invocation ();
       break;
     }
@@ -971,17 +975,31 @@ Log::get_timestamp (void)
 {
   const char *time_tok = ACE_OS::strchr (this->line_,'@');
   size_t len = (size_t)(time_tok - this->line_);
-  if (time_tok != 0 && len < 30)
+
+  if (time_tok != 0 && len < 28 )
     {
+      if (this->line_[4] != '-' ||
+          this->line_[7] != '-' ||
+          this->line_[10] != ' ')
+        {
+          return;
+        }
+      ACE_CString prev_st = this->timestamp_;
       this->timestamp_ = ACE_CString (this->line_, len);
-#if 0
-      int year, mon, day;
-      int hr, min, sec, msec;
-      ::sscanf (hms+1,"%d-%d-%d %d:%d:%d.%d", &year, &mon, &day, &hr, &min, &sec, &msec);
-      time = (hr * 3600 + min *60 + sec) * 1000 + msec;
-      if (this->time_ > time)
-        time += 24 * 3600 * 1000;
-#endif
+
+      struct tm tms;
+      int msec;
+      ::sscanf (this->timestamp_.c_str(),"%d-%d-%d %d:%d:%d.%d",
+        &tms.tm_year, &tms.tm_mon, &tms.tm_mday,
+        &tms.tm_hour, &tms.tm_min, &tms.tm_sec, &msec);
+      tms.tm_year -= 1900;
+      tms.tm_mon -= 1;
+      tms.tm_isdst = 0;
+      tms.tm_wday = 0;
+      tms.tm_yday = 0;
+
+      this->time_ = ::mktime (&tms);
+      this->time_.usec (msec * 1000);
     }
 }
 
@@ -994,8 +1012,8 @@ Log::parse_line (void)
       return;
     }
 
-  this->get_preamble();
   this->get_timestamp();
+  this->get_preamble();
 
   if (ACE_OS::strstr (this->info_, "Handler::open, IIOP connection to peer") != 0)
     {
diff --git a/TAO/utils/logWalker/Log.h b/TAO/utils/logWalker/Log.h
index bd5fafe48f0..813895c9df5 100644
--- a/TAO/utils/logWalker/Log.h
+++ b/TAO/utils/logWalker/Log.h
@@ -87,6 +87,7 @@ protected:
 
   // parsed for every line
   ACE_CString timestamp_;
+  ACE_Time_Value time_;
   char *line_;
   char *info_;
   size_t offset_;
diff --git a/TAO/utils/logWalker/Session.cpp b/TAO/utils/logWalker/Session.cpp
index a52574afb77..a23ed050981 100644
--- a/TAO/utils/logWalker/Session.cpp
+++ b/TAO/utils/logWalker/Session.cpp
@@ -304,6 +304,20 @@ Session::dump ()
 
   if (single)
     *strm << "\n\n\nSession detail invocation by thread report: " << endl;
+
+  ACE_Time_Value start = ACE_Time_Value::zero;
+  for (Procs_By_Name::ITERATOR i (this->procs_by_name_); !i.done(); i.advance())
+    {
+      Procs_By_Name::ENTRY *entry;
+      if (i.next(entry) == 0)
+        continue;
+      if (start == ACE_Time_Value::zero ||
+          entry->item()->start_time().msec() < start.msec())
+        {
+          start = entry->item()->start_time();
+        }
+    }
+
   for (Procs_By_Name::ITERATOR i (this->procs_by_name_); !i.done(); i.advance())
     {
       Procs_By_Name::ENTRY *entry;
@@ -311,12 +325,12 @@ Session::dump ()
         continue;
       if (this->split_details_)
         {
-          entry->item()->split_thread_invocations (this);
+          entry->item()->split_thread_invocations (this, start);
         }
       else
         {
           strm = stream_for (strm,entry->item(),"invocation_by_thread.txt");
-          entry->item()->dump_thread_invocations (*strm);
+          entry->item()->dump_thread_invocations (*strm, start);
         }
     }
   if (this->has_outfile() || this->has_dir())
diff --git a/TAO/utils/logWalker/Thread.cpp b/TAO/utils/logWalker/Thread.cpp
index 9b07eb76f35..72fca9285b1 100644
--- a/TAO/utils/logWalker/Thread.cpp
+++ b/TAO/utils/logWalker/Thread.cpp
@@ -337,7 +337,7 @@ Thread::dump_invocations (ostream &strm)
 }
 
 void
-Thread::dump_incidents (ostream &strm)
+Thread::dump_incidents (ostream &strm, const ACE_Time_Value& relstart)
 {
   if (this->nested_ == 0)
     return;
@@ -362,7 +362,7 @@ Thread::dump_incidents (ostream &strm)
             }
           nested_queue.pop_back ();
           level--;
-          prev->dump_finish_line (strm, level);
+          prev->dump_finish_line (strm, level, relstart);
         }
       if (nested_queue.size() > 1)
         {
@@ -373,12 +373,12 @@ Thread::dump_incidents (ostream &strm)
             {
               if ((*j)->repl_line () < inv_line)
                 {
-                  (*j)->dump_finish_line (strm, level);
+                  (*j)->dump_finish_line (strm, level, relstart);
                 }
             }
         }
       nested_queue.push_back (inv);
-      inv->dump_start_line (strm, level);
+      inv->dump_start_line (strm, level, relstart);
     }
 }
 
diff --git a/TAO/utils/logWalker/Thread.h b/TAO/utils/logWalker/Thread.h
index d4f3bb1cee5..951a9a6d864 100644
--- a/TAO/utils/logWalker/Thread.h
+++ b/TAO/utils/logWalker/Thread.h
@@ -42,7 +42,7 @@ public:
   void set_giop_target (GIOP_Buffer *buffer);
   void dump_summary (ostream &strm);
   void dump_invocations (ostream &strm);
-  void dump_incidents (ostream &strm);
+  void dump_incidents (ostream &strm, const ACE_Time_Value& start);
 
   void get_summary (long &sent_reqs, long &recv_reqs, size_t &sent_size, size_t &recv_size);