diff mbox series

[04/12] usb: xhci: remove excessive isoc frame debug message spam

Message ID 20240905143300.1959279-5-mathias.nyman@linux.intel.com
State New
Headers show
Series xhci features for usb-next | expand

Commit Message

Mathias Nyman Sept. 5, 2024, 2:32 p.m. UTC 
From: Niklas Neronin <niklas.neronin@linux.intel.com>

The removed debug messages trigger each time an isoc frame is handled.
In case of an error, a dedicated debug message exists.

For example, a 60fps USB camera will trigger the debug message every 0.6s.

Signed-off-by: Niklas Neronin <niklas.neronin@linux.intel.com>
Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
---
 drivers/usb/host/xhci-ring.c | 4 ----
 1 file changed, 4 deletions(-)

Comments

Thinh Nguyen Sept. 5, 2024, 9:30 p.m. UTC | #1 
On Thu, Sep 05, 2024, Mathias Nyman wrote:
> From: Niklas Neronin <niklas.neronin@linux.intel.com>
> 
> The removed debug messages trigger each time an isoc frame is handled.
> In case of an error, a dedicated debug message exists.
> 
> For example, a 60fps USB camera will trigger the debug message every 0.6s.
> 
> Signed-off-by: Niklas Neronin <niklas.neronin@linux.intel.com>
> Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
> ---
>  drivers/usb/host/xhci-ring.c | 4 ----
>  1 file changed, 4 deletions(-)
> 
> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> index 4ea2c3e072a9..e1c9838084bf 100644
> --- a/drivers/usb/host/xhci-ring.c
> +++ b/drivers/usb/host/xhci-ring.c
> @@ -3941,10 +3941,6 @@ static int xhci_get_isoc_frame_id(struct xhci_hcd *xhci,
>  	start_frame_id = (start_frame_id >> 3) & 0x7ff;
>  	end_frame_id = (end_frame_id >> 3) & 0x7ff;
>  
> -	xhci_dbg(xhci, "%s: index %d, reg 0x%x start_frame_id 0x%x, end_frame_id 0x%x, start_frame 0x%x\n",
> -		 __func__, index, readl(&xhci->run_regs->microframe_index),
> -		 start_frame_id, end_frame_id, start_frame);
> -
>  	if (start_frame_id < end_frame_id) {
>  		if (start_frame > end_frame_id ||
>  				start_frame < start_frame_id)
> -- 
> 2.25.1
> 

Please capture this info in the tracepoint instead. Otherwise we have no
idea if the isoc is scheduled as SIA or CFI. If it's CFI, I want to know
the start frame value. Currently, I don't think you're decoding this in
the TRB tracepoints.

BR,
Thinh
Mathias Nyman Sept. 6, 2024, 1:27 p.m. UTC | #2 
On 6.9.2024 0.30, Thinh Nguyen wrote:
> On Thu, Sep 05, 2024, Mathias Nyman wrote:
>> From: Niklas Neronin <niklas.neronin@linux.intel.com>
>>
>> The removed debug messages trigger each time an isoc frame is handled.
>> In case of an error, a dedicated debug message exists.
>>
>> For example, a 60fps USB camera will trigger the debug message every 0.6s.
>>
>> Signed-off-by: Niklas Neronin <niklas.neronin@linux.intel.com>
>> Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
>> ---
>>   drivers/usb/host/xhci-ring.c | 4 ----
>>   1 file changed, 4 deletions(-)
>>
>> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
>> index 4ea2c3e072a9..e1c9838084bf 100644
>> --- a/drivers/usb/host/xhci-ring.c
>> +++ b/drivers/usb/host/xhci-ring.c
>> @@ -3941,10 +3941,6 @@ static int xhci_get_isoc_frame_id(struct xhci_hcd *xhci,
>>   	start_frame_id = (start_frame_id >> 3) & 0x7ff;
>>   	end_frame_id = (end_frame_id >> 3) & 0x7ff;
>>   
>> -	xhci_dbg(xhci, "%s: index %d, reg 0x%x start_frame_id 0x%x, end_frame_id 0x%x, start_frame 0x%x\n",
>> -		 __func__, index, readl(&xhci->run_regs->microframe_index),
>> -		 start_frame_id, end_frame_id, start_frame);
>> -
>>   	if (start_frame_id < end_frame_id) {
>>   		if (start_frame > end_frame_id ||
>>   				start_frame < start_frame_id)
>> -- 
>> 2.25.1
>>
> 
> Please capture this info in the tracepoint instead. Otherwise we have no
> idea if the isoc is scheduled as SIA or CFI. If it's CFI, I want to know
> the start frame value. Currently, I don't think you're decoding this in
> the TRB tracepoints.

Good point

Added TBC, TLBPC, frame_id, as SIA enabled 'S' or disabled 's' flag to Isoch TRB tracing.
76.383778: xhci_queue_trb: ISOC: Buffer 0000000118dfa000 length 3 TD size/TBC 0 intr 0 type 'Isoch' TBC 0 TLBPC 0 frame_id 610 flags s:b:i:I:c:s:I:e:C

code:

diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index 1f6ca0231c84..48b643ae8a40 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -1023,9 +1023,6 @@ enum xhci_setup_dev {
  /* Interrupter Target - which MSI-X vector to target the completion event at */
  #define TRB_INTR_TARGET(p)     (((p) & 0x3ff) << 22)
  #define GET_INTR_TARGET(p)     (((p) >> 22) & 0x3ff)
-/* Total burst count field, Rsvdz on xhci 1.1 with Extended TBC enabled (ETE) */
-#define TRB_TBC(p)             (((p) & 0x3) << 7)
-#define TRB_TLBPC(p)           (((p) & 0xf) << 16)
  
  /* Cycle bit - indicates TRB ownership by HC or HCD */
  #define TRB_CYCLE              (1<<0)
@@ -1059,6 +1056,12 @@ enum xhci_setup_dev {
  /* Isochronous TRB specific fields */
  #define TRB_SIA                        (1<<31)
  #define TRB_FRAME_ID(p)                (((p) & 0x7ff) << 20)
+#define GET_FRAME_ID(p)                (((p) >> 20) & 0x7ff)
+/* Total burst count field, Rsvdz on xhci 1.1 with Extended TBC enabled (ETE) */
+#define TRB_TBC(p)             (((p) & 0x3) << 7)
+#define GET_TBC(p)             (((p) >> 7) & 0x3)
+#define TRB_TLBPC(p)           (((p) & 0xf) << 16)
+#define GET_TLBPC(p)           (((p) >> 16) & 0xf)
  
  /* TRB cache size for xHC with TRB cache */
  #define TRB_CACHE_SIZE_HS      8
@@ -2068,7 +2071,6 @@ static inline const char *xhci_decode_trb(char *str, size_t size,
                                 field3 & TRB_CYCLE ? 'C' : 'c');
                 break;
         case TRB_NORMAL:
-       case TRB_ISOC:
         case TRB_EVENT_DATA:
         case TRB_TR_NOOP:
                 snprintf(str, size,
@@ -2085,7 +2087,25 @@ static inline const char *xhci_decode_trb(char *str, size_t size,
                         field3 & TRB_ENT ? 'E' : 'e',
                         field3 & TRB_CYCLE ? 'C' : 'c');
                 break;
-
+       case TRB_ISOC:
+               snprintf(str, size,
+                       "Buffer %08x%08x length %d TD size/TBC %d intr %d type '%s' TBC %u TLBPC %u frame_id %u flags %c:%c:%c:%c:%c:%c:%c:%c:%c",
+                       field1, field0, TRB_LEN(field2), GET_TD_SIZE(field2),
+                       GET_INTR_TARGET(field2),
+                       xhci_trb_type_string(type),
+                       GET_TBC(field3),
+                       GET_TLBPC(field3),
+                       GET_FRAME_ID(field3),
+                       field3 & TRB_SIA ? 'S' : 's',
+                       field3 & TRB_BEI ? 'B' : 'b',
+                       field3 & TRB_IDT ? 'I' : 'i',
+                       field3 & TRB_IOC ? 'I' : 'i',
+                       field3 & TRB_CHAIN ? 'C' : 'c',
+                       field3 & TRB_NO_SNOOP ? 'S' : 's',
+                       field3 & TRB_ISP ? 'I' : 'i',
+                       field3 & TRB_ENT ? 'E' : 'e',
+                       field3 & TRB_CYCLE ? 'C' : 'c');
+               break;



Does this look good to you?

Patch on top of my for-usb-next branch:
https://git.kernel.org/pub/scm/linux/kernel/git/mnyman/xhci.git/log/?h=for-usb-next

Thanks
Mathias
Thinh Nguyen Sept. 7, 2024, 12:41 a.m. UTC | #3 
On Fri, Sep 06, 2024, Mathias Nyman wrote:
> On 6.9.2024 0.30, Thinh Nguyen wrote:
> > On Thu, Sep 05, 2024, Mathias Nyman wrote:
> > > From: Niklas Neronin <niklas.neronin@linux.intel.com>
> > > 
> > > The removed debug messages trigger each time an isoc frame is handled.
> > > In case of an error, a dedicated debug message exists.
> > > 
> > > For example, a 60fps USB camera will trigger the debug message every 0.6s.
> > > 
> > > Signed-off-by: Niklas Neronin <niklas.neronin@linux.intel.com>
> > > Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
> > > ---
> > >   drivers/usb/host/xhci-ring.c | 4 ----
> > >   1 file changed, 4 deletions(-)
> > > 
> > > diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> > > index 4ea2c3e072a9..e1c9838084bf 100644
> > > --- a/drivers/usb/host/xhci-ring.c
> > > +++ b/drivers/usb/host/xhci-ring.c
> > > @@ -3941,10 +3941,6 @@ static int xhci_get_isoc_frame_id(struct xhci_hcd *xhci,
> > >   	start_frame_id = (start_frame_id >> 3) & 0x7ff;
> > >   	end_frame_id = (end_frame_id >> 3) & 0x7ff;
> > > -	xhci_dbg(xhci, "%s: index %d, reg 0x%x start_frame_id 0x%x, end_frame_id 0x%x, start_frame 0x%x\n",
> > > -		 __func__, index, readl(&xhci->run_regs->microframe_index),
> > > -		 start_frame_id, end_frame_id, start_frame);
> > > -
> > >   	if (start_frame_id < end_frame_id) {
> > >   		if (start_frame > end_frame_id ||
> > >   				start_frame < start_frame_id)
> > > -- 
> > > 2.25.1
> > > 
> > 
> > Please capture this info in the tracepoint instead. Otherwise we have no
> > idea if the isoc is scheduled as SIA or CFI. If it's CFI, I want to know
> > the start frame value. Currently, I don't think you're decoding this in
> > the TRB tracepoints.
> 
> Good point
> 
> Added TBC, TLBPC, frame_id, as SIA enabled 'S' or disabled 's' flag to Isoch TRB tracing.
> 76.383778: xhci_queue_trb: ISOC: Buffer 0000000118dfa000 length 3 TD size/TBC 0 intr 0 type 'Isoch' TBC 0 TLBPC 0 frame_id 610 flags s:b:i:I:c:s:I:e:C
> 
> code:
> 
> diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
> index 1f6ca0231c84..48b643ae8a40 100644
> --- a/drivers/usb/host/xhci.h
> +++ b/drivers/usb/host/xhci.h
> @@ -1023,9 +1023,6 @@ enum xhci_setup_dev {
>  /* Interrupter Target - which MSI-X vector to target the completion event at */
>  #define TRB_INTR_TARGET(p)     (((p) & 0x3ff) << 22)
>  #define GET_INTR_TARGET(p)     (((p) >> 22) & 0x3ff)
> -/* Total burst count field, Rsvdz on xhci 1.1 with Extended TBC enabled (ETE) */
> -#define TRB_TBC(p)             (((p) & 0x3) << 7)
> -#define TRB_TLBPC(p)           (((p) & 0xf) << 16)
>  /* Cycle bit - indicates TRB ownership by HC or HCD */
>  #define TRB_CYCLE              (1<<0)
> @@ -1059,6 +1056,12 @@ enum xhci_setup_dev {
>  /* Isochronous TRB specific fields */
>  #define TRB_SIA                        (1<<31)
>  #define TRB_FRAME_ID(p)                (((p) & 0x7ff) << 20)
> +#define GET_FRAME_ID(p)                (((p) >> 20) & 0x7ff)
> +/* Total burst count field, Rsvdz on xhci 1.1 with Extended TBC enabled (ETE) */
> +#define TRB_TBC(p)             (((p) & 0x3) << 7)
> +#define GET_TBC(p)             (((p) >> 7) & 0x3)
> +#define TRB_TLBPC(p)           (((p) & 0xf) << 16)
> +#define GET_TLBPC(p)           (((p) >> 16) & 0xf)
>  /* TRB cache size for xHC with TRB cache */
>  #define TRB_CACHE_SIZE_HS      8
> @@ -2068,7 +2071,6 @@ static inline const char *xhci_decode_trb(char *str, size_t size,
>                                 field3 & TRB_CYCLE ? 'C' : 'c');
>                 break;
>         case TRB_NORMAL:
> -       case TRB_ISOC:
>         case TRB_EVENT_DATA:
>         case TRB_TR_NOOP:
>                 snprintf(str, size,
> @@ -2085,7 +2087,25 @@ static inline const char *xhci_decode_trb(char *str, size_t size,
>                         field3 & TRB_ENT ? 'E' : 'e',
>                         field3 & TRB_CYCLE ? 'C' : 'c');
>                 break;
> -
> +       case TRB_ISOC:
> +               snprintf(str, size,
> +                       "Buffer %08x%08x length %d TD size/TBC %d intr %d type '%s' TBC %u TLBPC %u frame_id %u flags %c:%c:%c:%c:%c:%c:%c:%c:%c",
> +                       field1, field0, TRB_LEN(field2), GET_TD_SIZE(field2),
> +                       GET_INTR_TARGET(field2),
> +                       xhci_trb_type_string(type),
> +                       GET_TBC(field3),
> +                       GET_TLBPC(field3),
> +                       GET_FRAME_ID(field3),
> +                       field3 & TRB_SIA ? 'S' : 's',
> +                       field3 & TRB_BEI ? 'B' : 'b',
> +                       field3 & TRB_IDT ? 'I' : 'i',
> +                       field3 & TRB_IOC ? 'I' : 'i',
> +                       field3 & TRB_CHAIN ? 'C' : 'c',
> +                       field3 & TRB_NO_SNOOP ? 'S' : 's',
> +                       field3 & TRB_ISP ? 'I' : 'i',
> +                       field3 & TRB_ENT ? 'E' : 'e',
> +                       field3 & TRB_CYCLE ? 'C' : 'c');
> +               break;
> 
> 
> 
> Does this look good to you?
> 
> Patch on top of my for-usb-next branch:
> https://urldefense.com/v3/__https://git.kernel.org/pub/scm/linux/kernel/git/mnyman/xhci.git/log/?h=for-usb-next__;!!A4F2R9G_pg!bo3LI3JLGNnmgpFB0wXYpvuY5aWKXUpzASgaQr6NImxYghpqzI3t5abRR8-tcGM0pKPSKiOvIgVg-rRQvkngu3z_q31D9m2C$
> 

Looks good to me!

Thanks,
Thinh
diff mbox series

Patch

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 4ea2c3e072a9..e1c9838084bf 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -3941,10 +3941,6 @@  static int xhci_get_isoc_frame_id(struct xhci_hcd *xhci,
 	start_frame_id = (start_frame_id >> 3) & 0x7ff;
 	end_frame_id = (end_frame_id >> 3) & 0x7ff;
 
-	xhci_dbg(xhci, "%s: index %d, reg 0x%x start_frame_id 0x%x, end_frame_id 0x%x, start_frame 0x%x\n",
-		 __func__, index, readl(&xhci->run_regs->microframe_index),
-		 start_frame_id, end_frame_id, start_frame);
-
 	if (start_frame_id < end_frame_id) {
 		if (start_frame > end_frame_id ||
 				start_frame < start_frame_id)