i40e: rework logging to also include timestamps

i40e_bm/Makefile

@@ -3,7 +3,7 @@ CPPFLAGS += -I../libnicbm/include/
 CXXFLAGS += -Wall -Wextra -Wno-unused-parameter -O3 -g
 LDFLGAS = -g
 
-OBJS := i40e_bm.o i40e_queues.o i40e_adminq.o i40e_hmc.o i40e_lan.o xsums.o
+OBJS := i40e_bm.o i40e_queues.o i40e_adminq.o i40e_hmc.o i40e_lan.o xsums.o logger.o
 
 all: i40e_bm
 

i40e_bm/i40e_adminq.cc

@@ -32,13 +32,13 @@ void queue_admin_tx::reg_updated()
 
     if (!enabled  && (reg_len & I40E_GL_ATQLEN_ATQENABLE_MASK)) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq: enable base=" << base << " len=" << len <<
-            std::endl;
+        log << " enable base=" << base << " len=" << len <<
+            logger::endl;
 #endif
         enabled = true;
     } else if (enabled && !(reg_len & I40E_GL_ATQLEN_ATQENABLE_MASK)) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq: disable" << std::endl;
+        log << " disable" << logger::endl;
 #endif
         enabled = false;
     }
@@ -68,8 +68,8 @@ void queue_admin_tx::admin_desc_ctx::desc_compl_prepare(uint16_t retval,
     d->retval = retval;
 
 #ifdef DEBUG_ADMINQ
-    std::cerr << "atq: desc_compl_prepare index=" << index << " retval=" <<
-        retval << std::endl;
+    queue.log << " desc_compl_prepare index=" << index << " retval=" <<
+        retval << logger::endl;
 #endif
 }
 
@@ -84,8 +84,8 @@ void queue_admin_tx::admin_desc_ctx::desc_complete_indir(uint16_t retval,
         const void *data, size_t len, uint16_t extra_flags, bool ignore_datalen)
 {
     if (!ignore_datalen && len > d->datalen) {
-        std::cerr << "queue_admin_tx::desc_complete_indir: data too long ("
-            << len << ") got buffer for (" << d->datalen << ")" << std::endl;
+        queue.log << "queue_admin_tx::desc_complete_indir: data too long ("
+            << len << ") got buffer for (" << d->datalen << ")" << logger::endl;
         abort();
     }
     d->datalen = len;
@@ -103,8 +103,8 @@ void queue_admin_tx::admin_desc_ctx::prepare()
         uint64_t addr = d->params.external.addr_low |
             (((uint64_t) d->params.external.addr_high) << 32);
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq: desc with buffer opc=" << d->opcode << " addr=" <<
-            addr << std::endl;
+        queue.log << " desc with buffer opc=" << d->opcode << " addr=" <<
+            addr << logger::endl;
 #endif
         data_fetch(addr, d->datalen);
     } else {
@@ -115,12 +115,12 @@ void queue_admin_tx::admin_desc_ctx::prepare()
 void queue_admin_tx::admin_desc_ctx::process()
 {
 #ifdef DEBUG_ADMINQ
-    std::cerr << "atq: descriptor " << index << " fetched" << std::endl;
+    queue.log << " descriptor " << index << " fetched" << logger::endl;
 #endif
 
     if (d->opcode == i40e_aqc_opc_get_version) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  get version" << std::endl;
+        queue.log << "  get version" << logger::endl;
 #endif
         struct i40e_aqc_get_version *gv =
             reinterpret_cast<struct i40e_aqc_get_version *>(d->params.raw);
@@ -134,32 +134,32 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_request_resource) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  request resource" << std::endl;
+        queue.log << "  request resource" << logger::endl;
 #endif
         struct i40e_aqc_request_resource *rr =
             reinterpret_cast<struct i40e_aqc_request_resource *>(
                     d->params.raw);
         rr->timeout = 180000;
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:    res_id=" << rr->resource_id << std::endl;
-        std::cerr << "atq:    res_nu=" << rr->resource_number << std::endl;
+        queue.log << "    res_id=" << rr->resource_id << logger::endl;
+        queue.log << "    res_nu=" << rr->resource_number << logger::endl;
 #endif
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_release_resource) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  release resource" << std::endl;
+        queue.log << "  release resource" << logger::endl;
 #endif
 #ifdef DEBUG_ADMINQ
         struct i40e_aqc_request_resource *rr =
             reinterpret_cast<struct i40e_aqc_request_resource *>(
                     d->params.raw);
