Revert "Use nanoseconds for v2 method tracing"

This reverts commit 1a9a8abf19e7641149fcaed3971bf0aa99f4dfb8.

Reason for revert: causes flakes on art-jit-on-first-use-gcstress

Change-Id: I38161f65e2fc584e5e6221f85982035fb66c13ae

1 files changed, 29 insertions, 31 deletions

diff --git a/runtime/trace.cc b/runtime/trace.cc
index 2892023074..13a7dd26d4 100644
--- a/runtime/trace.cc
+++ b/runtime/trace.cc
@@ -61,8 +61,8 @@ namespace art HIDDEN {
 struct MethodTraceRecord {
   ArtMethod* method;
   TraceAction action;
-  uint64_t wall_clock_time;
-  uint64_t thread_cpu_time;
+  uint32_t wall_clock_time;
+  uint32_t thread_cpu_time;
 };
 
 using android::base::StringPrintf;
@@ -95,7 +95,7 @@ static constexpr size_t kScalingFactorEncodedEntries = 6;
 // The key identifying the tracer to update instrumentation.
 static constexpr const char* kTracerInstrumentationKey = "Tracer";
 
-double TimestampCounter::tsc_to_nanosec_scaling_factor = -1;
+double TimestampCounter::tsc_to_microsec_scaling_factor = -1;
 
 Trace* Trace::the_trace_ = nullptr;
 pthread_t Trace::sampling_pthread_ = 0U;
@@ -288,7 +288,7 @@ bool UseFastTraceListeners(TraceClockSource clock_source) {
 
 void Trace::MeasureClockOverhead() {
   if (UseThreadCpuClock(clock_source_)) {
-    Thread::Current()->GetCpuNanoTime();
+    Thread::Current()->GetCpuMicroTime();
   }
   if (UseWallClock(clock_source_)) {
     TimestampCounter::GetTimestamp();
@@ -296,12 +296,11 @@ void Trace::MeasureClockOverhead() {
 }
 
 // Compute an average time taken to measure clocks.
-uint64_t Trace::GetClockOverheadNanoSeconds() {
+uint32_t Trace::GetClockOverheadNanoSeconds() {
   Thread* self = Thread::Current();
-  uint64_t start = self->GetCpuNanoTime();
+  uint64_t start = self->GetCpuMicroTime();
 
-  const uint64_t numIter = 4000;
-  for (int i = numIter; i > 0; i--) {
+  for (int i = 4000; i > 0; i--) {
     MeasureClockOverhead();
     MeasureClockOverhead();
     MeasureClockOverhead();
@@ -312,8 +311,8 @@ uint64_t Trace::GetClockOverheadNanoSeconds() {
     MeasureClockOverhead();
   }
 
-  uint64_t elapsed_ns = self->GetCpuNanoTime() - start;
-  return elapsed_ns / (numIter * 8);
+  uint64_t elapsed_us = self->GetCpuMicroTime() - start;
+  return static_cast<uint32_t>(elapsed_us / 32);
 }
 
 static void GetSample(Thread* thread, void* arg) REQUIRES_SHARED(Locks::mutator_lock_) {
@@ -348,7 +347,7 @@ void Trace::CompareAndUpdateStackTrace(Thread* thread,
   // Update the thread's stack trace sample.
   thread->SetStackTraceSample(stack_trace);
   // Read timer clocks to use for all events in this trace.
-  uint64_t thread_clock_diff = 0;
+  uint32_t thread_clock_diff = 0;
   uint64_t timestamp_counter = 0;
   ReadClocks(thread, &thread_clock_diff, &timestamp_counter);
   if (old_stack_trace == nullptr) {
@@ -897,14 +896,14 @@ TraceWriter::TraceWriter(File* trace_file,
                          size_t buffer_size,
                          int num_trace_buffers,
                          int trace_format_version,
-                         uint64_t clock_overhead_ns)
+                         uint32_t clock_overhead_ns)
     : trace_file_(trace_file),
       trace_output_mode_(output_mode),
       clock_source_(clock_source),
       buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()),
       buffer_size_(std::max(kMinBufSize, buffer_size)),
       trace_format_version_(trace_format_version),
-      start_time_(TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp())),
+      start_time_(TimestampCounter::GetMicroTime(TimestampCounter::GetTimestamp())),
       overflow_(false),
       num_records_(0),
       clock_overhead_ns_(clock_overhead_ns),
@@ -922,7 +921,7 @@ TraceWriter::TraceWriter(File* trace_file,
   // construct a cpu profile. See b/318052824 for more context.
   uint64_t start_time_monotonic =
       start_time_ +
-      (NanoTime() - TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp()));
+      (MicroTime() - TimestampCounter::GetMicroTime(TimestampCounter::GetTimestamp()));
   uint16_t trace_version = GetTraceVersion(clock_source_, trace_format_version_);
   if (output_mode == TraceOutputMode::kStreaming) {
     trace_version |= 0xF0U;
@@ -1005,7 +1004,7 @@ Trace::Trace(File* trace_file,
 std::string TraceWriter::CreateSummary(int flags) {
   std::ostringstream os;
   // Compute elapsed time.
-  uint64_t elapsed = TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp()) - start_time_;
+  uint64_t elapsed = TimestampCounter::GetMicroTime(TimestampCounter::GetTimestamp()) - start_time_;
   os << StringPrintf("%cversion\n", kTraceTokenChar);
   os << StringPrintf("%d\n", GetTraceVersion(clock_source_, trace_format_version_));
   os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
@@ -1022,7 +1021,7 @@ std::string TraceWriter::CreateSummary(int flags) {
   if (trace_output_mode_ != TraceOutputMode::kStreaming) {
     os << StringPrintf("num-method-calls=%zd\n", num_records_);
   }
-  os << StringPrintf("clock-call-overhead-nsec=%" PRIu64 "\n", clock_overhead_ns_);
+  os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead_ns_);
   os << StringPrintf("vm=art\n");
   os << StringPrintf("pid=%d\n", getpid());
   if ((flags & Trace::kTraceCountAllocs) != 0) {
@@ -1174,7 +1173,7 @@ void Trace::FieldWritten([[maybe_unused]] Thread* thread,
 }
 
 void Trace::MethodEntered(Thread* thread, ArtMethod* method) {
-  uint64_t thread_clock_diff = 0;
+  uint32_t thread_clock_diff = 0;
   uint64_t timestamp_counter = 0;
   ReadClocks(thread, &thread_clock_diff, &timestamp_counter);
   LogMethodTraceEvent(thread, method, kTraceMethodEnter, thread_clock_diff, timestamp_counter);
@@ -1184,14 +1183,14 @@ void Trace::MethodExited(Thread* thread,
                          ArtMethod* method,
                          [[maybe_unused]] instrumentation::OptionalFrame frame,
                          [[maybe_unused]] JValue& return_value) {
-  uint64_t thread_clock_diff = 0;
+  uint32_t thread_clock_diff = 0;
   uint64_t timestamp_counter = 0;
   ReadClocks(thread, &thread_clock_diff, &timestamp_counter);
   LogMethodTraceEvent(thread, method, kTraceMethodExit, thread_clock_diff, timestamp_counter);
 }
 
 void Trace::MethodUnwind(Thread* thread, ArtMethod* method, [[maybe_unused]] uint32_t dex_pc) {
-  uint64_t thread_clock_diff = 0;
+  uint32_t thread_clock_diff = 0;
   uint64_t timestamp_counter = 0;
   ReadClocks(thread, &thread_clock_diff, &timestamp_counter);
   LogMethodTraceEvent(thread, method, kTraceUnroll, thread_clock_diff, timestamp_counter);
@@ -1220,15 +1219,15 @@ void Trace::WatchedFramePop([[maybe_unused]] Thread* self,
   LOG(ERROR) << "Unexpected WatchedFramePop event in tracing";
 }
 
-void Trace::ReadClocks(Thread* thread, uint64_t* thread_clock_diff, uint64_t* timestamp_counter) {
+void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint64_t* timestamp_counter) {
   if (UseThreadCpuClock(clock_source_)) {
     uint64_t clock_base = thread->GetTraceClockBase();
     if (UNLIKELY(clock_base == 0)) {
       // First event, record the base time in the map.
-      uint64_t time = thread->GetCpuNanoTime();
+      uint64_t time = thread->GetCpuMicroTime();
       thread->SetTraceClockBase(time);
     } else {
-      *thread_clock_diff = thread->GetCpuNanoTime() - clock_base;
+      *thread_clock_diff = thread->GetCpuMicroTime() - clock_base;
     }
   }
   if (UseWallClock(clock_source_)) {
@@ -1551,7 +1550,7 @@ void TraceWriter::ReadValuesFromRecord(uintptr_t* method_trace_entries,
       uint64_t high_timestamp = method_trace_entries[record_index++];
       timestamp = (high_timestamp << 32 | timestamp);
     }
-    record.wall_clock_time = TimestampCounter::GetNanoTime(timestamp) - start_time_;
+    record.wall_clock_time = TimestampCounter::GetMicroTime(timestamp) - start_time_;
   }
 }
 
@@ -1607,8 +1606,8 @@ void TraceWriter::FlushEntriesFormatV2(
   bool has_thread_cpu_clock = UseThreadCpuClock(clock_source_);
   bool has_wall_clock = UseWallClock(clock_source_);
   size_t num_entries = GetNumEntries(clock_source_);
-  uint64_t prev_wall_timestamp = 0;
-  uint64_t prev_thread_timestamp = 0;
+  uint32_t prev_wall_timestamp = 0;
+  uint32_t prev_thread_timestamp = 0;
   uint64_t prev_method_action_encoding = 0;
   size_t entry_index = kPerThreadBufSize;
   for (size_t i = 0; i < num_records; i++) {
@@ -1704,7 +1703,7 @@ void TraceWriter::FlushBuffer(uintptr_t* method_trace_entries,
 void Trace::LogMethodTraceEvent(Thread* thread,
                                 ArtMethod* method,
                                 TraceAction action,
-                                uint64_t thread_clock_diff,
+                                uint32_t thread_clock_diff,
                                 uint64_t timestamp_counter) {
   // This method is called in both tracing modes (method and sampling). In sampling mode, this
   // method is only called by the sampling thread. In method tracing mode, it can be called
@@ -1764,8 +1763,8 @@ void TraceWriter::EncodeEventEntry(uint8_t* ptr,
                                    uint16_t thread_id,
                                    uint32_t method_index,
                                    TraceAction action,
-                                   uint64_t thread_clock_diff,
-                                   uint64_t wall_clock_diff) {
+                                   uint32_t thread_clock_diff,
+                                   uint32_t wall_clock_diff) {
   static constexpr size_t kPacketSize = 14U;  // The maximum size of data in a packet.
   DCHECK(method_index < (1 << (32 - TraceActionBits)));
   uint32_t method_value = (method_index << TraceActionBits) | action;
@@ -1773,13 +1772,12 @@ void TraceWriter::EncodeEventEntry(uint8_t* ptr,
   Append4LE(ptr + 2, method_value);
   ptr += 6;
 
-  static constexpr uint64_t ns_to_us = 1000;
   if (UseThreadCpuClock(clock_source_)) {
-    Append4LE(ptr, thread_clock_diff / ns_to_us);
+    Append4LE(ptr, thread_clock_diff);
     ptr += 4;
   }
   if (UseWallClock(clock_source_)) {
-    Append4LE(ptr, wall_clock_diff / ns_to_us);
+    Append4LE(ptr, wall_clock_diff);
   }
   static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect.");
 }