1 #include <c10/util/Backtrace.h>
2 #include <c10/util/CallOnce.h>
3 #include <c10/util/Flags.h>
4 #include <c10/util/Lazy.h>
5 #include <c10/util/Logging.h>
6 #ifdef FBCODE_CAFFE2
7 #include <folly/synchronization/SanitizeThread.h>
8 #endif
9
10 #ifndef _WIN32
11 #include <sys/time.h>
12 #endif
13
14 #include <algorithm>
15 #include <cstdlib>
16 #include <iostream>
17
18 // Common code that we use regardless of whether we use glog or not.
19
20 C10_DEFINE_bool(
21 caffe2_use_fatal_for_enforce,
22 false,
23 "If set true, when CAFFE_ENFORCE is not met, abort instead "
24 "of throwing an exception.");
25
26 namespace c10 {
27
28 namespace {
GetFetchStackTrace()29 std::function<::c10::Backtrace()>& GetFetchStackTrace() {
30 static std::function<::c10::Backtrace()> func = []() {
31 return get_lazy_backtrace(/*frames_to_skip=*/1);
32 };
33 return func;
34 }
35 } // namespace
36
SetStackTraceFetcher(std::function<::c10::Backtrace ()> fetcher)37 void SetStackTraceFetcher(std::function<::c10::Backtrace()> fetcher) {
38 GetFetchStackTrace() = std::move(fetcher);
39 }
40
SetStackTraceFetcher(std::function<string ()> fetcher)41 void SetStackTraceFetcher(std::function<string()> fetcher) {
42 SetStackTraceFetcher([fetcher = std::move(fetcher)] {
43 return std::make_shared<PrecomputedLazyValue<std::string>>(fetcher());
44 });
45 }
46
ThrowEnforceNotMet(const char * file,const int line,const char * condition,const std::string & msg,const void * caller)47 void ThrowEnforceNotMet(
48 const char* file,
49 const int line,
50 const char* condition,
51 const std::string& msg,
52 const void* caller) {
53 c10::Error e(file, line, condition, msg, GetFetchStackTrace()(), caller);
54 if (FLAGS_caffe2_use_fatal_for_enforce) {
55 LOG(FATAL) << e.msg();
56 }
57 throw std::move(e);
58 }
59
ThrowEnforceNotMet(const char * file,const int line,const char * condition,const char * msg,const void * caller)60 void ThrowEnforceNotMet(
61 const char* file,
62 const int line,
63 const char* condition,
64 const char* msg,
65 const void* caller) {
66 ThrowEnforceNotMet(file, line, condition, std::string(msg), caller);
67 }
68
ThrowEnforceFiniteNotMet(const char * file,const int line,const char * condition,const std::string & msg,const void * caller)69 void ThrowEnforceFiniteNotMet(
70 const char* file,
71 const int line,
72 const char* condition,
73 const std::string& msg,
74 const void* caller) {
75 throw c10::EnforceFiniteError(
76 file, line, condition, msg, GetFetchStackTrace()(), caller);
77 }
78
ThrowEnforceFiniteNotMet(const char * file,const int line,const char * condition,const char * msg,const void * caller)79 void ThrowEnforceFiniteNotMet(
80 const char* file,
81 const int line,
82 const char* condition,
83 const char* msg,
84 const void* caller) {
85 ThrowEnforceFiniteNotMet(file, line, condition, std::string(msg), caller);
86 }
87
88 namespace {
89
90 class PyTorchStyleBacktrace : public OptimisticLazyValue<std::string> {
91 public:
PyTorchStyleBacktrace(SourceLocation source_location)92 PyTorchStyleBacktrace(SourceLocation source_location)
93 : backtrace_(GetFetchStackTrace()()), source_location_(source_location) {}
94
95 private:
compute() const96 std::string compute() const override {
97 return str(
98 "Exception raised from ",
99 source_location_,
100 " (most recent call first):\n",
101 backtrace_->get());
102 }
103
104 ::c10::Backtrace backtrace_;
105 SourceLocation source_location_;
106 };
107
108 } // namespace
109
110 // PyTorch-style error message
111 // (This must be defined here for access to GetFetchStackTrace)
Error(SourceLocation source_location,std::string msg)112 Error::Error(SourceLocation source_location, std::string msg)
113 : Error(
114 std::move(msg),
115 std::make_shared<PyTorchStyleBacktrace>(source_location)) {}
116
117 using APIUsageLoggerType = std::function<void(const std::string&)>;
118 using APIUsageMetadataLoggerType = std::function<void(
119 const std::string&,
120 const std::map<std::string, std::string>& metadata_map)>;
121 using DDPUsageLoggerType = std::function<void(const DDPLoggingData&)>;
122
123 namespace {
IsAPIUsageDebugMode()124 bool IsAPIUsageDebugMode() {
125 const char* val = getenv("PYTORCH_API_USAGE_STDERR");
126 return val && *val; // any non-empty value
127 }
128
APIUsageDebug(const string & event)129 void APIUsageDebug(const string& event) {
130 // use stderr to avoid messing with glog
131 std::cerr << "PYTORCH_API_USAGE " << event << std::endl;
132 }
133
GetAPIUsageLogger()134 APIUsageLoggerType* GetAPIUsageLogger() {
135 static APIUsageLoggerType func =
136 IsAPIUsageDebugMode() ? &APIUsageDebug : [](const string&) {};
137 return &func;
138 }
139
GetAPIUsageMetadataLogger()140 APIUsageMetadataLoggerType* GetAPIUsageMetadataLogger() {
141 static APIUsageMetadataLoggerType func =
142 [](const std::string&,
143 const std::map<std::string, std::string>& metadata_map) {};
144 return &func;
145 }
146
GetDDPUsageLogger()147 DDPUsageLoggerType* GetDDPUsageLogger() {
148 static DDPUsageLoggerType func = [](const DDPLoggingData&) {};
149 return &func;
150 }
151
EventSampledHandlerRegistry()152 auto& EventSampledHandlerRegistry() {
153 static auto& registry =
154 *new std::map<std::string, std::unique_ptr<EventSampledHandler>>();
155 return registry;
156 }
157
158 } // namespace
159
InitEventSampledHandlers(std::vector<std::pair<std::string_view,std::unique_ptr<EventSampledHandler>>> handlers)160 void InitEventSampledHandlers(
161 std::vector<
162 std::pair<std::string_view, std::unique_ptr<EventSampledHandler>>>
163 handlers) {
164 static c10::once_flag flag;
165 c10::call_once(flag, [&]() {
166 auto& registry = EventSampledHandlerRegistry();
167 for (auto& [event, handler] : handlers) {
168 auto entry = registry.find(std::string{event});
169 if (entry == registry.end()) {
170 entry = registry.emplace(event, nullptr).first;
171 }
172 entry->second = std::move(handler);
173 }
174 });
175 }
176
GetEventSampledHandler(std::string_view event)177 const std::unique_ptr<EventSampledHandler>& GetEventSampledHandler(
178 std::string_view event) {
179 static std::mutex guard;
180 auto& registry = EventSampledHandlerRegistry();
181
182 // The getter can be executed from different threads.
183 std::lock_guard<std::mutex> lock(guard);
184 auto entry = registry.find(std::string{event});
185 if (entry == registry.end()) {
186 entry = registry.emplace(event, nullptr).first;
187 }
188 return entry->second;
189 }
190
SetAPIUsageLogger(std::function<void (const std::string &)> logger)191 void SetAPIUsageLogger(std::function<void(const std::string&)> logger) {
192 TORCH_CHECK(logger);
193 *GetAPIUsageLogger() = std::move(logger);
194 }
195
SetAPIUsageMetadataLogger(std::function<void (const std::string &,const std::map<std::string,std::string> & metadata_map)> logger)196 void SetAPIUsageMetadataLogger(
197 std::function<void(
198 const std::string&,
199 const std::map<std::string, std::string>& metadata_map)> logger) {
200 TORCH_CHECK(logger);
201 *GetAPIUsageMetadataLogger() = std::move(logger);
202 }
203
SetPyTorchDDPUsageLogger(std::function<void (const DDPLoggingData &)> logger)204 void SetPyTorchDDPUsageLogger(
205 std::function<void(const DDPLoggingData&)> logger) {
206 TORCH_CHECK(logger);
207 *GetDDPUsageLogger() = std::move(logger);
208 }
209
210 static int64_t GLOBAL_RANK = -1;
211
GetGlobalRank()212 int64_t GetGlobalRank() {
213 return GLOBAL_RANK;
214 }
215
SetGlobalRank(int64_t rank)216 void SetGlobalRank(int64_t rank) {
217 GLOBAL_RANK = rank;
218 }
219
LogAPIUsage(const std::string & event)220 void LogAPIUsage(const std::string& event) try {
221 if (auto logger = GetAPIUsageLogger())
222 (*logger)(event);
223 } catch (std::bad_function_call&) {
224 // static destructor race
225 }
226
LogAPIUsageMetadata(const std::string & context,const std::map<std::string,std::string> & metadata_map)227 void LogAPIUsageMetadata(
228 const std::string& context,
229 const std::map<std::string, std::string>& metadata_map) try {
230 if (auto logger = GetAPIUsageMetadataLogger())
231 (*logger)(context, metadata_map);
232 } catch (std::bad_function_call&) {
233 // static destructor race
234 }
235
LogPyTorchDDPUsage(const DDPLoggingData & ddpData)236 void LogPyTorchDDPUsage(const DDPLoggingData& ddpData) try {
237 if (auto logger = GetDDPUsageLogger())
238 (*logger)(ddpData);
239 } catch (std::bad_function_call&) {
240 // static destructor race
241 }
242
243 namespace detail {
LogAPIUsageFakeReturn(const std::string & event)244 bool LogAPIUsageFakeReturn(const std::string& event) try {
245 if (auto logger = GetAPIUsageLogger())
246 (*logger)(event);
247 return true;
248 } catch (std::bad_function_call&) {
249 // static destructor race
250 return true;
251 }
252
253 namespace {
254
255 void setLogLevelFlagFromEnv();
256
257 } // namespace
258 } // namespace detail
259 } // namespace c10
260
261 #if defined(C10_USE_GFLAGS) && defined(C10_USE_GLOG)
262 // When GLOG depends on GFLAGS, these variables are being defined in GLOG
263 // directly via the GFLAGS definition, so we will use DECLARE_* to declare
264 // them, and use them in Caffe2.
265 // GLOG's minloglevel
266 DECLARE_int32(minloglevel);
267 // GLOG's verbose log value.
268 DECLARE_int32(v);
269 // GLOG's logtostderr value
270 DECLARE_bool(logtostderr);
271 #endif // defined(C10_USE_GFLAGS) && defined(C10_USE_GLOG)
272
273 #if !defined(C10_USE_GLOG)
274 // This backward compatibility flags are in order to deal with cases where
275 // Caffe2 are not built with glog, but some init flags still pass in these
276 // flags. They may go away in the future.
277 C10_DEFINE_int32(minloglevel, 0, "Equivalent to glog minloglevel");
278 C10_DEFINE_int32(v, 0, "Equivalent to glog verbose");
279 C10_DEFINE_bool(logtostderr, false, "Equivalent to glog logtostderr");
280 #endif // !defined(c10_USE_GLOG)
281
282 #ifdef C10_USE_GLOG
283
284 // Provide easy access to the above variables, regardless whether GLOG is
285 // dependent on GFLAGS or not. Note that the namespace (fLI, fLB) is actually
286 // consistent between GLOG and GFLAGS, so we can do the below declaration
287 // consistently.
288 namespace c10 {
289 using fLB::FLAGS_logtostderr;
290 using fLI::FLAGS_minloglevel;
291 using fLI::FLAGS_v;
292 } // namespace c10
293
294 C10_DEFINE_int(
295 caffe2_log_level,
296 google::GLOG_WARNING,
297 "The minimum log level that caffe2 will output.");
298
299 // Google glog's api does not have an external function that allows one to check
300 // if glog is initialized or not. It does have an internal function - so we are
301 // declaring it here. This is a hack but has been used by a bunch of others too
302 // (e.g. Torch).
303 namespace google {
304 namespace glog_internal_namespace_ {
305 bool IsGoogleLoggingInitialized();
306 } // namespace glog_internal_namespace_
307 } // namespace google
308
309 namespace c10 {
310 namespace {
311
initGoogleLogging(char const * name)312 void initGoogleLogging(char const* name) {
313 #if !defined(_MSC_VER)
314 // This trick can only be used on UNIX platforms
315 if (!::google::glog_internal_namespace_::IsGoogleLoggingInitialized())
316 #endif
317 {
318 ::google::InitGoogleLogging(name);
319 #if !defined(_MSC_VER)
320 // This is never defined on Windows
321 ::google::InstallFailureSignalHandler();
322 #endif
323 }
324 }
325
326 } // namespace
327
initLogging()328 void initLogging() {
329 detail::setLogLevelFlagFromEnv();
330
331 UpdateLoggingLevelsFromFlags();
332 }
333
InitCaffeLogging(int * argc,char ** argv)334 bool InitCaffeLogging(int* argc, char** argv) {
335 if (*argc == 0) {
336 return true;
337 }
338
339 initGoogleLogging(argv[0]);
340
341 UpdateLoggingLevelsFromFlags();
342
343 return true;
344 }
345
UpdateLoggingLevelsFromFlags()346 void UpdateLoggingLevelsFromFlags() {
347 #ifdef FBCODE_CAFFE2
348 // TODO(T82645998): Fix data race exposed by TSAN.
349 folly::annotate_ignore_thread_sanitizer_guard g(__FILE__, __LINE__);
350 #endif
351 // If caffe2_log_level is set and is lower than the min log level by glog,
352 // we will transfer the caffe2_log_level setting to glog to override that.
353 FLAGS_minloglevel = std::min(FLAGS_caffe2_log_level, FLAGS_minloglevel);
354 // If caffe2_log_level is explicitly set, let's also turn on logtostderr.
355 if (FLAGS_caffe2_log_level < google::GLOG_WARNING) {
356 FLAGS_logtostderr = 1;
357 }
358 // Also, transfer the caffe2_log_level verbose setting to glog.
359 if (FLAGS_caffe2_log_level < 0) {
360 FLAGS_v = std::min(FLAGS_v, -FLAGS_caffe2_log_level);
361 }
362 }
363
ShowLogInfoToStderr()364 void ShowLogInfoToStderr() {
365 FLAGS_logtostderr = 1;
366 FLAGS_minloglevel = std::min(FLAGS_minloglevel, google::GLOG_INFO);
367 }
368 } // namespace c10
369
370 #else // !C10_USE_GLOG
371
372 #ifdef ANDROID
373 #include <android/log.h>
374 #endif // ANDROID
375
376 C10_DEFINE_int(
377 caffe2_log_level,
378 c10::GLOG_WARNING,
379 "The minimum log level that caffe2 will output.");
380
381 namespace c10 {
382
initLogging()383 void initLogging() {
384 detail::setLogLevelFlagFromEnv();
385 }
386
InitCaffeLogging(int * argc,char ** argv)387 bool InitCaffeLogging(int* argc, char** argv) {
388 // When doing InitCaffeLogging, we will assume that caffe's flag parser has
389 // already finished.
390 if (*argc == 0)
391 return true;
392 if (!c10::CommandLineFlagsHasBeenParsed()) {
393 std::cerr << "InitCaffeLogging() has to be called after "
394 "c10::ParseCommandLineFlags. Modify your program to make sure "
395 "of this."
396 << std::endl;
397 return false;
398 }
399 if (FLAGS_caffe2_log_level > GLOG_FATAL) {
400 std::cerr << "The log level of Caffe2 has to be no larger than GLOG_FATAL("
401 << GLOG_FATAL << "). Capping it to GLOG_FATAL." << std::endl;
402 FLAGS_caffe2_log_level = GLOG_FATAL;
403 }
404 return true;
405 }
406
UpdateLoggingLevelsFromFlags()407 void UpdateLoggingLevelsFromFlags() {}
408
ShowLogInfoToStderr()409 void ShowLogInfoToStderr() {
410 FLAGS_caffe2_log_level = GLOG_INFO;
411 }
412
MessageLogger(const char * file,int line,int severity)413 MessageLogger::MessageLogger(const char* file, int line, int severity)
414 : severity_(severity) {
415 if (severity_ < FLAGS_caffe2_log_level) {
416 // Nothing needs to be logged.
417 return;
418 }
419 #ifdef ANDROID
420 tag_ = "native";
421 #else // !ANDROID
422 tag_ = "";
423 #endif // ANDROID
424
425 time_t rawtime = 0;
426 time(&rawtime);
427
428 #ifndef _WIN32
429 struct tm raw_timeinfo = {0};
430 struct tm* timeinfo = &raw_timeinfo;
431 localtime_r(&rawtime, timeinfo);
432 #else
433 // is thread safe on Windows
434 struct tm* timeinfo = localtime(&rawtime);
435 #endif
436
437 #ifndef _WIN32
438 // Get the current nanoseconds since epoch
439 struct timespec ts = {0};
440 clock_gettime(CLOCK_MONOTONIC, &ts);
441 long ns = ts.tv_nsec;
442 #else
443 long ns = 0;
444 #endif
445
446 if (GLOBAL_RANK != -1) {
447 stream_ << "[rank" << GLOBAL_RANK << "]:";
448 }
449 stream_ << "[" << CAFFE2_SEVERITY_PREFIX[std::min(4, GLOG_FATAL - severity_)]
450 << (timeinfo->tm_mon + 1) * 100 + timeinfo->tm_mday
451 << std::setfill('0') << " " << std::setw(2) << timeinfo->tm_hour
452 << ":" << std::setw(2) << timeinfo->tm_min << ":" << std::setw(2)
453 << timeinfo->tm_sec << "." << std::setw(9) << ns << " "
454 << c10::detail::StripBasename(std::string(file)) << ":" << line
455 << "] ";
456 }
457
458 // Output the contents of the stream to the proper channel on destruction.
~MessageLogger()459 MessageLogger::~MessageLogger() {
460 if (severity_ < FLAGS_caffe2_log_level) {
461 // Nothing needs to be logged.
462 return;
463 }
464 stream_ << "\n";
465 #ifdef ANDROID
466 static const int android_log_levels[] = {
467 ANDROID_LOG_FATAL, // LOG_FATAL
468 ANDROID_LOG_ERROR, // LOG_ERROR
469 ANDROID_LOG_WARN, // LOG_WARNING
470 ANDROID_LOG_INFO, // LOG_INFO
471 ANDROID_LOG_DEBUG, // VLOG(1)
472 ANDROID_LOG_VERBOSE, // VLOG(2) .. VLOG(N)
473 };
474 int android_level_index = GLOG_FATAL - std::min(GLOG_FATAL, severity_);
475 int level = android_log_levels[std::min(android_level_index, 5)];
476 // Output the log string the Android log at the appropriate level.
477 __android_log_print(level, tag_, "%s", stream_.str().c_str());
478 // Indicate termination if needed.
479 if (severity_ == GLOG_FATAL) {
480 __android_log_print(ANDROID_LOG_FATAL, tag_, "terminating.\n");
481 }
482 #else // !ANDROID
483 if (severity_ >= FLAGS_caffe2_log_level) {
484 // If not building on Android, log all output to std::cerr.
485 std::cerr << stream_.str();
486 // Simulating the glog default behavior: if the severity is above INFO,
487 // we flush the stream so that the output appears immediately on std::cerr.
488 // This is expected in some of our tests.
489 if (severity_ > GLOG_INFO) {
490 std::cerr << std::flush;
491 }
492 }
493 #endif // ANDROID
494 if (severity_ == GLOG_FATAL) {
495 DealWithFatal();
496 }
497 }
498
499 } // namespace c10
500
501 #endif // !C10_USE_GLOG
502
503 namespace c10::detail {
504 namespace {
505
setLogLevelFlagFromEnv()506 void setLogLevelFlagFromEnv() {
507 const char* level_str = std::getenv("TORCH_CPP_LOG_LEVEL");
508
509 // Not set, fallback to the default level (i.e. WARNING).
510 std::string level{level_str != nullptr ? level_str : ""};
511 if (level.empty()) {
512 return;
513 }
514
515 std::transform(
516 level.begin(), level.end(), level.begin(), [](unsigned char c) {
517 return toupper(c);
518 });
519
520 if (level == "0" || level == "INFO") {
521 FLAGS_caffe2_log_level = 0;
522
523 return;
524 }
525 if (level == "1" || level == "WARNING") {
526 FLAGS_caffe2_log_level = 1;
527
528 return;
529 }
530 if (level == "2" || level == "ERROR") {
531 FLAGS_caffe2_log_level = 2;
532
533 return;
534 }
535 if (level == "3" || level == "FATAL") {
536 FLAGS_caffe2_log_level = 3;
537
538 return;
539 }
540
541 std::cerr
542 << "`TORCH_CPP_LOG_LEVEL` environment variable cannot be parsed. Valid values are "
543 "`INFO`, `WARNING`, `ERROR`, and `FATAL` or their numerical equivalents `0`, `1`, "
544 "`2`, and `3`."
545 << std::endl;
546 }
547
548 } // namespace
549 } // namespace c10::detail
550