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 #if defined(__linux__) || defined(__FreeBSD__)
  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 std::vector<std::regex> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
  45 std::set<std::string> log_warnings;
  46 int log_warnings_count = 0;
  47 bool log_hdump_all = false;
  48 FILE *log_errfile = NULL;
  49 SHA1 *log_hasher = NULL;
  50
  51 bool log_time = false;
  52 bool log_error_stderr = false;
  53 bool log_cmd_error_throw = false;
  54 bool log_quiet_warnings = false;
  55 int log_verbose_level;
  56 string log_last_error;
  57 void (*log_error_atexit)() = NULL;
  58
  59 vector<int> header_count;
  60 pool<RTLIL::IdString> log_id_cache;
  61 vector<shared_str> string_buf;
  62 int string_buf_index = -1;
  63
  64 static struct timeval initial_tv = { 0, 0 };
  65 static bool next_print_log = false;
  66 static int log_newline_count = 0;
  67
  68 #if defined(_WIN32) && !defined(__MINGW32__)
  69 // this will get time information and return it in timeval, simulating gettimeofday()
  70 int gettimeofday(struct timeval *tv, struct timezone *tz)
  71 {
  72         LARGE_INTEGER counter;
  73         LARGE_INTEGER freq;
  74
  75         QueryPerformanceFrequency(&freq);
  76         QueryPerformanceCounter(&counter);
  77
  78         counter.QuadPart *= 1000000;
  79         counter.QuadPart /= freq.QuadPart;
  80
  81         tv->tv_sec = long(counter.QuadPart / 1000000);
  82         tv->tv_usec = counter.QuadPart % 1000000;
  83
  84         return 0;
  85 }
  86 #endif
  87
  88 void logv(const char *format, va_list ap)
  89 {
  90         while (format[0] == '\n' && format[1] != 0) {
  91                 log("\n");
  92                 format++;
  93         }
  94
  95         std::string str = vstringf(format, ap);
  96
  97         if (str.empty())
  98                 return;
  99
 100         size_t nnl_pos = str.find_last_not_of('\n');
 101         if (nnl_pos == std::string::npos)
 102                 log_newline_count += GetSize(str);
 103         else
 104                 log_newline_count = GetSize(str) - nnl_pos - 1;
 105
 106         if (log_hasher)
 107                 log_hasher->update(str);
 108
 109         if (log_time)
 110         {
 111                 std::string time_str;
 112
 113                 if (next_print_log || initial_tv.tv_sec == 0) {
 114                         next_print_log = false;
 115                         struct timeval tv;
 116                         gettimeofday(&tv, NULL);
 117                         if (initial_tv.tv_sec == 0)
 118                                 initial_tv = tv;
 119                         if (tv.tv_usec < initial_tv.tv_usec) {
 120                                 tv.tv_sec--;
 121                                 tv.tv_usec += 1000000;
 122                         }
 123                         tv.tv_sec -= initial_tv.tv_sec;
 124                         tv.tv_usec -= initial_tv.tv_usec;
 125                         time_str += stringf("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec));
 126                 }
 127
 128                 if (format[0] && format[strlen(format)-1] == '\n')
 129                         next_print_log = true;
 130
 131                 for (auto f : log_files)
 132                         fputs(time_str.c_str(), f);
 133
 134                 for (auto f : log_streams)
 135                         *f << time_str;
 136         }
 137
 138         for (auto f : log_files)
 139                 fputs(str.c_str(), f);
 140
 141         for (auto f : log_streams)
 142                 *f << str;
 143
 144         static std::string linebuffer;
 145         static bool log_warn_regex_recusion_guard = false;
 146
 147         if (!log_warn_regex_recusion_guard)
 148         {
 149                 log_warn_regex_recusion_guard = true;
 150
 151                 if (log_warn_regexes.empty())
 152                 {
 153                         linebuffer.clear();
 154                 }
 155                 else
 156                 {
 157                         linebuffer += str;
 158
 159                         if (!linebuffer.empty() && linebuffer.back() == '\n') {
 160                                 for (auto &re : log_warn_regexes)
 161                                         if (std::regex_search(linebuffer, re))
 162                                                 log_warning("Found log message matching -W regex:\n%s", str.c_str());
 163                                 linebuffer.clear();
 164                         }
 165                 }
 166
 167                 log_warn_regex_recusion_guard = false;
 168         }
 169 }
 170
 171 void logv_header(RTLIL::Design *design, const char *format, va_list ap)
 172 {
 173         bool pop_errfile = false;
 174
 175         log_spacer();
 176         if (header_count.size() > 0)
 177                 header_count.back()++;
 178
 179         if (int(header_count.size()) <= log_verbose_level && log_errfile != NULL) {
 180                 log_files.push_back(log_errfile);
 181                 pop_errfile = true;
 182         }
 183
 184         std::string header_id;
 185
 186         for (int c : header_count)
 187                 header_id += stringf("%s%d", header_id.empty() ? "" : ".", c);
 188
 189         log("%s. ", header_id.c_str());
 190         logv(format, ap);
 191         log_flush();
 192
 193         if (log_hdump_all)
 194                 log_hdump[header_id].insert("yosys_dump_" + header_id + ".il");
 195
 196         if (log_hdump.count(header_id) && design != nullptr)
 197                 for (auto &filename : log_hdump.at(header_id)) {
 198                         log("Dumping current design to '%s'.\n", filename.c_str());
 199                         Pass::call(design, {"dump", "-o", filename});
 200                 }
 201
 202         if (pop_errfile)
 203                 log_files.pop_back();
 204 }
 205
 206 static void logv_warning_with_prefix(const char *prefix,
 207                                      const char *format, va_list ap)
 208 {
 209         std::string message = vstringf(format, ap);
 210         bool suppressed = false;
 211
 212         for (auto &re : log_nowarn_regexes)
 213                 if (std::regex_search(message, re))
 214                         suppressed = true;
 215
 216         if (suppressed)
 217         {
 218                 log("Suppressed %s%s", prefix, message.c_str());
 219         }
 220         else
 221         {
 222                 for (auto &re : log_werror_regexes)
 223                         if (std::regex_search(message, re))
 224                                 log_error("%s",  message.c_str());
 225
 226                 if (log_warnings.count(message))
 227                 {
 228                         log("%s%s", prefix, message.c_str());
 229                         log_flush();
 230                 }
 231                 else
 232                 {
 233                         if (log_errfile != NULL && !log_quiet_warnings)
 234                                 log_files.push_back(log_errfile);
 235
 236                         log("%s%s", prefix, message.c_str());
 237                         log_flush();
 238
 239                         if (log_errfile != NULL && !log_quiet_warnings)
 240                                 log_files.pop_back();
 241
 242                         log_warnings.insert(message);
 243                 }
 244
 245                 log_warnings_count++;
 246         }
 247 }
 248
 249 void logv_warning(const char *format, va_list ap)
 250 {
 251         logv_warning_with_prefix("Warning: ", format, ap);
 252 }
 253
 254 void logv_warning_noprefix(const char *format, va_list ap)
 255 {
 256         logv_warning_with_prefix("", format, ap);
 257 }
 258
 259 void log_file_warning(const std::string &filename, int lineno,
 260                       const char *format, ...)
 261 {
 262         va_list ap;
 263         va_start(ap, format);
 264         std::string prefix = stringf("%s:%d: Warning: ",
 265                                      filename.c_str(), lineno);
 266         logv_warning_with_prefix(prefix.c_str(), format, ap);
 267         va_end(ap);
 268 }
 269
 270 YS_ATTRIBUTE(noreturn)
 271 static void logv_error_with_prefix(const char *prefix,
 272                                    const char *format, va_list ap)
 273 {
 274 #ifdef EMSCRIPTEN
 275         auto backup_log_files = log_files;
 276 #endif
 277
 278         if (log_errfile != NULL)
 279                 log_files.push_back(log_errfile);
 280
 281         if (log_error_stderr)
 282                 for (auto &f : log_files)
 283                         if (f == stdout)
 284                                 f = stderr;
 285
 286         log_last_error = vstringf(format, ap);
 287         log("%s%s", prefix, log_last_error.c_str());
 288         log_flush();
 289
 290         if (log_error_atexit)
 291                 log_error_atexit();
 292
 293 #ifdef EMSCRIPTEN
 294         log_files = backup_log_files;
 295         throw 0;
 296 #elif defined(_MSC_VER)
 297         _exit(1);
 298 #else
 299         _Exit(1);
 300 #endif
 301 }
 302
 303 void logv_error(const char *format, va_list ap)
 304 {
 305         logv_error_with_prefix("ERROR: ", format, ap);
 306 }
 307
 308 void log_file_error(const string &filename, int lineno,
 309                     const char *format, ...)
 310 {
 311         va_list ap;
 312         va_start(ap, format);
 313         std::string prefix = stringf("%s:%d: ERROR: ",
 314                                      filename.c_str(), lineno);
 315         logv_error_with_prefix(prefix.c_str(), format, ap);
 316 }
 317
 318 void log(const char *format, ...)
 319 {
 320         va_list ap;
 321         va_start(ap, format);
 322         logv(format, ap);
 323         va_end(ap);
 324 }
 325
 326 void log_header(RTLIL::Design *design, const char *format, ...)
 327 {
 328         va_list ap;
 329         va_start(ap, format);
 330         logv_header(design, format, ap);
 331         va_end(ap);
 332 }
 333
 334 void log_warning(const char *format, ...)
 335 {
 336         va_list ap;
 337         va_start(ap, format);
 338         logv_warning(format, ap);
 339         va_end(ap);
 340 }
 341
 342 void log_warning_noprefix(const char *format, ...)
 343 {
 344         va_list ap;
 345         va_start(ap, format);
 346         logv_warning_noprefix(format, ap);
 347         va_end(ap);
 348 }
 349
 350 void log_error(const char *format, ...)
 351 {
 352         va_list ap;
 353         va_start(ap, format);
 354         logv_error(format, ap);
 355 }
 356
 357 void log_cmd_error(const char *format, ...)
 358 {
 359         va_list ap;
 360         va_start(ap, format);
 361
 362         if (log_cmd_error_throw) {
 363                 log_last_error = vstringf(format, ap);
 364                 log("ERROR: %s", log_last_error.c_str());
 365                 log_flush();
 366                 throw log_cmd_error_exception();
 367         }
 368
 369         logv_error(format, ap);
 370 }
 371
 372 void log_spacer()
 373 {
 374         if (log_newline_count < 2) log("\n");
 375         if (log_newline_count < 2) log("\n");
 376 }
 377
 378 void log_push()
 379 {
 380         header_count.push_back(0);
 381 }
 382
 383 void log_pop()
 384 {
 385         header_count.pop_back();
 386         log_id_cache.clear();
 387         string_buf.clear();
 388         string_buf_index = -1;
 389         log_flush();
 390 }
 391
 392 #if (defined(__linux__) || defined(__FreeBSD__)) && defined(YOSYS_ENABLE_PLUGINS)
 393 void log_backtrace(const char *prefix, int levels)
 394 {
 395         if (levels <= 0) return;
 396
 397         Dl_info dli;
 398         void *p;
 399
 400         if ((p = __builtin_extract_return_addr(__builtin_return_address(0))) && dladdr(p, &dli)) {
 401                 log("%sframe #1: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 402         } else {
 403                 log("%sframe #1: ---\n", prefix);
 404                 return;
 405         }
 406
 407         if (levels <= 1) return;
 408
 409 #ifndef DEBUG
 410         log("%sframe #2: [build Yosys with ENABLE_DEBUG for deeper backtraces]\n", prefix);
 411 #else
 412         if ((p = __builtin_extract_return_addr(__builtin_return_address(1))) && dladdr(p, &dli)) {
 413                 log("%sframe #2: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 414         } else {
 415                 log("%sframe #2: ---\n", prefix);
 416                 return;
 417         }
 418
 419         if (levels <= 2) return;
 420
 421         if ((p = __builtin_extract_return_addr(__builtin_return_address(2))) && dladdr(p, &dli)) {
 422                 log("%sframe #3: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 423         } else {
 424                 log("%sframe #3: ---\n", prefix);
 425                 return;
 426         }
 427
 428         if (levels <= 3) return;
 429
 430         if ((p = __builtin_extract_return_addr(__builtin_return_address(3))) && dladdr(p, &dli)) {
 431                 log("%sframe #4: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 432         } else {
 433                 log("%sframe #4: ---\n", prefix);
 434                 return;
 435         }
 436
 437         if (levels <= 4) return;
 438
 439         if ((p = __builtin_extract_return_addr(__builtin_return_address(4))) && dladdr(p, &dli)) {
 440                 log("%sframe #5: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 441         } else {
 442                 log("%sframe #5: ---\n", prefix);
 443                 return;
 444         }
 445
 446         if (levels <= 5) return;
 447
 448         if ((p = __builtin_extract_return_addr(__builtin_return_address(5))) && dladdr(p, &dli)) {
 449                 log("%sframe #6: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 450         } else {
 451                 log("%sframe #6: ---\n", prefix);
 452                 return;
 453         }
 454
 455         if (levels <= 6) return;
 456
 457         if ((p = __builtin_extract_return_addr(__builtin_return_address(6))) && dladdr(p, &dli)) {
 458                 log("%sframe #7: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 459         } else {
 460                 log("%sframe #7: ---\n", prefix);
 461                 return;
 462         }
 463
 464         if (levels <= 7) return;
 465
 466         if ((p = __builtin_extract_return_addr(__builtin_return_address(7))) && dladdr(p, &dli)) {
 467                 log("%sframe #8: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 468         } else {
 469                 log("%sframe #8: ---\n", prefix);
 470                 return;
 471         }
 472
 473         if (levels <= 8) return;
 474
 475         if ((p = __builtin_extract_return_addr(__builtin_return_address(8))) && dladdr(p, &dli)) {
 476                 log("%sframe #9: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 477         } else {
 478                 log("%sframe #9: ---\n", prefix);
 479                 return;
 480         }
 481
 482         if (levels <= 9) return;
 483 #endif
 484 }
 485 #else
 486 void log_backtrace(const char*, int) { }
 487 #endif
 488
 489 void log_reset_stack()
 490 {
 491         while (header_count.size() > 1)
 492                 header_count.pop_back();
 493         log_id_cache.clear();
 494         string_buf.clear();
 495         string_buf_index = -1;
 496         log_flush();
 497 }
 498
 499 void log_flush()
 500 {
 501         for (auto f : log_files)
 502                 fflush(f);
 503
 504         for (auto f : log_streams)
 505                 f->flush();
 506 }
 507
 508 void log_dump_val_worker(RTLIL::IdString v) {
 509         log("%s", log_id(v));
 510 }
 511
 512 void log_dump_val_worker(RTLIL::SigSpec v) {
 513         log("%s", log_signal(v));
 514 }
 515
 516 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint)
 517 {
 518         std::stringstream buf;
 519         ILANG_BACKEND::dump_sigspec(buf, sig, autoint);
 520
 521         if (string_buf.size() < 100) {
 522                 string_buf.push_back(buf.str());
 523                 return string_buf.back().c_str();
 524         } else {
 525                 if (++string_buf_index == 100)
 526                         string_buf_index = 0;
 527                 string_buf[string_buf_index] = buf.str();
 528                 return string_buf[string_buf_index].c_str();
 529         }
 530 }
 531
 532 const char *log_const(const RTLIL::Const &value, bool autoint)
 533 {
 534         if ((value.flags & RTLIL::CONST_FLAG_STRING) == 0)
 535                 return log_signal(value, autoint);
 536
 537         std::string str = "\"" + value.decode_string() + "\"";
 538
 539         if (string_buf.size() < 100) {
 540                 string_buf.push_back(str);
 541                 return string_buf.back().c_str();
 542         } else {
 543                 if (++string_buf_index == 100)
 544                         string_buf_index = 0;
 545                 string_buf[string_buf_index] = str;
 546                 return string_buf[string_buf_index].c_str();
 547         }
 548 }
 549
 550 const char *log_id(RTLIL::IdString str)
 551 {
 552         log_id_cache.insert(str);
 553         const char *p = str.c_str();
 554         if (p[0] != '\\')
 555                 return p;
 556         if (p[1] == '$' || p[1] == '\\' || p[1] == 0)
 557                 return p;
 558         if (p[1] >= '0' && p[1] <= '9')
 559                 return p;
 560         return p+1;
 561 }
 562
 563 void log_module(RTLIL::Module *module, std::string indent)
 564 {
 565         std::stringstream buf;
 566         ILANG_BACKEND::dump_module(buf, indent, module, module->design, false);
 567         log("%s", buf.str().c_str());
 568 }
 569
 570 void log_cell(RTLIL::Cell *cell, std::string indent)
 571 {
 572         std::stringstream buf;
 573         ILANG_BACKEND::dump_cell(buf, indent, cell);
 574         log("%s", buf.str().c_str());
 575 }
 576
 577 void log_wire(RTLIL::Wire *wire, std::string indent)
 578 {
 579         std::stringstream buf;
 580         ILANG_BACKEND::dump_wire(buf, indent, wire);
 581         log("%s", buf.str().c_str());
 582 }
 583
 584 // ---------------------------------------------------
 585 // This is the magic behind the code coverage counters
 586 // ---------------------------------------------------
 587 #if defined(YOSYS_ENABLE_COVER) && (defined(__linux__) || defined(__FreeBSD__))
 588
 589 dict<std::string, std::pair<std::string, int>> extra_coverage_data;
 590
 591 void cover_extra(std::string parent, std::string id, bool increment) {
 592         if (extra_coverage_data.count(id) == 0) {
 593                 for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++)
 594                         if (p->id == parent)
 595                                 extra_coverage_data[id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 596                 log_assert(extra_coverage_data.count(id));
 597         }
 598         if (increment)
 599                 extra_coverage_data[id].second++;
 600 }
 601
 602 dict<std::string, std::pair<std::string, int>> get_coverage_data()
 603 {
 604         dict<std::string, std::pair<std::string, int>> coverage_data;
 605
 606         for (auto &it : pass_register) {
 607                 std::string key = stringf("passes.%s", it.first.c_str());
 608                 coverage_data[key].first = stringf("%s:%d:%s", __FILE__, __LINE__, __FUNCTION__);
 609                 coverage_data[key].second += it.second->call_counter;
 610         }
 611
 612         for (auto &it : extra_coverage_data) {
 613                 if (coverage_data.count(it.first))
 614                         log_warning("found duplicate coverage id \"%s\".\n", it.first.c_str());
 615                 coverage_data[it.first].first = it.second.first;
 616                 coverage_data[it.first].second += it.second.second;
 617         }
 618
 619         for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++) {
 620                 if (coverage_data.count(p->id))
 621                         log_warning("found duplicate coverage id \"%s\".\n", p->id);
 622                 coverage_data[p->id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 623                 coverage_data[p->id].second += p->counter;
 624         }
 625
 626         for (auto &it : coverage_data)
 627                 if (!it.second.first.compare(0, strlen(YOSYS_SRC "/"), YOSYS_SRC "/"))
 628                         it.second.first = it.second.first.substr(strlen(YOSYS_SRC "/"));
 629
 630         return coverage_data;
 631 }
 632
 633 #endif
 634
 635 YOSYS_NAMESPACE_END