commit 9c38fb522a83b56c57d95dc7a0773c80fe60ae56
author George Karpenkov <cheshire@google.com> Wed Nov 06 15:29:05 2019 -0800
committer TensorFlower Gardener <gardener@tensorflow.org> Wed Nov 06 15:33:28 2019 -0800
tree b40c87f9272ded5e06d33f56cf73242faae5d309
parent c65244d8eb3ef82dd4c9fbed628ec194f14be485

[XLA] Fix up the XLA timer location in logs.

Previously, all timers would log the location util.cc:XX. Now it will show the
actual macro location.

PiperOrigin-RevId: 278953363
Change-Id: I2c6dcd825eefc70aba4ac97f189ea5789cefc554

tensorflow/compiler/xla/util.cc

diff --git a/tensorflow/compiler/xla/util.cc b/tensorflow/compiler/xla/util.cc
index b569d92..8800457 100644
--- a/tensorflow/compiler/xla/util.cc
+++ b/tensorflow/compiler/xla/util.cc
@@ -48,8 +48,13 @@
 }
 
 ScopedLoggingTimer::ScopedLoggingTimer(const std::string& label, bool enabled,
+                                       const char* file, int line,
                                        TimerStats* timer_stats)
-    : enabled(enabled), label(label), timer_stats(timer_stats) {
+    : enabled(enabled),
+      file(file),
+      line(line),
+      label(label),
+      timer_stats(timer_stats) {
   if (enabled) {
     start_micros = tensorflow::Env::Default()->NowMicros();
   }
@@ -68,14 +73,14 @@
     }
     stats.times_called++;
 
-    LOG(INFO) << label << " time: "
-              << tensorflow::strings::HumanReadableElapsedTime(secs)
-              << " (cumulative: "
-              << tensorflow::strings::HumanReadableElapsedTime(
-                     stats.cumulative_secs)
-              << ", max: "
-              << tensorflow::strings::HumanReadableElapsedTime(stats.max_secs)
-              << ", #called: " << stats.times_called << ")";
+    LOG(INFO).AtLocation(file, line)
+        << label
+        << " time: " << tensorflow::strings::HumanReadableElapsedTime(secs)
+        << " (cumulative: "
+        << tensorflow::strings::HumanReadableElapsedTime(stats.cumulative_secs)
+        << ", max: "
+        << tensorflow::strings::HumanReadableElapsedTime(stats.max_secs)
+        << ", #called: " << stats.times_called << ")";
     enabled = false;
   }
 }

tensorflow/compiler/xla/util.h

diff --git a/tensorflow/compiler/xla/util.h b/tensorflow/compiler/xla/util.h
index 75fe28c..e32c540 100644
--- a/tensorflow/compiler/xla/util.h
+++ b/tensorflow/compiler/xla/util.h
@@ -89,7 +89,8 @@
 #define XLA_SCOPED_LOGGING_TIMER_HELPER2(label, level, counter)      \
   static ::xla::TimerStats XLA_TimerStats##counter;                  \
   ::xla::ScopedLoggingTimer XLA_ScopedLoggingTimerInstance##counter( \
-      label, /*enabled=*/VLOG_IS_ON(level), &XLA_TimerStats##counter);
+      label, /*enabled=*/VLOG_IS_ON(level), __FILE__, __LINE__,      \
+      &XLA_TimerStats##counter);
 
 struct TimerStats {
   tensorflow::mutex stats_mutex;
@@ -102,13 +103,14 @@
 // macros above.  Recommended usage is via the macros so you don't have to give
 // the timer a name or worry about calling VLOG_IS_ON yourself.
 struct ScopedLoggingTimer {
-  // The timer does nothing if enabled is false.  This lets you pass in your
-  // file's VLOG_IS_ON value.
-  //
-  // timer_stats is unowned non-null pointer which is used to populate the
+  // label: Label to display for logging.
+  // enabled: Whether this timer should do anything at all.
+  // file: Filename to display in logging.
+  // line: Line number to display in logging.
+  // `timer_stats`: unowned non-null pointer which is used to populate the
   // global timer statistics.
-  ScopedLoggingTimer(const std::string& label, bool enabled,
-                     TimerStats* timer_stats);
+  ScopedLoggingTimer(const std::string& label, bool enabled, const char* file,
+                     int line, TimerStats* timer_stats);
 
   // Stop the timer and log the tracked time. Timer is disabled after this
   // function is called.
@@ -117,6 +119,8 @@
   ~ScopedLoggingTimer();
 
   bool enabled;
+  const char* file;
+  int line;
   string label;
   uint64 start_micros;
   TimerStats* timer_stats;