-        std::cerr << "atq:    res_id=" << rr->resource_id << std::endl;
-        std::cerr << "atq:    res_nu=" << rr->resource_number << std::endl;
+        queue.log << "    res_id=" << rr->resource_id << logger::endl;
+        queue.log << "    res_nu=" << rr->resource_number << logger::endl;
 #endif
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_clear_pxe_mode)  {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  clear PXE mode" << std::endl;
+        queue.log << "  clear PXE mode" << logger::endl;
 #endif
         dev.regs.gllan_rctl_0 &= ~I40E_GLLAN_RCTL_0_PXE_MODE_MASK;
         desc_complete(0);
@@ -167,7 +167,7 @@ void queue_admin_tx::admin_desc_ctx::process()
             d->opcode == i40e_aqc_opc_list_dev_capabilities)
     {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  get dev/fun caps" << std::endl;
+        queue.log << "  get dev/fun caps" << logger::endl;
 #endif
         struct i40e_aqc_list_capabilites *lc =
             reinterpret_cast<struct i40e_aqc_list_capabilites *>(
@@ -185,14 +185,14 @@ void queue_admin_tx::admin_desc_ctx::process()
 
         if (sizeof(caps) <= d->datalen) {
 #ifdef DEBUG_ADMINQ
-            std::cerr << "atq:    data fits" << std::endl;
+            queue.log << "    data fits" << logger::endl;
 #endif
             // data fits within the buffer
             lc->count = num_caps;
             desc_complete_indir(0, caps, sizeof(caps));
         } else {
 #ifdef DEBUG_ADMINQ
-            std::cerr << "atq:    data doesn't fit" << std::endl;
+            queue.log << "    data doesn't fit" << logger::endl;
 #endif
             // data does not fit
             d->datalen = sizeof(caps);
@@ -200,12 +200,12 @@ void queue_admin_tx::admin_desc_ctx::process()
         }
     } else if (d->opcode == i40e_aqc_opc_lldp_stop) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  lldp stop" << std::endl;
+        queue.log << "  lldp stop" << logger::endl;
 #endif
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_mac_address_read) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  read mac" << std::endl;
+        queue.log << "  read mac" << logger::endl;
 #endif
         struct i40e_aqc_mac_address_read *ar =
             reinterpret_cast<struct i40e_aqc_mac_address_read *>(
@@ -214,7 +214,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         struct i40e_aqc_mac_address_read_data ard;
         uint64_t mac = runner->get_mac_addr();
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:    mac = " << mac << std::endl;
+        queue.log << "    mac = " << mac << logger::endl;
 #endif
         memcpy(ard.pf_lan_mac, &mac, 6);
         memcpy(ard.port_mac, &mac, 6);
@@ -223,7 +223,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, &ard, sizeof(ard));
     } else if (d->opcode == i40e_aqc_opc_get_phy_abilities) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  get phy abilities" << std::endl;
+        queue.log << "  get phy abilities" << logger::endl;
 #endif
         struct i40e_aq_get_phy_abilities_resp par;
         memset(&par, 0, sizeof(par));
@@ -240,7 +240,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, &par, sizeof(par), 0, true);
     } else if (d->opcode == i40e_aqc_opc_get_link_status) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  link status" << std::endl;
+        queue.log << "  link status" << logger::endl;
 #endif
         struct i40e_aqc_get_link_status *gls =
             reinterpret_cast<struct i40e_aqc_get_link_status *>(
@@ -262,7 +262,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_get_switch_config) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  get switch config" << std::endl;
+        queue.log << "  get switch config" << logger::endl;
 #endif
         struct i40e_aqc_switch_seid *sw = reinterpret_cast<
             struct i40e_aqc_switch_seid *>(d->params.raw);
@@ -312,8 +312,8 @@ void queue_admin_tx::admin_desc_ctx::process()
         hr.num_reported = report;
         hr.num_total = cnt;
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:    report=" << report << " cnt=" << cnt <<
-            "  seid=" << sw->seid << std::endl;
+        queue.log << "    report=" << report << " cnt=" << cnt <<
+            "  seid=" << sw->seid << logger::endl;
 #endif
 
         // create temporary contiguous buffer
@@ -325,7 +325,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, buf, buflen);
     } else if (d->opcode == i40e_aqc_opc_set_switch_config) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  set switch config" << std::endl;
+        queue.log << "  set switch config" << logger::endl;
 #endif
         /* TODO: lots of interesting things here like l2 filtering etc. that are
          * relevant.
@@ -336,7 +336,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_get_vsi_parameters) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  get vsi parameters" << std::endl;
+        queue.log << "  get vsi parameters" << logger::endl;
 #endif
         /*struct i40e_aqc_add_get_update_vsi *v =
             reinterpret_cast<struct i40e_aqc_add_get_update_vsi *>(
@@ -351,24 +351,24 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, &pd, sizeof(pd));
     } else if (d->opcode == i40e_aqc_opc_update_vsi_parameters) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  update vsi parameters" << std::endl;
+        queue.log << "  update vsi parameters" << logger::endl;
 #endif
         /* TODO */
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_set_dcb_parameters) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  set dcb parameters" << std::endl;
+        queue.log << "  set dcb parameters" << logger::endl;
 #endif
         /* TODO */
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_configure_vsi_bw_limit) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  configure vsi bw limit" << std::endl;
+        queue.log << "  configure vsi bw limit" << logger::endl;
 #endif
         desc_complete(0);
     } else if (d->opcode == i40e_aqc_opc_query_vsi_bw_config) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  query vsi bw config" << std::endl;
+        queue.log << "  query vsi bw config" << logger::endl;
 #endif
         struct i40e_aqc_query_vsi_bw_config_resp bwc;
         memset(&bwc, 0, sizeof(bwc));
