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