Make cygprofile use clock_gettime() instead of gettimeofday().

Some of the generated orderfiles looked suspicious. I could observe that one of
them had the renderer PID show up before the browser one.

The mergetraces.py file was also occasionally complaining about unsorted
timestamps.

There are not many situations where gettimeofday() should be used instead of
clock_gettime(). The former is not monotonic in particular.
The original code also had the issue that it was using both gettimeofday() and 
time().

This also replaces the occurrences of 'ms(ec)' with 'us(ec)' to make it clear
that microseconds are used as opposed to milliseconds.

BUG=372323

Review URL: https://codereview.chromium.org/272393004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@270090 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 21 insertions, 21 deletions

diff --git a/tools/cygprofile/cygprofile.cc b/tools/cygprofile/cygprofile.cc
index 2086bea..980fa9e 100644
--- a/tools/cygprofile/cygprofile.cc
+++ b/tools/cygprofile/cygprofile.cc
@@ -208,7 +208,7 @@ CygCommon::CygCommon() {
     }
   }
   mapsfile.close();
-  header_line_.append("\nsecs\tmsecs\tpid:threadid\tfunc\n");
+  header_line_.append("\nsecs\tusecs\tpid:threadid\tfunc\n");
 }
 
 void CygTlsLog::LogEnter(void* this_fn) {
@@ -222,9 +222,9 @@ void CygTlsLog::LogEnter(void* this_fn) {
     base::AutoLock lock(log_mutex_);
     if (buf_.capacity() < kBufMaxSize)
       buf_.reserve(kBufMaxSize);
-    struct timeval timestamp;
-    gettimeofday(&timestamp, NULL);
-    buf_.push_back(CygLogEntry(time(NULL), timestamp.tv_usec,
+    struct timespec timestamp;
+    clock_gettime(CLOCK_MONOTONIC, &timestamp);
+    buf_.push_back(CygLogEntry(timestamp.tv_sec, timestamp.tv_nsec / 1000,
                                getpid(), pthread_self(), this_fn));
     if (buf_.size() == kBufMaxSize) {
       FlushLog();
diff --git a/tools/cygprofile/mergetraces.py b/tools/cygprofile/mergetraces.py
index 5d85920..1c7627a 100755
--- a/tools/cygprofile/mergetraces.py
+++ b/tools/cygprofile/mergetraces.py
@@ -26,7 +26,7 @@ def ParseLogLines(lines):
 
     Below is an example of a small log file:
     5086e000-52e92000 r-xp 00000000 b3:02 51276      libchromeview.so
-    secs       msecs      pid:threadid    func
+    secs       usecs      pid:threadid    func
     START
     1314897086 795828     3587:1074648168 0x509e105c
     1314897086 795874     3587:1074648168 0x509e0eb4
@@ -78,18 +78,18 @@ def CheckTimestamps(calls):
   """
   index = 0
   last_timestamp_secs = -1
-  last_timestamp_ms = -1
+  last_timestamp_us = -1
   while (index < len (calls)):
     timestamp_secs = int (calls[index][0])
-    timestamp_ms = int (calls[index][1])
-    timestamp = (timestamp_secs * 1000000) + timestamp_ms
-    last_timestamp = (last_timestamp_secs * 1000000) + last_timestamp_ms
+    timestamp_us = int (calls[index][1])
+    timestamp = (timestamp_secs * 1000000) + timestamp_us
+    last_timestamp = (last_timestamp_secs * 1000000) + last_timestamp_us
     if (timestamp < last_timestamp):
-      sys.stderr.write("WARNING: last_timestamp: " + str(last_timestamp_secs)
-                       + " " + str(last_timestamp_ms) + " timestamp: "
-                       + str(timestamp_secs) + " " + str(timestamp_ms) + "\n")
+      raise Exception("last_timestamp: " + str(last_timestamp_secs)
+                       + " " + str(last_timestamp_us) + " timestamp: "
+                       + str(timestamp_secs) + " " + str(timestamp_us) + "\n")
     last_timestamp_secs = timestamp_secs
-    last_timestamp_ms = timestamp_ms
+    last_timestamp_us = timestamp_us
     index = index + 1
 
 def Convert (call_lines, startAddr, endAddr):
@@ -100,19 +100,19 @@ def Convert (call_lines, startAddr, endAddr):
   address in shared library.
 
   Returns:
-     list of calls as tuples (sec, msec, pid:tid, callee)
+     list of calls as tuples (sec, usec, pid:tid, callee)
   """
   converted_calls = []
   call_addresses = []
   for fields in call_lines:
     secs = int (fields[0])
-    msecs = int (fields[1])
+    usecs = int (fields[1])
     callee = int (fields[3], 16)
     # print ("callee: " + hex (callee) + " start: " + hex (startAddr) + " end: "
     #        + hex (endAddr))
     if (callee >= startAddr and callee < endAddr
         and (not callee in call_addresses)):
-      converted_calls.append((secs, msecs, fields[2], (callee - startAddr)))
+      converted_calls.append((secs, usecs, fields[2], (callee - startAddr)))
       call_addresses.append(callee)
   return converted_calls
 
@@ -177,7 +177,7 @@ def main():
   merged_trace.sort(key=Timestamp)
 
   print "0-ffffffff r-xp 00000000 xx:00 00000 ./"
-  print "secs\tmsecs\tpid:threadid\tfunc"
+  print "secs\tusecs\tpid:threadid\tfunc"
   for call in merged_trace:
     print (str(call[0]) + "\t" + str(call[1]) + "\t" + call[2] + "\t" +
            hex(call[3]))
diff --git a/tools/cygprofile/symbolize.py b/tools/cygprofile/symbolize.py
index 694ae54..027da57 100755
--- a/tools/cygprofile/symbolize.py
+++ b/tools/cygprofile/symbolize.py
@@ -26,7 +26,7 @@ def ParseLogLines(log_file_lines):
 
     Below is an example of a small log file:
     5086e000-52e92000 r-xp 00000000 b3:02 51276      libchromeview.so
-    secs       msecs      pid:threadid    func
+    secs       usecs      pid:threadid    func
     START
     1314897086 795828     3587:1074648168 0x509e105c
     1314897086 795874     3587:1074648168 0x509e0eb4
@@ -35,7 +35,7 @@ def ParseLogLines(log_file_lines):
     END
 
   Returns:
-    call_info list with list of tuples of the format (sec, msec, call id,
+    call_info list with list of tuples of the format (sec, usec, call id,
     function address called)
   """
   call_lines = []
@@ -54,12 +54,12 @@ def ParseLogLines(log_file_lines):
   # Convert strings to int in fields.
   call_info = []
   for call_line in call_lines:
-    (sec_timestamp, msec_timestamp) = map(int, call_line[0:2])
+    (sec_timestamp, usec_timestamp) = map(int, call_line[0:2])
     callee_id = call_line[2]
     addr = int(call_line[3], 16)
     if vm_start < addr:
       addr -= vm_start
-      call_info.append((sec_timestamp, msec_timestamp, callee_id, addr))
+      call_info.append((sec_timestamp, usec_timestamp, callee_id, addr))
 
   return call_info