@@ -377,7 +377,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, &bwc, sizeof(bwc));
     } else if (d->opcode == i40e_aqc_opc_query_vsi_ets_sla_config) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  query vsi ets sla config" << std::endl;
+        queue.log << "  query vsi ets sla config" << logger::endl;
 #endif
         struct i40e_aqc_query_vsi_ets_sla_config_resp sla;
         memset(&sla, 0, sizeof(sla));
@@ -386,7 +386,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, &sla, sizeof(sla));
     } else if (d->opcode == i40e_aqc_opc_remove_macvlan) {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  remove macvlan" << std::endl;
+        queue.log << "  remove macvlan" << logger::endl;
 #endif
         struct i40e_aqc_macvlan *m = reinterpret_cast<
             struct i40e_aqc_macvlan *>(d->params.raw);
@@ -399,7 +399,7 @@ void queue_admin_tx::admin_desc_ctx::process()
         desc_complete_indir(0, data, d->datalen);
     } else {
 #ifdef DEBUG_ADMINQ
-        std::cerr << "atq:  uknown opcode=" << d->opcode << std::endl;
+        queue.log << "  uknown opcode=" << d->opcode << logger::endl;
 #endif
         //desc_complete(I40E_AQ_RC_ESRCH);
         desc_complete(0);

i40e_bm/i40e_bm.cc

@@ -12,7 +12,8 @@ nicbm::Runner *runner;
 namespace i40e {
 
 i40e_bm::i40e_bm()
-    : pf_atq(*this, regs.pf_atqba, regs.pf_atqlen, regs.pf_atqh, regs.pf_atqt),
+    : log("i40e"),
+    pf_atq(*this, regs.pf_atqba, regs.pf_atqlen, regs.pf_atqh, regs.pf_atqt),
     hmc(*this), shram(*this), lanmgr(*this, NUM_QUEUES)
 {
     reset(false);
@@ -40,7 +41,7 @@ void i40e_bm::dma_complete(nicbm::DMAOp &op)
 {
     dma_base &dma = dynamic_cast<dma_base &>(op);
 #ifdef DEBUG_DEV
-    std::cerr << "dma_complete(" << &op << ")" << std::endl;
+    log << "dma_complete(" << &op << ")" << logger::endl;
 #endif
     dma.done();
 }
@@ -48,7 +49,7 @@ void i40e_bm::dma_complete(nicbm::DMAOp &op)
 void i40e_bm::eth_rx(uint8_t port, const void *data, size_t len)
 {
 #ifdef DEBUG_DEV
-    std::cerr << "i40e: received packet len=" << len << std::endl;
+    log << "i40e: received packet len=" << len << logger::endl;
 #endif
     lanmgr.packet_received(data, len);
 }
@@ -63,8 +64,8 @@ void i40e_bm::reg_read(uint8_t bar, uint64_t addr, void *dest, size_t len)
         dest_p[0] = reg_read32(bar, addr);
         dest_p[1] = reg_read32(bar, addr + 4);
     } else {
-        std::cerr << "currently we only support 4/8B reads (got " << len << ")"
-            << std::endl;
+        log << "currently we only support 4/8B reads (got " << len << ")"
+            << logger::endl;
         abort();
     }
 }
@@ -76,7 +77,7 @@ uint32_t i40e_bm::reg_read32(uint8_t bar, uint64_t addr)
     } else if (bar == BAR_IO) {
         return reg_io_read(addr);
     } else {
-        std::cerr << "invalid BAR " << (int) bar << std::endl;
+        log << "invalid BAR " << (int) bar << logger::endl;
         abort();
     }
 }
@@ -91,8 +92,8 @@ void i40e_bm::reg_write(uint8_t bar, uint64_t addr, const void *src, size_t len)
         reg_write32(bar, addr, src_p[0]);
         reg_write32(bar, addr + 4, src_p[1]);
     } else {
-        std::cerr << "currently we only support 4/8B writes (got " << len << ")"
-            << std::endl;
+        log << "currently we only support 4/8B writes (got " << len << ")"
+            << logger::endl;
         abort();
     }
 }
@@ -104,21 +105,21 @@ void i40e_bm::reg_write32(uint8_t bar, uint64_t addr, uint32_t val)
     } else if (bar == BAR_IO) {
         reg_io_write(addr, val);
     } else {
-        std::cerr << "invalid BAR " << (int) bar << std::endl;
+        log << "invalid BAR " << (int) bar << logger::endl;
         abort();
     }
 }
 
 uint32_t i40e_bm::reg_io_read(uint64_t addr)
 {
-    std::cerr << "unhandled io read addr=" << std::hex << addr << std::endl;
+    log << "unhandled io read addr="  << addr << logger::endl;
     return 0;
 }
 
 void i40e_bm::reg_io_write(uint64_t addr, uint32_t val)
 {
-    std::cerr << "unhandled io write addr=" << std::hex << addr << " val="
-        << val << std::endl;
+    log << "unhandled io write addr="  << addr << " val="
+        << val << logger::endl;
 }
 
 uint32_t i40e_bm::reg_mem_read32(uint64_t addr)
