diff options
author | pliard@chromium.org <pliard@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-05-13 14:06:07 +0000 |
---|---|---|
committer | pliard@chromium.org <pliard@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-05-13 14:06:07 +0000 |
commit | 8f3215e30b1223866710145d05fe29ba5863a34b (patch) | |
tree | ef5e20f40dcac785c222007180039f431acdf731 /tools/cygprofile | |
parent | 723127ce19134c3d17b9a66e463f0581411225c5 (diff) | |
download | chromium_src-8f3215e30b1223866710145d05fe29ba5863a34b.zip chromium_src-8f3215e30b1223866710145d05fe29ba5863a34b.tar.gz chromium_src-8f3215e30b1223866710145d05fe29ba5863a34b.tar.bz2 |
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
Diffstat (limited to 'tools/cygprofile')
-rw-r--r-- | tools/cygprofile/cygprofile.cc | 8 | ||||
-rwxr-xr-x | tools/cygprofile/mergetraces.py | 26 | ||||
-rwxr-xr-x | tools/cygprofile/symbolize.py | 8 |
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(×tamp, NULL); - buf_.push_back(CygLogEntry(time(NULL), timestamp.tv_usec, + struct timespec timestamp; + clock_gettime(CLOCK_MONOTONIC, ×tamp); + 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 |