kernel/log.h

   1 /*
   2  *  yosys -- Yosys Open SYnthesis Suite
   3  *
   4  *  Copyright (C) 2012  Claire Xenia Wolf <claire@yosyshq.com>
   5  *
   6  *  Permission to use, copy, modify, and/or distribute this software for any
   7  *  purpose with or without fee is hereby granted, provided that the above
   8  *  copyright notice and this permission notice appear in all copies.
   9  *
  10  *  THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
  11  *  WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
  12  *  MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
  13  *  ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
  14  *  WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
  15  *  ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
  16  *  OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  17  *
  18  */
  19
  20 #include "kernel/yosys.h"
  21
  22 #ifndef LOG_H
  23 #define LOG_H
  24
  25 #include <time.h>
  26
  27 // In the libstdc++ headers that are provided by GCC 4.8, std::regex is not
  28 // working correctly. In order to make features using regular expressions
  29 // work, a replacement regex library is used. Just checking for GCC version
  30 // is not enough though, because at least on RHEL7/CentOS7 even when compiling
  31 // with Clang instead of GCC, the GCC 4.8 headers are still used for std::regex.
  32 // We have to check the version of the libstdc++ headers specifically, not the
  33 // compiler version. GCC headers of libstdc++ before version 3.4 define
  34 // __GLIBCPP__, later versions define __GLIBCXX__. GCC 7 and newer additionaly
  35 // define _GLIBCXX_RELEASE with a version number.
  36 // Include limits std C++ header, so we get the version macros defined:
  37 #if defined(__cplusplus)
  38 #  include <limits>
  39 #endif
  40 // Check if libstdc++ is from GCC
  41 #if defined(__GLIBCPP__) || defined(__GLIBCXX__)
  42 // Check if version could be 4.8 or lower (this also matches for some 4.9 and
  43 // 5.0 releases). See:
  44 // https://gcc.gnu.org/onlinedocs/libstdc++/manual/abi.html#abi.versioning
  45 #  if !defined(_GLIBCXX_RELEASE) && (defined(__GLIBCPP__) || __GLIBCXX__ <= 20150623)
  46 #    define YS_HAS_BAD_STD_REGEX
  47 #  endif
  48 #endif
  49 #if defined(YS_HAS_BAD_STD_REGEX)
  50         #include <boost/xpressive/xpressive.hpp>
  51         #define YS_REGEX_TYPE boost::xpressive::sregex
  52         #define YS_REGEX_MATCH_TYPE boost::xpressive::smatch
  53         #define YS_REGEX_NS boost::xpressive
  54         #define YS_REGEX_COMPILE(param) boost::xpressive::sregex::compile(param, \
  55                                         boost::xpressive::regex_constants::nosubs | \
  56                                         boost::xpressive::regex_constants::optimize)
  57         #define YS_REGEX_COMPILE_WITH_SUBS(param) boost::xpressive::sregex::compile(param, \
  58                                         boost::xpressive::regex_constants::optimize)
  59 # else
  60         #include <regex>
  61         #define YS_REGEX_TYPE std::regex
  62         #define YS_REGEX_MATCH_TYPE std::smatch
  63         #define YS_REGEX_NS std
  64         #define YS_REGEX_COMPILE(param) std::regex(param, \
  65                                         std::regex_constants::nosubs | \
  66                                         std::regex_constants::optimize | \
  67                                         std::regex_constants::egrep)
  68         #define YS_REGEX_COMPILE_WITH_SUBS(param) std::regex(param, \
  69                                         std::regex_constants::optimize | \
  70                                         std::regex_constants::egrep)
  71 #endif
  72
  73 #if defined(_WIN32)
  74 #  include <intrin.h>
  75 #else
  76 #  include <sys/time.h>
  77 #  include <sys/resource.h>
  78 #  if defined(__unix__) || (defined(__APPLE__) && defined(__MACH__))
  79 #    include <signal.h>
  80 #  endif
  81 #endif
  82
  83 #if defined(_MSC_VER)
  84 // At least this is not in MSVC++ 2013.
  85 #  define __PRETTY_FUNCTION__ __FUNCTION__
  86 #endif
  87
  88 // from libs/sha1/sha1.h
  89 class SHA1;
  90
  91 YOSYS_NAMESPACE_BEGIN
  92
  93 #define S__LINE__sub2(x) #x
  94 #define S__LINE__sub1(x) S__LINE__sub2(x)
  95 #define S__LINE__ S__LINE__sub1(__LINE__)
  96
  97 // YS_DEBUGTRAP is a macro that is functionally equivalent to a breakpoint
  98 // if the platform provides such functionality, and does nothing otherwise.
  99 // If no debugger is attached, it starts a just-in-time debugger if available,
 100 // and crashes the process otherwise.
 101 #if defined(_WIN32)
 102 # define YS_DEBUGTRAP __debugbreak()
 103 #else
 104 # ifndef __has_builtin
 105 // __has_builtin is a GCC/Clang extension; on a different compiler (or old enough GCC/Clang)
 106 // that does not have it, using __has_builtin(...) is a syntax error.
 107 #  define __has_builtin(x) 0
 108 # endif
 109 # if __has_builtin(__builtin_debugtrap)
 110 #  define YS_DEBUGTRAP __builtin_debugtrap()
 111 # elif defined(__unix__) || (defined(__APPLE__) && defined(__MACH__))
 112 #  define YS_DEBUGTRAP raise(SIGTRAP)
 113 # else
 114 #  define YS_DEBUGTRAP do {} while(0)
 115 # endif
 116 #endif
 117
 118 // YS_DEBUGTRAP_IF_DEBUGGING is a macro that is functionally equivalent to a breakpoint
 119 // if a debugger is attached, and does nothing otherwise.
 120 #if defined(_WIN32)
 121 # define YS_DEBUGTRAP_IF_DEBUGGING do { if (IsDebuggerPresent()) DebugBreak(); } while(0)
 122 # elif defined(__unix__) || (defined(__APPLE__) && defined(__MACH__))
 123 // There is no reliable (or portable) *nix equivalent of IsDebuggerPresent(). However,
 124 // debuggers will stop when SIGTRAP is raised, even if the action is set to ignore.
 125 # define YS_DEBUGTRAP_IF_DEBUGGING do { \
 126                 auto old = signal(SIGTRAP, SIG_IGN); raise(SIGTRAP); signal(SIGTRAP, old); \
 127         } while(0)
 128 #else
 129 # define YS_DEBUGTRAP_IF_DEBUGGING do {} while(0)
 130 #endif
 131
 132 struct log_cmd_error_exception { };
 133
 134 extern std::vector<FILE*> log_files;
 135 extern std::vector<std::ostream*> log_streams;
 136 extern std::map<std::string, std::set<std::string>> log_hdump;
 137 extern std::vector<YS_REGEX_TYPE> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
 138 extern std::set<std::string> log_warnings, log_experimentals, log_experimentals_ignored;
 139 extern int log_warnings_count;
 140 extern int log_warnings_count_noexpect;
 141 extern bool log_expect_no_warnings;
 142 extern bool log_hdump_all;
 143 extern FILE *log_errfile;
 144 extern SHA1 *log_hasher;
 145
 146 extern bool log_time;
 147 extern bool log_error_stderr;
 148 extern bool log_cmd_error_throw;
 149 extern bool log_quiet_warnings;
 150 extern int log_verbose_level;
 151 extern string log_last_error;
 152 extern void (*log_error_atexit)();
 153
 154 extern int log_make_debug;
 155 extern int log_force_debug;
 156 extern int log_debug_suppressed;
 157
 158 void logv(const char *format, va_list ap);
 159 void logv_header(RTLIL::Design *design, const char *format, va_list ap);
 160 void logv_warning(const char *format, va_list ap);
 161 void logv_warning_noprefix(const char *format, va_list ap);
 162 [[noreturn]] void logv_error(const char *format, va_list ap);
 163
 164 void log(const char *format, ...)  YS_ATTRIBUTE(format(printf, 1, 2));
 165 void log_header(RTLIL::Design *design, const char *format, ...) YS_ATTRIBUTE(format(printf, 2, 3));
 166 void log_warning(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2));
 167 void log_experimental(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2));
 168
 169 // Log with filename to report a problem in a source file.
 170 void log_file_warning(const std::string &filename, int lineno, const char *format, ...) YS_ATTRIBUTE(format(printf, 3, 4));
 171 void log_file_info(const std::string &filename, int lineno, const char *format, ...) YS_ATTRIBUTE(format(printf, 3, 4));
 172
 173 void log_warning_noprefix(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2));
 174 [[noreturn]] void log_error(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2));
 175 [[noreturn]] void log_file_error(const string &filename, int lineno, const char *format, ...) YS_ATTRIBUTE(format(printf, 3, 4));
 176 [[noreturn]] void log_cmd_error(const char *format, ...) YS_ATTRIBUTE(format(printf, 1, 2));
 177
 178 #ifndef NDEBUG
 179 static inline bool ys_debug(int n = 0) { if (log_force_debug) return true; log_debug_suppressed += n; return false; }
 180 #else
 181 static inline bool ys_debug(int = 0) { return false; }
 182 #endif
 183 #  define log_debug(...) do { if (ys_debug(1)) log(__VA_ARGS__); } while (0)
 184
 185 static inline void log_suppressed() {
 186         if (log_debug_suppressed && !log_make_debug) {
 187                 log("<suppressed ~%d debug messages>\n", log_debug_suppressed);
 188                 log_debug_suppressed = 0;
 189         }
 190 }
 191
 192 struct LogMakeDebugHdl {
 193         bool status = false;
 194         LogMakeDebugHdl(bool start_on = false) {
 195                 if (start_on)
 196                         on();
 197         }
 198         ~LogMakeDebugHdl() {
 199                 off();
 200         }
 201         void on() {
 202                 if (status) return;
 203                 status=true;
 204                 log_make_debug++;
 205         }
 206         void off_silent() {
 207                 if (!status) return;
 208                 status=false;
 209                 log_make_debug--;
 210         }
 211         void off() {
 212                 off_silent();
 213         }
 214 };
 215
 216 void log_spacer();
 217 void log_push();
 218 void log_pop();
 219
 220 void log_backtrace(const char *prefix, int levels);
 221 void log_reset_stack();
 222 void log_flush();
 223
 224 struct LogExpectedItem
 225 {
 226         LogExpectedItem(const YS_REGEX_TYPE &pat, int expected) :
 227                         pattern(pat), expected_count(expected), current_count(0) {}
 228         LogExpectedItem() : expected_count(0), current_count(0) {}
 229
 230         YS_REGEX_TYPE pattern;
 231         int expected_count;
 232         int current_count;
 233 };
 234
 235 extern dict<std::string, LogExpectedItem> log_expect_log, log_expect_warning, log_expect_error;
 236 void log_check_expected();
 237
 238 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint = true);
 239 const char *log_const(const RTLIL::Const &value, bool autoint = true);
 240 const char *log_id(RTLIL::IdString id);
 241
 242 template<typename T> static inline const char *log_id(T *obj, const char *nullstr = nullptr) {
 243         if (nullstr && obj == nullptr)
 244                 return nullstr;
 245         return log_id(obj->name);
 246 }
 247
 248 void log_module(RTLIL::Module *module, std::string indent = "");
 249 void log_cell(RTLIL::Cell *cell, std::string indent = "");
 250 void log_wire(RTLIL::Wire *wire, std::string indent = "");
 251
 252 #ifndef NDEBUG
 253 static inline void log_assert_worker(bool cond, const char *expr, const char *file, int line) {
 254         if (!cond) log_error("Assert `%s' failed in %s:%d.\n", expr, file, line);
 255 }
 256 #  define log_assert(_assert_expr_) YOSYS_NAMESPACE_PREFIX log_assert_worker(_assert_expr_, #_assert_expr_, __FILE__, __LINE__)
 257 #else
 258 #  define log_assert(_assert_expr_) do { if (0) { (void)(_assert_expr_); } } while(0)
 259 #endif
 260
 261 #define log_abort() YOSYS_NAMESPACE_PREFIX log_error("Abort in %s:%d.\n", __FILE__, __LINE__)
 262 #define log_ping() YOSYS_NAMESPACE_PREFIX log("-- %s:%d %s --\n", __FILE__, __LINE__, __PRETTY_FUNCTION__)
 263
 264
 265 // ---------------------------------------------------
 266 // This is the magic behind the code coverage counters
 267 // ---------------------------------------------------
 268
 269 #if defined(YOSYS_ENABLE_COVER) && (defined(__linux__) || defined(__FreeBSD__))
 270
 271 #define cover(_id) do { \
 272     static CoverData __d __attribute__((section("yosys_cover_list"), aligned(1), used)) = { __FILE__, __FUNCTION__, _id, __LINE__, 0 }; \
 273     __d.counter++; \
 274 } while (0)
 275
 276 struct CoverData {
 277         const char *file, *func, *id;
 278         int line, counter;
 279 } YS_ATTRIBUTE(packed);
 280
 281 // this two symbols are created by the linker for the "yosys_cover_list" ELF section
 282 extern "C" struct CoverData __start_yosys_cover_list[];
 283 extern "C" struct CoverData __stop_yosys_cover_list[];
 284
 285 extern dict<std::string, std::pair<std::string, int>> extra_coverage_data;
 286
 287 void cover_extra(std::string parent, std::string id, bool increment = true);
 288 dict<std::string, std::pair<std::string, int>> get_coverage_data();
 289
 290 #define cover_list(_id, ...) do { cover(_id); \
 291         std::string r = cover_list_worker(_id, __VA_ARGS__); \
 292         log_assert(r.empty()); \
 293 } while (0)
 294
 295 static inline std::string cover_list_worker(std::string, std::string last) {
 296         return last;
 297 }
 298
 299 template<typename... T>
 300 std::string cover_list_worker(std::string prefix, std::string first, T... rest) {
 301         std::string selected = cover_list_worker(prefix, rest...);
 302         cover_extra(prefix, prefix + "." + first, first == selected);
 303         return first == selected ? "" : selected;
 304 }
 305
 306 #else
 307 #  define cover(...) do { } while (0)
 308 #  define cover_list(...) do { } while (0)
 309 #endif
 310
 311
 312 // ------------------------------------------------------------
 313 // everything below this line are utilities for troubleshooting
 314 // ------------------------------------------------------------
 315
 316 // simple timer for performance measurements
 317 // toggle the '#if 1' to get a baseline for the performance penalty added by the measurement
 318 struct PerformanceTimer
 319 {
 320 #if 1
 321         int64_t total_ns;
 322
 323         PerformanceTimer() {
 324                 total_ns = 0;
 325         }
 326
 327         static int64_t query() {
 328 #  ifdef _WIN32
 329                 return 0;
 330 #  elif defined(RUSAGE_SELF)
 331                 struct rusage rusage;
 332                 int64_t t = 0;
 333                 for (int who : {RUSAGE_SELF, RUSAGE_CHILDREN}) {
 334                         if (getrusage(who, &rusage) == -1) {
 335                                 log_cmd_error("getrusage failed!\n");
 336                                 log_abort();
 337                         }
 338                         t += 1000000000ULL * (int64_t) rusage.ru_utime.tv_sec + (int64_t) rusage.ru_utime.tv_usec * 1000ULL;
 339                         t += 1000000000ULL * (int64_t) rusage.ru_stime.tv_sec + (int64_t) rusage.ru_stime.tv_usec * 1000ULL;
 340                 }
 341                 return t;
 342 #  else
 343 #    error "Don't know how to measure per-process CPU time. Need alternative method (times()/clocks()/gettimeofday()?)."
 344 #  endif
 345         }
 346
 347         void reset() {
 348                 total_ns = 0;
 349         }
 350
 351         void begin() {
 352                 total_ns -= query();
 353         }
 354
 355         void end() {
 356                 total_ns += query();
 357         }
 358
 359         float sec() const {
 360                 return total_ns * 1e-9f;
 361         }
 362 #else
 363         static int64_t query() { return 0; }
 364         void reset() { }
 365         void begin() { }
 366         void end() { }
 367         float sec() const { return 0; }
 368 #endif
 369 };
 370
 371 // simple API for quickly dumping values when debugging
 372
 373 static inline void log_dump_val_worker(short v) { log("%d", v); }
 374 static inline void log_dump_val_worker(unsigned short v) { log("%u", v); }
 375 static inline void log_dump_val_worker(int v) { log("%d", v); }
 376 static inline void log_dump_val_worker(unsigned int v) { log("%u", v); }
 377 static inline void log_dump_val_worker(long int v) { log("%ld", v); }
 378 static inline void log_dump_val_worker(unsigned long int v) { log("%lu", v); }
 379 #ifndef _WIN32
 380 static inline void log_dump_val_worker(long long int v) { log("%lld", v); }
 381 static inline void log_dump_val_worker(unsigned long long int v) { log("%lld", v); }
 382 #endif
 383 static inline void log_dump_val_worker(char c) { log(c >= 32 && c < 127 ? "'%c'" : "'\\x%02x'", c); }
 384 static inline void log_dump_val_worker(unsigned char c) { log(c >= 32 && c < 127 ? "'%c'" : "'\\x%02x'", c); }
 385 static inline void log_dump_val_worker(bool v) { log("%s", v ? "true" : "false"); }
 386 static inline void log_dump_val_worker(double v) { log("%f", v); }
 387 static inline void log_dump_val_worker(char *v) { log("%s", v); }
 388 static inline void log_dump_val_worker(const char *v) { log("%s", v); }
 389 static inline void log_dump_val_worker(std::string v) { log("%s", v.c_str()); }
 390 static inline void log_dump_val_worker(PerformanceTimer p) { log("%f seconds", p.sec()); }
 391 static inline void log_dump_args_worker(const char *p) { log_assert(*p == 0); }
 392 void log_dump_val_worker(RTLIL::IdString v);
 393 void log_dump_val_worker(RTLIL::SigSpec v);
 394 void log_dump_val_worker(RTLIL::State v);
 395
 396 template<typename K, typename T, typename OPS>
 397 static inline void log_dump_val_worker(dict<K, T, OPS> &v) {
 398         log("{");
 399         bool first = true;
 400         for (auto &it : v) {
 401                 log(first ? " " : ", ");
 402                 log_dump_val_worker(it.first);
 403                 log(": ");
 404                 log_dump_val_worker(it.second);
 405                 first = false;
 406         }
 407         log(" }");
 408 }
 409
 410 template<typename K, typename OPS>
 411 static inline void log_dump_val_worker(pool<K, OPS> &v) {
 412         log("{");
 413         bool first = true;
 414         for (auto &it : v) {
 415                 log(first ? " " : ", ");
 416                 log_dump_val_worker(it);
 417                 first = false;
 418         }
 419         log(" }");
 420 }
 421
 422 template<typename T>
 423 static inline void log_dump_val_worker(T *ptr) { log("%p", ptr); }
 424
 425 template<typename T, typename ... Args>
 426 void log_dump_args_worker(const char *p, T first, Args ... args)
 427 {
 428         int next_p_state = 0;
 429         const char *next_p = p;
 430         while (*next_p && (next_p_state != 0 || *next_p != ',')) {
 431                 if (*next_p == '"')
 432                         do {
 433                                 next_p++;
 434                                 while (*next_p == '\\' && *(next_p + 1))
 435                                         next_p += 2;
 436                         } while (*next_p && *next_p != '"');
 437                 if (*next_p == '\'') {
 438                         next_p++;
 439                         if (*next_p == '\\')
 440                                 next_p++;
 441                         if (*next_p)
 442                                 next_p++;
 443                 }
 444                 if (*next_p == '(' || *next_p == '[' || *next_p == '{')
 445                         next_p_state++;
 446                 if ((*next_p == ')' || *next_p == ']' || *next_p == '}') && next_p_state > 0)
 447                         next_p_state--;
 448                 next_p++;
 449         }
 450         log("\n\t%.*s => ", int(next_p - p), p);
 451         if (*next_p == ',')
 452                 next_p++;
 453         while (*next_p == ' ' || *next_p == '\t' || *next_p == '\r' || *next_p == '\n')
 454                 next_p++;
 455         log_dump_val_worker(first);
 456         log_dump_args_worker(next_p, args ...);
 457 }
 458
 459 #define log_dump(...) do { \
 460         log("DEBUG DUMP IN %s AT %s:%d:", __PRETTY_FUNCTION__, __FILE__, __LINE__); \
 461         log_dump_args_worker(#__VA_ARGS__, __VA_ARGS__); \
 462         log("\n"); \
 463 } while (0)
 464
 465 YOSYS_NAMESPACE_END
 466
 467 #endif