@@ -358,8 +359,8 @@ uint32_t i40e_bm::reg_mem_read32(uint64_t addr)
 
             default:
 #ifdef DEBUG_DEV
-                std::cerr << "unhandled mem read addr=" << std::hex << addr
-                    << std::endl;
+                log << "unhandled mem read addr="  << addr
+                    << logger::endl;
 #endif
                 break;
         }
@@ -536,8 +537,8 @@ void i40e_bm::reg_mem_write32(uint64_t addr, uint32_t val)
 
             default:
 #ifdef DEBUG_DEV
-                std::cerr << "unhandled mem write addr=" << std::hex << addr
-                    << " val=" << val << std::endl;
+                log << "unhandled mem write addr="  << addr
+                    << " val=" << val << logger::endl;
 #endif
                 break;
         }
@@ -547,7 +548,7 @@ void i40e_bm::reg_mem_write32(uint64_t addr, uint32_t val)
 void i40e_bm::reset(bool indicate_done)
 {
 #ifdef DEBUG_DEV
-    std::cout << "reset triggered" << std::endl;
+    std::cout << "reset triggered" << logger::endl;
 #endif
 
     pf_atq.reset();
@@ -560,7 +561,7 @@ void i40e_bm::reset(bool indicate_done)
 }
 
 shadow_ram::shadow_ram(i40e_bm &dev_)
-    : dev(dev_)
+    : dev(dev_), log("sram")
 {
 }
 
@@ -578,8 +579,8 @@ void shadow_ram::reg_updated()
     is_write = (val & I40E_GLNVM_SRCTL_WRITE_MASK);
 
 #ifdef DEBUG_DEV
-    std::cerr << "shadow ram op addr=" << std::hex << addr << " w=" << is_write
-        << std::endl;
+    log << "shadow ram op addr="  << addr << " w=" << is_write
+        << logger::endl;
 #endif
 
     if (is_write) {
@@ -615,8 +616,8 @@ uint16_t shadow_ram::read(uint16_t addr)
 
         default:
 #ifdef DEBUG_DEV
-             std::cerr << "TODO shadow memory read addr=" << std::hex << addr
-                 << std::endl;
+             log << "TODO shadow memory read addr="  << addr
+                 << logger::endl;
 #endif
              break;
     }
@@ -627,8 +628,8 @@ uint16_t shadow_ram::read(uint16_t addr)
 void shadow_ram::write(uint16_t addr, uint16_t val)
 {
 #ifdef DEBUG_DEV
-    std::cerr << "TODO shadow memory write addr=" << std::hex << addr <<
-        " val=" << val << std::endl;
+    log << "TODO shadow memory write addr="  << addr <<
+        " val=" << val << logger::endl;
 #endif
 }
 

i40e_bm/i40e_bm.h

 #pragma once
 
 #include <deque>
