[v3] hw/net/imx_fec.c: Convert debug fprintf() to trace event

Signed-off-by: Jean-Christophe Dubois <jcd@tribudubois.net>
---

 v2: fix coding style issues.
 v3: improve tracing code based on feedback
     * change some tracing function names
     * remove unnecessary cast
     * add register index in addition to name

 hw/net/imx_fec.c    | 106 +++++++++++++++++++-------------------------
 hw/net/trace-events |  18 ++++++++
 2 files changed, 63 insertions(+), 61 deletions(-)

On 5/30/20 12:27 PM, Jean-Christophe Dubois wrote:
> Signed-off-by: Jean-Christophe Dubois <jcd@tribudubois.net>
> ---
> 
>  v2: fix coding style issues.
>  v3: improve tracing code based on feedback
>      * change some tracing function names
>      * remove unnecessary cast
>      * add register index in addition to name

Thanks for the changes!

> 
>  hw/net/imx_fec.c    | 106 +++++++++++++++++++-------------------------
>  hw/net/trace-events |  18 ++++++++
>  2 files changed, 63 insertions(+), 61 deletions(-)
> 
> diff --git a/hw/net/imx_fec.c b/hw/net/imx_fec.c
> index 7adcc9df654..eefedc252de 100644
> --- a/hw/net/imx_fec.c
> +++ b/hw/net/imx_fec.c
> @@ -31,34 +31,11 @@
>  #include "qemu/module.h"
>  #include "net/checksum.h"
>  #include "net/eth.h"
> +#include "trace.h"
>  
>  /* For crc32 */
>  #include <zlib.h>
>  
> -#ifndef DEBUG_IMX_FEC
> -#define DEBUG_IMX_FEC 0
> -#endif
> -
> -#define FEC_PRINTF(fmt, args...) \
> -    do { \
> -        if (DEBUG_IMX_FEC) { \
> -            fprintf(stderr, "[%s]%s: " fmt , TYPE_IMX_FEC, \
> -                                             __func__, ##args); \
> -        } \
> -    } while (0)
> -
> -#ifndef DEBUG_IMX_PHY
> -#define DEBUG_IMX_PHY 0
> -#endif
> -
> -#define PHY_PRINTF(fmt, args...) \
> -    do { \
> -        if (DEBUG_IMX_PHY) { \
> -            fprintf(stderr, "[%s.phy]%s: " fmt , TYPE_IMX_FEC, \
> -                                                 __func__, ##args); \
> -        } \
> -    } while (0)
> -
>  #define IMX_MAX_DESC    1024
>  
>  static const char *imx_default_reg_name(IMXFECState *s, uint32_t index)
> @@ -262,43 +239,45 @@ static void imx_eth_update(IMXFECState *s);
>   * For now we don't handle any GPIO/interrupt line, so the OS will
>   * have to poll for the PHY status.
>   */
> -static void phy_update_irq(IMXFECState *s)
> +static void imx_phy_update_irq(IMXFECState *s)
>  {
>      imx_eth_update(s);
>  }
>  
> -static void phy_update_link(IMXFECState *s)
> +static void imx_phy_update_link(IMXFECState *s)
>  {
>      /* Autonegotiation status mirrors link status.  */
>      if (qemu_get_queue(s->nic)->link_down) {
> -        PHY_PRINTF("link is down\n");
> +        trace_imx_phy_update_link("down");
>          s->phy_status &= ~0x0024;
>          s->phy_int |= PHY_INT_DOWN;
>      } else {
> -        PHY_PRINTF("link is up\n");
> +        trace_imx_phy_update_link("up");
>          s->phy_status |= 0x0024;
>          s->phy_int |= PHY_INT_ENERGYON;
>          s->phy_int |= PHY_INT_AUTONEG_COMPLETE;
>      }
> -    phy_update_irq(s);
> +    imx_phy_update_irq(s);
>  }
>  
>  static void imx_eth_set_link(NetClientState *nc)
>  {
> -    phy_update_link(IMX_FEC(qemu_get_nic_opaque(nc)));
> +    imx_phy_update_link(IMX_FEC(qemu_get_nic_opaque(nc)));
>  }
>  
> -static void phy_reset(IMXFECState *s)
> +static void imx_phy_reset(IMXFECState *s)
>  {
> +    trace_imx_phy_reset();
> +
>      s->phy_status = 0x7809;
>      s->phy_control = 0x3000;
>      s->phy_advertise = 0x01e1;
>      s->phy_int_mask = 0;
>      s->phy_int = 0;
> -    phy_update_link(s);
> +    imx_phy_update_link(s);
>  }
>  
> -static uint32_t do_phy_read(IMXFECState *s, int reg)
> +static uint32_t imx_phy_read(IMXFECState *s, int reg)
>  {
>      uint32_t val;
>  
> @@ -332,7 +311,7 @@ static uint32_t do_phy_read(IMXFECState *s, int reg)
>      case 29:    /* Interrupt source.  */
>          val = s->phy_int;
>          s->phy_int = 0;
> -        phy_update_irq(s);
> +        imx_phy_update_irq(s);
>          break;
>      case 30:    /* Interrupt mask */
>          val = s->phy_int_mask;
> @@ -352,14 +331,14 @@ static uint32_t do_phy_read(IMXFECState *s, int reg)
>          break;
>      }
>  
> -    PHY_PRINTF("read 0x%04x @ %d\n", val, reg);
> +    trace_imx_phy_read(val, reg);
>  
>      return val;
>  }
>  
> -static void do_phy_write(IMXFECState *s, int reg, uint32_t val)
> +static void imx_phy_write(IMXFECState *s, int reg, uint32_t val)
>  {
> -    PHY_PRINTF("write 0x%04x @ %d\n", val, reg);
> +    trace_imx_phy_write(val, reg);
>  
>      if (reg > 31) {
>          /* we only advertise one phy */
> @@ -369,7 +348,7 @@ static void do_phy_write(IMXFECState *s, int reg, uint32_t val)
>      switch (reg) {
>      case 0:     /* Basic Control */
>          if (val & 0x8000) {
> -            phy_reset(s);
> +            imx_phy_reset(s);
>          } else {
>              s->phy_control = val & 0x7980;
>              /* Complete autonegotiation immediately.  */
> @@ -383,7 +362,7 @@ static void do_phy_write(IMXFECState *s, int reg, uint32_t val)
>          break;
>      case 30:    /* Interrupt mask */
>          s->phy_int_mask = val & 0xff;
> -        phy_update_irq(s);
> +        imx_phy_update_irq(s);
>          break;
>      case 17:
>      case 18:
> @@ -402,6 +381,8 @@ static void do_phy_write(IMXFECState *s, int reg, uint32_t val)
>  static void imx_fec_read_bd(IMXFECBufDesc *bd, dma_addr_t addr)
>  {
>      dma_memory_read(&address_space_memory, addr, bd, sizeof(*bd));
> +
> +    trace_imx_fec_read_bd(addr, bd->flags, bd->length, bd->data);
>  }
>  
>  static void imx_fec_write_bd(IMXFECBufDesc *bd, dma_addr_t addr)
> @@ -412,6 +393,9 @@ static void imx_fec_write_bd(IMXFECBufDesc *bd, dma_addr_t addr)
>  static void imx_enet_read_bd(IMXENETBufDesc *bd, dma_addr_t addr)
>  {
>      dma_memory_read(&address_space_memory, addr, bd, sizeof(*bd));
> +
> +    trace_imx_enet_read_bd(addr, bd->flags, bd->length, bd->data,
> +                   bd->option, bd->status);
>  }
>  
>  static void imx_enet_write_bd(IMXENETBufDesc *bd, dma_addr_t addr)
> @@ -471,11 +455,11 @@ static void imx_fec_do_tx(IMXFECState *s)
>          int len;
>  
>          imx_fec_read_bd(&bd, addr);
> -        FEC_PRINTF("tx_bd %x flags %04x len %d data %08x\n",
> -                   addr, bd.flags, bd.length, bd.data);
>          if ((bd.flags & ENET_BD_R) == 0) {
> +
>              /* Run out of descriptors to transmit.  */
> -            FEC_PRINTF("tx_bd ran out of descriptors to transmit\n");
> +            trace_imx_eth_tx_bd_busy();
> +
>              break;
>          }
>          len = bd.length;
> @@ -552,11 +536,11 @@ static void imx_enet_do_tx(IMXFECState *s, uint32_t index)
>          int len;
>  
>          imx_enet_read_bd(&bd, addr);
> -        FEC_PRINTF("tx_bd %x flags %04x len %d data %08x option %04x "
> -                   "status %04x\n", addr, bd.flags, bd.length, bd.data,
> -                   bd.option, bd.status);
>          if ((bd.flags & ENET_BD_R) == 0) {
>              /* Run out of descriptors to transmit.  */
> +
> +            trace_imx_eth_tx_bd_busy();
> +
>              break;
>          }
>          len = bd.length;
> @@ -633,7 +617,7 @@ static void imx_eth_enable_rx(IMXFECState *s, bool flush)
>      s->regs[ENET_RDAR] = (bd.flags & ENET_BD_E) ? ENET_RDAR_RDAR : 0;
>  
>      if (!s->regs[ENET_RDAR]) {
> -        FEC_PRINTF("RX buffer full\n");
> +        trace_imx_eth_rx_bd_full();
>      } else if (flush) {
>          qemu_flush_queued_packets(qemu_get_queue(s->nic));
>      }
> @@ -676,7 +660,7 @@ static void imx_eth_reset(DeviceState *d)
>      memset(s->tx_descriptor, 0, sizeof(s->tx_descriptor));
>  
>      /* We also reset the PHY */
> -    phy_reset(s);
> +    imx_phy_reset(s);
>  }
>  
>  static uint32_t imx_default_read(IMXFECState *s, uint32_t index)
> @@ -774,8 +758,7 @@ static uint64_t imx_eth_read(void *opaque, hwaddr offset, unsigned size)
>          break;
>      }
>  
> -    FEC_PRINTF("reg[%s] => 0x%" PRIx32 "\n", imx_eth_reg_name(s, index),
> -                                              value);
> +    trace_imx_eth_read(index, imx_eth_reg_name(s, index), value);
>  
>      return value;
>  }
> @@ -884,8 +867,7 @@ static void imx_eth_write(void *opaque, hwaddr offset, uint64_t value,
>      const bool single_tx_ring = !imx_eth_is_multi_tx_ring(s);
>      uint32_t index = offset >> 2;
>  
> -    FEC_PRINTF("reg[%s] <= 0x%" PRIx32 "\n", imx_eth_reg_name(s, index),
> -                (uint32_t)value);
> +    trace_imx_eth_write(index, imx_eth_reg_name(s, index), value);
>  
>      switch (index) {
>      case ENET_EIR:
> @@ -940,12 +922,12 @@ static void imx_eth_write(void *opaque, hwaddr offset, uint64_t value,
>          if (extract32(value, 29, 1)) {
>              /* This is a read operation */
>              s->regs[ENET_MMFR] = deposit32(s->regs[ENET_MMFR], 0, 16,
> -                                           do_phy_read(s,
> +                                           imx_phy_read(s,
>                                                         extract32(value,
>                                                                   18, 10)));
>          } else {
>              /* This a write operation */
> -            do_phy_write(s, extract32(value, 18, 10), extract32(value, 0, 16));
> +            imx_phy_write(s, extract32(value, 18, 10), extract32(value, 0, 16));
>          }
>          /* raise the interrupt as the PHY operation is done */
>          s->regs[ENET_EIR] |= ENET_INT_MII;
> @@ -1053,8 +1035,6 @@ static bool imx_eth_can_receive(NetClientState *nc)
>  {
>      IMXFECState *s = IMX_FEC(qemu_get_nic_opaque(nc));
>  
> -    FEC_PRINTF("\n");
> -
>      return !!s->regs[ENET_RDAR];
>  }
>  
> @@ -1071,7 +1051,7 @@ static ssize_t imx_fec_receive(NetClientState *nc, const uint8_t *buf,
>      unsigned int buf_len;
>      size_t size = len;
>  
> -    FEC_PRINTF("len %d\n", (int)size);
> +    trace_imx_fec_receive(size);
>  
>      if (!s->regs[ENET_RDAR]) {
>          qemu_log_mask(LOG_GUEST_ERROR, "[%s]%s: Unexpected packet\n",
> @@ -1113,7 +1093,7 @@ static ssize_t imx_fec_receive(NetClientState *nc, const uint8_t *buf,
>          bd.length = buf_len;
>          size -= buf_len;
>  
> -        FEC_PRINTF("rx_bd 0x%x length %d\n", addr, bd.length);
> +        trace_imx_fec_receive_len(addr, bd.length);
>  
>          /* The last 4 bytes are the CRC.  */
>          if (size < 4) {
> @@ -1131,7 +1111,9 @@ static ssize_t imx_fec_receive(NetClientState *nc, const uint8_t *buf,
>          if (size == 0) {
>              /* Last buffer in frame.  */
>              bd.flags |= flags | ENET_BD_L;
> -            FEC_PRINTF("rx frame flags %04x\n", bd.flags);
> +
> +            trace_imx_fec_receive_last(bd.flags);
> +
>              s->regs[ENET_EIR] |= ENET_INT_RXF;
>          } else {
>              s->regs[ENET_EIR] |= ENET_INT_RXB;
> @@ -1164,7 +1146,7 @@ static ssize_t imx_enet_receive(NetClientState *nc, const uint8_t *buf,
>      size_t size = len;
>      bool shift16 = s->regs[ENET_RACC] & ENET_RACC_SHIFT16;
>  
> -    FEC_PRINTF("len %d\n", (int)size);
> +    trace_imx_enet_receive(size);
>  
>      if (!s->regs[ENET_RDAR]) {
>          qemu_log_mask(LOG_GUEST_ERROR, "[%s]%s: Unexpected packet\n",
> @@ -1210,7 +1192,7 @@ static ssize_t imx_enet_receive(NetClientState *nc, const uint8_t *buf,
>          bd.length = buf_len;
>          size -= buf_len;
>  
> -        FEC_PRINTF("rx_bd 0x%x length %d\n", addr, bd.length);
> +        trace_imx_enet_receive_len(addr, bd.length);
>  
>          /* The last 4 bytes are the CRC.  */
>          if (size < 4) {
> @@ -1246,7 +1228,9 @@ static ssize_t imx_enet_receive(NetClientState *nc, const uint8_t *buf,
>          if (size == 0) {
>              /* Last buffer in frame.  */
>              bd.flags |= flags | ENET_BD_L;
> -            FEC_PRINTF("rx frame flags %04x\n", bd.flags);
> +
> +            trace_imx_enet_receive_last(bd.flags);
> +
>              /* Indicate that we've updated the last buffer descriptor. */
>              bd.last_buffer = ENET_BD_BDU;
>              if (bd.option & ENET_BD_RX_INT) {
> diff --git a/hw/net/trace-events b/hw/net/trace-events
> index e18f883cfd4..430ee36b257 100644
> --- a/hw/net/trace-events
> +++ b/hw/net/trace-events
> @@ -408,3 +408,21 @@ i82596_receive_packet(size_t sz) "len=%zu"
>  i82596_new_mac(const char *id_with_mac) "New MAC for: %s"
>  i82596_set_multicast(uint16_t count) "Added %d multicast entries"
>  i82596_channel_attention(void *s) "%p: Received CHANNEL ATTENTION"
> +
> +# imx_fec.c
> +imx_phy_read(uint32_t val, int reg) "0x%04x <= reg[%d]"
> +imx_phy_write(uint32_t val, int reg) "0x%04x => reg[%d]"
> +imx_phy_update_link(const char *s) "%s"
> +imx_phy_reset(void) ""
> +imx_fec_read_bd(uint64_t addr, int flags, int len, int data) "tx_bd 0x%lx flags 0x%04x len %d data 0x%08x"
> +imx_enet_read_bd(uint64_t addr, int flags, int len, int data, int options, int status) "tx_bd 0x%lx flags 0x%04x len %d data 0x%08x option 0x%04x status 0x%04x"
> +imx_eth_tx_bd_busy(void) "tx_bd ran out of descriptors to transmit"
> +imx_eth_rx_bd_full(void) "RX buffer is full"
> +imx_eth_read(int reg, const char *reg_name, uint32_t value) "reg[%d:%s] => 0x%08x"
> +imx_eth_write(int reg, const char *reg_name, uint64_t value) "reg[%d:%s] <= 0x%08lx"
> +imx_fec_receive(size_t size) "len %ld"
> +imx_fec_receive_len(uint64_t addr, int len) "rx_bd 0x%lx length %d"
> +imx_fec_receive_last(int last) "rx frame flags 0x%04x"
> +imx_enet_receive(size_t size) "len %ld"
> +imx_enet_receive_len(uint64_t addr, int len) "rx_bd 0x%lx length %d"
> +imx_enet_receive_last(int last) "rx frame flags 0x%04x"
> 

Format string is incorrect on 32-bit host:

  CC      hw/net/imx_fec.o
In file included from hw/net/imx_fec.c:34:0:
hw/net/trace.h: In function '_nocheck__trace_imx_fec_read_bd':
hw/net/trace.h:9208:18: error: format '%lx' expects argument of type
'long unsigned int', but argument 5 has type 'uint64_t {aka long long
unsigned int}' [-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_fec_read_bd " "tx_bd 0x%lx flags
0x%04x len %d data 0x%08x" "\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_enet_read_bd':
hw/net/trace.h:9231:18: error: format '%lx' expects argument of type
'long unsigned int', but argument 5 has type 'uint64_t {aka long long
unsigned int}' [-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_enet_read_bd " "tx_bd 0x%lx flags
0x%04x len %d data 0x%08x option 0x%04x status 0x%04x" "\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_eth_write':
hw/net/trace.h:9323:18: error: format '%lx' expects argument of type
'long unsigned int', but argument 7 has type 'uint64_t {aka long long
unsigned int}' [-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_eth_write " "reg[%d:%s] <= 0x%08lx"
"\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_fec_receive':
hw/net/trace.h:9346:18: error: format '%ld' expects argument of type
'long int', but argument 5 has type 'size_t {aka unsigned int}'
[-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_fec_receive " "len %ld" "\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_fec_receive_len':
hw/net/trace.h:9369:18: error: format '%lx' expects argument of type
'long unsigned int', but argument 5 has type 'uint64_t {aka long long
unsigned int}' [-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_fec_receive_len " "rx_bd 0x%lx
length %d" "\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_enet_receive':
hw/net/trace.h:9415:18: error: format '%ld' expects argument of type
'long int', but argument 5 has type 'size_t {aka unsigned int}'
[-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_enet_receive " "len %ld" "\n",
                  ^
hw/net/trace.h: In function '_nocheck__trace_imx_enet_receive_len':
hw/net/trace.h:9438:18: error: format '%lx' expects argument of type
'long unsigned int', but argument 5 has type 'uint64_t {aka long long
unsigned int}' [-Werror=format=]
         qemu_log("%d@%zu.%06zu:imx_enet_receive_len " "rx_bd 0x%lx
length %d" "\n",
                  ^

This build using:

-- >8 --
--- a/hw/net/trace-events
+++ b/hw/net/trace-events
@@ -410,19 +410,19 @@ i82596_set_multicast(uint16_t count) "Added %d
multicast entries"
 i82596_channel_attention(void *s) "%p: Received CHANNEL ATTENTION"

 # imx_fec.c
-imx_phy_read(uint32_t val, int reg) "0x%04x <= reg[%d]"
-imx_phy_write(uint32_t val, int reg) "0x%04x => reg[%d]"
+imx_phy_read(uint32_t val, int reg) "0x%04"PRIx32" <= reg[%d]"
+imx_phy_write(uint32_t val, int reg) "0x%04"PRIx32" => reg[%d]"
 imx_phy_update_link(const char *s) "%s"
 imx_phy_reset(void) ""
-imx_fec_read_bd(uint64_t addr, int flags, int len, int data) "tx_bd
0x%lx flags 0x%04x len %d data 0x%08x"
-imx_enet_read_bd(uint64_t addr, int flags, int len, int data, int
options, int status) "tx_bd 0x%lx flags 0x%04x len %d data 0x%08x option
0x%04x status 0x%04x"
+imx_fec_read_bd(uint64_t addr, int flags, int len, int data) "tx_bd
0x%"PRIx64" flags 0x%04x len %d data 0x%08x"
+imx_enet_read_bd(uint64_t addr, int flags, int len, int data, int
options, int status) "tx_bd 0x%"PRIx64" flags 0x%04x len %d data 0x%08x
option 0x%04x status 0x%04x"
 imx_eth_tx_bd_busy(void) "tx_bd ran out of descriptors to transmit"
 imx_eth_rx_bd_full(void) "RX buffer is full"
-imx_eth_read(int reg, const char *reg_name, uint32_t value) "reg[%d:%s]
=> 0x%08x"
-imx_eth_write(int reg, const char *reg_name, uint64_t value)
"reg[%d:%s] <= 0x%08lx"
-imx_fec_receive(size_t size) "len %ld"
-imx_fec_receive_len(uint64_t addr, int len) "rx_bd 0x%lx length %d"
+imx_eth_read(int reg, const char *reg_name, uint32_t value) "reg[%d:%s]
=> 0x%08"PRIx32
+imx_eth_write(int reg, const char *reg_name, uint64_t value)
"reg[%d:%s] <= 0x%08"PRIx64
+imx_fec_receive(size_t size) "len %zu"
+imx_fec_receive_len(uint64_t addr, int len) "rx_bd 0x%"PRIx64" length %d"
 imx_fec_receive_last(int last) "rx frame flags 0x%04x"
-imx_enet_receive(size_t size) "len %ld"
-imx_enet_receive_len(uint64_t addr, int len) "rx_bd 0x%lx length %d"
+imx_enet_receive(size_t size) "len %zu"
+imx_enet_receive_len(uint64_t addr, int len) "rx_bd 0x%"PRIx64" length %d"
 imx_enet_receive_last(int last) "rx frame flags 0x%04x"
---

So:
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Tested-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

I changed
 "x" -> PRIx32
 "lx" -> PRIx64
 "ld" -> "zu" for size_t type.

Since the patch is already done locally, I'll simply post it as v4.

Regards,

Phil.