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