+#include <sstream>
 #include <stdint.h>
 extern "C" {
 #include <cosim_pcie_proto.h>
@@ -27,6 +28,27 @@ class dma_base : public nicbm::DMAOp {
         virtual void done() = 0;
 };
 
+class logger : public std::ostream {
+    public:
+        static const char endl = '\n';
+
+    protected:
+        std::string label;
+        std::stringstream ss;
+
+    public:
+        logger(const std::string &label_);
+        logger &operator<<(char c);
+        logger &operator<<(int32_t c);
+        logger &operator<<(uint8_t i);
+        logger &operator<<(uint16_t i);
+        logger &operator<<(uint32_t i);
+        logger &operator<<(uint64_t i);
+        logger &operator<<(bool c);
+        logger &operator<<(const char *str);
+        logger &operator<<(void *str);
+};
+
 /**
  * Base-class for descriptor queues (RX/TX, Admin RX/TX).
  *
@@ -135,6 +157,7 @@ class queue_base {
 
     public:
         std::string qname;
+        logger log;
     protected:
         desc_ctx *desc_ctxs[MAX_ACTIVE_DESCS];
         uint32_t active_first_pos;
@@ -377,6 +400,7 @@ class lan {
         friend class lan_queue_rx;
 
         i40e_bm &dev;
+        logger log;
         const size_t num_qs;
         lan_queue_rx **rxqs;
         lan_queue_tx **txqs;
@@ -392,6 +416,7 @@ class lan {
 class shadow_ram {
     protected:
         i40e_bm &dev;
+        logger log;
 
     public:
         shadow_ram(i40e_bm &dev);
@@ -481,6 +506,7 @@ public:
     virtual void eth_rx(uint8_t port, const void *data, size_t len);
 
 protected:
+    logger log;
     i40e_regs regs;
     queue_admin_tx pf_atq;
     host_mem_cache hmc;

i40e_bm/i40e_lan.cc

@@ -12,7 +12,7 @@ using namespace i40e;
 extern nicbm::Runner *runner;
 
 lan::lan(i40e_bm &dev_, size_t num_qs_)
-    : dev(dev_), num_qs(num_qs_)
+    : dev(dev_), log("lan"), num_qs(num_qs_)
 {
     rxqs = new lan_queue_rx *[num_qs];
     txqs = new lan_queue_tx *[num_qs];
@@ -38,7 +38,7 @@ void lan::reset()
 void lan::qena_updated(uint16_t idx, bool rx)
 {
 #ifdef DEBUG_LAN
-    std::cerr << "lan: qena updated idx=" << idx << " rx=" << rx << std::endl;
+    log << " qena updated idx=" << idx << " rx=" << rx << logger::endl;
 #endif
     uint32_t &reg = (rx ? dev.regs.qrx_ena[idx] : dev.regs.qtx_ena[idx]);
     lan_queue_base &q = (rx ? static_cast<lan_queue_base &>(*rxqs[idx]) :
@@ -54,7 +54,7 @@ void lan::qena_updated(uint16_t idx, bool rx)
 void lan::tail_updated(uint16_t idx, bool rx)
 {
 #ifdef DEBUG_LAN
-    std::cerr << "lan: tail updated idx=" << idx << " rx=" << rx << std::endl;
+    log << " tail updated idx=" << idx << " rx=" << rx << logger::endl;
 #endif
 
     lan_queue_base &q = (rx ? static_cast<lan_queue_base &>(*rxqs[idx]) :
@@ -67,7 +67,7 @@ void lan::tail_updated(uint16_t idx, bool rx)
 void lan::packet_received(const void *data, size_t len)
 {
 #ifdef DEBUG_LAN
-    std::cerr << "lan: packet received len=" << len << std::endl;
+    log << " packet received len=" << len << logger::endl;
 #endif
 
     // TODO: steering
@@ -98,7 +98,7 @@ void lan_queue_base::enable()
         return;
 
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": lan enabling queue " << idx << std::endl;
+    log << " lan enabling queue " << idx << logger::endl;
 #endif
     enabling = true;
 
@@ -116,7 +116,7 @@ void lan_queue_base::enable()
 void lan_queue_base::ctx_fetched()
 {
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": lan ctx fetched " << idx << std::endl;
+    log << " lan ctx fetched " << idx << logger::endl;
 #endif
 
     initialize();
@@ -131,7 +131,7 @@ void lan_queue_base::ctx_fetched()
 void lan_queue_base::disable()
 {
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": lan disabling queue " << idx << std::endl;
+    log << " lan disabling queue " << idx << logger::endl;
 #endif
     enabled = false;
     // TODO: write back
@@ -142,7 +142,7 @@ void lan_queue_base::interrupt()
 {
     uint32_t qctl = reg_intqctl;
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": interrupt intctl=" << qctl << std::endl;
+    log << " interrupt intctl=" << qctl << logger::endl;
 #endif
 
     uint16_t msix_idx = (qctl & I40E_QINT_TQCTL_MSIX_INDX_MASK) >>
@@ -153,19 +153,19 @@ void lan_queue_base::interrupt()
 
     if (!cause_ena) {
 #ifdef DEBUG_LAN
-        std::cerr << qname << ": interrupt cause disabled" << std::endl;
+        log << " interrupt cause disabled" << logger::endl;
 #endif
         return;
     }
 
     if (msix_idx != 0) {
-        std::cerr << "TODO: only int 0 is supported" << std::endl;
+        log << "TODO: only int 0 is supported" << logger::endl;
         abort();
     }
 
     // TODO throttling?
 #ifdef DEBUG_LAN
-    std::cerr << qname << ":   setting int0.qidx=" << msix0_idx << std::endl;
+    log << "   setting int0.qidx=" << msix0_idx << logger::endl;
 #endif
     lanmgr.dev.regs.pfint_icr0 |= I40E_PFINT_ICR0_INTEVENT_MASK |
         (1 << (I40E_PFINT_ICR0_QUEUE_0_SHIFT + msix0_idx));
@@ -202,7 +202,7 @@ void lan_queue_rx::reset()
 void lan_queue_rx::initialize()
 {
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": initialize()" << std::endl;
+    log << " initialize()" << logger::endl;
 #endif
     uint8_t *ctx_p = reinterpret_cast<uint8_t *>(ctx);
 
@@ -227,21 +227,21 @@ void lan_queue_rx::initialize()
     rxmax = (((*rxmax_p) >> 6) & ((1 << 14) - 1)) * 128;
 
     if (!longdesc) {
-        std::cerr << "lan_queue_rx::initialize: currently only 32B descs "
-            " supported" << std::endl;
+        log << "lan_queue_rx::initialize: currently only 32B descs "
+            " supported" << logger::endl;
         abort();
     }
     if (dtype != 0) {
-        std::cerr << "lan_queue_rx::initialize: no header split supported"
-            << std::endl;
+        log << "lan_queue_rx::initialize: no header split supported"
+            << logger::endl;
         abort();
     }
 
 #ifdef DEBUG_LAN
-    std::cerr << qname << ":  head=" << reg_dummy_head << " base=" << base <<
+    log << "  head=" << reg_dummy_head << " base=" << base <<
         " len=" << len << " dbsz=" << dbuff_size << " hbsz=" << hbuff_size <<
         " dtype=" << (unsigned) dtype << " longdesc=" << longdesc <<
-        " crcstrip=" << crc_strip << " rxmax=" << rxmax << std::endl;
+        " crcstrip=" << crc_strip << " rxmax=" << rxmax << logger::endl;
 #endif
 }
 
@@ -254,7 +254,7 @@ void lan_queue_rx::packet_received(const void *data, size_t pktlen)
 {
     if (dcache.empty()) {
 #ifdef DEBUG_LAN
-        std::cerr << qname << ": empty, dropping packet" << std::endl;
+        log << " empty, dropping packet" << logger::endl;
 #endif
         return;
     }
@@ -262,8 +262,8 @@ void lan_queue_rx::packet_received(const void *data, size_t pktlen)
     rx_desc_ctx &ctx = *dcache.front();
 
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": packet received didx=" << ctx.index << " cnt=" <<
-        dcache.size() << std::endl;
+    log << " packet received didx=" << ctx.index << " cnt=" <<
+        dcache.size() << logger::endl;
 #endif
 
     dcache.pop_front();
@@ -320,7 +320,7 @@ void lan_queue_tx::reset()
 void lan_queue_tx::initialize()
 {
 #ifdef DEBUG_LAN
-    std::cerr << qname << ": initialize()" << std::endl;
+    log << " initialize()" << logger::endl;
 #endif
     uint8_t *ctx_p = reinterpret_cast<uint8_t *>(ctx);
 
@@ -338,9 +338,9 @@ void lan_queue_tx::initialize()
     hwb_addr = *hwb_addr_p;
 
 #ifdef DEBUG_LAN
-    std::cerr << qname << ":  head=" << reg_dummy_head << " base=" << base <<
+    log << "  head=" << reg_dummy_head << " base=" << base <<
         " len=" << len << " hwb=" << hwb << " hwb_addr=" << hwb_addr <<
-        std::endl;
+        logger::endl;
 #endif
 }
 
@@ -362,7 +362,7 @@ void lan_queue_tx::do_writeback(uint32_t first_idx, uint32_t first_pos,
         dma->dma_addr = hwb_addr;
 
 #ifdef DEBUG_LAN
-        std::cerr << qname << ": hwb=" << *((uint32_t *) dma->data) << std::endl;
+        log << " hwb=" << *((uint32_t *) dma->data) << logger::endl;
 #endif
         runner->issue_dma(*dma);
     }
@@ -383,14 +383,14 @@ bool lan_queue_tx::trigger_tx_packet()
 
         d1 = rd->d->cmd_type_offset_bsz;
 #ifdef DEBUG_LAN
-        std::cerr << qname << ": data fetched didx=" << rd->index << " d1=" <<
-            d1 << std::endl;
+        log << " data fetched didx=" << rd->index << " d1=" <<
+            d1 << logger::endl;
 #endif
 
         uint16_t pkt_len = (d1 & I40E_TXD_QW1_TX_BUF_SZ_MASK) >>
             I40E_TXD_QW1_TX_BUF_SZ_SHIFT;
         if (total_len + pkt_len > MTU) {
-            std::cerr << "txq: trigger_tx_packet too large" << std::endl;
+            log << "txq: trigger_tx_packet too large" << logger::endl;
             abort();
         }
 
@@ -402,8 +402,8 @@ bool lan_queue_tx::trigger_tx_packet()
         l4t = (cmd & I40E_TX_DESC_CMD_L4T_EOFT_MASK);
 
 #ifdef DEBUG_LAN
-        std::cerr << qname << ":    eop=" << eop << " len=" << pkt_len <<
-            std::endl;
+        log << "    eop=" << eop << " len=" << pkt_len <<
+            logger::endl;
 #endif
 
         total_len += pkt_len;
@@ -426,8 +426,8 @@ bool lan_queue_tx::trigger_tx_packet()
         xsum_tcp(pktbuf + tcp_off, total_len - tcp_off);
     }
 #ifdef DEBUG_LAN
-    std::cerr << qname << ":    iipt=" << iipt << " l4t=" << l4t <<
-        " maclen=" << maclen << " iplen=" << iplen<< std::endl;
+    log << "    iipt=" << iipt << " l4t=" << l4t <<
+        " maclen=" << maclen << " iplen=" << iplen<< logger::endl;
 #else
     (void) iipt;
 #endif
@@ -458,8 +458,8 @@ void lan_queue_tx::tx_desc_ctx::prepare()
     uint64_t d1 = d->cmd_type_offset_bsz;
 
 #ifdef DEBUG_LAN
-    std::cerr << queue.qname << ": desc fetched didx=" << index << " d1=" <<
-        d1 << std::endl;
+    queue.log << " desc fetched didx=" << index << " d1=" <<
+        d1 << logger::endl;
 #endif
 
     uint8_t dtype = (d1 & I40E_TXD_QW1_DTYPE_MASK) >> I40E_TXD_QW1_DTYPE_SHIFT;
@@ -468,16 +468,16 @@ void lan_queue_tx::tx_desc_ctx::prepare()
             I40E_TXD_QW1_TX_BUF_SZ_SHIFT;
 
 #ifdef DEBUG_LAN
-        std::cerr << queue.qname << ":  bufaddr=" << d->buffer_addr <<
-            " len=" << len << std::endl;
+        queue.log << "  bufaddr=" << d->buffer_addr <<
+            " len=" << len << logger::endl;
 #endif
 
         data_fetch(d->buffer_addr, len);
     } else if (dtype == I40E_TX_DESC_DTYPE_CONTEXT) {
         struct i40e_tx_context_desc *ctxd =
             reinterpret_cast<struct i40e_tx_context_desc *> (d);
-        std::cerr << "  context descriptor: tp=" << ctxd->tunneling_params <<
-            " l2t=" << ctxd->l2tag2 << " tctm=" << ctxd->type_cmd_tso_mss << std::endl;
+        queue.log << "  context descriptor: tp=" << ctxd->tunneling_params <<
+            " l2t=" << ctxd->l2tag2 << " tctm=" << ctxd->type_cmd_tso_mss << logger::endl;
         abort();
 
         /*desc->buffer_addr = 0;
@@ -486,7 +486,7 @@ void lan_queue_tx::tx_desc_ctx::prepare()
 
         desc_writeback(desc_buf, didx);*/
     } else {
-        std::cerr << "txq: only support context & data descriptors" << std::endl;
+        queue.log << "txq: only support context & data descriptors" << logger::endl;
         abort();
     }
 
