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 #ifndef LOG_H
  21 #define LOG_H
  22
  23 #include "kernel/rtlil.h"
  24 #include "kernel/register.h"
  25
  26 #include <stdio.h>
  27 #include <string.h>
  28 #include <time.h>
  29 #include <sys/time.h>
  30 #include <sys/resource.h>
  31 #include <vector>
  32
  33 #define S__LINE__sub2(x) #x
  34 #define S__LINE__sub1(x) S__LINE__sub2(x)
  35 #define S__LINE__ S__LINE__sub1(__LINE__)
  36
  37 extern std::vector<FILE*> log_files;
  38 extern FILE *log_errfile;
  39 extern bool log_time;
  40 extern bool log_cmd_error_throw;
  41 extern int log_verbose_level;
  42
  43 std::string stringf(const char *fmt, ...);
  44
  45 void logv(const char *format, va_list ap);
  46 void logv_header(const char *format, va_list ap);
  47 void logv_error(const char *format, va_list ap) __attribute__ ((noreturn));
  48
  49 void log(const char *format, ...)  __attribute__ ((format (printf, 1, 2)));
  50 void log_header(const char *format, ...) __attribute__ ((format (printf, 1, 2)));
  51 void log_error(const char *format, ...) __attribute__ ((format (printf, 1, 2))) __attribute__ ((noreturn));
  52 void log_cmd_error(const char *format, ...) __attribute__ ((format (printf, 1, 2))) __attribute__ ((noreturn));
  53
  54 void log_push();
  55 void log_pop();
  56
  57 void log_reset_stack();
  58 void log_flush();
  59
  60 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint = true);
  61 const char *log_id(std::string id);
  62
  63 template<typename T> static inline const char *log_id(T *obj) {
  64         return log_id(obj->name);
  65 }
  66
  67 void log_cell(RTLIL::Cell *cell, std::string indent = "");
  68
  69 #define log_abort() log_error("Abort in %s:%d.\n", __FILE__, __LINE__)
  70 #define log_assert(_assert_expr_) do { if (_assert_expr_) break; log_error("Assert `%s' failed in %s:%d.\n", #_assert_expr_, __FILE__, __LINE__); } while (0)
  71 #define log_ping() log("-- %s:%d %s --\n", __FILE__, __LINE__, __PRETTY_FUNCTION__)
  72
  73
  74 // ---------------------------------------------------
  75 // This is the magic behind the code coverage counters
  76 // ---------------------------------------------------
  77
  78 #if defined(__linux__) && !defined(NDEBUG)
  79 #define COVER_ACTIVE
  80
  81 #define cover(_id) do { \
  82     static CoverData __d __attribute__((section("yosys_cover_list"), aligned(1))) = { __FILE__, __FUNCTION__, _id, __LINE__, 0 }; \
  83     __d.counter++; \
  84 } while (0)
  85
  86 struct CoverData {
  87         const char *file, *func, *id;
  88         int line, counter;
  89 } __attribute__ ((packed));
  90
  91 // this two symbols are created by the linker for the "yosys_cover_list" ELF section
  92 extern "C" struct CoverData __start_yosys_cover_list[];
  93 extern "C" struct CoverData __stop_yosys_cover_list[];
  94
  95 extern std::map<std::string, std::pair<std::string, int>> extra_coverage_data;
  96
  97 static inline void cover_extra(std::string parent, std::string id, bool increment = true) {
  98         if (extra_coverage_data.count(id) == 0) {
  99                 for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++)
 100                         if (p->id == parent)
 101                                 extra_coverage_data[id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 102                 log_assert(extra_coverage_data.count(id));
 103         }
 104         if (increment)
 105                 extra_coverage_data[id].second++;
 106 }
 107
 108 static inline std::map<std::string, std::pair<std::string, int>> get_coverage_data()
 109 {
 110         std::map<std::string, std::pair<std::string, int>> coverage_data;
 111
 112         for (auto &it : REGISTER_INTERN::pass_register) {
 113                 std::string key = stringf("passes.%s", it.first.c_str());
 114                 coverage_data[key].first = stringf("%s:%d:%s", __FILE__, __LINE__, __FUNCTION__);
 115                 coverage_data[key].second += it.second->call_counter;
 116         }
 117
 118         for (auto &it : extra_coverage_data) {
 119                 if (coverage_data.count(it.first))
 120                         log("WARNING: found duplicate coverage id \"%s\".\n", it.first.c_str());
 121                 coverage_data[it.first].first = it.second.first;
 122                 coverage_data[it.first].second += it.second.second;
 123         }
 124
 125         for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++) {
 126                 if (coverage_data.count(p->id))
 127                         log("WARNING: found duplicate coverage id \"%s\".\n", p->id);
 128                 coverage_data[p->id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 129                 coverage_data[p->id].second += p->counter;
 130         }
 131
 132         for (auto &it : coverage_data)
 133                 if (!it.second.first.compare(0, strlen(YOSYS_SRC "/"), YOSYS_SRC "/"))
 134                         it.second.first = it.second.first.substr(strlen(YOSYS_SRC "/"));
 135
 136         return coverage_data;
 137 }
 138
 139 #define cover_list(_id, ...) do { cover(_id); \
 140         std::string r = cover_list_worker(_id, __VA_ARGS__); \
 141         log_assert(r.empty()); \
 142 } while (0)
 143
 144 static inline std::string cover_list_worker(std::string, std::string last) {
 145         return last;
 146 }
 147
 148 template<typename... T>
 149 std::string cover_list_worker(std::string prefix, std::string first, T... rest) {
 150         std::string selected = cover_list_worker(prefix, rest...);
 151         cover_extra(prefix, prefix + "." + first, first == selected);
 152         return first == selected ? "" : selected;
 153 }
 154
 155 #else
 156 #  define cover(...) do { } while (0)
 157 #  define cover_list(...) do { } while (0)
 158 #endif
 159
 160
 161 // ------------------------------------------------------------
 162 // everything below this line are utilities for troubleshooting
 163 // ------------------------------------------------------------
 164
 165 // simple timer for performance measurements
 166 // toggle the '#if 1' to get a baseline for the perormance penalty added by the measurement
 167 struct PerformanceTimer
 168 {
 169 #if 1
 170         int64_t total_ns;
 171
 172         PerformanceTimer() {
 173                 total_ns = 0;
 174         }
 175
 176         static int64_t query() {
 177 #if defined(_POSIX_TIMERS) && (_POSIX_TIMERS > 0)
 178                 struct timespec ts;
 179                 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts);
 180                 return int64_t(ts.tv_sec)*1000000000 + ts.tv_nsec;
 181 #elif defined(RUSAGE_SELF)
 182                 struct rusage rusage;
 183                 int64_t t;
 184                 if (getrusage(RUSAGE_SELF, &rusage) == -1) {
 185                         log_cmd_error("getrusage failed!\n");
 186                         log_abort();
 187                 }
 188                 t = 1000000000ULL * (int64_t) rusage.ru_utime.tv_sec + (int64_t) rusage.ru_utime.tv_usec * 1000ULL;
 189                 t += 1000000000ULL * (int64_t) rusage.ru_stime.tv_sec + (int64_t) rusage.ru_stime.tv_usec * 1000ULL;
 190                 return t;
 191 #else
 192         #error Dont know how to measure per-process CPU time. Need alternative method (times()/clocks()/gettimeofday()?).
 193 #endif
 194         }
 195
 196         void reset() {
 197                 total_ns = 0;
 198         }
 199
 200         void add() {
 201                 total_ns += query();
 202         }
 203
 204         void sub() {
 205                 total_ns -= query();
 206         }
 207
 208         float sec() const {
 209                 return total_ns * 1e-9;
 210         }
 211 #else
 212         void reset() { }
 213         void add() { }
 214         void sub() { }
 215         float sec() const { return 0; }
 216 #endif
 217 };
 218
 219 // simple API for quickly dumping values when debugging
 220
 221 static inline void log_dump_val_worker(short v) { log("%d", v); }
 222 static inline void log_dump_val_worker(unsigned short v) { log("%u", v); }
 223 static inline void log_dump_val_worker(int v) { log("%d", v); }
 224 static inline void log_dump_val_worker(unsigned int v) { log("%u", v); }
 225 static inline void log_dump_val_worker(long int v) { log("%ld", v); }
 226 static inline void log_dump_val_worker(unsigned long int v) { log("%lu", v); }
 227 static inline void log_dump_val_worker(long long int v) { log("%lld", v); }
 228 static inline void log_dump_val_worker(unsigned long long int v) { log("%lld", v); }
 229 static inline void log_dump_val_worker(char c) { log(c >= 32 && c < 127 ? "'%c'" : "'\\x%02x'", c); }
 230 static inline void log_dump_val_worker(unsigned char c) { log(c >= 32 && c < 127 ? "'%c'" : "'\\x%02x'", c); }
 231 static inline void log_dump_val_worker(bool v) { log("%s", v ? "true" : "false"); }
 232 static inline void log_dump_val_worker(double v) { log("%f", v); }
 233 static inline void log_dump_val_worker(const char *v) { log("%s", v); }
 234 static inline void log_dump_val_worker(std::string v) { log("%s", v.c_str()); }
 235 static inline void log_dump_val_worker(RTLIL::SigSpec v) { log("%s", log_signal(v)); }
 236 static inline void log_dump_args_worker(const char *p) { log_assert(*p == 0); }
 237
 238 template<typename T>
 239 static inline void log_dump_val_worker(T *ptr) { log("%p", ptr); }
 240
 241 template<typename T, typename ... Args>
 242 void log_dump_args_worker(const char *p, T first, Args ... args)
 243 {
 244         int next_p_state = 0;
 245         const char *next_p = p;
 246         while (*next_p && (next_p_state != 0 || *next_p != ',')) {
 247                 if (*next_p == '"')
 248                         do {
 249                                 next_p++;
 250                                 while (*next_p == '\\' && *(next_p + 1))
 251                                         next_p += 2;
 252                         } while (*next_p && *next_p != '"');
 253                 if (*next_p == '\'') {
 254                         next_p++;
 255                         if (*next_p == '\\')
 256                                 next_p++;
 257                         if (*next_p)
 258                                 next_p++;
 259                 }
 260                 if (*next_p == '(' || *next_p == '[' || *next_p == '{')
 261                         next_p_state++;
 262                 if ((*next_p == ')' || *next_p == ']' || *next_p == '}') && next_p_state > 0)
 263                         next_p_state--;
 264                 next_p++;
 265         }
 266         log("\n\t%.*s => ", int(next_p - p), p);
 267         if (*next_p == ',')
 268                 next_p++;
 269         while (*next_p == ' ' || *next_p == '\t' || *next_p == '\r' || *next_p == '\n')
 270                 next_p++;
 271         log_dump_val_worker(first);
 272         log_dump_args_worker(next_p, args ...);
 273 }
 274
 275 #define log_dump(...) do { \
 276         log("DEBUG DUMP IN %s AT %s:%d:", __PRETTY_FUNCTION__, __FILE__, __LINE__); \
 277         log_dump_args_worker(#__VA_ARGS__, __VA_ARGS__); \
 278         log("\n"); \
 279 } while (0)
 280
 281 #endif