kernel/log.cc

   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 #include "libs/sha1/sha1.h"
  22 #include "backends/ilang/ilang_backend.h"
  23
  24 #if !defined(_WIN32) || defined(__MINGW32__)
  25 #  include <sys/time.h>
  26 #endif
  27
  28 #ifdef __linux__
  29 #  include <dlfcn.h>
  30 #endif
  31
  32 #include <stdlib.h>
  33 #include <stdio.h>
  34 #include <string.h>
  35 #include <stdarg.h>
  36 #include <vector>
  37 #include <list>
  38
  39 YOSYS_NAMESPACE_BEGIN
  40
  41 std::vector<FILE*> log_files;
  42 std::vector<std::ostream*> log_streams;
  43 std::map<std::string, std::set<std::string>> log_hdump;
  44 FILE *log_errfile = NULL;
  45 SHA1 *log_hasher = NULL;
  46
  47 bool log_time = false;
  48 bool log_error_stderr = false;
  49 bool log_cmd_error_throw = false;
  50 bool log_quiet_warnings = false;
  51 int log_verbose_level;
  52 string log_last_error;
  53
  54 vector<int> header_count;
  55 pool<RTLIL::IdString> log_id_cache;
  56 vector<shared_str> string_buf;
  57 int string_buf_index = -1;
  58
  59 static struct timeval initial_tv = { 0, 0 };
  60 static bool next_print_log = false;
  61 static int log_newline_count = 0;
  62
  63 #if defined(_WIN32) && !defined(__MINGW32__)
  64 // this will get time information and return it in timeval, simulating gettimeofday()
  65 int gettimeofday(struct timeval *tv, struct timezone *tz)
  66 {
  67         LARGE_INTEGER counter;
  68         LARGE_INTEGER freq;
  69
  70         QueryPerformanceFrequency(&freq);
  71         QueryPerformanceCounter(&counter);
  72
  73         counter.QuadPart *= 1000000;
  74         counter.QuadPart /= freq.QuadPart;
  75
  76         tv->tv_sec = long(counter.QuadPart / 1000000);
  77         tv->tv_usec = counter.QuadPart % 1000000;
  78
  79         return 0;
  80 }
  81 #endif
  82
  83 void logv(const char *format, va_list ap)
  84 {
  85         while (format[0] == '\n' && format[1] != 0) {
  86                 log("\n");
  87                 format++;
  88         }
  89
  90         std::string str = vstringf(format, ap);
  91
  92         if (str.empty())
  93                 return;
  94
  95         size_t nnl_pos = str.find_last_not_of('\n');
  96         if (nnl_pos == std::string::npos)
  97                 log_newline_count += GetSize(str);
  98         else
  99                 log_newline_count = GetSize(str) - nnl_pos - 1;
 100
 101         if (log_hasher)
 102                 log_hasher->update(str);
 103
 104         if (log_time)
 105         {
 106                 std::string time_str;
 107
 108                 if (next_print_log || initial_tv.tv_sec == 0) {
 109                         next_print_log = false;
 110                         struct timeval tv;
 111                         gettimeofday(&tv, NULL);
 112                         if (initial_tv.tv_sec == 0)
 113                                 initial_tv = tv;
 114                         if (tv.tv_usec < initial_tv.tv_usec) {
 115                                 tv.tv_sec--;
 116                                 tv.tv_usec += 1000000;
 117                         }
 118                         tv.tv_sec -= initial_tv.tv_sec;
 119                         tv.tv_usec -= initial_tv.tv_usec;
 120                         time_str += stringf("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec));
 121                 }
 122
 123                 if (format[0] && format[strlen(format)-1] == '\n')
 124                         next_print_log = true;
 125
 126                 for (auto f : log_files)
 127                         fputs(time_str.c_str(), f);
 128
 129                 for (auto f : log_streams)
 130                         *f << time_str;
 131         }
 132
 133         for (auto f : log_files)
 134                 fputs(str.c_str(), f);
 135
 136         for (auto f : log_streams)
 137                 *f << str;
 138 }
 139
 140 void logv_header(RTLIL::Design *design, const char *format, va_list ap)
 141 {
 142         bool pop_errfile = false;
 143
 144         log_spacer();
 145         if (header_count.size() > 0)
 146                 header_count.back()++;
 147
 148         if (int(header_count.size()) <= log_verbose_level && log_errfile != NULL) {
 149                 log_files.push_back(log_errfile);
 150                 pop_errfile = true;
 151         }
 152
 153         std::string header_id;
 154
 155         for (int c : header_count)
 156                 header_id += stringf("%s%d", header_id.empty() ? "" : ".", c);
 157
 158         log("%s. ", header_id.c_str());
 159         logv(format, ap);
 160         log_flush();
 161
 162         if (log_hdump.count(header_id) && design != nullptr)
 163                 for (auto &filename : log_hdump.at(header_id)) {
 164                         log("Dumping current design to '%s'.\n", filename.c_str());
 165                         Pass::call(design, {"dump", "-o", filename});
 166                 }
 167
 168         if (pop_errfile)
 169                 log_files.pop_back();
 170 }
 171
 172 void logv_warning(const char *format, va_list ap)
 173 {
 174         if (log_errfile != NULL && !log_quiet_warnings)
 175                 log_files.push_back(log_errfile);
 176
 177         log("Warning: ");
 178         logv(format, ap);
 179         log_flush();
 180
 181         if (log_errfile != NULL && !log_quiet_warnings)
 182                 log_files.pop_back();
 183 }
 184
 185 void logv_error(const char *format, va_list ap)
 186 {
 187 #ifdef EMSCRIPTEN
 188         auto backup_log_files = log_files;
 189 #endif
 190
 191         if (log_errfile != NULL)
 192                 log_files.push_back(log_errfile);
 193
 194         if (log_error_stderr)
 195                 for (auto &f : log_files)
 196                         if (f == stdout)
 197                                 f = stderr;
 198
 199         log_last_error = vstringf(format, ap);
 200         log("ERROR: %s", log_last_error.c_str());
 201         log_flush();
 202
 203 #ifdef EMSCRIPTEN
 204         log_files = backup_log_files;
 205         throw 0;
 206 #else
 207         exit(1);
 208 #endif
 209 }
 210
 211 void log(const char *format, ...)
 212 {
 213         va_list ap;
 214         va_start(ap, format);
 215         logv(format, ap);
 216         va_end(ap);
 217 }
 218
 219 void log_header(RTLIL::Design *design, const char *format, ...)
 220 {
 221         va_list ap;
 222         va_start(ap, format);
 223         logv_header(design, format, ap);
 224         va_end(ap);
 225 }
 226
 227 void log_warning(const char *format, ...)
 228 {
 229         va_list ap;
 230         va_start(ap, format);
 231         logv_warning(format, ap);
 232         va_end(ap);
 233 }
 234
 235 void log_error(const char *format, ...)
 236 {
 237         va_list ap;
 238         va_start(ap, format);
 239         logv_error(format, ap);
 240 }
 241
 242 void log_cmd_error(const char *format, ...)
 243 {
 244         va_list ap;
 245         va_start(ap, format);
 246
 247         if (log_cmd_error_throw) {
 248                 log_last_error = vstringf(format, ap);
 249                 log("ERROR: %s", log_last_error.c_str());
 250                 log_flush();
 251                 throw log_cmd_error_exception();
 252         }
 253
 254         logv_error(format, ap);
 255 }
 256
 257 void log_spacer()
 258 {
 259         while (log_newline_count < 2)
 260                 log("\n");
 261 }
 262
 263 void log_push()
 264 {
 265         header_count.push_back(0);
 266 }
 267
 268 void log_pop()
 269 {
 270         header_count.pop_back();
 271         log_id_cache.clear();
 272         string_buf.clear();
 273         string_buf_index = -1;
 274         log_flush();
 275 }
 276
 277 #if defined(__linux__) && defined(YOSYS_ENABLE_PLUGINS)
 278 void log_backtrace(const char *prefix, int levels)
 279 {
 280         if (levels <= 0) return;
 281
 282         Dl_info dli;
 283         void *p;
 284
 285         if ((p = __builtin_extract_return_addr(__builtin_return_address(0))) && dladdr(p, &dli)) {
 286                 log("%sframe #1: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 287         } else {
 288                 log("%sframe #1: ---\n", prefix);
 289                 return;
 290         }
 291
 292         if (levels <= 1) return;
 293
 294         if ((p = __builtin_extract_return_addr(__builtin_return_address(1))) && dladdr(p, &dli)) {
 295                 log("%sframe #2: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 296         } else {
 297                 log("%sframe #2: ---\n", prefix);
 298                 return;
 299         }
 300
 301         if (levels <= 2) return;
 302
 303         if ((p = __builtin_extract_return_addr(__builtin_return_address(2))) && dladdr(p, &dli)) {
 304                 log("%sframe #3: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 305         } else {
 306                 log("%sframe #3: ---\n", prefix);
 307                 return;
 308         }
 309
 310         if (levels <= 3) return;
 311
 312         if ((p = __builtin_extract_return_addr(__builtin_return_address(3))) && dladdr(p, &dli)) {
 313                 log("%sframe #4: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 314         } else {
 315                 log("%sframe #4: ---\n", prefix);
 316                 return;
 317         }
 318
 319         if (levels <= 4) return;
 320
 321         if ((p = __builtin_extract_return_addr(__builtin_return_address(4))) && dladdr(p, &dli)) {
 322                 log("%sframe #5: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 323         } else {
 324                 log("%sframe #5: ---\n", prefix);
 325                 return;
 326         }
 327
 328         if (levels <= 5) return;
 329
 330         if ((p = __builtin_extract_return_addr(__builtin_return_address(5))) && dladdr(p, &dli)) {
 331                 log("%sframe #6: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 332         } else {
 333                 log("%sframe #6: ---\n", prefix);
 334                 return;
 335         }
 336
 337         if (levels <= 6) return;
 338
 339         if ((p = __builtin_extract_return_addr(__builtin_return_address(6))) && dladdr(p, &dli)) {
 340                 log("%sframe #7: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 341         } else {
 342                 log("%sframe #7: ---\n", prefix);
 343                 return;
 344         }
 345
 346         if (levels <= 7) return;
 347
 348         if ((p = __builtin_extract_return_addr(__builtin_return_address(7))) && dladdr(p, &dli)) {
 349                 log("%sframe #8: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 350         } else {
 351                 log("%sframe #8: ---\n", prefix);
 352                 return;
 353         }
 354
 355         if (levels <= 8) return;
 356
 357         if ((p = __builtin_extract_return_addr(__builtin_return_address(8))) && dladdr(p, &dli)) {
 358                 log("%sframe #9: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 359         } else {
 360                 log("%sframe #9: ---\n", prefix);
 361                 return;
 362         }
 363
 364         if (levels <= 9) return;
 365 }
 366 #else
 367 void log_backtrace(const char*, int) { }
 368 #endif
 369
 370 void log_reset_stack()
 371 {
 372         while (header_count.size() > 1)
 373                 header_count.pop_back();
 374         log_id_cache.clear();
 375         string_buf.clear();
 376         string_buf_index = -1;
 377         log_flush();
 378 }
 379
 380 void log_flush()
 381 {
 382         for (auto f : log_files)
 383                 fflush(f);
 384
 385         for (auto f : log_streams)
 386                 f->flush();
 387 }
 388
 389 void log_dump_val_worker(RTLIL::IdString v) {
 390         log("%s", log_id(v));
 391 }
 392
 393 void log_dump_val_worker(RTLIL::SigSpec v) {
 394         log("%s", log_signal(v));
 395 }
 396
 397 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint)
 398 {
 399         std::stringstream buf;
 400         ILANG_BACKEND::dump_sigspec(buf, sig, autoint);
 401
 402         if (string_buf.size() < 100) {
 403                 string_buf.push_back(buf.str());
 404                 return string_buf.back().c_str();
 405         } else {
 406                 if (++string_buf_index == 100)
 407                         string_buf_index = 0;
 408                 string_buf[string_buf_index] = buf.str();
 409                 return string_buf[string_buf_index].c_str();
 410         }
 411 }
 412
 413 const char *log_id(RTLIL::IdString str)
 414 {
 415         log_id_cache.insert(str);
 416         const char *p = str.c_str();
 417         if (p[0] != '\\')
 418                 return p;
 419         if (p[1] == '$' || p[1] == '\\' || p[1] == 0)
 420                 return p;
 421         if (p[1] >= '0' && p[1] <= '9')
 422                 return p;
 423         return p+1;
 424 }
 425
 426 void log_cell(RTLIL::Cell *cell, std::string indent)
 427 {
 428         std::stringstream buf;
 429         ILANG_BACKEND::dump_cell(buf, indent, cell);
 430         log("%s", buf.str().c_str());
 431 }
 432
 433 // ---------------------------------------------------
 434 // This is the magic behind the code coverage counters
 435 // ---------------------------------------------------
 436 #if defined(YOSYS_ENABLE_COVER) && defined(__linux__)
 437
 438 dict<std::string, std::pair<std::string, int>> extra_coverage_data;
 439
 440 void cover_extra(std::string parent, std::string id, bool increment) {
 441         if (extra_coverage_data.count(id) == 0) {
 442                 for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++)
 443                         if (p->id == parent)
 444                                 extra_coverage_data[id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 445                 log_assert(extra_coverage_data.count(id));
 446         }
 447         if (increment)
 448                 extra_coverage_data[id].second++;
 449 }
 450
 451 dict<std::string, std::pair<std::string, int>> get_coverage_data()
 452 {
 453         dict<std::string, std::pair<std::string, int>> coverage_data;
 454
 455         for (auto &it : pass_register) {
 456                 std::string key = stringf("passes.%s", it.first.c_str());
 457                 coverage_data[key].first = stringf("%s:%d:%s", __FILE__, __LINE__, __FUNCTION__);
 458                 coverage_data[key].second += it.second->call_counter;
 459         }
 460
 461         for (auto &it : extra_coverage_data) {
 462                 if (coverage_data.count(it.first))
 463                         log_warning("found duplicate coverage id \"%s\".\n", it.first.c_str());
 464                 coverage_data[it.first].first = it.second.first;
 465                 coverage_data[it.first].second += it.second.second;
 466         }
 467
 468         for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++) {
 469                 if (coverage_data.count(p->id))
 470                         log_warning("found duplicate coverage id \"%s\".\n", p->id);
 471                 coverage_data[p->id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 472                 coverage_data[p->id].second += p->counter;
 473         }
 474
 475         for (auto &it : coverage_data)
 476                 if (!it.second.first.compare(0, strlen(YOSYS_SRC "/"), YOSYS_SRC "/"))
 477                         it.second.first = it.second.first.substr(strlen(YOSYS_SRC "/"));
 478
 479         return coverage_data;
 480 }
 481
 482 #endif
 483
 484 YOSYS_NAMESPACE_END
 485