@@ -521,7 +521,7 @@ lan_queue_tx::dma_hwb::~dma_hwb()
 void lan_queue_tx::dma_hwb::done()
 {
 #ifdef DEBUG_LAN
-    std::cerr << queue.qname << ": tx head written back" << std::endl;
+    queue.log << " tx head written back" << logger::endl;
 #endif
     queue.writeback_done(pos, cnt);
     delete this;

i40e_bm/i40e_queues.cc

@@ -13,7 +13,7 @@ extern nicbm::Runner *runner;
 
 queue_base::queue_base(const std::string &qname_, uint32_t &reg_head_,
         uint32_t &reg_tail_)
-    : qname(qname_), active_first_pos(0), active_first_idx(0), active_cnt(0),
+    : qname(qname_), log(qname_), active_first_pos(0), active_first_idx(0), active_cnt(0),
     base(0), len(0), reg_head(reg_head_), reg_tail(reg_tail_),
     enabled(false), desc_len(0)
 {
@@ -47,8 +47,8 @@ void queue_base::trigger_fetch()
         fetch_cnt = len - next_idx;
 
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ": fetching avail=" << desc_avail <<
-        " cnt=" << fetch_cnt << " idx=" << next_idx << std::endl;
+    log << "fetching avail=" << desc_avail << " cnt=" << fetch_cnt << " idx=" <<
+        next_idx << logger::endl;
 #endif
 
     // abort if nothign to fetch
@@ -72,7 +72,7 @@ void queue_base::trigger_fetch()
     dma->dma_addr = base + next_idx * desc_len;
     dma->pos = first_pos;
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ":    dma = " << dma << std::endl;
+    log << "    dma = " << dma << logger::endl;
 #endif
     runner->issue_dma(*dma);
 }
@@ -99,7 +99,7 @@ void queue_base::trigger_process()
 
         ctx.state = desc_ctx::DESC_PROCESSING;
 #ifdef DEBUG_QUEUES
-        std::cerr << qname << ": processing desc " << ctx.index << std::endl;
+        log << "processing desc " << ctx.index << logger::endl;
 #endif
         ctx.process();
     }
