usb: dwc3: debugfs: add snapshot to dump requests trbs events
A message that is not in the archive (sent off-list or not yet received): [email protected]
Quoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
you need to explain what are you trying to provide to our users here.
What "problem" are you trying to solve ?
Quoted 2 lines
As ep0 requests are more complex than others. It's not included in this patch.
For ep0, you could at least print the endpoint phase we are currently in and if we have requests in flight or not.
Quoted 58 lines
Signed-off-by Zhuang Jin Can <[email protected]>--- drivers/usb/dwc3/core.h | 4 + drivers/usb/dwc3/debugfs.c | 192 ++++++++++++++++++++++++++++++++++++++++++++ drivers/usb/dwc3/gadget.h | 41 ++++++++++ 3 files changed, 237 insertions(+)drivers/usb/dwc3/core.h +4
-0@@ -849,6 +849,10 @@ struct dwc3_event_devt { u32 type:4; u32 reserved15_12:4; u32 event_info:9; + +#define DEVT_EVTINFO_SUPERSPEED (1 << 4) +#define DEVT_EVTINFO_HIRD (n) (((n) & (0xf << 5)) >> 5) + u32 reserved31_25:7; } __packed;drivers/usb/dwc3/debugfs.c +28
-0@@ -618,6 +618,191 @@ static const struct file_operations dwc3_link_state_fops = { .release = single_release, }; +static void dwc3_dump_requests (struct seq_file *s,struct list_head *head, +const char *list_name) +{ +struct dwc3_request *req; + +if (list_empty (head)) { +seq_printf (s,"list %s is empty\n" , list_name); +return ; + } + +seq_printf (s,"list %s:\n" , list_name); +list_for_each_entry (req, head, list) { +struct usb_request *request = &req->request; + +seq_printf (s,"usb_request@0x%p: buf@0x%p(dma@0x%pad), len=%d\n" , + request, request->buf, &request->dma, + request->length); + +if (req->queued) +seq_printf (s,"\tstatus=%d: actual=%d; start_slot=%u: trb@0x%p(dma@0x%pad)\n" , + request->status, request->actual, + req->start_slot, req->trb, + &req->trb_dma); + } +} + +static void dwc3_dump_trbs (struct seq_file *s,struct dwc3_ep *dep) +{
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 658
Quoted 10 lines
drivers/usb/dwc3/debugfs.c +10
-0+struct dwc3_trb *trb; +int i; + +seq_printf (s,"busy_slot = %u, free_slot = %u\n" , + dep->busy_slot &DWC3_TRB_MASK , + dep->free_slot &DWC3_TRB_MASK ); + +for (i =0 ; i <DWC3_TRB_NUM ; i++) { + trb = &dep->trb_pool[i]; +if (i == (dep->busy_slot &DWC3_TRB_MASK )) {
I really dislike these Yoda Conditionals. Fix this up.
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 666
Quoted 8 lines
drivers/usb/dwc3/debugfs.c +8
-0+seq_puts (s,"busy_slot--|\n" ); +seq_puts (s," \\\n" ); + } +if (i == (dep->free_slot &DWC3_TRB_MASK )) { +seq_puts (s,"free_slot--|\n" ); +seq_puts (s," \\\n" ); + } + seq_printf(s, "trb[%02d](dma@0x%pad): %08x(bpl), %08x(bph), %08x(size), %08x(ctrl)\n",
I'm not sure you need to print out the TRB address. bpl, bph, size and ctrl are desired though.
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 668
Quoted 2 lines
drivers/usb/dwc3/debugfs.c +2
-0+ i, &dep->trb_pool_dma + i *sizeof (*trb), + trb->bpl, trb->bph, trb->size, trb->ctrl);
this will be pretty difficult to parse by a human. I would rather see you creating one directory per TRB (and also one directory per endpoint) which holds the details for that entity, so that it looks like:
dwc3
|-- current_state (or perhaps a better name, but snapshot isn't very good either)
|-- ep2
| |-- direction
| |-- maxpacket
| |-- number
| |-- state
| |-- stream_capable
| |-- type
| |-- trbs
| | |-- trb0
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb1
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb2
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb3
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
. . .
. . .
. . .
| |-- request0
| | |-- direction
| | |-- mapped
| | |-- queued
| | |-- trb0 (symlink to actual trb directory)
| | |-- ep2 (symlink to actual ep2 directory)
| | |-- usbrequest
| | |-- actual
| | |-- length
| | |-- no_interrupt
| | |-- num_mapped_sgs
| | |-- num_sgs
| | |-- short_not_ok
| | |-- status
| | |-- stream_id
| | |-- zero
| |-- request1
| | |-- direction
| | |-- mapped
| | |-- queued
| | |-- trb1 (symlink to actual trb directory)
| | |-- ep2 (symlink to actual ep2 directory)
| | |-- usbrequest
| | |-- actual
| | |-- length
| | |-- no_interrupt
| | |-- num_mapped_sgs
| | |-- num_sgs
| | |-- short_not_ok
| | |-- status
| | |-- stream_id
| | |-- zero
. . . .
. . . .
. . . .and so forth. That way we get a structured view of everything the controller and the driver are managing.
Quoted 82 lines
drivers/usb/dwc3/debugfs.c +82
-0+static void dwc3_dump_dev_event (struct seq_file *s, +const struct dwc3_event_devt *event) +{ +seq_puts (s,"[0]DEV " ); +seq_printf (s,"[1:7]%s " , + event->device_event ==DWC3_EVENT_TYPE_DEV ?"TYPE_DEV" : + event->device_event ==DWC3_EVENT_TYPE_CARKIT ?"TYPE_CARKIT" : + event->device_event ==DWC3_EVENT_TYPE_I2C ?"TYPE_CARKIT" : +"TYPE_UNKOWN" ); +seq_printf (s,"[8:11]%s " ,dwc3_gadget_event_string (event->type)); + +if (event->type ==DWC3_DEVICE_EVENT_LINK_STATUS_CHANGE || + event->type ==DWC3_DEVICE_EVENT_HIBER_REQ ) { + +seq_printf (s,"[16:20]%s %s " , +dwc3_link_state_string ( + event->event_info &DEVT_EVTINFO_SUPERSPEED , + event->event_info &DWC3_LINK_STATE_MASK ), + event->event_info &DEVT_EVTINFO_SUPERSPEED ? +"SS" :"HS" ); + +if (!(event->event_info &DEVT_EVTINFO_SUPERSPEED )) +seq_printf (s,"[21:24]HIRD %u " , +DEVT_EVTINFO_HIRD (event->event_info)); + } +} + +static void dwc3_dump_ep_event (struct seq_file *s, +const struct dwc3_event_depevt *event) +{ +seq_puts (s,"[0]EP " ); +seq_printf (s,"[1:5]ep%d " , event->endpoint_number); +seq_printf (s,"[6:9]%s " , +dwc3_ep_event_string (event->endpoint_event)); + +switch (event->endpoint_event) { +case DWC3_DEPEVT_XFERCOMPLETE : +case DWC3_DEPEVT_XFERINPROGRESS : +if (event->status &DEPEVT_STATUS_BUSERR ) +seq_puts (s,"[12]BUSERR " ); +if (event->status &DEPEVT_STATUS_SHORT ) +seq_puts (s,"[13]SHORT " ); +if (event->status &DEPEVT_STATUS_IOC ) +seq_puts (s,"[14]IOC " ); +if (event->status &DEPEVT_STATUS_LST ) +seq_puts (s,"[15]LST " ); +break ; +case DWC3_DEPEVT_XFERNOTREADY : +if ((event->status &0x3 ) ==1 ) +seq_puts (s,"[12:13]Data_Stage " ); +else if ((event->status &0x3 ) ==2 ) +seq_puts (s,"[12:13]Status_Stage " ); +if (event->status &DEPEVT_STATUS_TRANSFER_ACTIVE ) +seq_puts (s,"[15]XferActive " ); +else +seq_puts (s,"[15]XferNotActive " ); +break ; +case DWC3_DEPEVT_EPCMDCMPLT : +if (event->status &BIT (0 )) +seq_puts (s,"[12:15]Invalid Transfer Resource " ); +break ; +default : +seq_puts (s,"[12:15]UNKOWN " ); + } +seq_printf (s,"[16:31]PARAM 0x%04x " , event->parameters); +} + +static void dwc3_dump_event_buf (struct seq_file *s, +struct dwc3_event_buffer *evt) +{ +union dwc3_event event; +int i; + +seq_printf (s,"evt->buf@0x%p(dma@0x%pad), length=%u, lpos=%u, count=%u, flags=%s\n" , + evt->buf, &evt->dma, + evt->length, evt->lpos, evt->count, + evt->flags &DWC3_EVENT_PENDING ?"pending" :"0" ); + +for (i =0 ; i < evt->length; i +=4 ) { + event.raw = *(u32 *) (evt->buf + i); +if (i == evt->lpos) { +seq_puts (s,"lpos-------|\n" );
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 760
Quoted 10 lines
drivers/usb/dwc3/debugfs.c +10
-0+seq_puts (s," \\\n" ); + } +seq_printf (s,"event[%d]: %08x " , i, event.raw); + +if (event.type.is_devspec) +dwc3_dump_dev_event (s, &event.devt); +else +dwc3_dump_ep_event (s, &event.depevt); +seq_puts (s,"\n" ); + }
how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
It's still a bit easier to reproduce part of the event handling here. I think it's best to make a choice of caching the last 5 events in a ring buffer and provide a helper for IRQ handlers to push events into the ring buffer, then from here you just iterate over that ring buffer instead of accessing our actual event buffer.
Also note that we can hold up to 64 events in our event buffer so this call could take a looooooot of time to complete and you probably don't need all that information anyway because you can get them by just enabling VERBOSE_DEBUG on dwc3 and capturing the entire driver behavior on dmesg.
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 768
Quoted 8 lines
drivers/usb/dwc3/debugfs.c +8
-0+static int dwc3_snapshot_show (struct seq_file *s,void *unused) +{ +struct dwc3 *dwc = s->private; +unsigned long flags; +int i; + +spin_lock_irqsave (&dwc->lock, flags); +for (i =2 ; i <DWC3_ENDPOINTS_NUM ; i++) {
some platforms don't have all 32 physical endpoints, we just had a bug fix for that, see commit 32702e9.
Quoted 54 lines
drivers/usb/dwc3/debugfs.c +39
-0+struct dwc3_ep *dep = dwc->eps[i]; + +if (!(dep->flags &DWC3_EP_ENABLED )) +continue ; + +seq_printf (s,"[%s]\n" , dep->name); +dwc3_dump_requests (s, &dep->request_list,"request_list" ); +dwc3_dump_requests (s, &dep->req_queued,"req_queued" ); +if (!list_empty (&dep->req_queued)) +dwc3_dump_trbs (s, dep); +seq_puts (s,"\n" ); + } + +for (i =0 ; i < dwc->num_event_buffers; i++) +dwc3_dump_event_buf (s, dwc->ev_buffs[i]); +spin_unlock_irqrestore (&dwc->lock, flags); + +return 0 ; +} + +static int dwc3_snapshot_open (struct inode *inode,struct file *file) +{ +return single_open (file, dwc3_snapshot_show, inode->i_private); +} + +static const struct file_operations dwc3_snapshot_fops = { + .open = dwc3_snapshot_open, + .read = seq_read, + .llseek = seq_lseek, + .release = single_release, +}; +int dwc3_debugfs_init (struct dwc3 *dwc) {struct dentry *root;@@ -672,6 +857,13 @@ int dwc3_debugfs_init(struct dwc3 *dwc) ret = -ENOMEM ; goto err1; } + + file =debugfs_create_file ("snapshot" ,S_IRUGO , root, + dwc, &dwc3_snapshot_fops); +if (!file) { + ret = -ENOMEM ; + goto err1; + } }return 0 ;drivers/usb/dwc3/gadget.h +0
-0
drivers/usb/dwc3/gadget.h static inline const char *dwc3_gadget_event_string(u8 event) · line 124
Quoted 5 lines
drivers/usb/dwc3/gadget.h +2
-0@@ -120,6 +120,8 @@ static inline const char *dwc3_gadget_event_string(u8 event)return "Link Status Change" ;case DWC3_DEVICE_EVENT_WAKEUP :return "WakeUp" ; +case DWC3_DEVICE_EVENT_HIBER_REQ : +return "Hibernation Request" ;
this should be in a separate patch.
Quoted 33 lines
drivers/usb/dwc3/gadget.h +26
-0case DWC3_DEVICE_EVENT_EOPF :return "End-Of-Frame" ;case DWC3_DEVICE_EVENT_SOF :@@ -159,4 +161,43 @@ static inline const char *dwc3_ep_event_string(u8 event)return "UNKNOWN" ; } +/** +* dwc3_link_state_string - returns link state +* @link_state: the link state code +*/ +static inline const char *dwc3_link_state_string (u8 is_ss,u8 link_state) +{ +switch (link_state) { +case DWC3_LINK_STATE_U0 : +return is_ss ?"U0" :"L0" ; +case DWC3_LINK_STATE_U1 : +return "U1" ; +case DWC3_LINK_STATE_U2 : +return is_ss ?"U2" :"L1" ; +case DWC3_LINK_STATE_U3 : +return is_ss ?"U3" :"L2" ; +case DWC3_LINK_STATE_SS_DIS : +return is_ss ?"SS.Disabled" :"L3" ; +case DWC3_LINK_STATE_RX_DET : +return is_ss ?"Rx.Detect" :"Early_Suspend" ; +case DWC3_LINK_STATE_SS_INACT : +return "SS.Inactive" ; +case DWC3_LINK_STATE_POLL : +return "Poll" ; +case DWC3_LINK_STATE_RECOV : +return "Recovery" ; +case DWC3_LINK_STATE_HRESET :
drivers/usb/dwc3/gadget.h static inline const char *dwc3_ep_event_string(u8 event) · line 199
Quoted 10 lines
drivers/usb/dwc3/gadget.h +10
-0+return "HRESET" ; +case DWC3_LINK_STATE_CMPLY : +return "Compliance" ; +case DWC3_LINK_STATE_LPBK : +return "Loopback" ; +case DWC3_LINK_STATE_RESET : +return "Reset" ; +case DWC3_LINK_STATE_RESUME : +return "Resume" ; + }
should be part of a separate patch, also I recently added my version of this, see the archives (although I didn't care for differentiating U0 from L0 depending on speed, but that's not really a big deal IMO).
cheers
Signature · 1 line
balbi
Quoted 5 lines
From: [email protected] [mailto:[email protected]] On Behalf Of Felipe Balbi
Sent: Monday, April 28, 2014 8:56 AMQuoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
< snip >
Quoted 9 lines
Quoted 9 lines
(quoted diff) +9
-0+ for (i = 0; i < evt->length; i += 4) { + event.raw = *(u32 *) (evt->buf + i); + if (i == evt->lpos) { + seq_puts(s, "lpos-------|\n"); + seq_puts(s, " \\\n"); + } + seq_printf(s, "event[%d]: %08x ", i, event.raw); + + if (event.type.is_devspec)
Quoted 8 lines
Review
Quoted 5 lines
(quoted diff) +5
-0+ dwc3_dump_dev_event(s, &event.devt); + else + dwc3_dump_ep_event(s, &event.depevt); + seq_puts(s, "\n"); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Just FYI, it is fine to read from the event buffer memory at any time. But of course, if you happen to read from a location at the same time the core is writing to it, you may read either the old value or the new, depending on the timing. So the results might not be 100% reliable.
Signature · 1 line
Paul
Quoted 26 lines · Paul Zimmerman
Quoted 5 lines
From: [email protected] [mailto:[email protected]] On Behalf Of Felipe Balbi
Sent: Monday, April 28, 2014 8:56 AMQuoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
< snip >
Quoted 9 lines
Quoted 9 lines
(quoted diff) +9
-0+ for (i = 0; i < evt->length; i += 4) { + event.raw = *(u32 *) (evt->buf + i); + if (i == evt->lpos) { + seq_puts(s, "lpos-------|\n"); + seq_puts(s, " \\\n"); + } + seq_printf(s, "event[%d]: %08x ", i, event.raw); + + if (event.type.is_devspec)Quoted 8 lines
Review
Quoted 5 lines
(quoted diff) +5
-0+ dwc3_dump_dev_event(s, &event.devt); + else + dwc3_dump_ep_event(s, &event.depevt); + seq_puts(s, "\n"); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Quoted 4 lines
Just FYI, it is fine to read from the event buffer memory at any time. But of course, if you happen to read from a location at the same time the core is writing to it, you may read either the old value or the new, depending on the timing. So the results might not be 100% reliable.
Thanks, based on this I'll stick to my "use-a-ring-buffer-to-store-last-5-events" suggestion :-)
Signature · 1 line
balbi
Quoted 7 lines · Felipe Balbi
Quoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
you need to explain what are you trying to provide to our users here.
What "problem" are you trying to solve ?
The interface enables users to easily peek into requests, trbs and events to know the current transfer state of each request.
If an transfer is stuck, user can use the interface to check why it's stuck (e.g. Is it because a gadget doesn't queued the request? Or it's queued but it's not primed to the controller? Or It's primed to the controller but the TRBs and events indicate the transfer never completes?). User can immediately narrow down the issue without enabling verbose log or reproduce the issue again. It's helpful when we need to deal with some hard-to-reproduce bugs or timing sensitive bugs can't be reproduced with verbose log enabled.
Quoted 6 lines
Quoted 2 lines
As ep0 requests are more complex than others. It's not included in this patch.
For ep0, you could at least print the endpoint phase we are currently in and if we have requests in flight or not.
Agree. Will add it in [PATCH v2].
Quoted 62 lines
Quoted 62 lines
Signed-off-by Zhuang Jin Can <[email protected]>--- drivers/usb/dwc3/core.h | 4 + drivers/usb/dwc3/debugfs.c | 192 ++++++++++++++++++++++++++++++++++++++++++++ drivers/usb/dwc3/gadget.h | 41 ++++++++++ 3 files changed, 237 insertions(+)drivers/usb/dwc3/core.h +4
-0@@ -849,6 +849,10 @@ struct dwc3_event_devt { u32 type:4; u32 reserved15_12:4; u32 event_info:9; + +#define DEVT_EVTINFO_SUPERSPEED (1 << 4) +#define DEVT_EVTINFO_HIRD (n) (((n) & (0xf << 5)) >> 5) + u32 reserved31_25:7; } __packed;drivers/usb/dwc3/debugfs.c +32
-0@@ -618,6 +618,191 @@ static const struct file_operations dwc3_link_state_fops = { .release = single_release, }; +static void dwc3_dump_requests (struct seq_file *s,struct list_head *head, +const char *list_name) +{ +struct dwc3_request *req; + +if (list_empty (head)) { +seq_printf (s,"list %s is empty\n" , list_name); +return ; + } + +seq_printf (s,"list %s:\n" , list_name); +list_for_each_entry (req, head, list) { +struct usb_request *request = &req->request; + +seq_printf (s,"usb_request@0x%p: buf@0x%p(dma@0x%pad), len=%d\n" , + request, request->buf, &request->dma, + request->length); + +if (req->queued) +seq_printf (s,"\tstatus=%d: actual=%d; start_slot=%u: trb@0x%p(dma@0x%pad)\n" , + request->status, request->actual, + req->start_slot, req->trb, + &req->trb_dma); + } +} + +static void dwc3_dump_trbs (struct seq_file *s,struct dwc3_ep *dep) +{ +struct dwc3_trb *trb; +int i; + + seq_printf(s, "busy_slot = %u, free_slot = %u\n",
Quoted 9 lines
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 658
Quoted 6 lines
drivers/usb/dwc3/debugfs.c +6
-0+ dep->busy_slot &DWC3_TRB_MASK , + dep->free_slot & DWC3_TRB_MASK); + +for (i =0 ; i <DWC3_TRB_NUM ; i++) { + trb = &dep->trb_pool[i]; +if (i == (dep->busy_slot &DWC3_TRB_MASK )) {I really dislike these Yoda Conditionals. Fix this up.
Agree. Will fix it in [PATCH v2].
Quoted 12 lines
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 666
Quoted 8 lines
drivers/usb/dwc3/debugfs.c +8
-0+seq_puts (s,"busy_slot--|\n" ); +seq_puts (s," \\\n" ); + } +if (i == (dep->free_slot &DWC3_TRB_MASK )) { +seq_puts (s,"free_slot--|\n" ); +seq_puts (s," \\\n" ); + } + seq_printf(s, "trb[%02d](dma@0x%pad): %08x(bpl), %08x(bph), %08x(size), %08x(ctrl)\n",I'm not sure you need to print out the TRB address. bpl, bph, size and ctrl are desired though.
printing out the TRB DMA address helps user to locate the start TRB of a request. I admit that we can achive the same purose using the "start_slot" of the request. I'll remove it in [PATCH v2].
Quoted 10 lines
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 668
Quoted 2 lines
drivers/usb/dwc3/debugfs.c +2
-0+ i, &dep->trb_pool_dma + i *sizeof (*trb), + trb->bpl, trb->bph, trb->size, trb->ctrl);this will be pretty difficult to parse by a human. I would rather see you creating one directory per TRB (and also one directory per endpoint) which holds the details for that entity, so that it looks like:
dwc3
|--current_state(or perhaps a better name, but snapshot isn't very good either)
Actually, it's hard to find a perfect name. "current_state" or "snapshot" doesn't make too much difference to me. If "current_state" makes more sense to you, I can change to use this name. Or let me know if you have a better suggestion.
Quoted 68 lines
|-- ep2
| |-- direction
| |-- maxpacket
| |-- number
| |-- state
| |-- stream_capable
| |-- type
| |-- trbs
| | |-- trb0
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb1
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb2
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
| | |-- trb3
| | | |-- bph
| | | |-- bpl
| | | |-- ctrl
| | | |-- size
. . .
. . .
. . .
| |-- request0
| | |-- direction
| | |-- mapped
| | |-- queued
| | |-- trb0 (symlink to actual trb directory)
| | |-- ep2 (symlink to actual ep2 directory)
| | |-- usbrequest
| | |-- actual
| | |-- length
| | |-- no_interrupt
| | |-- num_mapped_sgs
| | |-- num_sgs
| | |-- short_not_ok
| | |-- status
| | |-- stream_id
| | |-- zero
| |-- request1
| | |-- direction
| | |-- mapped
| | |-- queued
| | |-- trb1 (symlink to actual trb directory)
| | |-- ep2 (symlink to actual ep2 directory)
| | |-- usbrequest
| | |-- actual
| | |-- length
| | |-- no_interrupt
| | |-- num_mapped_sgs
| | |-- num_sgs
| | |-- short_not_ok
| | |-- status
| | |-- stream_id
| | |-- zero
. . . .
. . . .
. . . .Quoted 3 lines
and so forth. That way we get a structured view of everything the controller and the driver are managing.
The patch intends to dump the most important RUNTIME information the driver is dealing with the controller, STATIC information is not valuable here as we can get them before running. I consider information like "direction", "maxpactsize", "types" are STATIC, as they're not going to change once they are configured. Dumping everying is not the intention of the patch. (Sorry that the name "snapshot" confused you and I didn't describe the intention well).
So are you suggesting to organize the information in multiple debugfs directories and files or just to print information with appropriate indents so that users can easily read it? IMO, organizing them in multiple files makes it impossible for the user to lock dwc3->lock and get information atomically. The problem of reading them separately is that it won't give you the consistent information regarding the current transfer state.
Quoted 96 lines
Quoted 82 lines
drivers/usb/dwc3/debugfs.c +82
-0+static void dwc3_dump_dev_event (struct seq_file *s, +const struct dwc3_event_devt *event) +{ +seq_puts (s,"[0]DEV " ); +seq_printf (s,"[1:7]%s " , + event->device_event ==DWC3_EVENT_TYPE_DEV ?"TYPE_DEV" : + event->device_event ==DWC3_EVENT_TYPE_CARKIT ?"TYPE_CARKIT" : + event->device_event ==DWC3_EVENT_TYPE_I2C ?"TYPE_CARKIT" : +"TYPE_UNKOWN" ); +seq_printf (s,"[8:11]%s " ,dwc3_gadget_event_string (event->type)); + +if (event->type ==DWC3_DEVICE_EVENT_LINK_STATUS_CHANGE || + event->type ==DWC3_DEVICE_EVENT_HIBER_REQ ) { + +seq_printf (s,"[16:20]%s %s " , +dwc3_link_state_string ( + event->event_info &DEVT_EVTINFO_SUPERSPEED , + event->event_info &DWC3_LINK_STATE_MASK ), + event->event_info &DEVT_EVTINFO_SUPERSPEED ? +"SS" :"HS" ); + +if (!(event->event_info &DEVT_EVTINFO_SUPERSPEED )) +seq_printf (s,"[21:24]HIRD %u " , +DEVT_EVTINFO_HIRD (event->event_info)); + } +} + +static void dwc3_dump_ep_event (struct seq_file *s, +const struct dwc3_event_depevt *event) +{ +seq_puts (s,"[0]EP " ); +seq_printf (s,"[1:5]ep%d " , event->endpoint_number); +seq_printf (s,"[6:9]%s " , +dwc3_ep_event_string (event->endpoint_event)); + +switch (event->endpoint_event) { +case DWC3_DEPEVT_XFERCOMPLETE : +case DWC3_DEPEVT_XFERINPROGRESS : +if (event->status &DEPEVT_STATUS_BUSERR ) +seq_puts (s,"[12]BUSERR " ); +if (event->status &DEPEVT_STATUS_SHORT ) +seq_puts (s,"[13]SHORT " ); +if (event->status &DEPEVT_STATUS_IOC ) +seq_puts (s,"[14]IOC " ); +if (event->status &DEPEVT_STATUS_LST ) +seq_puts (s,"[15]LST " ); +break ; +case DWC3_DEPEVT_XFERNOTREADY : +if ((event->status &0x3 ) ==1 ) +seq_puts (s,"[12:13]Data_Stage " ); +else if ((event->status &0x3 ) ==2 ) +seq_puts (s,"[12:13]Status_Stage " ); +if (event->status &DEPEVT_STATUS_TRANSFER_ACTIVE ) +seq_puts (s,"[15]XferActive " ); +else +seq_puts (s,"[15]XferNotActive " ); +break ; +case DWC3_DEPEVT_EPCMDCMPLT : +if (event->status &BIT (0 )) +seq_puts (s,"[12:15]Invalid Transfer Resource " ); +break ; +default : +seq_puts (s,"[12:15]UNKOWN " ); + } +seq_printf (s,"[16:31]PARAM 0x%04x " , event->parameters); +} + +static void dwc3_dump_event_buf (struct seq_file *s, +struct dwc3_event_buffer *evt) +{ +union dwc3_event event; +int i; + +seq_printf (s,"evt->buf@0x%p(dma@0x%pad), length=%u, lpos=%u, count=%u, flags=%s\n" , + evt->buf, &evt->dma, + evt->length, evt->lpos, evt->count, + evt->flags &DWC3_EVENT_PENDING ?"pending" :"0" ); + +for (i =0 ; i < evt->length; i +=4 ) { + event.raw = *(u32 *) (evt->buf + i); +if (i == evt->lpos) { +seq_puts (s,"lpos-------|\n" );drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 760
Quoted 10 lines
drivers/usb/dwc3/debugfs.c +10
-0+seq_puts (s," \\\n" ); + } +seq_printf (s,"event[%d]: %08x " , i, event.raw); + +if (event.type.is_devspec) +dwc3_dump_dev_event (s, &event.devt); +else +dwc3_dump_ep_event (s, &event.depevt); +seq_puts (s,"\n" ); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Quoted 6 lines
It's still a bit easier to reproduce part of the event handling here. I think it's best to make a choice of caching the last 5 events in a ring buffer and provide a helper for IRQ handlers to push events into the ring buffer, then from here you just iterate over that ring buffer instead of accessing our actual event buffer.
Thanks Paul Zimmerman and you for reminding me that fact that controller may write to the event buffers when we're reading them.
Instead of trying to make things perfect and complex, the interface is just to dump the events while leaving the responsibilty to developers to judge if the events are reliable.
Developer should be able to sense if the data is reliable depending on when he dumps the data. If a transfer is stuck and controller doesn't generate anymore events, then the data is reliable, and this is the main senario this patch wants to handle. If a transfer is stuck but controller keeps generating events due to other transfers, there's nothing we can do about it, as the new events will quickly overwrite the ring, and developer will know the events are not valuable. If you dump the events when all transfers are still on-going, it just provides you some a history of the events to sense how it looks like, and you know the data might not be reliable. And this usage is not really helpful for debugging or not used at all, as you should have no intereset to check the events if everythings goes well.
I think above is acceptable for debugging purpose, it's simple without introducing any overhead or timing effect.
Quoted 6 lines
Also note that we can hold up to 64 events in our event buffer so this call could take a looooooot of time to complete and you probably don't need all that information anyway because you can get them by just enabling
VERBOSE_DEBUGon dwc3 and capturing the entire driver behavior on dmesg.
Even though a user may be scared by the lots of events, when a failure happens, he actually wants to read as many events as he can to see what happened before the failure. 5 events is not enough, user can at most only see one or two transfers through these 5 events or nothing if the last few events are generated from other transfers which are unrelated to the failure. The time to dump the events doesn't matter as it's for debugging and most often usage is after a transfer is stuck.
Quoted 12 lines
drivers/usb/dwc3/debugfs.c static const struct file_operations dwc3_link_state_fops = { · line 768
Quoted 8 lines
drivers/usb/dwc3/debugfs.c +8
-0+static int dwc3_snapshot_show (struct seq_file *s,void *unused) +{ +struct dwc3 *dwc = s->private; +unsigned long flags; +int i; + +spin_lock_irqsave (&dwc->lock, flags); +for (i =2 ; i <DWC3_ENDPOINTS_NUM ; i++) {some platforms don't have all 32 physical endpoints, we just had a bug fix for that, see commit 32702e9.
Will fix it as below:
for (i = 2; i < DWC3_ENDPOINTS_NUM; i++) {
struct dwc3_ep *dep = dwc->eps[i];
if (!dep || !(dep->flags & DWC3_EP_ENABLED))
continue;Quoted 48 lines
Quoted 48 lines
drivers/usb/dwc3/debugfs.c +39
-0+struct dwc3_ep *dep = dwc->eps[i]; + +if (!(dep->flags &DWC3_EP_ENABLED )) +continue ; + +seq_printf (s,"[%s]\n" , dep->name); +dwc3_dump_requests (s, &dep->request_list,"request_list" ); +dwc3_dump_requests (s, &dep->req_queued,"req_queued" ); +if (!list_empty (&dep->req_queued)) +dwc3_dump_trbs (s, dep); +seq_puts (s,"\n" ); + } + +for (i =0 ; i < dwc->num_event_buffers; i++) +dwc3_dump_event_buf (s, dwc->ev_buffs[i]); +spin_unlock_irqrestore (&dwc->lock, flags); + +return 0 ; +} + +static int dwc3_snapshot_open (struct inode *inode,struct file *file) +{ +return single_open (file, dwc3_snapshot_show, inode->i_private); +} + +static const struct file_operations dwc3_snapshot_fops = { + .open = dwc3_snapshot_open, + .read = seq_read, + .llseek = seq_lseek, + .release = single_release, +}; +int dwc3_debugfs_init (struct dwc3 *dwc) {struct dentry *root;@@ -672,6 +857,13 @@ int dwc3_debugfs_init(struct dwc3 *dwc) ret = -ENOMEM ; goto err1; } + + file =debugfs_create_file ("snapshot" ,S_IRUGO , root, + dwc, &dwc3_snapshot_fops); +if (!file) { + ret = -ENOMEM ; + goto err1; + } }
Quoted 14 lines
drivers/usb/dwc3/gadget.h static inline const char *dwc3_gadget_event_string(u8 event) · line 124
Quoted 11 lines
drivers/usb/dwc3/debugfs.c +0
-0return 0 ;drivers/usb/dwc3/gadget.h +2
-0@@ -120,6 +120,8 @@ static inline const char *dwc3_gadget_event_string(u8 event)return "Link Status Change" ;case DWC3_DEVICE_EVENT_WAKEUP :return "WakeUp" ; +case DWC3_DEVICE_EVENT_HIBER_REQ : +return "Hibernation Request" ;this should be in a separate patch.
Agree. Will add it in a another patch.
Quoted 39 lines
Quoted 39 lines
drivers/usb/dwc3/gadget.h +32
-0case DWC3_DEVICE_EVENT_EOPF :return "End-Of-Frame" ;case DWC3_DEVICE_EVENT_SOF :@@ -159,4 +161,43 @@ static inline const char *dwc3_ep_event_string(u8 event)return "UNKNOWN" ; } +/** +* dwc3_link_state_string - returns link state +* @link_state: the link state code +*/ +static inline const char *dwc3_link_state_string (u8 is_ss,u8 link_state) +{ +switch (link_state) { +case DWC3_LINK_STATE_U0 : +return is_ss ?"U0" :"L0" ; +case DWC3_LINK_STATE_U1 : +return "U1" ; +case DWC3_LINK_STATE_U2 : +return is_ss ?"U2" :"L1" ; +case DWC3_LINK_STATE_U3 : +return is_ss ?"U3" :"L2" ; +case DWC3_LINK_STATE_SS_DIS : +return is_ss ?"SS.Disabled" :"L3" ; +case DWC3_LINK_STATE_RX_DET : +return is_ss ?"Rx.Detect" :"Early_Suspend" ; +case DWC3_LINK_STATE_SS_INACT : +return "SS.Inactive" ; +case DWC3_LINK_STATE_POLL : +return "Poll" ; +case DWC3_LINK_STATE_RECOV : +return "Recovery" ; +case DWC3_LINK_STATE_HRESET : +return "HRESET" ; +case DWC3_LINK_STATE_CMPLY : +return "Compliance" ; +case DWC3_LINK_STATE_LPBK : +return "Loopback" ; +case DWC3_LINK_STATE_RESET :
Quoted 9 lines
drivers/usb/dwc3/gadget.h static inline const char *dwc3_ep_event_string(u8 event) · line 199
Quoted 4 lines
drivers/usb/dwc3/gadget.h +4
-0+return "Reset" ; +case DWC3_LINK_STATE_RESUME : +return "Resume" ; + }should be part of a separate patch, also I recently added my version of this, see the archives (although I didn't care for differentiating U0 from L0 depending on speed, but that's not really a big deal IMO).
Agree. I'll remove this change and rebase on your change.
Thanks
Jincan
Hi,
Quoted 8 lines · Zhuang Jin Can
Quoted 7 lines · Felipe Balbi
Quoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
you need to explain what are you trying to provide to our users here.
What "problem" are you trying to solve ?
Quoted 10 lines
The interface enables users to easily peek into requests, trbs and events to know the current transfer state of each request.
If an transfer is stuck, user can use the interface to check why it's stuck (e.g. Is it because a gadget doesn't queued the request? Or it's queued but it's not primed to the controller? Or It's primed to the controller but the TRBs and events indicate the transfer never completes?). User can immediately narrow down the issue without enabling verbose log or reproduce the issue again. It's helpful when we need to deal with some hard-to-reproduce bugs or timing sensitive bugs can't be reproduced with verbose log enabled.
this should be part of the commit log in some shape or form.
Quoted 7 lines
Quoted 6 lines
Quoted 2 lines
As ep0 requests are more complex than others. It's not included in this patch.
For ep0, you could at least print the endpoint phase we are currently in and if we have requests in flight or not.
Agree. Will add it in [PATCH v2].
tks
Quoted 12 lines
Quoted 12 lines
Review
Quoted 8 lines
(quoted diff) +8
-0+ seq_puts(s, "busy_slot--|\n"); + seq_puts(s, " \\\n"); + } + if (i == (dep->free_slot & DWC3_TRB_MASK)) { + seq_puts(s, "free_slot--|\n"); + seq_puts(s, " \\\n"); + } + seq_printf(s, "trb[%02d](dma@0x%pad): %08x(bpl), %08x(bph), %08x(size), %08x(ctrl)\n",I'm not sure you need to print out the TRB address. bpl, bph, size and ctrl are desired though.
Quoted 3 lines
printing out the TRB DMA address helps user to locate the start TRB of a request. I admit that we can achive the same purose using the "
start_slot" of the request. I'll remove it in [PATCH v2].
thanks
Quoted 8 lines
Quoted 8 lines
Review
Quoted 2 lines
(quoted diff) +2
-0+ i, &dep->trb_pool_dma + i * sizeof(*trb), + trb->bpl, trb->bph, trb->size, trb->ctrl);this will be pretty difficult to parse by a human. I would rather see you creating one directory per TRB (and also one directory per endpoint) which holds the details for that entity, so that it looks like:
Quoted 5 lines
Quoted 2 lines
dwc3
|--current_state(or perhaps a better name, but snapshot isn't very good either)Actually, it's hard to find a perfect name. "
current_state" or "snapshot" doesn't make too much difference to me. If "current_state" makes more sense to you, I can change to use this name. Or let me know if you have a better suggestion.
the name is important as we will have to deal with it for the next 50 years. We also need to think about someone starting out on dwc3 5 years from now or a QA engineer in whatever OEM trying to provide details of the failure for the development team. It needs to be well thought out.
I don't have a better idea but snapshot gives me the idea that we will end up with a copy of everything which we can revisit at any time and that's not true. If we read this file twice there's no guarantee it'll contain the same information.
Quoted 68 lines
Quoted 68 lines
|-- ep2 | |-- direction | |-- maxpacket | |-- number | |-- state | |-- stream_capable | |-- type | |-- trbs | | |-- trb0 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb1 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb2 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb3 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size . . . . . . . . . | |-- request0 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb0 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero | |-- request1 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb1 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero . . . . . . . . . . . .
Quoted 7 lines
Quoted 3 lines
and so forth. That way we get a structured view of everything the controller and the driver are managing.
The patch intends to dump the most important RUNTIME information the driver is dealing with the controller, STATIC information is not valuable here as we can get them before running. I consider information like "direction", "maxpactsize", "types" are STATIC, as they're not going to change once they are configured.
they are still important and easy enough to print out. Sometimes direction is the key information for a debug session. For example if a Bulk OUT transaction of length 2000 never completes we *know* the reason why.
We know OUT endpoints can't handle transfers which are not aligned to wMaxPacketSize.
Quoted 1 line
Dumping everying is not the intention of the patch. (Sorry that the name
so ? I'm making a suggestion to improve the patch. Dumping only the information you judged necessary during your debug sessions with no consideration for other users isn't generally a good practice. I'm trying to help you improve the patch so that it can be accepted.
Note that dumping all of that information out of a single file isn't very nice either and it'll be difficult to parse, even for humans.
Quoted 2 lines
So are you suggesting to organize the information in multiple debugfs directories and files or just to print information with appropriate indents so that
multiple directories.
Quoted 4 lines
users can easily read it? IMO, organizing them in multiple files makes it impossible for the user to lock
dwc3->lockand get information atomically. The problem of reading them separately is that it won't give you the consistent information regarding the current transfer state.
it depends on where you hold the lock. Also, now that I think of it, it really seems like what you want is tracepoints on this driver, rather than dumping a whole bunch of information out of a single read to a single file. The kernel has a very nice tracing infrastructure and I'd be really happy to read a patch adding support for that in this driver.
Quoted 102 lines
Quoted 96 lines
Quoted 82 lines
(quoted diff) +82
-0+static void dwc3_dump_dev_event(struct seq_file *s, + const struct dwc3_event_devt *event) +{ + seq_puts(s, "[0]DEV "); + seq_printf(s, "[1:7]%s ", + event->device_event == DWC3_EVENT_TYPE_DEV ? "TYPE_DEV" : + event->device_event == DWC3_EVENT_TYPE_CARKIT ? "TYPE_CARKIT" : + event->device_event == DWC3_EVENT_TYPE_I2C ? "TYPE_CARKIT" : + "TYPE_UNKOWN"); + seq_printf(s, "[8:11]%s ", dwc3_gadget_event_string(event->type)); + + if (event->type == DWC3_DEVICE_EVENT_LINK_STATUS_CHANGE || + event->type == DWC3_DEVICE_EVENT_HIBER_REQ) { + + seq_printf(s, "[16:20]%s %s ", + dwc3_link_state_string( + event->event_info & DEVT_EVTINFO_SUPERSPEED, + event->event_info & DWC3_LINK_STATE_MASK), + event->event_info & DEVT_EVTINFO_SUPERSPEED ? + "SS" : "HS"); + + if (!(event->event_info & DEVT_EVTINFO_SUPERSPEED)) + seq_printf(s, "[21:24]HIRD %u ", + DEVT_EVTINFO_HIRD(event->event_info)); + } +} + +static void dwc3_dump_ep_event(struct seq_file *s, + const struct dwc3_event_depevt *event) +{ + seq_puts(s, "[0]EP "); + seq_printf(s, "[1:5]ep%d ", event->endpoint_number); + seq_printf(s, "[6:9]%s ", + dwc3_ep_event_string(event->endpoint_event)); + + switch (event->endpoint_event) { + case DWC3_DEPEVT_XFERCOMPLETE: + case DWC3_DEPEVT_XFERINPROGRESS: + if (event->status & DEPEVT_STATUS_BUSERR) + seq_puts(s, "[12]BUSERR "); + if (event->status & DEPEVT_STATUS_SHORT) + seq_puts(s, "[13]SHORT "); + if (event->status & DEPEVT_STATUS_IOC) + seq_puts(s, "[14]IOC "); + if (event->status & DEPEVT_STATUS_LST) + seq_puts(s, "[15]LST "); + break; + case DWC3_DEPEVT_XFERNOTREADY: + if ((event->status & 0x3) == 1) + seq_puts(s, "[12:13]Data_Stage "); + else if ((event->status & 0x3) == 2) + seq_puts(s, "[12:13]Status_Stage "); + if (event->status & DEPEVT_STATUS_TRANSFER_ACTIVE) + seq_puts(s, "[15]XferActive "); + else + seq_puts(s, "[15]XferNotActive "); + break; + case DWC3_DEPEVT_EPCMDCMPLT: + if (event->status & BIT(0)) + seq_puts(s, "[12:15]Invalid Transfer Resource "); + break; + default: + seq_puts(s, "[12:15]UNKOWN "); + } + seq_printf(s, "[16:31]PARAM 0x%04x ", event->parameters); +} + +static void dwc3_dump_event_buf(struct seq_file *s, + struct dwc3_event_buffer *evt) +{ + union dwc3_event event; + int i; + + seq_printf(s, "evt->buf@0x%p(dma@0x%pad), length=%u, lpos=%u, count=%u, flags=%s\n", + evt->buf, &evt->dma, + evt->length, evt->lpos, evt->count, + evt->flags & DWC3_EVENT_PENDING ? "pending" : "0"); + + for (i = 0; i < evt->length; i += 4) { + event.raw = *(u32 *) (evt->buf + i); + if (i == evt->lpos) { + seq_puts(s, "lpos-------|\n");Review
Quoted 10 lines
(quoted diff) +10
-0+ seq_puts(s, " \\\n"); + } + seq_printf(s, "event[%d]: %08x ", i, event.raw); + + if (event.type.is_devspec) + dwc3_dump_dev_event(s, &event.devt); + else + dwc3_dump_ep_event(s, &event.depevt); + seq_puts(s, "\n"); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Quoted 6 lines
It's still a bit easier to reproduce part of the event handling here. I think it's best to make a choice of caching the last 5 events in a ring buffer and provide a helper for IRQ handlers to push events into the ring buffer, then from here you just iterate over that ring buffer instead of accessing our actual event buffer.
Quoted 6 lines
Thanks Paul Zimmerman and you for reminding me that fact that controller may write to the event buffers when we're reading them.
Instead of trying to make things perfect and complex, the interface is just to dump the events while leaving the responsibilty to developers to judge if the events are reliable.
That's a crappy interface then. Why would anybody use anything they can't trust ?
Quoted 2 lines
Developer should be able to sense if the data is reliable depending on when he dumps the data. If a transfer is stuck and controller doesn't generate anymore
or Developer might spend more time looking at somehting that doesn't make sense and trying to figure out if the current trace is valid then the time spent actually understanding the problem.
Logs are suppose to aid debugging and if the data isn't trustworthy we will have developers spending time debugging the logs themselves. Sorry, but I won't accept that.
Quoted 2 lines
events, then the data is reliable, and this is the main senario this patch wants to handle. If a transfer is stuck but controller keeps generating events due to
that you already get with Verbose debug anyway and you get *all* that data with a simple dmesg.
Quoted 2 lines
other transfers, there's nothing we can do about it, as the new events will quickly overwrite the ring, and developer will know the events are not valuable.
and there goes a debug session down the drain, it turned out to be a waste of time after all.
Quoted 7 lines
If you dump the events when all transfers are still on-going, it just provides you some a history of the events to sense how it looks like, and you know the data might not be reliable. And this usage is not really helpful for debugging or not used at all, as you should have no intereset to check the events if everythings goes well.
I think above is acceptable for debugging purpose, it's simple without introducing any overhead or timing effect.
wait, what ? everytime you read that file you hold the controller lock god knows for how long and you say it doesn't introduce any timing effect ?
Verbose logs have a lower overhead than what you're suggesting here.
Quoted 6 lines
Quoted 6 lines
Also note that we can hold up to 64 events in our event buffer so this call could take a looooooot of time to complete and you probably don't need all that information anyway because you can get them by just enabling
VERBOSE_DEBUGon dwc3 and capturing the entire driver behavior on dmesg.
Quoted 7 lines
Even though a user may be scared by the lots of events, when a failure happens, he actually wants to read as many events as he can to see what happened before the failure. 5 events is not enough, user can at most only see one or two transfers through these 5 events or nothing if the last few events are generated from other transfers which are unrelated to the failure. The time to dump the events doesn't matter as it's for debugging and most often usage is after a transfer is stuck.
right, so if the transfer is stuch there are no extra generated anyway.
And I continue to say that all of this information is already available by enabling VERBOSE_DEBUG for this driver.
If you want to capture logs without VERBOSE_DEBUG tracepoints sound like the way to go.
Quoted 12 lines
Quoted 12 lines
Review
Quoted 8 lines
(quoted diff) +8
-0+static int dwc3_snapshot_show(struct seq_file *s, void *unused) +{ + struct dwc3 *dwc = s->private; + unsigned long flags; + int i; + + spin_lock_irqsave(&dwc->lock, flags); + for (i = 2; i < DWC3_ENDPOINTS_NUM; i++) {some platforms don't have all 32 physical endpoints, we just had a bug fix for that, see commit 32702e9.
Quoted 2 lines
Will fix it as below:
for (i = 2; i < DWC3_ENDPOINTS_NUM; i++) {
no dude, iterate for IN eps and for OUT eps separately. We already have dwc->num_in_eps and dwc->num_out_eps
ps: use tracepoints.
Signature · 1 line
balbi
Hi,
Quoted 22 lines · Felipe Balbi
Hi,
Quoted 8 lines · Zhuang Jin Can
Quoted 7 lines · Felipe Balbi
Quoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
you need to explain what are you trying to provide to our users here.
What "problem" are you trying to solve ?
Quoted 10 lines
The interface enables users to easily peek into requests, trbs and events to know the current transfer state of each request.
If an transfer is stuck, user can use the interface to check why it's stuck (e.g. Is it because a gadget doesn't queued the request? Or it's queued but it's not primed to the controller? Or It's primed to the controller but the TRBs and events indicate the transfer never completes?). User can immediately narrow down the issue without enabling verbose log or reproduce the issue again. It's helpful when we need to deal with some hard-to-reproduce bugs or timing sensitive bugs can't be reproduced with verbose log enabled.
Quoted 2 lines
this should be part of the commit log in some shape or form.
Yes.
Quoted 47 lines
Quoted 7 lines
Quoted 6 lines
Quoted 2 lines
As ep0 requests are more complex than others. It's not included in this patch.
For ep0, you could at least print the endpoint phase we are currently in and if we have requests in flight or not.
Agree. Will add it in [PATCH v2].
tks
Quoted 12 lines
Quoted 12 lines
Review
Quoted 8 lines
(quoted diff) +8
-0+ seq_puts(s, "busy_slot--|\n"); + seq_puts(s, " \\\n"); + } + if (i == (dep->free_slot & DWC3_TRB_MASK)) { + seq_puts(s, "free_slot--|\n"); + seq_puts(s, " \\\n"); + } + seq_printf(s, "trb[%02d](dma@0x%pad): %08x(bpl), %08x(bph), %08x(size), %08x(ctrl)\n",I'm not sure you need to print out the TRB address. bpl, bph, size and ctrl are desired though.
Quoted 3 lines
printing out the TRB DMA address helps user to locate the start TRB of a request. I admit that we can achive the same purose using the "
start_slot" of the request. I'll remove it in [PATCH v2].thanks
Quoted 8 lines
Quoted 8 lines
Review
Quoted 2 lines
(quoted diff) +2
-0+ i, &dep->trb_pool_dma + i * sizeof(*trb), + trb->bpl, trb->bph, trb->size, trb->ctrl);this will be pretty difficult to parse by a human. I would rather see you creating one directory per TRB (and also one directory per endpoint) which holds the details for that entity, so that it looks like:
Quoted 5 lines
Quoted 2 lines
dwc3
|--current_state(or perhaps a better name, but snapshot isn't very good either)Actually, it's hard to find a perfect name. "
current_state" or "snapshot" doesn't make too much difference to me. If "current_state" makes more sense to you, I can change to use this name. Or let me know if you have a better suggestion.the name is important as we will have to deal with it for the next 50 years. We also need to think about someone starting out on dwc3 5 years from now or a QA engineer in whatever OEM trying to provide details of the failure for the development team. It needs to be well thought out.
Quoted 5 lines
I don't have a better idea but snapshot gives me the idea that we will end up with a copy of everything which we can revisit at any time and that's not true. If we read this file twice there's no guarantee it'll contain the same information.
Let's discuss the name later after I explain more about the motivation.
[Motivation]
The patch is inspired from echi-dbg.c debugfs. It contains four files "async", ""bandwidth", "periodic" and "registers".
The "registers" functions as what "regdump" does in dwc3. And the patch implements a "snapshot" to do the similar things done by "async" and "periodic". Because a way to inspect the content of data structures (i.e. TRBs, Events) interacting with the controller is really important for debugging, especially for HW issues. It just simply provides you a interface to check what's currently in TRBs and event buffers (and nothing more, no more guarantees).
In EHCI, "async" and "periodic" also can't guarantee you the reliable data, as you can't prevent the controller from writing the interacting data structures (unless you stop it). It's developer's decision to how to analyze the data. They're not perfect, but simple and helpful.
As far as I see, it's useful for below senarios:
1. Bugs can't be reproduced with VERBOSE_DEBUG, as printk introduces timing effect. Some HW bugs are timing sensitive, even a single printk will prevent you from reproducing the issue.
With "snapshot", we can check the TRBs, events, requests to see the final status to get more clues to triage an issue.
2. Some bugs are hard to reproduce, and can be seen once or
twice after many devices running for a long time. (e.g. MTBF runing with ADB). And they most often uses the builds with debugfs available, ask them to turn on VERBOSE_DEBUG and run the tests are not acceptable. After the failure happens, if you ask the tester to turn on the VERBOSE_DEBUG to reproduce the issue again. He may come back to you a week later with an answer "I can't reproduce it. It's a random issue".
With "snapshot", when the issue happens, tester can just dump the TRBs, events to provide more data to a developer. It won't guarantee you to root cause the issue, but something is better than nothing.
Regarding what are important to dump, regarding the motivation, they should be TRBs and Events which are the parts interfacing with HW. But only dumping them is not enough, it's useless if user can't tell which TRB belongs to which endpont and request. That's why I also dump the necessary info about the requests and endpoints to track their relationship. Infos like maxpacket size, direction, types are not really important regarding this. You can get the information by running it once and see the printks. And they're common properties which can just be handed off to udc core.
Quoted 76 lines
Quoted 68 lines
Quoted 68 lines
|-- ep2 | |-- direction | |-- maxpacket | |-- number | |-- state | |-- stream_capable | |-- type | |-- trbs | | |-- trb0 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb1 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb2 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb3 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size . . . . . . . . . | |-- request0 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb0 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero | |-- request1 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb1 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero . . . . . . . . . . . .Quoted 7 lines
Quoted 3 lines
and so forth. That way we get a structured view of everything the controller and the driver are managing.
The patch intends to dump the most important RUNTIME information the driver is dealing with the controller, STATIC information is not valuable here as we can get them before running. I consider information like "direction", "maxpactsize", "types" are STATIC, as they're not going to change once they are configured.
Quoted 8 lines
they are still important and easy enough to print out. Sometimes direction is the key information for a debug session. For example if a Bulk OUT transaction of length 2000 never completes we *know* the reason why.
We know OUT endpoints can't handle transfers which are not aligned to wMaxPacketSize.
Explained in [Motivation], these info can be got by VERBOSE_DEBUG by running it once. It's not the "snapshot" really want to handle.
Quoted 10 lines
Quoted 1 line
Dumping everying is not the intention of the patch. (Sorry that the name
so ? I'm making a suggestion to improve the patch. Dumping only the information you judged necessary during your debug sessions with no consideration for other users isn't generally a good practice. I'm trying to help you improve the patch so that it can be accepted.
Note that dumping all of that information out of a single file isn't very nice either and it'll be difficult to parse, even for humans.
Explained in [Motivation].
Quoted 5 lines
Quoted 2 lines
So are you suggesting to organize the information in multiple debugfs directories and files or just to print information with appropriate indents so that
multiple directories.
Explained in [Motivation]. echi-dbg.c also uses a single file to dump the structures. But I admit that dumping event buffers can be in a separate file.
Quoted 11 lines
Quoted 4 lines
users can easily read it? IMO, organizing them in multiple files makes it impossible for the user to lock
dwc3->lockand get information atomically. The problem of reading them separately is that it won't give you the consistent information regarding the current transfer state.it depends on where you hold the lock. Also, now that I think of it, it really seems like what you want is tracepoints on this driver, rather than dumping a whole bunch of information out of a single read to a single file. The kernel has a very nice tracing infrastructure and I'd be really happy to read a patch adding support for that in this driver.
Explained in [Motivation], I'm sorry that I have no experience of using tracepoint:(, so I googled it, and found that I can't use them to achieve the same purpose as "snapshot". But I maybe wrong.
Quoted 105 lines
Quoted 105 lines
Quoted 96 lines
Quoted 82 lines
(quoted diff) +82
-0+static void dwc3_dump_dev_event(struct seq_file *s, + const struct dwc3_event_devt *event) +{ + seq_puts(s, "[0]DEV "); + seq_printf(s, "[1:7]%s ", + event->device_event == DWC3_EVENT_TYPE_DEV ? "TYPE_DEV" : + event->device_event == DWC3_EVENT_TYPE_CARKIT ? "TYPE_CARKIT" : + event->device_event == DWC3_EVENT_TYPE_I2C ? "TYPE_CARKIT" : + "TYPE_UNKOWN"); + seq_printf(s, "[8:11]%s ", dwc3_gadget_event_string(event->type)); + + if (event->type == DWC3_DEVICE_EVENT_LINK_STATUS_CHANGE || + event->type == DWC3_DEVICE_EVENT_HIBER_REQ) { + + seq_printf(s, "[16:20]%s %s ", + dwc3_link_state_string( + event->event_info & DEVT_EVTINFO_SUPERSPEED, + event->event_info & DWC3_LINK_STATE_MASK), + event->event_info & DEVT_EVTINFO_SUPERSPEED ? + "SS" : "HS"); + + if (!(event->event_info & DEVT_EVTINFO_SUPERSPEED)) + seq_printf(s, "[21:24]HIRD %u ", + DEVT_EVTINFO_HIRD(event->event_info)); + } +} + +static void dwc3_dump_ep_event(struct seq_file *s, + const struct dwc3_event_depevt *event) +{ + seq_puts(s, "[0]EP "); + seq_printf(s, "[1:5]ep%d ", event->endpoint_number); + seq_printf(s, "[6:9]%s ", + dwc3_ep_event_string(event->endpoint_event)); + + switch (event->endpoint_event) { + case DWC3_DEPEVT_XFERCOMPLETE: + case DWC3_DEPEVT_XFERINPROGRESS: + if (event->status & DEPEVT_STATUS_BUSERR) + seq_puts(s, "[12]BUSERR "); + if (event->status & DEPEVT_STATUS_SHORT) + seq_puts(s, "[13]SHORT "); + if (event->status & DEPEVT_STATUS_IOC) + seq_puts(s, "[14]IOC "); + if (event->status & DEPEVT_STATUS_LST) + seq_puts(s, "[15]LST "); + break; + case DWC3_DEPEVT_XFERNOTREADY: + if ((event->status & 0x3) == 1) + seq_puts(s, "[12:13]Data_Stage "); + else if ((event->status & 0x3) == 2) + seq_puts(s, "[12:13]Status_Stage "); + if (event->status & DEPEVT_STATUS_TRANSFER_ACTIVE) + seq_puts(s, "[15]XferActive "); + else + seq_puts(s, "[15]XferNotActive "); + break; + case DWC3_DEPEVT_EPCMDCMPLT: + if (event->status & BIT(0)) + seq_puts(s, "[12:15]Invalid Transfer Resource "); + break; + default: + seq_puts(s, "[12:15]UNKOWN "); + } + seq_printf(s, "[16:31]PARAM 0x%04x ", event->parameters); +} + +static void dwc3_dump_event_buf(struct seq_file *s, + struct dwc3_event_buffer *evt) +{ + union dwc3_event event; + int i; + + seq_printf(s, "evt->buf@0x%p(dma@0x%pad), length=%u, lpos=%u, count=%u, flags=%s\n", + evt->buf, &evt->dma, + evt->length, evt->lpos, evt->count, + evt->flags & DWC3_EVENT_PENDING ? "pending" : "0"); + + for (i = 0; i < evt->length; i += 4) { + event.raw = *(u32 *) (evt->buf + i); + if (i == evt->lpos) { + seq_puts(s, "lpos-------|\n");Review
Quoted 10 lines
(quoted diff) +10
-0+ seq_puts(s, " \\\n"); + } + seq_printf(s, "event[%d]: %08x ", i, event.raw); + + if (event.type.is_devspec) + dwc3_dump_dev_event(s, &event.devt); + else + dwc3_dump_ep_event(s, &event.depevt); + seq_puts(s, "\n"); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Quoted 6 lines
It's still a bit easier to reproduce part of the event handling here. I think it's best to make a choice of caching the last 5 events in a ring buffer and provide a helper for IRQ handlers to push events into the ring buffer, then from here you just iterate over that ring buffer instead of accessing our actual event buffer.
Thanks Paul Zimmerman and you for reminding me that fact that controller may write to the event buffers when we're reading them.
Quoted 7 lines
Quoted 3 lines
Instead of trying to make things perfect and complex, the interface is just to dump the events while leaving the responsibilty to developers to judge if the events are reliable.
That's a crappy interface then. Why would anybody use anything they can't trust ?
Explained in [Motivation]. Simply treat it as an interface just dumping the structures.
Quoted 11 lines
Quoted 2 lines
Developer should be able to sense if the data is reliable depending on when he dumps the data. If a transfer is stuck and controller doesn't generate anymore
or Developer might spend more time looking at somehting that doesn't make sense and trying to figure out if the current trace is valid then the time spent actually understanding the problem.
Logs are suppose to aid debugging and if the data isn't trustworthy we will have developers spending time debugging the logs themselves. Sorry, but I won't accept that.
Explained in [Motivation]. Something is better than nothing. Debugging is not just about looking at the data and "Oh, here it is". Analyze the data. It's developer's responsibilty to check how the data is correlated with a specific failure.
Quoted 6 lines
Quoted 2 lines
events, then the data is reliable, and this is the main senario this patch wants to handle. If a transfer is stuck but controller keeps generating events due to
that you already get with Verbose debug anyway and you get *all* that data with a simple dmesg.
Explained in [Motivation], verbose debug has its limitations.
Quoted 14 lines
Quoted 2 lines
other transfers, there's nothing we can do about it, as the new events will quickly overwrite the ring, and developer will know the events are not valuable.
and there goes a debug session down the drain, it turned out to be a waste of time after all.
Quoted 7 lines
If you dump the events when all transfers are still on-going, it just provides you some a history of the events to sense how it looks like, and you know the data might not be reliable. And this usage is not really helpful for debugging or not used at all, as you should have no intereset to check the events if everythings goes well.
I think above is acceptable for debugging purpose, it's simple without introducing any overhead or timing effect.
Quoted 6 lines
wait, what ? everytime you read that file you hold the controller lock god knows for how long and you say it doesn't introduce any timing effect ?
Verbose logs have a lower overhead than what you're suggesting here.
If the test doesn't fail, you should have no interest to read the file. So no overhead during running.
After the failure, you can read the file, the overhead is not a big deal at this point.
Quoted 14 lines
Quoted 6 lines
Quoted 6 lines
Also note that we can hold up to 64 events in our event buffer so this call could take a looooooot of time to complete and you probably don't need all that information anyway because you can get them by just enabling
VERBOSE_DEBUGon dwc3 and capturing the entire driver behavior on dmesg.Quoted 7 lines
Even though a user may be scared by the lots of events, when a failure happens, he actually wants to read as many events as he can to see what happened before the failure. 5 events is not enough, user can at most only see one or two transfers through these 5 events or nothing if the last few events are generated from other transfers which are unrelated to the failure. The time to dump the events doesn't matter as it's for debugging and most often usage is after a transfer is stuck.
Quoted 8 lines
right, so if the transfer is stuch there are no extra generated anyway.
And I continue to say that all of this information is already available by enabling
VERBOSE_DEBUGfor this driver.If you want to capture logs without
VERBOSE_DEBUGtracepoints sound like the way to go.
Explained in [Motivation], I'm not trying to capture logs without VERBOSE_DEBUG.
Quoted 12 lines
Quoted 12 lines
Quoted 12 lines
Review
Quoted 8 lines
(quoted diff) +8
-0+static int dwc3_snapshot_show(struct seq_file *s, void *unused) +{ + struct dwc3 *dwc = s->private; + unsigned long flags; + int i; + + spin_lock_irqsave(&dwc->lock, flags); + for (i = 2; i < DWC3_ENDPOINTS_NUM; i++) {some platforms don't have all 32 physical endpoints, we just had a bug fix for that, see commit 32702e9.
Quoted 6 lines
Quoted 2 lines
Will fix it as below:
for (i = 2; i < DWC3_ENDPOINTS_NUM; i++) {no dude, iterate for IN eps and for OUT eps separately. We already have
dwc->num_in_epsanddwc->num_out_eps
Will fix it. Thanks.
Thanks
Jincan
Hi,
Quoted 427 lines · Zhuang Jin Can
Hi,
Quoted 22 lines · Felipe Balbi
Hi,
Quoted 8 lines · Zhuang Jin Can
Quoted 7 lines · Felipe Balbi
Quoted 1 line · Zhuang Jin Can
Adds a debugfs file "snapshot" to dump dwc3 requests, trbs and events.
you need to explain what are you trying to provide to our users here.
What "problem" are you trying to solve ?
Quoted 10 lines
The interface enables users to easily peek into requests, trbs and events to know the current transfer state of each request.
If an transfer is stuck, user can use the interface to check why it's stuck (e.g. Is it because a gadget doesn't queued the request? Or it's queued but it's not primed to the controller? Or It's primed to the controller but the TRBs and events indicate the transfer never completes?). User can immediately narrow down the issue without enabling verbose log or reproduce the issue again. It's helpful when we need to deal with some hard-to-reproduce bugs or timing sensitive bugs can't be reproduced with verbose log enabled.Quoted 2 lines
this should be part of the commit log in some shape or form.
Yes.
Quoted 47 lines
Quoted 7 lines
Quoted 6 lines
Quoted 2 lines
As ep0 requests are more complex than others. It's not included in this patch.
For ep0, you could at least print the endpoint phase we are currently in and if we have requests in flight or not.
Agree. Will add it in [PATCH v2].
tks
Quoted 12 lines
Quoted 12 lines
Review
Quoted 8 lines
(quoted diff) +8
-0+ seq_puts(s, "busy_slot--|\n"); + seq_puts(s, " \\\n"); + } + if (i == (dep->free_slot & DWC3_TRB_MASK)) { + seq_puts(s, "free_slot--|\n"); + seq_puts(s, " \\\n"); + } + seq_printf(s, "trb[%02d](dma@0x%pad): %08x(bpl), %08x(bph), %08x(size), %08x(ctrl)\n",I'm not sure you need to print out the TRB address. bpl, bph, size and ctrl are desired though.
Quoted 3 lines
printing out the TRB DMA address helps user to locate the start TRB of a request. I admit that we can achive the same purose using the "
start_slot" of the request. I'll remove it in [PATCH v2].thanks
Quoted 8 lines
Quoted 8 lines
Review
Quoted 2 lines
(quoted diff) +2
-0+ i, &dep->trb_pool_dma + i * sizeof(*trb), + trb->bpl, trb->bph, trb->size, trb->ctrl);this will be pretty difficult to parse by a human. I would rather see you creating one directory per TRB (and also one directory per endpoint) which holds the details for that entity, so that it looks like:
Quoted 5 lines
Quoted 2 lines
dwc3
|--current_state(or perhaps a better name, but snapshot isn't very good either)Actually, it's hard to find a perfect name. "
current_state" or "snapshot" doesn't make too much difference to me. If "current_state" makes more sense to you, I can change to use this name. Or let me know if you have a better suggestion.the name is important as we will have to deal with it for the next 50 years. We also need to think about someone starting out on dwc3 5 years from now or a QA engineer in whatever OEM trying to provide details of the failure for the development team. It needs to be well thought out.
Quoted 5 lines
I don't have a better idea but snapshot gives me the idea that we will end up with a copy of everything which we can revisit at any time and that's not true. If we read this file twice there's no guarantee it'll contain the same information.
Let's discuss the name later after I explain more about the motivation.
[Motivation]
The patch is inspired fromechi-dbg.cdebugfs. It contains four files "async", ""bandwidth", "periodic" and "registers".
The "registers" functions as what "regdump" does in dwc3. And the patch implements a "snapshot" to do the similar things done by "async" and "periodic". Because a way to inspect the content of data structures (i.e. TRBs, Events) interacting with the controller is really important for debugging, especially for HW issues. It just simply provides you a interface to check what's currently in TRBs and event buffers (and nothing more, no more guarantees).
In EHCI, "async" and "periodic" also can't guarantee you the reliable data, as you can't prevent the controller from writing the interacting data structures (unless you stop it). It's developer's decision to how to analyze the data. They're not perfect, but simple and helpful.As far as I see, it's useful for below senarios:
1. Bugs can't be reproduced withVERBOSE_DEBUG, as printk introduces timing effect. Some HW bugs are timing sensitive, even a single printk will prevent you from reproducing the issue.
With "snapshot", we can check the TRBs, events, requests to see the final status to get more clues to triage an issue.2. Some bugs are hard to reproduce, and can be seen once or
twice after many devices running for a long time. (e.g. MTBF runing with ADB). And they most often uses the builds with debugfs available, ask them to turn onVERBOSE_DEBUGand run the tests are not acceptable. After the failure happens, if you ask the tester to turn on theVERBOSE_DEBUGto reproduce the issue again. He may come back to you a week later with an answer "I can't reproduce it. It's a random issue".
With "snapshot", when the issue happens, tester can just dump the TRBs, events to provide more data to a developer. It won't guarantee you to root cause the issue, but something is better than nothing.Regarding what are important to dump, regarding the motivation, they should be TRBs and Events which are the parts interfacing with HW. But only dumping them is not enough, it's useless if user can't tell which TRB belongs to which endpont and request. That's why I also dump the necessary info about the requests and endpoints to track their relationship. Infos like maxpacket size, direction, types are not really important regarding this. You can get the information by running it once and see the printks. And they're common properties which can just be handed off to udc core.
Quoted 76 lines
Quoted 68 lines
Quoted 68 lines
|-- ep2 | |-- direction | |-- maxpacket | |-- number | |-- state | |-- stream_capable | |-- type | |-- trbs | | |-- trb0 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb1 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb2 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size | | |-- trb3 | | | |-- bph | | | |-- bpl | | | |-- ctrl | | | |-- size . . . . . . . . . | |-- request0 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb0 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero | |-- request1 | | |-- direction | | |-- mapped | | |-- queued | | |-- trb1 (symlink to actual trb directory) | | |-- ep2 (symlink to actual ep2 directory) | | |-- usbrequest | | |-- actual | | |-- length | | |-- no_interrupt | | |-- num_mapped_sgs | | |-- num_sgs | | |-- short_not_ok | | |-- status | | |-- stream_id | | |-- zero . . . . . . . . . . . .Quoted 7 lines
Quoted 3 lines
and so forth. That way we get a structured view of everything the controller and the driver are managing.
The patch intends to dump the most important RUNTIME information the driver is dealing with the controller, STATIC information is not valuable here as we can get them before running. I consider information like "direction", "maxpactsize", "types" are STATIC, as they're not going to change once they are configured.
Quoted 8 lines
they are still important and easy enough to print out. Sometimes direction is the key information for a debug session. For example if a Bulk OUT transaction of length 2000 never completes we *know* the reason why.
We know OUT endpoints can't handle transfers which are not aligned to wMaxPacketSize.
Explained in [Motivation], these info can be got by
VERBOSE_DEBUGby running it once. It's not the "snapshot" really want to handle.Quoted 10 lines
Quoted 1 line
Dumping everying is not the intention of the patch. (Sorry that the name
so ? I'm making a suggestion to improve the patch. Dumping only the information you judged necessary during your debug sessions with no consideration for other users isn't generally a good practice. I'm trying to help you improve the patch so that it can be accepted.
Note that dumping all of that information out of a single file isn't very nice either and it'll be difficult to parse, even for humans.
Explained in [Motivation].
Quoted 5 lines
Quoted 2 lines
So are you suggesting to organize the information in multiple debugfs directories and files or just to print information with appropriate indents so that
multiple directories.
Explained in [Motivation].
echi-dbg.calso uses a single file to dump the structures. But I admit that dumping event buffers can be in a separate file.Quoted 11 lines
Quoted 4 lines
users can easily read it? IMO, organizing them in multiple files makes it impossible for the user to lock
dwc3->lockand get information atomically. The problem of reading them separately is that it won't give you the consistent information regarding the current transfer state.it depends on where you hold the lock. Also, now that I think of it, it really seems like what you want is tracepoints on this driver, rather than dumping a whole bunch of information out of a single read to a single file. The kernel has a very nice tracing infrastructure and I'd be really happy to read a patch adding support for that in this driver.
Explained in [Motivation], I'm sorry that I have no experience of using tracepoint:(, so I googled it, and found that I can't use them to achieve the same purpose as "snapshot". But I maybe wrong.
Quoted 105 lines
Quoted 105 lines
Quoted 96 lines
Quoted 82 lines
(quoted diff) +82
-0+static void dwc3_dump_dev_event(struct seq_file *s, + const struct dwc3_event_devt *event) +{ + seq_puts(s, "[0]DEV "); + seq_printf(s, "[1:7]%s ", + event->device_event == DWC3_EVENT_TYPE_DEV ? "TYPE_DEV" : + event->device_event == DWC3_EVENT_TYPE_CARKIT ? "TYPE_CARKIT" : + event->device_event == DWC3_EVENT_TYPE_I2C ? "TYPE_CARKIT" : + "TYPE_UNKOWN"); + seq_printf(s, "[8:11]%s ", dwc3_gadget_event_string(event->type)); + + if (event->type == DWC3_DEVICE_EVENT_LINK_STATUS_CHANGE || + event->type == DWC3_DEVICE_EVENT_HIBER_REQ) { + + seq_printf(s, "[16:20]%s %s ", + dwc3_link_state_string( + event->event_info & DEVT_EVTINFO_SUPERSPEED, + event->event_info & DWC3_LINK_STATE_MASK), + event->event_info & DEVT_EVTINFO_SUPERSPEED ? + "SS" : "HS"); + + if (!(event->event_info & DEVT_EVTINFO_SUPERSPEED)) + seq_printf(s, "[21:24]HIRD %u ", + DEVT_EVTINFO_HIRD(event->event_info)); + } +} + +static void dwc3_dump_ep_event(struct seq_file *s, + const struct dwc3_event_depevt *event) +{ + seq_puts(s, "[0]EP "); + seq_printf(s, "[1:5]ep%d ", event->endpoint_number); + seq_printf(s, "[6:9]%s ", + dwc3_ep_event_string(event->endpoint_event)); + + switch (event->endpoint_event) { + case DWC3_DEPEVT_XFERCOMPLETE: + case DWC3_DEPEVT_XFERINPROGRESS: + if (event->status & DEPEVT_STATUS_BUSERR) + seq_puts(s, "[12]BUSERR "); + if (event->status & DEPEVT_STATUS_SHORT) + seq_puts(s, "[13]SHORT "); + if (event->status & DEPEVT_STATUS_IOC) + seq_puts(s, "[14]IOC "); + if (event->status & DEPEVT_STATUS_LST) + seq_puts(s, "[15]LST "); + break; + case DWC3_DEPEVT_XFERNOTREADY: + if ((event->status & 0x3) == 1) + seq_puts(s, "[12:13]Data_Stage "); + else if ((event->status & 0x3) == 2) + seq_puts(s, "[12:13]Status_Stage "); + if (event->status & DEPEVT_STATUS_TRANSFER_ACTIVE) + seq_puts(s, "[15]XferActive "); + else + seq_puts(s, "[15]XferNotActive "); + break; + case DWC3_DEPEVT_EPCMDCMPLT: + if (event->status & BIT(0)) + seq_puts(s, "[12:15]Invalid Transfer Resource "); + break; + default: + seq_puts(s, "[12:15]UNKOWN "); + } + seq_printf(s, "[16:31]PARAM 0x%04x ", event->parameters); +} + +static void dwc3_dump_event_buf(struct seq_file *s, + struct dwc3_event_buffer *evt) +{ + union dwc3_event event; + int i; + + seq_printf(s, "evt->buf@0x%p(dma@0x%pad), length=%u, lpos=%u, count=%u, flags=%s\n", + evt->buf, &evt->dma, + evt->length, evt->lpos, evt->count, + evt->flags & DWC3_EVENT_PENDING ? "pending" : "0"); + + for (i = 0; i < evt->length; i += 4) { + event.raw = *(u32 *) (evt->buf + i); + if (i == evt->lpos) { + seq_puts(s, "lpos-------|\n");Review
Quoted 10 lines
(quoted diff) +10
-0+ seq_puts(s, " \\\n"); + } + seq_printf(s, "event[%d]: %08x ", i, event.raw); + + if (event.type.is_devspec) + dwc3_dump_dev_event(s, &event.devt); + else + dwc3_dump_ep_event(s, &event.depevt); + seq_puts(s, "\n"); + }how well have you tested this ? I'm not entirely sure you should be reading the event buffer at any time you want, though I might be wrong.
Quoted 6 lines
It's still a bit easier to reproduce part of the event handling here. I think it's best to make a choice of caching the last 5 events in a ring buffer and provide a helper for IRQ handlers to push events into the ring buffer, then from here you just iterate over that ring buffer instead of accessing our actual event buffer.
Thanks Paul Zimmerman and you for reminding me that fact that controller may write to the event buffers when we're reading them.
Quoted 7 lines
Quoted 3 lines
Instead of trying to make things perfect and complex, the interface is just to dump the events while leaving the responsibilty to developers to judge if the events are reliable.
That's a crappy interface then. Why would anybody use anything they can't trust ?
Explained in [Motivation]. Simply treat it as an interface just dumping the structures.
Quoted 11 lines
Quoted 2 lines
Developer should be able to sense if the data is reliable depending on when he dumps the data. If a transfer is stuck and controller doesn't generate anymore
or Developer might spend more time looking at somehting that doesn't make sense and trying to figure out if the current trace is valid then the time spent actually understanding the problem.
Logs are suppose to aid debugging and if the data isn't trustworthy we will have developers spending time debugging the logs themselves. Sorry, but I won't accept that.
Explained in [Motivation]. Something is better than nothing. Debugging is not just about looking at the data and "Oh, here it is". Analyze the data. It's developer's responsibilty to check how the data is correlated with a specific failure.
Quoted 6 lines
Quoted 2 lines
events, then the data is reliable, and this is the main senario this patch wants to handle. If a transfer is stuck but controller keeps generating events due to
that you already get with Verbose debug anyway and you get *all* that data with a simple dmesg.
Explained in [Motivation], verbose debug has its limitations.
Quoted 14 lines
Quoted 2 lines
other transfers, there's nothing we can do about it, as the new events will quickly overwrite the ring, and developer will know the events are not valuable.
and there goes a debug session down the drain, it turned out to be a waste of time after all.
Quoted 7 lines
If you dump the events when all transfers are still on-going, it just provides you some a history of the events to sense how it looks like, and you know the data might not be reliable. And this usage is not really helpful for debugging or not used at all, as you should have no intereset to check the events if everythings goes well.
I think above is acceptable for debugging purpose, it's simple without introducing any overhead or timing effect.Quoted 6 lines
wait, what ? everytime you read that file you hold the controller lock god knows for how long and you say it doesn't introduce any timing effect ?
Verbose logs have a lower overhead than what you're suggesting here.
If the test doesn't fail, you should have no interest to read the file. So no overhead during running.
After the failure, you can read the file, the overhead is not a big deal at this point.Quoted 16 lines
Quoted 6 lines
Quoted 6 lines
Also note that we can hold up to 64 events in our event buffer so this call could take a looooooot of time to complete and you probably don't need all that information anyway because you can get them by just enabling
VERBOSE_DEBUGon dwc3 and capturing the entire driver behavior on dmesg.Quoted 7 lines
Even though a user may be scared by the lots of events, when a failure happens, he actually wants to read as many events as he can to see what happened before the failure. 5 events is not enough, user can at most only see one or two transfers through these 5 events or nothing if the last few events are generated from other transfers which are unrelated to the failure. The time to dump the events doesn't matter as it's for debugging and most often usage is after a transfer is stuck.
right, so if the transfer is stuch there are no extra generated anyway.
Quoted 8 lines
Quoted 6 lines
And I continue to say that all of this information is already available by enabling
VERBOSE_DEBUGfor this driver.If you want to capture logs without
VERBOSE_DEBUGtracepoints sound like the way to go.Explained in [Motivation], I'm not trying to capture logs without
VERBOSE_DEBUG.
since you're just giving me a bunch of excuses to not modify your patch which, well, was written for your own use case then I'll just ignore this patch altogether.
When I get time, I'll add proper tracepoints to this driver which will help many other engineers in many other use cases, not just one.
sorry but your patch is not good for acceptance in mainline.
Signature · 1 line
balbi
Quoted 2 lines · Felipe Balbi
sorry but your patch is not good for acceptance in mainline.
Thanks your time.
Jincan