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