@@ -122,8 +122,8 @@ void queue_base::trigger_writeback()
         cnt = len - active_first_idx;
 
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ": writing back avail=" << avail << " cnt=" << cnt <<
-        " idx=" << active_first_idx << std::endl;
+    log << "writing back avail=" << avail << " cnt=" << cnt <<
+        " idx=" << active_first_idx << logger::endl;
 #endif
 
     if (cnt == 0)
@@ -141,7 +141,7 @@ void queue_base::trigger_writeback()
 void queue_base::reset()
 {
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ": reset" << std::endl;
+    log << "reset" << logger::endl;
 #endif
 
     enabled = false;
@@ -217,9 +217,9 @@ void queue_base::writeback_done(uint32_t first_pos, uint32_t cnt)
     }
 
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ": written back afi=" << active_first_idx <<
-        " afp=" << active_first_pos << " acnt=" << active_cnt << " pos=" <<
-        first_pos << " cnt=" << cnt << std::endl;
+    log << "written back afi=" << active_first_idx << " afp=" <<
+        active_first_pos << " acnt=" << active_cnt << " pos=" <<
+        first_pos << " cnt=" << cnt << logger::endl;
 #endif
 
     // then start at the beginning and check how many are written back and then
@@ -234,7 +234,7 @@ void queue_base::writeback_done(uint32_t first_pos, uint32_t cnt)
         ctx.state = desc_ctx::DESC_EMPTY;
     }
 #ifdef DEBUG_QUEUES
