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