kernel/log.h

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