-    std::cerr << qname << ":    bump_cnt=" << bump_cnt << std::endl;
+    log << "   bump_cnt=" << bump_cnt << logger::endl;
 #endif
 
     active_first_pos = (active_first_pos + bump_cnt) % MAX_ACTIVE_DESCS;
@@ -270,7 +270,7 @@ void queue_base::desc_ctx::prepare()
 void queue_base::desc_ctx::prepared()
 {
 #ifdef DEBUG_QUEUES
-    std::cerr << queue.qname << ": prepared desc " << index << std::endl;
+    queue.log << "prepared desc " << index << logger::endl;
 #endif
     assert(state == DESC_PREPARING);
     state = DESC_PREPARED;
@@ -280,7 +280,7 @@ void queue_base::desc_ctx::prepared()
 void queue_base::desc_ctx::processed()
 {
 #ifdef DEBUG_QUEUES
-    std::cerr << queue.qname << ": processed desc " << index << std::endl;
+    queue.log << "processed desc " << index << logger::endl;
 #endif
     assert(state == DESC_PROCESSING);
     state = DESC_PROCESSED;
@@ -291,7 +291,7 @@ void queue_base::desc_ctx::data_fetch(uint64_t addr, size_t data_len)
 {
     if (data_capacity < data_len) {
 #ifdef DEBUG_QUEUES
-        std::cerr << queue.qname << ": data_fetch allocating" << std::endl;
+        queue.log << "data_fetch allocating" << logger::endl;
 #endif
         if (data_capacity != 0)
             delete[] ((uint8_t *) data);
@@ -305,10 +305,9 @@ void queue_base::desc_ctx::data_fetch(uint64_t addr, size_t data_len)
     dma->dma_addr = addr;
 
 #ifdef DEBUG_QUEUES
-    std::cerr << queue.qname << ": fetching data idx=" << index << " addr=" <<
-        addr << " len=" << data_len << std::endl;
-    std::cerr << queue.qname << ": dma = " << dma << " data=" << data <<
-        std::endl;
+    queue.log << "fetching data idx=" << index << " addr=" << addr << " len=" <<
+        data_len << logger::endl;
+    queue.log << "  dma = " << dma << " data=" << data << logger::endl;
 #endif
     runner->issue_dma(*dma);
 
@@ -323,8 +322,8 @@ void queue_base::desc_ctx::data_write(uint64_t addr, size_t data_len,
         const void *buf)
 {
 #ifdef DEBUG_QUEUES
-    std::cerr << queue.qname << ": data_write(addr=" << addr << " datalen=" <<
-        data_len << ")" << std::endl;
+    queue.log << "data_write(addr=" << addr << " datalen=" << data_len << ")" <<
+        logger::endl;
 #endif
     dma_data_wb *data_dma = new dma_data_wb(*this, data_len);
     data_dma->write = true;
@@ -337,8 +336,8 @@ void queue_base::desc_ctx::data_write(uint64_t addr, size_t data_len,
 void queue_base::desc_ctx::data_written(uint64_t addr, size_t len)
 {
 #ifdef DEBUG_QUEUES
-    std::cerr << queue.qname << ": data_written(addr=" << addr << " datalen=" <<
-        len << ")" << std::endl;
+    queue.log << "data_written(addr=" << addr << " datalen=" << len << ")" <<
+        logger::endl;
 #endif
     processed();
 }
@@ -363,8 +362,7 @@ void queue_base::dma_fetch::done()
         memcpy(ctx.desc, buf + queue.desc_len * i, queue.desc_len);
 
 #ifdef DEBUG_QUEUES
-        std::cerr << ctx.queue.qname << ": preparing desc " << ctx.index <<
-            std::endl;
+        queue.log << "preparing desc " << ctx.index << logger::endl;
 #endif
         ctx.state = desc_ctx::DESC_PREPARING;
         ctx.prepare();

i40e_bm/logger.cc

+#include <iostream>
+
+#include "i40e_bm.h"
+
+using namespace i40e;
+
+extern nicbm::Runner *runner;
+
+logger::logger(const std::string &label_)
+    : label(label_)
+{
+}
+
+logger &logger::operator<<(char c)
+{
+    if (c == endl) {
+        std::cerr << runner->time_ps() << " " << label << ": " << ss.str() <<
+            std::endl;
+    } else {
+        ss << c;
+    }
+    return *this;
+}
+
+logger &logger::operator<<(int32_t i)
+{
+    ss << i;
+    return *this;
+}
+
+logger &logger::operator<<(uint8_t i)
+{
+    ss << (unsigned) i;
+    return *this;
+}
+
+logger &logger::operator<<(uint16_t i)
+{
+    ss << i;
+    return *this;
+}
+
+logger &logger::operator<<(uint32_t i)
+{
+    ss << i;
+    return *this;
+}
+
+logger &logger::operator<<(uint64_t i)
+{
+    ss << i;
+    return *this;
+}
+
+logger &logger::operator<<(bool b)
+{
+    ss << b;
+    return *this;
+}
+
+logger &logger::operator<<(const char *str)
+{
+    ss << str;
+    return *this;
+}
+
+logger &logger::operator<<(void *ptr)
+{
+    ss << ptr;
+    return *this;
+}