diff --git a/include/verilated.cpp b/include/verilated.cpp index b33f448a8..64731ba01 100644 --- a/include/verilated.cpp +++ b/include/verilated.cpp @@ -96,6 +96,37 @@ void VL_FATAL_MT (const char* filename, int linenum, const char* hier, const cha vl_fatal(filename, linenum, hier, msg); } +//=========================================================================== +// Debug prints + +/// sprintf but return as string (this isn't fast, for print messages only) +std::string _vl_string_vprintf(const char* formatp, va_list ap) { + int len = VL_VSNPRINTF(NULL, 0, formatp, ap); + if (VL_UNLIKELY(len < 1)) return ""; + char* bufp = new char[len+1]; + VL_VSNPRINTF(bufp, len+1, formatp, ap); + std::string out = std::string(bufp, len); + delete bufp; + return out; +} + +vluint64_t _vl_dbg_sequence_number() { + static vluint64_t sequence = 0; + return ++sequence; +} + +vluint32_t _vl_dbg_thread_number() { + return 0; +} + +void VL_DBG_MSGF(const char* formatp, ...) { + va_list ap; + va_start(ap, formatp); + std::string out = _vl_string_vprintf(formatp, ap); + va_end(ap); + VL_PRINTF_MT("-V{t%d,%" VL_PRI64 "d}%s", _vl_dbg_thread_number(), _vl_dbg_sequence_number(), out.c_str()); +} + //=========================================================================== // Overall class init @@ -631,7 +662,7 @@ static inline void _vl_vsss_read(FILE* fp, int& floc, WDataInP fromp, const std: _vl_vsss_advance(fp, floc); } *cp++ = '\0'; - //VL_PRINTF_MT("\t_read got='%s'\n", tmpp); + //VL_DBG_MSG("\t_read got='"<>=1) { @@ -678,7 +709,7 @@ IData _vl_vsscanf(FILE* fp, // If a fscanf bool inPct = false; const char* pos = formatp; for (; *pos && !_vl_vsss_eof(fp,floc); ++pos) { - //VL_PRINTF_MT("_vlscan fmt='%c' floc=%d file='%c'\n", pos[0], floc, _vl_vsss_peek(fp,floc,fromp,fstr)); + //VL_DBG_MSG("_vlscan fmt='"<,}.\n");); +#else + VL_PRINTF_MT("- Verilated::debug attempted, but compiled without VL_DEBUG, so messages suppressed.\n"); +#endif + } +} + const char* Verilated::catName(const char* n1, const char* n2) { // Returns new'ed data // Used by symbol table creation to make module names diff --git a/include/verilated.h b/include/verilated.h index 91617b524..445a872b8 100644 --- a/include/verilated.h +++ b/include/verilated.h @@ -248,7 +248,7 @@ public: static int randReset() { return s_s.s_randReset; } ///< Return randReset value /// Enable debug of internal verilated code - static inline void debug(int level) { s_s.s_debug = level; } + static void debug(int level); #ifdef VL_DEBUG static inline int debug() { return s_s.s_debug; } ///< Return debug value #else @@ -354,6 +354,8 @@ extern void VL_FATAL_MT (const char* filename, int linenum, const char* hier, const char* msg); /// Print a string, multithread safe. Eventually VL_PRINTF will get called. #define VL_PRINTF_MT VL_PRINTF +/// Print a debug message from internals with standard prefix, with printf style format +extern void VL_DBG_MSGF(const char* formatp, ...); extern IData VL_RANDOM_I(int obits); ///< Randomize a signal extern QData VL_RANDOM_Q(int obits); ///< Randomize a signal diff --git a/include/verilated_save.cpp b/include/verilated_save.cpp index 39537e3e8..3c765a80d 100644 --- a/include/verilated_save.cpp +++ b/include/verilated_save.cpp @@ -112,7 +112,7 @@ void VerilatedDeserialize::trailer() { void VerilatedSave::open (const char* filenamep) { if (isOpen()) return; - VL_DEBUG_IF(VL_PRINTF_MT("-vltSave: opening save file %s\n",filenamep);); + VL_DEBUG_IF(VL_DBG_MSGF("- save: opening save file %s\n",filenamep);); if (filenamep[0]=='|') { assert(0); // Not supported yet. @@ -134,7 +134,7 @@ void VerilatedSave::open (const char* filenamep) { void VerilatedRestore::open (const char* filenamep) { if (isOpen()) return; - VL_DEBUG_IF(VL_PRINTF_MT("-vltRestore: opening restore file %s\n",filenamep);); + VL_DEBUG_IF(VL_DBG_MSGF("- restore: opening restore file %s\n",filenamep);); if (filenamep[0]=='|') { assert(0); // Not supported yet. diff --git a/include/verilated_vcd_c.cpp b/include/verilated_vcd_c.cpp index 26a490ce2..63cebb3ea 100644 --- a/include/verilated_vcd_c.cpp +++ b/include/verilated_vcd_c.cpp @@ -317,7 +317,7 @@ void VerilatedVcd::printTime (vluint64_t timeui) { static VL_THREAD_LOCAL bool backTime = false; if (!backTime) { backTime = true; - VL_PRINTF_MT("VCD time is moving backwards, wave file may be incorrect.\n"); + VL_PRINTF_MT("%%Warning: VCD time is moving backwards, wave file may be incorrect.\n"); } } m_timeLastDump = timeui; diff --git a/include/verilated_vpi.cpp b/include/verilated_vpi.cpp index 634b5a6b7..ff6ba59e6 100644 --- a/include/verilated_vpi.cpp +++ b/include/verilated_vpi.cpp @@ -361,7 +361,7 @@ public: if (VL_UNLIKELY(it->first <= time)) { VerilatedVpioCb* vop = it->second; ++it; // iterator may be deleted by callback - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: timed_callback %p\n",vop);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: timed_callback %p\n",vop);); (vop->cb_rtnp()) (vop->cb_datap()); } else { ++it; } @@ -383,7 +383,7 @@ public: continue; } VerilatedVpioCb* vop = *it++; - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: reason_callback %d %p\n",reason,vop);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: reason_callback %d %p\n",reason,vop);); (vop->cb_rtnp()) (vop->cb_datap()); } } @@ -400,11 +400,11 @@ public: if (VerilatedVpioVar* varop = VerilatedVpioVar::castp(vop->cb_datap()->obj)) { void* newDatap = varop->varDatap(); void* prevDatap = varop->prevDatap(); // Was malloced when we added the callback - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: value_test %s v[0]=%d/%d %p %p\n", + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: value_test %s v[0]=%d/%d %p %p\n", varop->fullname(), *((CData*)newDatap), *((CData*)prevDatap), newDatap, prevDatap);); if (memcmp(prevDatap, newDatap, varop->entSize())) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: value_callback %p %s v[0]=%d\n", + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: value_callback %p %s v[0]=%d\n", vop,varop->fullname(), *((CData*)newDatap));); update.insert(varop); vpi_get_value(vop->cb_datap()->obj, vop->cb_datap()->value); @@ -913,7 +913,7 @@ vpiHandle vpi_register_cb(p_cb_data cb_data_p) { QData time = 0; if (cb_data_p->time) time = _VL_SET_QII(cb_data_p->time->high, cb_data_p->time->low); VerilatedVpioCb* vop = new VerilatedVpioCb(cb_data_p, VL_TIME_Q()+time); - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_register_cb %d %p delay=%" VL_PRI64 "u\n",cb_data_p->reason,vop,time);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_register_cb %d %p delay=%" VL_PRI64 "u\n",cb_data_p->reason,vop,time);); VerilatedVpiImp::cbTimedAdd(vop); return vop->castVpiHandle(); } @@ -928,7 +928,7 @@ vpiHandle vpi_register_cb(p_cb_data cb_data_p) { case cbExitInteractive: // FALLTHRU // NOP, but need to return handle, so make object case cbInteractiveScopeChange: { // FALLTHRU // NOP, but need to return handle, so make object VerilatedVpioCb* vop = new VerilatedVpioCb(cb_data_p, 0); - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_register_cb %d %p\n",cb_data_p->reason,vop);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_register_cb %d %p\n",cb_data_p->reason,vop);); VerilatedVpiImp::cbReasonAdd(vop); return vop->castVpiHandle(); } @@ -940,7 +940,7 @@ vpiHandle vpi_register_cb(p_cb_data cb_data_p) { } PLI_INT32 vpi_remove_cb(vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_remove_cb %p\n",object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_remove_cb %p\n",object);); VerilatedVpioCb* vop = VerilatedVpioCb::castp(object); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!vop)) return 0; @@ -967,7 +967,7 @@ void vpi_get_systf_info(vpiHandle object, p_vpi_systf_data systf_data_p) { vpiHandle vpi_handle_by_name(PLI_BYTE8* namep, vpiHandle scope) { _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!namep)) return NULL; - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_handle_by_name %s %p\n",namep,scope);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_handle_by_name %s %p\n",namep,scope);); VerilatedVpioScope* voScopep = VerilatedVpioScope::castp(scope); const VerilatedVar* varp; const VerilatedScope* scopep; @@ -999,7 +999,7 @@ vpiHandle vpi_handle_by_name(PLI_BYTE8* namep, vpiHandle scope) { vpiHandle vpi_handle_by_index(vpiHandle object, PLI_INT32 indx) { // Used to get array entries - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_handle_by_index %p %d\n",object, indx);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_handle_by_index %p %d\n",object, indx);); VerilatedVpioVar* varop = VerilatedVpioVar::castp(object); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_LIKELY(varop)) { @@ -1024,7 +1024,7 @@ vpiHandle vpi_handle_by_index(vpiHandle object, PLI_INT32 indx) { // for traversing relationships vpiHandle vpi_handle(PLI_INT32 type, vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_handle %d %p\n",type,object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_handle %d %p\n",type,object);); _VL_VPI_ERROR_RESET(); // reset vpi error status switch (type) { case vpiLeftRange: { @@ -1066,7 +1066,7 @@ vpiHandle vpi_handle_multi(PLI_INT32 type, vpiHandle refHandle1, vpiHandle refHa } vpiHandle vpi_iterate(PLI_INT32 type, vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_iterate %d %p\n",type,object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_iterate %d %p\n",type,object);); _VL_VPI_ERROR_RESET(); // reset vpi error status switch (type) { case vpiMemoryWord: { @@ -1103,7 +1103,7 @@ vpiHandle vpi_iterate(PLI_INT32 type, vpiHandle object) { } } vpiHandle vpi_scan(vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_scan %p\n",object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_scan %p\n",object);); _VL_VPI_ERROR_RESET(); // reset vpi error status VerilatedVpio* vop = VerilatedVpio::castp(object); if (VL_UNLIKELY(!vop)) return NULL; @@ -1114,7 +1114,7 @@ vpiHandle vpi_scan(vpiHandle object) { PLI_INT32 vpi_get(PLI_INT32 property, vpiHandle object) { // Leave this in the header file - in many cases the compiler can constant propagate "object" - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_get %d %p\n",property,object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_get %d %p\n",property,object);); _VL_VPI_ERROR_RESET(); // reset vpi error status switch (property) { case vpiTimePrecision: { @@ -1155,7 +1155,7 @@ PLI_INT64 vpi_get64(PLI_INT32 property, vpiHandle object) { } PLI_BYTE8 *vpi_get_str(PLI_INT32 property, vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_get_str %d %p\n",property,object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_get_str %d %p\n",property,object);); VerilatedVpio* vop = VerilatedVpio::castp(object); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!vop)) return NULL; @@ -1193,7 +1193,7 @@ void vpi_get_value(vpiHandle object, p_vpi_value value_p) { static VL_THREAD_LOCAL char outStr[1+VL_MULS_MAX_WORDS*32]; // Maximum required size is for binary string, one byte per bit plus null termination // cppcheck-suppress variableScope static VL_THREAD_LOCAL int outStrSz = sizeof(outStr)-1; - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_get_value %p\n",object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_get_value %p\n",object);); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!value_p)) return; if (VerilatedVpioVar* vop = VerilatedVpioVar::castp(object)) { @@ -1448,16 +1448,16 @@ void vpi_get_value(vpiHandle object, p_vpi_value value_p) { vpiHandle vpi_put_value(vpiHandle object, p_vpi_value value_p, p_vpi_time time_p, PLI_INT32 flags) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_put_value %p %p\n",object, value_p);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_put_value %p %p\n",object, value_p);); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!value_p)) { _VL_VPI_WARNING(__FILE__, __LINE__, "Ignoring vpi_put_value with NULL value pointer"); return 0; } if (VerilatedVpioVar* vop = VerilatedVpioVar::castp(object)) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_put_value name=%s fmt=%d vali=%d\n", + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_put_value name=%s fmt=%d vali=%d\n", vop->fullname(), value_p->format, value_p->value.integer); - VL_PRINTF_MT("-vltVpi: varp=%p putatp=%p\n", + VL_DBG_MSGF("- vpi: varp=%p putatp=%p\n", vop->varp()->datap(), vop->varDatap());); if (VL_UNLIKELY(!vop->varp()->isPublicRW())) { _VL_VPI_WARNING(__FILE__, __LINE__, "Ignoring vpi_put_value to signal marked read-only, use public_flat_rw instead: ", vop->fullname()); @@ -1822,7 +1822,7 @@ PLI_INT32 vpi_free_object(vpiHandle object) { } PLI_INT32 vpi_release_handle (vpiHandle object) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_release_handle %p\n",object);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_release_handle %p\n",object);); VerilatedVpio* vop = VerilatedVpio::castp(object); _VL_VPI_ERROR_RESET(); // reset vpi error status if (VL_UNLIKELY(!vop)) return 0; @@ -1856,7 +1856,7 @@ PLI_INT32 vpi_put_userdata(vpiHandle obj, void *userdata) { } PLI_INT32 vpi_control(PLI_INT32 operation, ...) { - VL_DEBUG_IF_PLI(VL_PRINTF_MT("-vltVpi: vpi_control %d\n",operation);); + VL_DEBUG_IF_PLI(VL_DBG_MSGF("- vpi: vpi_control %d\n",operation);); _VL_VPI_ERROR_RESET(); // reset vpi error status switch (operation) { case vpiFinish: { diff --git a/src/V3EmitC.cpp b/src/V3EmitC.cpp index 3b632e9f9..a7c1ca096 100644 --- a/src/V3EmitC.cpp +++ b/src/V3EmitC.cpp @@ -877,7 +877,8 @@ class EmitCImp : EmitCStmts { puts(modClassName(m_modp)+"::"+nodep->name() +"("+cFuncArgs(nodep)+") {\n"); - puts("VL_DEBUG_IF(VL_PRINTF_MT(\" "); + // "+" in the debug indicates a print from the model + puts("VL_DEBUG_IF(VL_DBG_MSGF(\"+ "); for (int i=0;ilevel();i++) { puts(" "); } puts(modClassName(m_modp)+"::"+nodep->name() +"\\n\"); );\n"); @@ -938,7 +939,7 @@ class EmitCImp : EmitCStmts { if (nodep->lhsp()->castVarRef()) { varname = ": "+nodep->lhsp()->castVarRef()->varp()->prettyName(); } - puts(")) VL_PRINTF_MT(\"\tCHANGE: "+nodep->fileline()->ascii() + puts(")) VL_DBG_MSGF(\" CHANGE: "+nodep->fileline()->ascii() +varname+"\\n\"); );\n"); } } @@ -1738,11 +1739,11 @@ void EmitCImp::emitWrapEval(AstNodeModule* modp) { puts("if (VL_UNLIKELY(__Vm_inhibitSim)) return;\n"); } putsDecoration("// Evaluate till stable\n"); - puts("VL_DEBUG_IF(VL_PRINTF_MT(\"\\n----TOP Evaluate "+modClassName(modp)+"::eval\\n\"); );\n"); + puts("VL_DEBUG_IF(VL_DBG_MSGF(\"+++++TOP Evaluate "+modClassName(modp)+"::eval\\n\"); );\n"); puts("int __VclockLoop = 0;\n"); puts("QData __Vchange = 1;\n"); puts("while (VL_LIKELY(__Vchange)) {\n"); - puts( "VL_DEBUG_IF(VL_PRINTF_MT(\" Clock loop\\n\"););\n"); + puts( "VL_DEBUG_IF(VL_DBG_MSGF(\"+ Clock loop\\n\"););\n"); if (v3Global.opt.trace()) { puts("vlSymsp->__Vm_activity = true;\n"); } diff --git a/test_regress/t/t_verilated_debug.out b/test_regress/t/t_verilated_debug.out new file mode 100644 index 000000000..e76c43f27 --- /dev/null +++ b/test_regress/t/t_verilated_debug.out @@ -0,0 +1,18 @@ +-V{t0,1}- Verilated::debug is on. Message prefix indicates {,}. +-V{t0,2}+ Vt_verilated_debug::_ctor_var_reset +-V{t0,3}+ Vt_verilated_debug::_eval_initial +-V{t0,4}+ Vt_verilated_debug::_eval_settle +-V{t0,5}+ Vt_verilated_debug::_eval +-V{t0,6}+ Vt_verilated_debug::_change_request +-V{t0,7}+++++TOP Evaluate Vt_verilated_debug::eval +-V{t0,8}+ Clock loop +-V{t0,9}+ Vt_verilated_debug::_eval +-V{t0,10}+ Vt_verilated_debug::_change_request +-V{t0,11}+++++TOP Evaluate Vt_verilated_debug::eval +-V{t0,12}+ Clock loop +-V{t0,13}+ Vt_verilated_debug::_eval +-V{t0,14}+ Vt_verilated_debug::_sequent__TOP__1 +*-* All Finished *-* +- t/t_verilated_debug.v:16: Verilog $finish +-V{t0,15}+ Vt_verilated_debug::_change_request +-V{t0,16}+ Vt_verilated_debug::final diff --git a/test_regress/t/t_verilated_debug.pl b/test_regress/t/t_verilated_debug.pl new file mode 100755 index 000000000..c364d3809 --- /dev/null +++ b/test_regress/t/t_verilated_debug.pl @@ -0,0 +1,23 @@ +#!/usr/bin/perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2003 by Wilson Snyder. This program is free software; you can +# redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. + +$Self->{verilated_debug} = 1; + +compile ( + verilator_flags2 => [], + ); + +execute ( + check_finished=>1, + ); + +ok(files_identical("$Self->{obj_dir}/vlt_sim.log", "t/$Self->{name}.out")); + +ok(1); +1; diff --git a/test_regress/t/t_verilated_debug.v b/test_regress/t/t_verilated_debug.v new file mode 100644 index 000000000..d90fb7797 --- /dev/null +++ b/test_regress/t/t_verilated_debug.v @@ -0,0 +1,19 @@ +// DESCRIPTION: Verilator: Verilog Test module +// +// This file ONLY is placed into the Public Domain, for any use, +// without warranty, 2017 by Wilson Snyder. + +module t (/*AUTOARG*/ + // Inputs + clk + ); + + input clk; + + // Test loop + always @ (posedge clk) begin + $write("*-* All Finished *-*\n"); + $finish; + end + +endmodule