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