Re: [PATCH net-next] ibmvnic: Increase driver logging

2020-07-16 Thread Stephen Hemminger 
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, 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.

Re: [PATCH net-next] ibmvnic: Increase driver logging

2020-07-16 Thread Jakub Kicinski 
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, 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

2020-07-16 Thread Michal Suchánek 
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, 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

2020-07-16 Thread Thomas Falcon 



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

2020-07-15 Thread David Miller 
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, 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

2020-07-15 Thread Jakub Kicinski 
On Wed, 15 Jul 2020 18:51:55 -0500 Thomas Falcon wrote:
>   free_netdev(netdev);
>   dev_set_drvdata(>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?

[PATCH net-next] ibmvnic: Increase driver logging

2020-07-15 Thread Thomas Falcon 
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(>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(>init_done);
rc = ibmvnic_send_crq(adapter, );
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 state to up
 */