[PATCH net-next] ibmvnic: Increase driver logging
Improve the ibmvnic driver's logging capabilities by providing more informational messages to track driver operations, facilitating first-pass debug. Signed-off-by: Thomas Falcon --- drivers/net/ethernet/ibm/ibmvnic.c | 76 -- 1 file changed, 62 insertions(+), 14 deletions(-) diff --git a/drivers/net/ethernet/ibm/ibmvnic.c b/drivers/net/ethernet/ibm/ibmvnic.c index 0fd7eae25fe9..7382f11872fc 100644 --- a/drivers/net/ethernet/ibm/ibmvnic.c +++ b/drivers/net/ethernet/ibm/ibmvnic.c @@ -561,6 +561,7 @@ static int init_rx_pools(struct net_device *netdev) u64 *size_array; int i, j; + netdev_info(netdev, "Initializing RX queue buffer pools.\n"); rxadd_subcrqs = be32_to_cpu(adapter->login_rsp_buf->num_rxadd_subcrqs); size_array = (u64 *)((u8 *)(adapter->login_rsp_buf) + @@ -618,6 +619,7 @@ static int init_rx_pools(struct net_device *netdev) rx_pool->next_alloc = 0; rx_pool->next_free = 0; } + netdev_info(netdev, "RX queue buffer pools allocated successfully.\n"); return 0; } @@ -738,6 +740,7 @@ static int init_tx_pools(struct net_device *netdev) int tx_subcrqs; int i, rc; + netdev_info(netdev, "Initializing TX queue buffer pools.\n"); tx_subcrqs = be32_to_cpu(adapter->login_rsp_buf->num_txsubm_subcrqs); adapter->tx_pool = kcalloc(tx_subcrqs, sizeof(struct ibmvnic_tx_pool), GFP_KERNEL); @@ -768,7 +771,7 @@ static int init_tx_pools(struct net_device *netdev) return rc; } } - + netdev_info(netdev, "TX queue buffer pools allocated successfully.\n"); return 0; } @@ -792,6 +795,7 @@ static void ibmvnic_napi_disable(struct ibmvnic_adapter *adapter) if (!adapter->napi_enabled) return; + netdev_info(adapter->netdev, "Disable all NAPI threads.\n"); for (i = 0; i < adapter->req_rx_queues; i++) { netdev_dbg(adapter->netdev, "Disabling napi[%d]\n", i); napi_disable(&adapter->napi[i]); @@ -910,12 +914,14 @@ static int ibmvnic_login(struct net_device *netdev) return -1; } } else if (adapter->init_done_rc) { - netdev_warn(netdev, "Adapter login failed\n"); + netdev_warn(netdev, "Adapter login failed, rc = %d\n", + adapter->init_done_rc); return -1; } } while (retry); __ibmvnic_set_mac(netdev, adapter->mac_addr); + netdev_info(netdev, "Adapter login success!\n"); return 0; } @@ -934,6 +940,7 @@ static void release_login_rsp_buffer(struct ibmvnic_adapter *adapter) static void release_resources(struct ibmvnic_adapter *adapter) { + netdev_info(adapter->netdev, "Releasing VNIC client device memory structures.\n"); release_vpd_data(adapter); release_tx_pools(adapter); @@ -941,6 +948,7 @@ static void release_resources(struct ibmvnic_adapter *adapter) release_napi(adapter); release_login_rsp_buffer(adapter); + netdev_info(adapter->netdev, "VNIC client device memory released.\n"); } static int set_link_state(struct ibmvnic_adapter *adapter, u8 link_state) @@ -964,7 +972,7 @@ static int set_link_state(struct ibmvnic_adapter *adapter, u8 link_state) reinit_completion(&adapter->init_done); rc = ibmvnic_send_crq(adapter, &crq); if (rc) { - netdev_err(netdev, "Failed to set link state\n"); + netdev_err(netdev, "Failed to set link state, rc = %d\n", rc); return rc; } @@ -1098,6 +1106,8 @@ static int init_resources(struct ibmvnic_adapter *adapter) struct net_device *netdev = adapter->netdev; int rc; + netdev_info(netdev, "Allocate device resources.\n"); + rc = set_real_num_queues(netdev); if (rc) return rc; @@ -1126,7 +1136,11 @@ static int init_resources(struct ibmvnic_adapter *adapter) return rc; rc = init_tx_pools(netdev); - return rc; + if (rc) + return rc; + + netdev_info(netdev, "Device resources allocated.\n"); + return 0; } static int __ibmvnic_open(struct net_device *netdev) @@ -1136,9 +1150,10 @@ static int __ibmvnic_open(struct net_device *netdev) int i, rc; adapter->state = VNIC_OPENING; + netdev_info(netdev, "Allocating RX buffer pools and enable NAPI structures.\n"); replenish_pools(adapter); ibmvnic_napi_enable(adapter); - + netdev_info(netdev, "Activating RX and TX interrupt lines.\n"); /* We're ready to receive frames, enable the sub-crq interrupts and * set the logical link stat
Re: [PATCH net-next] ibmvnic: Increase driver logging
On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: > free_netdev(netdev); > dev_set_drvdata(&dev->dev, NULL); > + netdev_info(netdev, "VNIC client device has been successfully > removed.\n"); A step too far, perhaps. In general this patch looks a little questionable IMHO, this amount of logging output is not commonly seen in drivers. All the the info messages are just static text, not even carrying any extra information. In an era of ftrace, and bpftrace, do we really need this?
Re: [PATCH net-next] ibmvnic: Increase driver logging
From: Jakub Kicinski Date: Wed, 15 Jul 2020 17:06:32 -0700 > On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: >> free_netdev(netdev); >> dev_set_drvdata(&dev->dev, NULL); >> +netdev_info(netdev, "VNIC client device has been successfully >> removed.\n"); > > A step too far, perhaps. > > In general this patch looks a little questionable IMHO, this amount of > logging output is not commonly seen in drivers. All the the info > messages are just static text, not even carrying any extra information. > In an era of ftrace, and bpftrace, do we really need this? Agreed, this is too much. This is debugging, and thus suitable for tracing facilities, at best.
Re: [PATCH net-next] ibmvnic: Increase driver logging
On 7/15/20 8:29 PM, David Miller wrote: From: Jakub Kicinski Date: Wed, 15 Jul 2020 17:06:32 -0700 On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: free_netdev(netdev); dev_set_drvdata(&dev->dev, NULL); + netdev_info(netdev, "VNIC client device has been successfully removed.\n"); A step too far, perhaps. In general this patch looks a little questionable IMHO, this amount of logging output is not commonly seen in drivers. All the the info messages are just static text, not even carrying any extra information. In an era of ftrace, and bpftrace, do we really need this? Agreed, this is too much. This is debugging, and thus suitable for tracing facilities, at best. Thanks for your feedback. I see now that I was overly aggressive with this patch to be sure, but it would help with narrowing down problems at a first glance, should they arise. The driver in its current state logs very little of what is it doing without the use of additional debugging or tracing facilities. Would it be worth it to pursue a less aggressive version or would that be dead on arrival? What are acceptable driver operations to log at this level? Thanks, Tom
Re: [PATCH net-next] ibmvnic: Increase driver logging
On Thu, Jul 16, 2020 at 10:59:58AM -0500, Thomas Falcon wrote: > > On 7/15/20 8:29 PM, David Miller wrote: > > From: Jakub Kicinski > > Date: Wed, 15 Jul 2020 17:06:32 -0700 > > > > > On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: > > > > free_netdev(netdev); > > > > dev_set_drvdata(&dev->dev, NULL); > > > > + netdev_info(netdev, "VNIC client device has been successfully > > > > removed.\n"); > > > A step too far, perhaps. > > > > > > In general this patch looks a little questionable IMHO, this amount of > > > logging output is not commonly seen in drivers. All the the info > > > messages are just static text, not even carrying any extra information. > > > In an era of ftrace, and bpftrace, do we really need this? > > Agreed, this is too much. This is debugging, and thus suitable for tracing > > facilities, at best. > > Thanks for your feedback. I see now that I was overly aggressive with this > patch to be sure, but it would help with narrowing down problems at a first > glance, should they arise. The driver in its current state logs very little > of what is it doing without the use of additional debugging or tracing > facilities. Would it be worth it to pursue a less aggressive version or > would that be dead on arrival? What are acceptable driver operations to log > at this level? Also would it be advisable to add the messages as pr_dbg to be enabled on demand? Thanks Michal
Re: [PATCH net-next] ibmvnic: Increase driver logging
On Thu, 16 Jul 2020 18:07:37 +0200 Michal Suchánek wrote: > On Thu, Jul 16, 2020 at 10:59:58AM -0500, Thomas Falcon wrote: > > On 7/15/20 8:29 PM, David Miller wrote: > > > From: Jakub Kicinski > > > Date: Wed, 15 Jul 2020 17:06:32 -0700 > > > > > > > On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: > > > > > free_netdev(netdev); > > > > > dev_set_drvdata(&dev->dev, NULL); > > > > > + netdev_info(netdev, "VNIC client device has been successfully > > > > > removed.\n"); > > > > A step too far, perhaps. > > > > > > > > In general this patch looks a little questionable IMHO, this amount of > > > > logging output is not commonly seen in drivers. All the the info > > > > messages are just static text, not even carrying any extra information. > > > > In an era of ftrace, and bpftrace, do we really need this? > > > Agreed, this is too much. This is debugging, and thus suitable for > > > tracing > > > facilities, at best. > > > > Thanks for your feedback. I see now that I was overly aggressive with this > > patch to be sure, but it would help with narrowing down problems at a first > > glance, should they arise. The driver in its current state logs very little > > of what is it doing without the use of additional debugging or tracing > > facilities. Would it be worth it to pursue a less aggressive version or > > would that be dead on arrival? What are acceptable driver operations to log > > at this level? Sadly it's much more of an art than hard science. Most networking drivers will print identifying information when they probe the device and then only about major config changes or when link comes up or goes down. And obviously when anything unexpected, like an error happens, that's key. You seem to be adding start / end information for each driver init / deinit stage. I'd say try to focus on the actual errors you're trying to catch. > Also would it be advisable to add the messages as pr_dbg to be enabled on > demand? I personally have had a pretty poor experience with pr_debug() because CONFIG_DYNAMIC_DEBUG is not always enabled. Since you're just printing static text there shouldn't be much difference between pr_debug and ftrace and/or bpftrace, honestly. Again, slightly hard to advise not knowing what you're trying to catch.
Re: [PATCH net-next] ibmvnic: Increase driver logging
On Thu, 16 Jul 2020 13:22:00 -0700 Jakub Kicinski wrote: > On Thu, 16 Jul 2020 18:07:37 +0200 Michal Suchánek wrote: > > On Thu, Jul 16, 2020 at 10:59:58AM -0500, Thomas Falcon wrote: > > > On 7/15/20 8:29 PM, David Miller wrote: > > > > From: Jakub Kicinski > > > > Date: Wed, 15 Jul 2020 17:06:32 -0700 > > > > > > > > > On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote: > > > > > > free_netdev(netdev); > > > > > > dev_set_drvdata(&dev->dev, NULL); > > > > > > + netdev_info(netdev, "VNIC client device has been successfully > > > > > > removed.\n"); > > > > > A step too far, perhaps. > > > > > > > > > > In general this patch looks a little questionable IMHO, this amount of > > > > > logging output is not commonly seen in drivers. All the the info > > > > > messages are just static text, not even carrying any extra > > > > > information. > > > > > In an era of ftrace, and bpftrace, do we really need this? > > > > Agreed, this is too much. This is debugging, and thus suitable for > > > > tracing > > > > facilities, at best. > > > > > > Thanks for your feedback. I see now that I was overly aggressive with this > > > patch to be sure, but it would help with narrowing down problems at a > > > first > > > glance, should they arise. The driver in its current state logs very > > > little > > > of what is it doing without the use of additional debugging or tracing > > > facilities. Would it be worth it to pursue a less aggressive version or > > > would that be dead on arrival? What are acceptable driver operations to > > > log > > > at this level? > > Sadly it's much more of an art than hard science. Most networking > drivers will print identifying information when they probe the device > and then only about major config changes or when link comes up or goes > down. And obviously when anything unexpected, like an error happens, > that's key. > > You seem to be adding start / end information for each driver init / > deinit stage. I'd say try to focus on the actual errors you're trying > to catch. > > > Also would it be advisable to add the messages as pr_dbg to be enabled on > > demand? > > I personally have had a pretty poor experience with pr_debug() because > CONFIG_DYNAMIC_DEBUG is not always enabled. Since you're just printing > static text there shouldn't be much difference between pr_debug and > ftrace and/or bpftrace, honestly. > > Again, slightly hard to advise not knowing what you're trying to catch. Linux drivers in general are far too noisy. In production it is not uncommon to set kernel to suppress all info messages.