• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /* Copyright 2015 The TensorFlow Authors. All Rights Reserved.
2 
3 Licensed under the Apache License, Version 2.0 (the "License");
4 you may not use this file except in compliance with the License.
5 You may obtain a copy of the License at
6 
7     http://www.apache.org/licenses/LICENSE-2.0
8 
9 Unless required by applicable law or agreed to in writing, software
10 distributed under the License is distributed on an "AS IS" BASIS,
11 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 See the License for the specific language governing permissions and
13 limitations under the License.
14 ==============================================================================*/
15 
16 #include "tensorflow/core/platform/default/logging.h"
17 
18 // TODO(b/142492876): Avoid depending on absl internal.
19 #ifdef TF_ANDROID_ENABLE_LOG_EVERY_N_SECONDS
20 #include "absl/base/internal/cycleclock.h"
21 #endif
22 #if !defined(PLATFORM_POSIX_ANDROID)
23 #include "absl/base/internal/sysinfo.h"
24 #endif
25 #include "tensorflow/core/platform/env_time.h"
26 #include "tensorflow/core/platform/macros.h"
27 
28 #if defined(PLATFORM_POSIX_ANDROID)
29 #include <android/log.h>
30 
31 #include <iostream>
32 #include <sstream>
33 #endif
34 
35 #include <stdlib.h>
36 #include <string.h>
37 #include <time.h>
38 
39 #include <string>
40 #include <unordered_map>
41 
42 namespace tensorflow {
43 
44 #ifdef TF_ANDROID_ENABLE_LOGSINK
TFAddLogSink(TFLogSink * sink)45 void TFAddLogSink(TFLogSink* sink) {
46   // LogSink is not implemented.
47   // If necessary, one can add the log sink support as follows.
48   // 1. Define a global vector<TFLogSink> to keep track of all registered
49   //    TFLogSink objects. Protect the global vector with mutex to make it
50   //    thread-safe.
51   // 2. Add/remove elements from the global vector<TFLogSink> in TFAddLogSink
52   //    and TFRemoveLogSink function
53   // 3. Add logic in LogMessage::GenerateLogMessage() below to dispatch log
54   //    messages to all the registered log sinks.
55 }
56 
TFRemoveLogSink(TFLogSink * sink)57 void TFRemoveLogSink(TFLogSink* sink) {
58   // LogSink is not implemented.
59 }
60 #endif  // TF_ANDROID_ENABLE_LOGSINK
61 
62 namespace internal {
63 namespace {
64 
ParseInteger(const char * str,size_t size)65 int ParseInteger(const char* str, size_t size) {
66   // Ideally we would use env_var / safe_strto64, but it is
67   // hard to use here without pulling in a lot of dependencies,
68   // so we use std:istringstream instead
69   string integer_str(str, size);
70   std::istringstream ss(integer_str);
71   int level = 0;
72   ss >> level;
73   return level;
74 }
75 
76 // Parse log level (int64) from environment variable (char*)
LogLevelStrToInt(const char * tf_env_var_val)77 int64 LogLevelStrToInt(const char* tf_env_var_val) {
78   if (tf_env_var_val == nullptr) {
79     return 0;
80   }
81   return ParseInteger(tf_env_var_val, strlen(tf_env_var_val));
82 }
83 
84 // Using StringPiece breaks Windows build.
85 struct StringData {
86   struct Hasher {
operator ()tensorflow::internal::__anon5de8043b0111::StringData::Hasher87     size_t operator()(const StringData& sdata) const {
88       // For dependency reasons, we cannot use hash.h here. Use DBJHash instead.
89       size_t hash = 5381;
90       const char* data = sdata.data;
91       for (const char* top = data + sdata.size; data < top; ++data) {
92         hash = ((hash << 5) + hash) + (*data);
93       }
94       return hash;
95     }
96   };
97 
98   StringData() = default;
StringDatatensorflow::internal::__anon5de8043b0111::StringData99   StringData(const char* data, size_t size) : data(data), size(size) {}
100 
operator ==tensorflow::internal::__anon5de8043b0111::StringData101   bool operator==(const StringData& rhs) const {
102     return size == rhs.size && memcmp(data, rhs.data, size) == 0;
103   }
104 
105   const char* data = nullptr;
106   size_t size = 0;
107 };
108 
109 using VmoduleMap = std::unordered_map<StringData, int, StringData::Hasher>;
110 
111 // Returns a mapping from module name to VLOG level, derived from the
112 // TF_CPP_VMODULE environment variable; ownership is transferred to the caller.
VmodulesMapFromEnv()113 VmoduleMap* VmodulesMapFromEnv() {
114   // The value of the env var is supposed to be of the form:
115   //    "foo=1,bar=2,baz=3"
116   const char* env = getenv("TF_CPP_VMODULE");
117   if (env == nullptr) {
118     // If there is no TF_CPP_VMODULE configuration (most common case), return
119     // nullptr so that the ShouldVlogModule() API can fast bail out of it.
120     return nullptr;
121   }
122   // The memory returned by getenv() can be invalidated by following getenv() or
123   // setenv() calls. And since we keep references to it in the VmoduleMap in
124   // form of StringData objects, make a copy of it.
125   const char* env_data = strdup(env);
126   VmoduleMap* result = new VmoduleMap();
127   while (true) {
128     const char* eq = strchr(env_data, '=');
129     if (eq == nullptr) {
130       break;
131     }
132     const char* after_eq = eq + 1;
133 
134     // Comma either points at the next comma delimiter, or at a null terminator.
135     // We check that the integer we parse ends at this delimiter.
136     const char* comma = strchr(after_eq, ',');
137     const char* new_env_data;
138     if (comma == nullptr) {
139       comma = strchr(after_eq, '\0');
140       new_env_data = comma;
141     } else {
142       new_env_data = comma + 1;
143     }
144     (*result)[StringData(env_data, eq - env_data)] =
145         ParseInteger(after_eq, comma - after_eq);
146     env_data = new_env_data;
147   }
148   return result;
149 }
150 
151 #if !defined(PLATFORM_POSIX_ANDROID)
EmitThreadIdFromEnv()152 bool EmitThreadIdFromEnv() {
153   const char* tf_env_var_val = getenv("TF_CPP_LOG_THREAD_ID");
154   return tf_env_var_val == nullptr
155              ? false
156              : ParseInteger(tf_env_var_val, strlen(tf_env_var_val)) != 0;
157 }
158 #endif
159 
160 }  // namespace
161 
MinLogLevelFromEnv()162 int64 MinLogLevelFromEnv() {
163   // We don't want to print logs during fuzzing as that would slow fuzzing down
164   // by almost 2x. So, if we are in fuzzing mode (not just running a test), we
165   // return a value so that nothing is actually printed. Since LOG uses >=
166   // (see ~LogMessage in this file) to see if log messages need to be printed,
167   // the value we're interested on to disable printing is the maximum severity.
168   // See also http://llvm.org/docs/LibFuzzer.html#fuzzer-friendly-build-mode
169 #ifdef FUZZING_BUILD_MODE_UNSAFE_FOR_PRODUCTION
170   return tensorflow::NUM_SEVERITIES;
171 #else
172   const char* tf_env_var_val = getenv("TF_CPP_MIN_LOG_LEVEL");
173   return LogLevelStrToInt(tf_env_var_val);
174 #endif
175 }
176 
MinVLogLevelFromEnv()177 int64 MinVLogLevelFromEnv() {
178   // We don't want to print logs during fuzzing as that would slow fuzzing down
179   // by almost 2x. So, if we are in fuzzing mode (not just running a test), we
180   // return a value so that nothing is actually printed. Since VLOG uses <=
181   // (see VLOG_IS_ON in logging.h) to see if log messages need to be printed,
182   // the value we're interested on to disable printing is 0.
183   // See also http://llvm.org/docs/LibFuzzer.html#fuzzer-friendly-build-mode
184 #ifdef FUZZING_BUILD_MODE_UNSAFE_FOR_PRODUCTION
185   return 0;
186 #else
187   const char* tf_env_var_val = getenv("TF_CPP_MIN_VLOG_LEVEL");
188   return LogLevelStrToInt(tf_env_var_val);
189 #endif
190 }
191 
LogMessage(const char * fname,int line,int severity)192 LogMessage::LogMessage(const char* fname, int line, int severity)
193     : fname_(fname), line_(line), severity_(severity) {}
194 
AtLocation(const char * fname,int line)195 LogMessage& LogMessage::AtLocation(const char* fname, int line) {
196   fname_ = fname;
197   line_ = line;
198   return *this;
199 }
200 
~LogMessage()201 LogMessage::~LogMessage() {
202   // Read the min log level once during the first call to logging.
203   static int64 min_log_level = MinLogLevelFromEnv();
204   if (severity_ >= min_log_level) {
205     GenerateLogMessage();
206   }
207 }
208 
209 #if defined(PLATFORM_POSIX_ANDROID)
GenerateLogMessage()210 void LogMessage::GenerateLogMessage() {
211   int android_log_level;
212   switch (severity_) {
213     case INFO:
214       android_log_level = ANDROID_LOG_INFO;
215       break;
216     case WARNING:
217       android_log_level = ANDROID_LOG_WARN;
218       break;
219     case ERROR:
220       android_log_level = ANDROID_LOG_ERROR;
221       break;
222     case FATAL:
223       android_log_level = ANDROID_LOG_FATAL;
224       break;
225     default:
226       if (severity_ < INFO) {
227         android_log_level = ANDROID_LOG_VERBOSE;
228       } else {
229         android_log_level = ANDROID_LOG_ERROR;
230       }
231       break;
232   }
233 
234   std::stringstream ss;
235   const char* const partial_name = strrchr(fname_, '/');
236   ss << (partial_name != nullptr ? partial_name + 1 : fname_) << ":" << line_
237      << " " << str();
238   __android_log_write(android_log_level, "native", ss.str().c_str());
239 
240   // Also log to stderr (for standalone Android apps).
241   std::cerr << "native : " << ss.str() << std::endl;
242 
243   // Android logging at level FATAL does not terminate execution, so abort()
244   // is still required to stop the program.
245   if (severity_ == FATAL) {
246     abort();
247   }
248 }
249 
250 #else
251 
GenerateLogMessage()252 void LogMessage::GenerateLogMessage() {
253   static bool log_thread_id = EmitThreadIdFromEnv();
254   uint64 now_micros = EnvTime::NowMicros();
255   time_t now_seconds = static_cast<time_t>(now_micros / 1000000);
256   int32 micros_remainder = static_cast<int32>(now_micros % 1000000);
257   const size_t time_buffer_size = 30;
258   char time_buffer[time_buffer_size];
259   strftime(time_buffer, time_buffer_size, "%Y-%m-%d %H:%M:%S",
260            localtime(&now_seconds));
261   const size_t tid_buffer_size = 10;
262   char tid_buffer[tid_buffer_size] = "";
263   if (log_thread_id) {
264     snprintf(tid_buffer, sizeof(tid_buffer), " %7u", gettid());
265   }
266   // TODO(jeff,sanjay): Replace this with something that logs through the env.
267   fprintf(stderr, "%s.%06d: %c%s %s:%d] %s\n", time_buffer, micros_remainder,
268           "IWEF"[severity_], tid_buffer, fname_, line_, str().c_str());
269 }
270 #endif
271 
MinVLogLevel()272 int64 LogMessage::MinVLogLevel() {
273   static int64 min_vlog_level = MinVLogLevelFromEnv();
274   return min_vlog_level;
275 }
276 
VmoduleActivated(const char * fname,int level)277 bool LogMessage::VmoduleActivated(const char* fname, int level) {
278   if (level <= MinVLogLevel()) {
279     return true;
280   }
281   static VmoduleMap* vmodules = VmodulesMapFromEnv();
282   if (TF_PREDICT_TRUE(vmodules == nullptr)) {
283     return false;
284   }
285   const char* last_slash = strrchr(fname, '/');
286   const char* module_start = last_slash == nullptr ? fname : last_slash + 1;
287   const char* dot_after = strchr(module_start, '.');
288   const char* module_limit =
289       dot_after == nullptr ? strchr(fname, '\0') : dot_after;
290   StringData module(module_start, module_limit - module_start);
291   auto it = vmodules->find(module);
292   return it != vmodules->end() && it->second >= level;
293 }
294 
LogMessageFatal(const char * file,int line)295 LogMessageFatal::LogMessageFatal(const char* file, int line)
296     : LogMessage(file, line, FATAL) {}
~LogMessageFatal()297 LogMessageFatal::~LogMessageFatal() {
298   // abort() ensures we don't return (we promised we would not via
299   // ATTRIBUTE_NORETURN).
300   GenerateLogMessage();
301   abort();
302 }
303 
LogString(const char * fname,int line,int severity,const string & message)304 void LogString(const char* fname, int line, int severity,
305                const string& message) {
306   LogMessage(fname, line, severity) << message;
307 }
308 
309 template <>
MakeCheckOpValueString(std::ostream * os,const char & v)310 void MakeCheckOpValueString(std::ostream* os, const char& v) {
311   if (v >= 32 && v <= 126) {
312     (*os) << "'" << v << "'";
313   } else {
314     (*os) << "char value " << static_cast<short>(v);
315   }
316 }
317 
318 template <>
MakeCheckOpValueString(std::ostream * os,const signed char & v)319 void MakeCheckOpValueString(std::ostream* os, const signed char& v) {
320   if (v >= 32 && v <= 126) {
321     (*os) << "'" << v << "'";
322   } else {
323     (*os) << "signed char value " << static_cast<short>(v);
324   }
325 }
326 
327 template <>
MakeCheckOpValueString(std::ostream * os,const unsigned char & v)328 void MakeCheckOpValueString(std::ostream* os, const unsigned char& v) {
329   if (v >= 32 && v <= 126) {
330     (*os) << "'" << v << "'";
331   } else {
332     (*os) << "unsigned char value " << static_cast<unsigned short>(v);
333   }
334 }
335 
336 #if LANG_CXX11
337 template <>
MakeCheckOpValueString(std::ostream * os,const std::nullptr_t & p)338 void MakeCheckOpValueString(std::ostream* os, const std::nullptr_t& p) {
339   (*os) << "nullptr";
340 }
341 #endif
342 
CheckOpMessageBuilder(const char * exprtext)343 CheckOpMessageBuilder::CheckOpMessageBuilder(const char* exprtext)
344     : stream_(new std::ostringstream) {
345   *stream_ << "Check failed: " << exprtext << " (";
346 }
347 
~CheckOpMessageBuilder()348 CheckOpMessageBuilder::~CheckOpMessageBuilder() { delete stream_; }
349 
ForVar2()350 std::ostream* CheckOpMessageBuilder::ForVar2() {
351   *stream_ << " vs. ";
352   return stream_;
353 }
354 
NewString()355 string* CheckOpMessageBuilder::NewString() {
356   *stream_ << ")";
357   return new string(stream_->str());
358 }
359 
360 namespace {
361 // The following code behaves like AtomicStatsCounter::LossyAdd() for
362 // speed since it is fine to lose occasional updates.
363 // Returns old value of *counter.
LossyIncrement(std::atomic<uint32> * counter)364 uint32 LossyIncrement(std::atomic<uint32>* counter) {
365   const uint32 value = counter->load(std::memory_order_relaxed);
366   counter->store(value + 1, std::memory_order_relaxed);
367   return value;
368 }
369 }  // namespace
370 
ShouldLog(int n)371 bool LogEveryNState::ShouldLog(int n) {
372   return n != 0 && (LossyIncrement(&counter_) % n) == 0;
373 }
374 
ShouldLog(int n)375 bool LogFirstNState::ShouldLog(int n) {
376   const uint32 counter_value = counter_.load(std::memory_order_relaxed);
377   if (counter_value < n) {
378     counter_.store(counter_value + 1, std::memory_order_relaxed);
379     return true;
380   }
381   return false;
382 }
383 
ShouldLog(int ignored)384 bool LogEveryPow2State::ShouldLog(int ignored) {
385   const uint32 new_value = LossyIncrement(&counter_) + 1;
386   return (new_value & (new_value - 1)) == 0;
387 }
388 
389 #ifdef TF_ANDROID_ENABLE_LOG_EVERY_N_SECONDS
ShouldLog(double seconds)390 bool LogEveryNSecState::ShouldLog(double seconds) {
391   LossyIncrement(&counter_);
392   const int64 now_cycles = absl::base_internal::CycleClock::Now();
393   int64 next_cycles = next_log_time_cycles_.load(std::memory_order_relaxed);
394   do {
395     if (now_cycles <= next_cycles) return false;
396   } while (!next_log_time_cycles_.compare_exchange_weak(
397       next_cycles,
398       now_cycles + seconds * absl::base_internal::CycleClock::Frequency(),
399       std::memory_order_relaxed, std::memory_order_relaxed));
400   return true;
401 }
402 #endif
403 
404 }  // namespace internal
405 }  // namespace tensorflow
406