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