Unify format of VL_DEBUG print messages

This commit is contained in:
Wilson Snyder 2017-10-24 22:56:58 -04:00
parent e403db5877
commit 5ead61dc7b
9 changed files with 135 additions and 30 deletions

View File

@ -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='"<<tmpp<<"'\n");
}
static inline void _vl_vsss_setbit(WDataOutP owp, int obits, int lsb, int nbits, IData ld) {
for (; nbits && lsb<obits; nbits--, lsb++, ld>>=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='"<<pos[0]<<"' floc="<<floc<<" file='"<<_vl_vsss_peek(fp,floc,fromp,fstr)<<"'"<<endl);
if (!inPct && pos[0]=='%') {
inPct = true;
} else if (!inPct && isspace(pos[0])) { // Format spaces
@ -1295,6 +1326,17 @@ std::string VL_CVT_PACK_STR_NW(int lwords, WDataInP lwp) {
//===========================================================================
// Verilated:: Methods
void Verilated::debug(int val) {
s_s.s_debug = val;
if (val) {
#ifdef VL_DEBUG
VL_DEBUG_IF(VL_DBG_MSGF("- Verilated::debug is on. Message prefix indicates {<thread>,<sequence_number>}.\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

View File

@ -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

View File

@ -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.

View File

@ -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;

View File

@ -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: {

View File

@ -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;i<m_modp->level();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");
}

View File

@ -0,0 +1,18 @@
-V{t0,1}- Verilated::debug is on. Message prefix indicates {<thread>,<sequence_number>}.
-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

View File

@ -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;

View File

@ -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