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