Re: Audio I/O parameters

[Alan Stern]

On Sun, 4 Aug 2013, James Stone wrote:

> Don't know if these syslog errors are also related?
> 
> Aug  3 18:34:06 blueberry kernel: [35122.375869] retire_capture_urb:
> 3189 callbacks suppressed

I don't know.  I can't tell where they come from or what they mean.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Aug 3, 2013 at 11:30 PM, James Stone  wrote:
>
> On Aug 3, 2013 9:28 PM, "Alan Stern"  wrote:
>>
>> On Fri, 2 Aug 2013, James Stone wrote:
>>
>> > > OK - here's a trace with all patches applied. It didn't occur when
>> > > the
>> > > webcam was re-plugged this time..  This one happened when opening the
>> > > trace file while it was being written to. I hope this is OK? It seems
>> > > to be a fairly consistent way to get the audio to hang up, but I'm
>> > > not
>> > > sure it is such a "natural" way to induce the bug tho?
>> > >
>> >
>> > Another trace - this time occurring when plugging in a usb game
>> > controller.. so I guess the webcam isn't the culprit!
>>
>> Traces that show a delay of less than 1 ms aren't very interesting, in
>> general.  However, they do show that the scheduling code in ehci-hcd
>> takes longer than it should (although it probably runs more quickly
>> when tracing isn't turned on).
>>
>> I've known for a long time that the scheduler in ehci-hcd needs to be
>> rewritten completely.  It's a big job, so I've been avoiding it...
>>
>> Some event that causes a whole bunch of those new "underrun" messages
>> in the system log would be worth seeing.
>>
>
> All of these traces were associated with underrun messages but it seems
> they
> are not really capturing anything useful.

Don't know if these syslog errors are also related?

Aug  3 18:34:06 blueberry kernel: [35122.375869] retire_capture_urb:
3189 callbacks suppressed

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 2 Aug 2013, James Stone wrote:

> > OK - here's a trace with all patches applied. It didn't occur when the
> > webcam was re-plugged this time..  This one happened when opening the
> > trace file while it was being written to. I hope this is OK? It seems
> > to be a fairly consistent way to get the audio to hang up, but I'm not
> > sure it is such a "natural" way to induce the bug tho?
> >
> 
> Another trace - this time occurring when plugging in a usb game
> controller.. so I guess the webcam isn't the culprit!

Traces that show a delay of less than 1 ms aren't very interesting, in
general.  However, they do show that the scheduling code in ehci-hcd
takes longer than it should (although it probably runs more quickly
when tracing isn't turned on).

I've known for a long time that the scheduler in ehci-hcd needs to be 
rewritten completely.  It's a big job, so I've been avoiding it...

Some event that causes a whole bunch of those new "underrun" messages
in the system log would be worth seeing.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Aug 2, 2013 at 8:40 PM, Alan Stern  wrote:
> On Fri, 2 Aug 2013, James Stone wrote:
>
>>  > Okay, so the USB controllers do share IRQ lines.  Were you using the
>>  > other USB buses when the errors occurred?
>> 
>>  Webcam microphone might have been on.
>> >>>
>> >>> You should try testing with no other USB activity going on.  Just in
>> >>> case.
>> >>>
>> >>
>> >> Not yet tried this, but I have tested the latest bios, and still get
>> >> the same lockup. Full function-trace attached.
>> >
>> > OK . I have now tested with the webcam disconnected, and I don't seem
>> > to be able to get this bug to occur.
>> >
>>
>> Ah - and on plugging the webcam in, it happened immediately.
>
> Is the webcam on the same bus as the audio card or a different bus?  I
> assume a different one, because the usbmon traces showed no signs of
> traffic to or from a webcam.
>
> Also, this doesn't explain why plugging in the webcam should interfere
> with audio.  If the webcam's driver was leaving interrupts disabled for
> too long, it should have shown up in the irqsoff output.
>
> Can you try applying the two patches posted by Steve and Peter and then
> seeing if the irqsoff report shows anything interesting when you plug
> in the webcam?
>

Yep - it's underway... The webcam does have an audio aspect to it tho
- in that it has a built-in mic. They are on different busses.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 2 Aug 2013, James Stone wrote:

>  > Okay, so the USB controllers do share IRQ lines.  Were you using the
>  > other USB buses when the errors occurred?
> 
>  Webcam microphone might have been on.
> >>>
> >>> You should try testing with no other USB activity going on.  Just in
> >>> case.
> >>>
> >>
> >> Not yet tried this, but I have tested the latest bios, and still get
> >> the same lockup. Full function-trace attached.
> >
> > OK . I have now tested with the webcam disconnected, and I don't seem
> > to be able to get this bug to occur.
> >
> 
> Ah - and on plugging the webcam in, it happened immediately.

Is the webcam on the same bus as the audio card or a different bus?  I 
assume a different one, because the usbmon traces showed no signs of 
traffic to or from a webcam.

Also, this doesn't explain why plugging in the webcam should interfere 
with audio.  If the webcam's driver was leaving interrupts disabled for 
too long, it should have shown up in the irqsoff output.

Can you try applying the two patches posted by Steve and Peter and then 
seeing if the irqsoff report shows anything interesting when you plug 
in the webcam?

Alan Stern


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Peter Zijlstra]

On Fri, Aug 02, 2013 at 02:57:26PM -0400, Steven Rostedt wrote:
> The other thing you can do is not run perf while this is going on.

URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
URL Clas-32862d.h.2us : watchdog_overflow_callback 
<-__perf_event_overflow
URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
<-nmi_handle.isra.0
URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler


So they're not running perf as such; it looks to be the NMI watchdog.  It also
looks like they're actually triggering the NMI watchdog --
arch_trigger_all_cpu_backtrace_handler() will cause unconditional 'fun' on all
CPUS.

Weirdly the report doesn't actually say this; one would think that an NMI
watchdog trigger would be a fair clue that something isn't right.

You can disable that with: echo 0 > /proc/sys/kernel/nmi_watchdog

This also raises the question why those events even bother calculating time
values; there's no (possible) consumer for them at all.

---
Subject: perf: Do not compute time values unnecessarily

We should not be calling calc_timer_values() for events that do not actually
have an mmap()'ed userpage.

Signed-off-by: Peter Zijlstra 
---
 kernel/events/core.c | 8 
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 916cf1f..8643069 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -3665,6 +3665,10 @@ void perf_event_update_userpage(struct perf_event *event)
u64 enabled, running, now;
 
rcu_read_lock();
+   rb = rcu_dereference(event->rb);
+   if (!rb)
+   goto unlock;
+
/*
 * compute total_time_enabled, total_time_running
 * based on snapshot values taken when the event
@@ -3675,12 +3679,8 @@ void perf_event_update_userpage(struct perf_event *event)
 * NMI context
 */
calc_timer_values(event, &now, &enabled, &running);
-   rb = rcu_dereference(event->rb);
-   if (!rb)
-   goto unlock;
 
userpg = rb->user_page;
-
/*
 * Disable preemption so as to not let the corresponding user-space
 * spin too long if we get preempted.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Aug 2, 2013 at 8:02 PM, James Stone  wrote:
> On Fri, Aug 2, 2013 at 8:49 AM, James Stone  wrote:
>> On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern  wrote:
>>> On Thu, 1 Aug 2013, James Stone wrote:
>>>
 > SMIs are controlled by the BIOS, not by the kernel.  I don't think
 > changing the kernel would affect their timings.
 >

 Hmm.. ok. So do I need to see if there is a bios update/report this to
 motherboard manufacturer?
>>>
>>> If there's an update available, you ought to apply it.
>>>
>>> I don't know if talking to the motherboard manufacturer will accomplish
>>> anything.  They're not likely to listen to you, and in any case, they
>>> probably didn't write their own BIOS.
>>>
 > Okay, so the USB controllers do share IRQ lines.  Were you using the
 > other USB buses when the errors occurred?

 Webcam microphone might have been on.
>>>
>>> You should try testing with no other USB activity going on.  Just in
>>> case.
>>>
>>
>> Not yet tried this, but I have tested the latest bios, and still get
>> the same lockup. Full function-trace attached.
>
> OK . I have now tested with the webcam disconnected, and I don't seem
> to be able to get this bug to occur.
>

Ah - and on plugging the webcam in, it happened immediately.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Aug 2, 2013 at 8:49 AM, James Stone  wrote:
> On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern  wrote:
>> On Thu, 1 Aug 2013, James Stone wrote:
>>
>>> > SMIs are controlled by the BIOS, not by the kernel.  I don't think
>>> > changing the kernel would affect their timings.
>>> >
>>>
>>> Hmm.. ok. So do I need to see if there is a bios update/report this to
>>> motherboard manufacturer?
>>
>> If there's an update available, you ought to apply it.
>>
>> I don't know if talking to the motherboard manufacturer will accomplish
>> anything.  They're not likely to listen to you, and in any case, they
>> probably didn't write their own BIOS.
>>
>>> > Okay, so the USB controllers do share IRQ lines.  Were you using the
>>> > other USB buses when the errors occurred?
>>>
>>> Webcam microphone might have been on.
>>
>> You should try testing with no other USB activity going on.  Just in
>> case.
>>
>
> Not yet tried this, but I have tested the latest bios, and still get
> the same lockup. Full function-trace attached.

OK . I have now tested with the webcam disconnected, and I don't seem
to be able to get this bug to occur.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Fri, 2013-08-02 at 14:57 -0400, Steven Rostedt wrote:

> The tracer started within the NMI, but out of sheer (bad) luck. That's
> because the NMI code has no logic to handle tracing interrupts on or
> off, due to the problems they cause. We may at most be able to just
> ignore all NMIs by adding a 'in_nmi()' check. I can send you a patch if
> you want.

It was trivial enough to make. Maybe this will fix things for you.

-- Steve

diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 2aefbee..500b2e0 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -453,13 +453,13 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
 #ifdef CONFIG_PROVE_LOCKING
 void time_hardirqs_on(unsigned long a0, unsigned long a1)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
stop_critical_timing(a0, a1);
 }
 
 void time_hardirqs_off(unsigned long a0, unsigned long a1)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
start_critical_timing(a0, a1);
 }
 
@@ -486,28 +486,28 @@ inline void print_irqtrace_events(struct task_struct 
*curr)
  */
 void trace_hardirqs_on(void)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
stop_critical_timing(CALLER_ADDR0, caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);
 
 void trace_hardirqs_off_caller(unsigned long caller_addr)
 {
-   if (!preempt_trace() && irq_trace())
+   if (!in_nmi() && !preempt_trace() && irq_trace())
start_critical_timing(CALLER_ADDR0, caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);
@@ -518,13 +518,13 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
 #ifdef CONFIG_PREEMPT_TRACER
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
-   if (preempt_trace() && !irq_trace())
+   if (!in_nmi() && preempt_trace() && !irq_trace())
stop_critical_timing(a0, a1);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
-   if (preempt_trace() && !irq_trace())
+   if (!in_nmi() && preempt_trace() && !irq_trace())
start_critical_timing(a0, a1);
 }
 #endif /* CONFIG_PREEMPT_TRACER */


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Fri, 2013-08-02 at 14:41 -0400, Alan Stern wrote:
> Steve:
> 
> Here's another irqsoff trace collected by James.  It's not as extreme 
> as before, but I don't know how to interpret the 875-us jump in the 
> time value.  Could this be a result of the timer being adjusted?
> 
> Also, what's the explanation for these two lines:
> 
> URL Clas-32862d...  881us : jiffies_to_timeval <-__acct_update_integrals
> URL Clas-32862d.h.  882us : exit_idle <-smp_apic_timer_interrupt
> 
> They appear to say that the CPU got a hardirq while interrupts were
> disabled.  How can that be?

If you have NMIs going off, that is probably what's causing issues.

> 
> Alan Stern
> 
> 
> # tracer: irqsoff
> #
> # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> # 
> # latency: 906 us, #93/93, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> #-
> #| task: URL Classifier-3286 (uid:1000 nice:0 policy:0 rt_prio:0)
> #-
> #  => started at: perf_event_update_userpage

I'm guessing that it enabled the tracing with perf in the NMI.
But NMI wont tell the tracer it ended :-(

> #  => ended at:   retint_swapgs
> #
> #
> #  _--=> CPU#
> # / _-=> irqs-off
> #| / _=> need-resched
> #|| / _---=> hardirq/softirq 
> #||| / _--=> preempt-depth   
> # / delay 
> #  cmd pid   | time  |   caller  
> # \   /  |  \|   /   
> URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
> URL Clas-32862d.h.2us : watchdog_overflow_callback 
> <-__perf_event_overflow
> URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
> <-nmi_handle.isra.0
> URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
> URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi

The tracer started within the NMI, but out of sheer (bad) luck. That's
because the NMI code has no logic to handle tracing interrupts on or
off, due to the problems they cause. We may at most be able to just
ignore all NMIs by adding a 'in_nmi()' check. I can send you a patch if
you want.

The other thing you can do is not run perf while this is going on.


> URL Clas-32862d...  879us : smp_apic_timer_interrupt 
> <-apic_timer_interrupt

Yes, we can have interrupts happen here. We may have even went into
userspace, as the return from NMI never told the tracer that we are
enabling interrupts again. Thus, the enable interrupt is what was
missed.

-- Steve

> URL Clas-32862d...  879us : irq_enter <-smp_apic_timer_interrupt
> URL Clas-32862d...  879us : rcu_irq_enter <-irq_enter
> URL Clas-32862d...  879us : rcu_eqs_exit_common.isra.45 <-rcu_irq_enter
> URL Clas-32862d...  880us : vtime_account_irq_enter <-irq_enter
> URL Clas-32862d...  880us : vtime_account_user <-vtime_account_irq_enter
> URL Clas-32862d...  880us : get_vtime_delta <-vtime_account_user
> URL Clas-32862d...  880us : _raw_spin_lock <-vtime_account_user


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 2 Aug 2013, Steven Rostedt wrote:

> On Fri, 2013-08-02 at 13:59 -0400, Alan Stern wrote:
> > On Fri, 2 Aug 2013, Steven Rostedt wrote:
> > 
> > > On Fri, 2013-08-02 at 16:36 +0200, Peter Zijlstra wrote:
> > > > On Fri, Aug 02, 2013 at 10:14:39AM -0400, Alan Stern wrote:
> > > > > URL Clas-32862d.h.1us : local_clock 
> > > > > <-perf_event_update_userpage
> > > > > URL Clas-32862d.h.2us : watchdog_overflow_callback 
> > > > > <-__perf_event_overflow
> > > > > URL Clas-32862d.h.3us : 
> > > > > arch_trigger_all_cpu_backtrace_handler <-nmi_handle.isra.0
> > > > > URL Clas-32862d.h.3us : perf_ibs_nmi_handler 
> > > > > <-nmi_handle.isra.0
> > > > > URL Clas-32862d.h.3us : perf_ibs_handle_irq 
> > > > > <-perf_ibs_nmi_handler
> > > > > URL Clas-32862d.h.4us : perf_ibs_handle_irq 
> > > > > <-perf_ibs_nmi_handler
> > > > > URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi
> > > > 
> > > > What's cute is that the trace starts when the NMI handler does
> > > > local_irq_save(), _not_ when the NMI starts, which is where the hardware
> > > > actually disabled interrupts.
> > > 
> > > Yeah, the NMI can be messing with the tracer. It's built on top of
> > > lockdep, which does not handle NMIs. Perhaps we can add NMI handling to
> > > the latency tracer, but that may need a bit of work to do that.
> > 
> > Do you have any suggestions with regard to the two questions in my 
> > previous email?
> 
> Do you mean the one Peter replied to? Or another one.

The one Peter replied to, where this trace output was first posted.

> I have to apologize, I'm doing admin work on my Red Hat box, and it's
> having network issues at the moment.

That's okay.  (And I finally remembered to switch to your goodmis.org
email address.)

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Fri, 2013-08-02 at 13:59 -0400, Alan Stern wrote:
> On Fri, 2 Aug 2013, Steven Rostedt wrote:
> 
> > On Fri, 2013-08-02 at 16:36 +0200, Peter Zijlstra wrote:
> > > On Fri, Aug 02, 2013 at 10:14:39AM -0400, Alan Stern wrote:
> > > > URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
> > > > URL Clas-32862d.h.2us : watchdog_overflow_callback 
> > > > <-__perf_event_overflow
> > > > URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
> > > > <-nmi_handle.isra.0
> > > > URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
> > > > URL Clas-32862d.h.3us : perf_ibs_handle_irq 
> > > > <-perf_ibs_nmi_handler
> > > > URL Clas-32862d.h.4us : perf_ibs_handle_irq 
> > > > <-perf_ibs_nmi_handler
> > > > URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi
> > > 
> > > What's cute is that the trace starts when the NMI handler does
> > > local_irq_save(), _not_ when the NMI starts, which is where the hardware
> > > actually disabled interrupts.
> > 
> > Yeah, the NMI can be messing with the tracer. It's built on top of
> > lockdep, which does not handle NMIs. Perhaps we can add NMI handling to
> > the latency tracer, but that may need a bit of work to do that.
> 
> Do you have any suggestions with regard to the two questions in my 
> previous email?

Do you mean the one Peter replied to? Or another one.

I have to apologize, I'm doing admin work on my Red Hat box, and it's
having network issues at the moment.

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 2 Aug 2013, Steven Rostedt wrote:

> On Fri, 2013-08-02 at 16:36 +0200, Peter Zijlstra wrote:
> > On Fri, Aug 02, 2013 at 10:14:39AM -0400, Alan Stern wrote:
> > > URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
> > > URL Clas-32862d.h.2us : watchdog_overflow_callback 
> > > <-__perf_event_overflow
> > > URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
> > > <-nmi_handle.isra.0
> > > URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
> > > URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> > > URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> > > URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi
> > 
> > What's cute is that the trace starts when the NMI handler does
> > local_irq_save(), _not_ when the NMI starts, which is where the hardware
> > actually disabled interrupts.
> 
> Yeah, the NMI can be messing with the tracer. It's built on top of
> lockdep, which does not handle NMIs. Perhaps we can add NMI handling to
> the latency tracer, but that may need a bit of work to do that.

Do you have any suggestions with regard to the two questions in my 
previous email?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Fri, 2013-08-02 at 16:36 +0200, Peter Zijlstra wrote:
> On Fri, Aug 02, 2013 at 10:14:39AM -0400, Alan Stern wrote:
> > URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
> > URL Clas-32862d.h.2us : watchdog_overflow_callback 
> > <-__perf_event_overflow
> > URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
> > <-nmi_handle.isra.0
> > URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
> > URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> > URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> > URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi
> 
> What's cute is that the trace starts when the NMI handler does
> local_irq_save(), _not_ when the NMI starts, which is where the hardware
> actually disabled interrupts.

Yeah, the NMI can be messing with the tracer. It's built on top of
lockdep, which does not handle NMIs. Perhaps we can add NMI handling to
the latency tracer, but that may need a bit of work to do that.

-- Steve

> 
> > URL Clas-32862d...  879us : smp_apic_timer_interrupt 
> > <-apic_timer_interrupt
> 
> And then we have hit massive jump.. out of nowhere. weirdness.


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Peter Zijlstra]

On Fri, Aug 02, 2013 at 10:14:39AM -0400, Alan Stern wrote:
> URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
> URL Clas-32862d.h.2us : watchdog_overflow_callback 
> <-__perf_event_overflow
> URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
> <-nmi_handle.isra.0
> URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
> URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
> URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi

What's cute is that the trace starts when the NMI handler does
local_irq_save(), _not_ when the NMI starts, which is where the hardware
actually disabled interrupts.

> URL Clas-32862d...  879us : smp_apic_timer_interrupt 
> <-apic_timer_interrupt

And then we have hit massive jump.. out of nowhere. weirdness.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

Steve:

Here's another irqsoff trace collected by James.  It's not as extreme 
as before, but I don't know how to interpret the 875-us jump in the 
time value.  Could this be a result of the timer being adjusted?

Also, what's the explanation for these two lines:

URL Clas-32862d...  881us : jiffies_to_timeval <-__acct_update_integrals
URL Clas-32862d.h.  882us : exit_idle <-smp_apic_timer_interrupt

They appear to say that the CPU got a hardirq while interrupts were
disabled.  How can that be?

Alan Stern


# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.10.0-ver5
# 
# latency: 906 us, #93/93, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
#-
#| task: URL Classifier-3286 (uid:1000 nice:0 policy:0 rt_prio:0)
#-
#  => started at: perf_event_update_userpage
#  => ended at:   retint_swapgs
#
#
#  _--=> CPU#
# / _-=> irqs-off
#| / _=> need-resched
#|| / _---=> hardirq/softirq 
#||| / _--=> preempt-depth   
# / delay 
#  cmd pid   | time  |   caller  
# \   /  |  \|   /   
URL Clas-32862d.h.1us : local_clock <-perf_event_update_userpage
URL Clas-32862d.h.2us : watchdog_overflow_callback 
<-__perf_event_overflow
URL Clas-32862d.h.3us : arch_trigger_all_cpu_backtrace_handler 
<-nmi_handle.isra.0
URL Clas-32862d.h.3us : perf_ibs_nmi_handler <-nmi_handle.isra.0
URL Clas-32862d.h.3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
URL Clas-32862d.h.4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler
URL Clas-32862d.h.4us!: rcu_nmi_exit <-do_nmi
URL Clas-32862d...  879us : smp_apic_timer_interrupt <-apic_timer_interrupt
URL Clas-32862d...  879us : irq_enter <-smp_apic_timer_interrupt
URL Clas-32862d...  879us : rcu_irq_enter <-irq_enter
URL Clas-32862d...  879us : rcu_eqs_exit_common.isra.45 <-rcu_irq_enter
URL Clas-32862d...  880us : vtime_account_irq_enter <-irq_enter
URL Clas-32862d...  880us : vtime_account_user <-vtime_account_irq_enter
URL Clas-32862d...  880us : get_vtime_delta <-vtime_account_user
URL Clas-32862d...  880us : _raw_spin_lock <-vtime_account_user
URL Clas-32862d...  881us : account_user_time <-vtime_account_user
URL Clas-32862d...  881us : cpuacct_account_field <-account_user_time
URL Clas-32862d...  881us : acct_account_cputime <-account_user_time
URL Clas-32862d...  881us : __acct_update_integrals <-acct_account_cputime
URL Clas-32862d...  881us : jiffies_to_timeval <-__acct_update_integrals
URL Clas-32862d.h.  882us : exit_idle <-smp_apic_timer_interrupt
URL Clas-32862d.h.  882us : hrtimer_interrupt <-smp_apic_timer_interrupt
URL Clas-32862d.h.  882us : _raw_spin_lock <-hrtimer_interrupt
URL Clas-32862d.h.  883us : ktime_get_update_offsets <-hrtimer_interrupt
URL Clas-32862d.h.  883us : __run_hrtimer <-hrtimer_interrupt
URL Clas-32862d.h.  884us : __remove_hrtimer <-__run_hrtimer
URL Clas-32862d.h.  884us : hrtimer_wakeup <-__run_hrtimer
URL Clas-32862d.h.  884us : wake_up_process <-hrtimer_wakeup
URL Clas-32862d.h.  885us : try_to_wake_up <-wake_up_process
URL Clas-32862d.h.  885us : _raw_spin_lock_irqsave <-try_to_wake_up
URL Clas-32862d.h.  886us : task_waking_fair <-try_to_wake_up
URL Clas-32862d.h.  886us : select_task_rq_fair <-try_to_wake_up
URL Clas-32862d.h.  887us : idle_cpu <-select_task_rq_fair
URL Clas-32862d.h.  888us : idle_cpu <-select_task_rq_fair
URL Clas-32862d.h.  889us : set_task_cpu <-try_to_wake_up
URL Clas-32862d.h.  889us : migrate_task_rq_fair <-set_task_cpu
URL Clas-32862d.h.  890us : atomic_notifier_call_chain <-set_task_cpu
URL Clas-32862d.h.  890us : __atomic_notifier_call_chain 
<-atomic_notifier_call_chain
URL Clas-32862d.h.  890us : notifier_call_chain 
<-__atomic_notifier_call_chain
URL Clas-32862d.h.  891us : _raw_spin_lock <-try_to_wake_up
URL Clas-32862d.h.  891us : ttwu_do_activate.constprop.76 <-try_to_wake_up
URL Clas-32862d.h.  892us : activate_task <-ttwu_do_activate.constprop.76
URL Clas-32862d.h.  892us : enqueue_task <-activate_task
URL Clas-32862d.h.  892us : update_rq_clock <-enqueue_task
URL Clas-32862d.h.  892us : enqueue_task_fair <-enqueue_task
URL Clas-32862d.h.  892us : enqueue_entity <-enqueue_task_fair
URL Clas-32862d.h.  893us : update_curr <-enqueue_entity
URL Clas-32862d.h.  894us : __compute_runnable_contrib <-enqueue_entity
URL Clas-32862d.h.  894us : __update_entity_load_avg_contrib 
<-enqueue_entity
URL Clas-32862d.h.  894us : update_cfs_rq_blocked_load <-enqueue_entity
URL Clas-32862d.h.  895us : account_entity_enqueue <-enqueue_entity
URL Clas-32862d.h.  895us : update_cfs_shares <-enqueue_enti

Re: Audio I/O parameters

[James Stone]

On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern  wrote:
> On Thu, 1 Aug 2013, James Stone wrote:
>
>> > SMIs are controlled by the BIOS, not by the kernel.  I don't think
>> > changing the kernel would affect their timings.
>> >
>>
>> Hmm.. ok. So do I need to see if there is a bios update/report this to
>> motherboard manufacturer?
>
> If there's an update available, you ought to apply it.
>
> I don't know if talking to the motherboard manufacturer will accomplish
> anything.  They're not likely to listen to you, and in any case, they
> probably didn't write their own BIOS.
>
>> > Okay, so the USB controllers do share IRQ lines.  Were you using the
>> > other USB buses when the errors occurred?
>>
>> Webcam microphone might have been on.
>
> You should try testing with no other USB activity going on.  Just in
> case.
>

Not yet tried this, but I have tested the latest bios, and still get
the same lockup. Full function-trace attached.


trace
Description: Binary data

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> On Thu, 1 Aug 2013, Clemens Ladisch wrote:
>>> It seems likely that the error is caused by an SMI taking too much
>>> time.  At least, we seem to have ruled out everything else.  Besides,
>>> this change has to be made eventually in any case -- underruns can
>>> occur at any time, in principle, and they shouldn't cause the audio
>>> driver to fail.
>>
>> Well, the failure is a bug in snd-usb-audio: when usb_submit_urb fails,
>> it should report the underrun so that the stream can be stopped and
>> restarted cleanly.  This would be done by the snd_pcm_stop() call in
>> endpoint.c which is currently commented out because of locking problems.
>
> Should we have some sort of threshold for how long an underrun can be
> before it causes a submission failure?
>
> Presumably an underrun of a few ms should not cause the stream to be
> stopped and restarted.  An underrun of 100 ms or more probably should.
> Where do we put the cutoff?

This is policy which should not be decided by the HCD; the driver can
decide whether to stop the stream when it sees the error in the
completion callback.

If there was an underrun, packets will fail+complete faster until the
queue has caught up to the actual schedule.  When the length of the
underrun is longer than ALSA's ring buffer, that fast draining of data
will result in an underrun of the ring buffer.  The policy for these
underruns (stop or ignore) can be set by ALSA applications.

So a longer cutoff allows drivers and applications to ignore longer
underruns, if they choose to do so, or to treat them as errors anyway.

So there is no reason for HCDs to make the cutoff smaller than required
for technical reasons.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 1 Aug 2013, James Stone wrote:

> > SMIs are controlled by the BIOS, not by the kernel.  I don't think
> > changing the kernel would affect their timings.
> >
> 
> Hmm.. ok. So do I need to see if there is a bios update/report this to
> motherboard manufacturer?

If there's an update available, you ought to apply it.

I don't know if talking to the motherboard manufacturer will accomplish 
anything.  They're not likely to listen to you, and in any case, they 
probably didn't write their own BIOS.

> > Okay, so the USB controllers do share IRQ lines.  Were you using the
> > other USB buses when the errors occurred?
> 
> Webcam microphone might have been on.

You should try testing with no other USB activity going on.  Just in
case.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 1 Aug 2013, Clemens Ladisch wrote:

> > It seems likely that the error is caused by an SMI taking too much
> > time.  At least, we seem to have ruled out everything else.  Besides,
> > this change has to be made eventually in any case -- underruns can
> > occur at any time, in principle, and they shouldn't cause the audio
> > driver to fail.
> 
> Well, the failure is a bug in snd-usb-audio: when usb_submit_urb fails,
> it should report the underrun so that the stream can be stopped and
> restarted cleanly.  This would be done by the snd_pcm_stop() call in
> endpoint.c which is currently commented out because of locking problems.

Should we have some sort of threshold for how long an underrun can be 
before it causes a submission failure?

Presumably an underrun of a few ms should not cause the stream to be 
stopped and restarted.  An underrun of 100 ms or more probably should.  
Where do we put the cutoff?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 1 Aug 2013, James Stone wrote:

> I've got some error messages written to syslog now - with no audible
> effect on audio processing:

> Aug  1 01:12:36 blueberry kernel: [ 6233.028335] ehci-pci
> :00:12.2: iso underrun 8800c872db00 (1407+0 < 1471)

That's an impressive one.  It indicates no interrupts occurred during a
period of at least (1471 - 1407)/8 = 8 ms!  That should have produced
an audible click, if you were listening at the right time and if a 
nonzero sound was playing.

> Aug  1 01:12:36 blueberry kernel: [ 6233.028341] ehci-pci
> :00:12.2: iso underrun 88002e6f6800 (1392+7 < 1471)
> Aug  1 01:12:36 blueberry kernel: [ 6233.028347] ehci-pci
> :00:12.2: iso underrun 8800b65b5e00 (1401+7 < 1471)
...
> Aug  1 01:12:36 blueberry kernel: [ 6233.028462] ehci-pci
> :00:12.2: iso underrun 88002e6f6800 (1464+7 < 1472)

These messages show the audio driver catching up.

> Aug  1 01:12:36 blueberry kernel: [ 6233.028493] ehci-pci
> :00:13.2: iso underrun 8800c9fa6900 (2535+0 < 2606)

I don't understand what happened here.  The microframe number increased
by 1134 from the preceding message, indicating that some 140 ms had
elapsed, but the kernel's timestamp went up by only 30 us.

Something is very wrong in your system.  Maybe in the EHCI hardware, 
maybe in the BIOS firmware, maybe somewhere else.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Wed, 31 Jul 2013, James Stone wrote:

> > It seems likely that the error is caused by an SMI taking too much
> > time.  At least, we seem to have ruled out everything else.  Besides,
> > this change has to be made eventually in any case -- underruns can
> > occur at any time, in principle, and they shouldn't cause the audio
> > driver to fail.
> 
> Yep - that makes sense. But has there been a change in SMI timings
> with the new kernel?

SMIs are controlled by the BIOS, not by the kernel.  I don't think 
changing the kernel would affect their timings.

>  I don't think this bug happened with earlier
> kernels.

It depends on what you mean.  The underruns almost certainly did occur 
with earlier kernels.  But they didn't cause failures, so you weren't 
aware of them.

> Oh, by the way, should I be adding anything to #1191603
> seeing as this (non-realtime) bug seems to be the same one everyone
> else is complaining about?

It's up to you.  Bear in mind that your problems have involved three or
four other bugs in addition.

> > By the way, can you post the contents of /proc/interrupts?  I'd like to
> > see if the IRQ line in question is shared.
> >
>CPU0   CPU1   CPU2   CPU3
>  17:5261388  0  1104   IO-APIC-fasteoi
> ehci_hcd:usb1, ehci_hcd:usb2, ehci_hcd:usb3
>  18:  0 52  26049408   IO-APIC-fasteoi
> ohci_hcd:usb4, ohci_hcd:usb5, ohci_hcd:usb6, ohci_hcd:usb7

Okay, so the USB controllers do share IRQ lines.  Were you using the 
other USB buses when the errors occurred?

> >> I just managed to induce another cannot submit URB bug, and there is
> >> definitely nothing written to trace around the time of this bug, with
> >> the settings:
> >>
> >> echo 0 > options/function-trace
> >> echo irqsoff > current_tracer
> >> echo 1 > tracing_on
> >> echo 0 > tracing_max_latency
> >
> > You may need to do "echo 0 >tracing_on" before looking at the file.
> > I'm not sure.
> >
> 
> I don't think that's necessary - it seems to update the file without this.

All right.

> > But the tracer certainly should contain _something_, because interrupts
> > are constantly being disabled and enabled during normal system
> > operation.  Even if nothing went wrong, there would still be a nonzero
> > latency.
> 
> Yes - there was something - from recollection it was some firefox
> process with a latency of 2000us, but what I meant is that nothing new
> seemed to be written at the time the bug happened.

That's to be expected.  The tracer records the _longest_ time that 
interrupts were disabled.  When the bug happened, interrupts were 
disabled for a long time, but it may not have been the longest up to 
that point.

> The file now has:
>  cc1-21060   2d.h.0us!: local_clock <-perf_event_update_userpage
>  cc1-21060   2dN.. 3803us+: trace_hardirqs_on_thunk <-retint_careful
>  cc1-21060   2dN.. 3806us+: trace_hardirqs_on_caller <-retint_careful
>  cc1-21060   2dN.. 3812us : 
>  => trace_hardirqs_on_thunk
> 
> but this is with kernel build going on..

The load shouldn't matter much, as far as I know.  Steven Rostedt said
that perf_event_update_userpage shouldn't take 2 ms; therefore we can
be pretty sure that it shouldn't take 3.8 ms.  :-)

Try running the tracer with "echo 1 > options/function-trace".  That 
ought to provide additional useful information.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> On Wed, 31 Jul 2013, James Stone wrote:
>> On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern  
>> wrote:
>>> James, see what happens with this patch.  It will print a warning
>>> message in the system log every time it detects an underrun, but it
>>> won't cause an URB submission failure any more.
>>
>> OK - I will try it, however, it seems a bit like papering over the
>> cracks without really understanding what's causing the error..
>
> It seems likely that the error is caused by an SMI taking too much
> time.  At least, we seem to have ruled out everything else.  Besides,
> this change has to be made eventually in any case -- underruns can
> occur at any time, in principle, and they shouldn't cause the audio
> driver to fail.

Well, the failure is a bug in snd-usb-audio: when usb_submit_urb fails,
it should report the underrun so that the stream can be stopped and
restarted cleanly.  This would be done by the snd_pcm_stop() call in
endpoint.c which is currently commented out because of locking problems.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 31, 2013 at 10:07 PM, Alan Stern  wrote:
> On Wed, 31 Jul 2013, James Stone wrote:
>
>> On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern  
>> wrote:
>> > On Tue, 30 Jul 2013, Alan Stern wrote:
>> >
>> >> I can try to ameliorate the situation.  Although the 7-ms delay will
>> >> inevitably cause an underrun, it doesn't have to cause errors the way
>> >> it does now.  I'll write a patch to handle this.  It may take a few
>> >> days.
>> >
>> > James, see what happens with this patch.  It will print a warning
>> > message in the system log every time it detects an underrun, but it
>> > won't cause an URB submission failure any more.
>> >
>>
>> OK - I will try it, however, it seems a bit like papering over the
>> cracks without really understanding what's causing the error..
>
> It seems likely that the error is caused by an SMI taking too much
> time.  At least, we seem to have ruled out everything else.  Besides,
> this change has to be made eventually in any case -- underruns can
> occur at any time, in principle, and they shouldn't cause the audio
> driver to fail.
>
> By the way, can you post the contents of /proc/interrupts?  I'd like to
> see if the IRQ line in question is shared.
>
>> I just managed to induce another cannot submit URB bug, and there is
>> definitely nothing written to trace around the time of this bug, with
>> the settings:
>>
>> echo 0 > options/function-trace
>> echo irqsoff > current_tracer
>> echo 1 > tracing_on
>> echo 0 > tracing_max_latency
>
> You may need to do "echo 0 >tracing_on" before looking at the file.
> I'm not sure.
>
> But the tracer certainly should contain _something_, because interrupts
> are constantly being disabled and enabled during normal system
> operation.  Even if nothing went wrong, there would still be a nonzero
> latency.
>
> Alan Stern
>

I've got some error messages written to syslog now - with no audible
effect on audio processing:

Aug  1 01:12:36 blueberry kernel: [ 6233.016246] ehci-pci
:00:12.2: iso underrun 88002e6f7600 (1360+7 < 1374)
Aug  1 01:12:36 blueberry kernel: [ 6233.016275] retire_capture_urb:
27 callbacks suppressed
Aug  1 01:12:36 blueberry kernel: [ 6233.016287] ehci-pci
:00:13.2: iso underrun 8800c9fa6700 (2503+0 < 2509)
Aug  1 01:12:36 blueberry kernel: [ 6233.028335] ehci-pci
:00:12.2: iso underrun 8800c872db00 (1407+0 < 1471)
Aug  1 01:12:36 blueberry kernel: [ 6233.028341] ehci-pci
:00:12.2: iso underrun 88002e6f6800 (1392+7 < 1471)
Aug  1 01:12:36 blueberry kernel: [ 6233.028347] ehci-pci
:00:12.2: iso underrun 8800b65b5e00 (1401+7 < 1471)
Aug  1 01:12:36 blueberry kernel: [ 6233.028350] ehci-pci
:00:12.2: iso underrun 88002df88800 (1415+0 < 1471)
Aug  1 01:12:36 blueberry kernel: [ 6233.028355] ehci-pci
:00:12.2: iso underrun 88002e6f7000 (1400+7 < 1471)
Aug  1 01:12:36 blueberry kernel: [ 6233.028361] ehci-pci
:00:12.2: iso underrun 8800b65b4600 (1409+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028364] ehci-pci
:00:12.2: iso underrun 8800c9c93600 (1423+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028369] ehci-pci
:00:12.2: iso underrun 88002e6f7600 (1408+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028374] ehci-pci
:00:12.2: iso underrun 8800b65b4800 (1417+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028377] ehci-pci
:00:12.2: iso underrun 8800c9c93f00 (1431+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028382] ehci-pci
:00:12.2: iso underrun 88002e6f6800 (1416+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028387] ehci-pci
:00:12.2: iso underrun 8800b65b4200 (1425+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028390] ehci-pci
:00:12.2: iso underrun 8800c872db00 (1439+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028395] ehci-pci
:00:12.2: iso underrun 88002e6f7000 (1424+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028400] ehci-pci
:00:12.2: iso underrun 8800b65b5e00 (1433+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028404] ehci-pci
:00:12.2: iso underrun 88002df88800 (1447+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028409] ehci-pci
:00:12.2: iso underrun 88002e6f7600 (1432+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028415] ehci-pci
:00:12.2: iso underrun 8800b65b4600 (1441+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028418] ehci-pci
:00:12.2: iso underrun 8800c9c93600 (1455+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028424] ehci-pci
:00:12.2: iso underrun 88002e6f6800 (1440+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028429] ehci-pci
:00:12.2: iso underrun 8800b65b4800 (1449+7 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028432] ehci-pci
:00:12.2: iso underrun 8800c9c93f00 (1463+0 < 1472)
Aug  1 01:12:36 blueberry kernel: [ 6233.028438] ehci-pci
:00:12.2: iso underrun 88002e6f7000 (1448+7 < 1472)
Aug  1 01:12:36 blueberry ke

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 31, 2013 at 10:07 PM, Alan Stern  wrote:
> On Wed, 31 Jul 2013, James Stone wrote:
>
>> On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern  
>> wrote:
>> > On Tue, 30 Jul 2013, Alan Stern wrote:
>> >
>> >> I can try to ameliorate the situation.  Although the 7-ms delay will
>> >> inevitably cause an underrun, it doesn't have to cause errors the way
>> >> it does now.  I'll write a patch to handle this.  It may take a few
>> >> days.
>> >
>> > James, see what happens with this patch.  It will print a warning
>> > message in the system log every time it detects an underrun, but it
>> > won't cause an URB submission failure any more.
>> >
>>
>> OK - I will try it, however, it seems a bit like papering over the
>> cracks without really understanding what's causing the error..
>
> It seems likely that the error is caused by an SMI taking too much
> time.  At least, we seem to have ruled out everything else.  Besides,
> this change has to be made eventually in any case -- underruns can
> occur at any time, in principle, and they shouldn't cause the audio
> driver to fail.

Yep - that makes sense. But has there been a change in SMI timings
with the new kernel? I don't think this bug happened with earlier
kernels. Oh, by the way, should I be adding anything to #1191603
seeing as this (non-realtime) bug seems to be the same one everyone
else is complaining about?

>
> By the way, can you post the contents of /proc/interrupts?  I'd like to
> see if the IRQ line in question is shared.
>
   CPU0   CPU1   CPU2   CPU3
  0: 43  0  0  0   IO-APIC-edge  timer
  1:  0  6125   8193   IO-APIC-edge  i8042
  4:  1  0  0  3   IO-APIC-edge
  7:  1  0  0  0   IO-APIC-edge
  8:  0  0  0  1   IO-APIC-edge  rtc0
  9:  0  0  0  0   IO-APIC-fasteoi   acpi
 12:  6 41   1399 132585   IO-APIC-edge  i8042
 14:  0  0  0  0   IO-APIC-edge  pata_atiixp
 15:  0  0  0  0   IO-APIC-edge  pata_atiixp
 17:5261388  0  1104   IO-APIC-fasteoi
ehci_hcd:usb1, ehci_hcd:usb2, ehci_hcd:usb3
 18:  0 52  26049408   IO-APIC-fasteoi
ohci_hcd:usb4, ohci_hcd:usb5, ohci_hcd:usb6, ohci_hcd:usb7
 19:285  1   2468 115973   IO-APIC-fasteoi   ahci
 20:  0 179690  3625   IO-APIC-fasteoi
:01:05.0
 40:  0  0  0  0   PCI-MSI-edge  PCIe PME
 41:  0  0  0  0   PCI-MSI-edge  PCIe PME
 42:  1  5136  13765   PCI-MSI-edge  radeon
 43:  0  0  0  0   PCI-MSI-edge  eth0
NMI:249250250251   Non-maskable interrupts
LOC:1429195155923313739521109102   Local timer interrupts
SPU:  0  0  0  0   Spurious interrupts
PMI:249250250251   Performance
monitoring interrupts
IWI:  10666   9404  10633  11032   IRQ work interrupts
RTR:  0  0  0  0   APIC ICR read retries
RES:1101840111518911413091180596   Rescheduling interrupts
CAL:652919780959   Function call interrupts
TLB:  33102  20339  28625  26571   TLB shootdowns
TRM:  0  0  0  0   Thermal event interrupts
THR:  0  0  0  0   Threshold APIC interrupts
MCE:  0  0  0  0   Machine check exceptions
MCP: 19 19 19 19   Machine check polls
ERR:  1
MIS:  0


>> I just managed to induce another cannot submit URB bug, and there is
>> definitely nothing written to trace around the time of this bug, with
>> the settings:
>>
>> echo 0 > options/function-trace
>> echo irqsoff > current_tracer
>> echo 1 > tracing_on
>> echo 0 > tracing_max_latency
>
> You may need to do "echo 0 >tracing_on" before looking at the file.
> I'm not sure.
>

I don't think that's necessary - it seems to update the file without this.

> But the tracer certainly should contain _something_, because interrupts
> are constantly being disabled and enabled during normal system
> operation.  Even if nothing went wrong, there would still be a nonzero
> latency.

Yes - there was something - from recollection it was some firefox
process with a latency of 2000us, but what I meant is that nothing new
seemed to be written at the time the bug happened.

The file now has:
 cc1-21060   2d.h.0us!: local_clock <-perf_event_update_userpage
 cc1-21060   2dN.. 3803us+: trace_hardirqs_on_thunk <-retint_careful
 cc1-21060   2dN.. 3806us+: trace_hardirqs_on_ca

Re: Audio I/O parameters

[Alan Stern]

On Wed, 31 Jul 2013, James Stone wrote:

> On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern  wrote:
> > On Tue, 30 Jul 2013, Alan Stern wrote:
> >
> >> I can try to ameliorate the situation.  Although the 7-ms delay will
> >> inevitably cause an underrun, it doesn't have to cause errors the way
> >> it does now.  I'll write a patch to handle this.  It may take a few
> >> days.
> >
> > James, see what happens with this patch.  It will print a warning
> > message in the system log every time it detects an underrun, but it
> > won't cause an URB submission failure any more.
> >
> 
> OK - I will try it, however, it seems a bit like papering over the
> cracks without really understanding what's causing the error..

It seems likely that the error is caused by an SMI taking too much 
time.  At least, we seem to have ruled out everything else.  Besides, 
this change has to be made eventually in any case -- underruns can 
occur at any time, in principle, and they shouldn't cause the audio 
driver to fail.

By the way, can you post the contents of /proc/interrupts?  I'd like to 
see if the IRQ line in question is shared.

> I just managed to induce another cannot submit URB bug, and there is
> definitely nothing written to trace around the time of this bug, with
> the settings:
> 
> echo 0 > options/function-trace
> echo irqsoff > current_tracer
> echo 1 > tracing_on
> echo 0 > tracing_max_latency

You may need to do "echo 0 >tracing_on" before looking at the file.  
I'm not sure.

But the tracer certainly should contain _something_, because interrupts
are constantly being disabled and enabled during normal system
operation.  Even if nothing went wrong, there would still be a nonzero
latency.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern  wrote:
> On Tue, 30 Jul 2013, Alan Stern wrote:
>
>> I can try to ameliorate the situation.  Although the 7-ms delay will
>> inevitably cause an underrun, it doesn't have to cause errors the way
>> it does now.  I'll write a patch to handle this.  It may take a few
>> days.
>
> James, see what happens with this patch.  It will print a warning
> message in the system log every time it detects an underrun, but it
> won't cause an URB submission failure any more.
>

OK - I will try it, however, it seems a bit like papering over the
cracks without really understanding what's causing the error..

I just managed to induce another cannot submit URB bug, and there is
definitely nothing written to trace around the time of this bug, with
the settings:

echo 0 > options/function-trace
echo irqsoff > current_tracer
echo 1 > tracing_on
echo 0 > tracing_max_latency

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 30 Jul 2013, Alan Stern wrote:

> I can try to ameliorate the situation.  Although the 7-ms delay will
> inevitably cause an underrun, it doesn't have to cause errors the way
> it does now.  I'll write a patch to handle this.  It may take a few
> days.

James, see what happens with this patch.  It will print a warning 
message in the system log every time it detects an underrun, but it 
won't cause an URB submission failure any more.

Alan Stern



Index: usb-3.11/drivers/usb/host/ehci-sched.c
===
--- usb-3.11.orig/drivers/usb/host/ehci-sched.c
+++ usb-3.11/drivers/usb/host/ehci-sched.c
@@ -1391,21 +1391,20 @@ iso_stream_schedule (
 
/* Behind the scheduling threshold? */
if (unlikely(start < next)) {
+   unsigned now2 = (now - base) & (mod - 1);
 
/* USB_ISO_ASAP: Round up to the first available slot */
if (urb->transfer_flags & URB_ISO_ASAP)
start += (next - start + period - 1) & -period;
 
/*
-* Not ASAP: Use the next slot in the stream.  If
-* the entire URB falls before the threshold, fail.
+* Not ASAP: Use the next slot in the stream,
+* no matter what.
 */
-   else if (start + span - period < next) {
-   ehci_dbg(ehci, "iso urb late %p (%u+%u < %u)\n",
+   else if (start + span - period < now2) {
+   ehci_warn(ehci, "iso underrun %p (%u+%u < 
%u)\n",
urb, start + base,
-   span - period, next + base);
-   status = -EXDEV;
-   goto fail;
+   span - period, now2 + base);
}
}
 

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Tue, 2013-07-30 at 14:41 -0400, Alan Stern wrote:
> On Tue, 30 Jul 2013, Steven Rostedt wrote:
> 
> > On Tue, 2013-07-30 at 11:42 -0400, Alan Stern wrote:
> > > On Mon, 29 Jul 2013, James Stone wrote:
> > 
> > Just an FYI, it is usually better to email my rost...@goodmis.org
> > account. I don't always read my redhat email. That's reserved for
> > bugzillas assigned to me ;-)
> 
> I got the address from the top of Documentation/trace/ftrace.txt (which
> I was reading at the time to make sure I understood the trace output
> correctly).  Should that file be updated?
> 

Yes, thanks for letting me know. I used that email a while ago, but I
didn't like having Red Hat business mixed in with my upstream work.


> > > > # tracer: irqsoff
> > > > #
> > > > # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> > > > # 
> > > > # latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> > > > #-
> > > > #| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
> > > > #-
> > > > #  => started at: perf_event_update_userpage
> > > > #  => ended at:   retint_careful
> > > > #
> > > > #
> > > > #  _--=> CPU#
> > > > # / _-=> irqs-off
> > > > #| / _=> need-resched
> > > > #|| / _---=> hardirq/softirq
> > > > #||| / _--=> preempt-depth
> > > > # / delay
> > > > #  cmd pid   | time  |   caller
> > > > # \   /  |  \|   /
> > > > apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage
> > 
> > perf_event_update_userpage should not be taking 2ms to complete.
> 
> How can that be chased down?  And even so, 2 ms is a lot smaller than 7 
> ms.
> 
> > > This suggests that the IRQ line was disabled or interrupts were
> > > disabled on all four CPUs for 7 ms.  However, the irqsoff trace shows
> > > that the maximum latency was 2 ms.  Something strange is going on, but
> > > I don't know what or how to find it.
> > > 
> > > Steve, do you have any ideas about this?  Or suggestions for other 
> > > people to ask?
> > 
> > Is there SMIs on this box? Those will not be detected by the latency
> > tracers directly. But we do have other tools to detect them.
> 
> What are they, and how can James try them?

We have them in the -rt kernel. But they need some work too. Which
should get me to push that up on my todo list :-/

-- Steve



--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Peter Zijlstra]

On Tue, Jul 30, 2013 at 02:05:29PM -0400, Steven Rostedt wrote:
> On Tue, 2013-07-30 at 11:42 -0400, Alan Stern wrote:
> > On Mon, 29 Jul 2013, James Stone wrote:
> 
> Just an FYI, it is usually better to email my rost...@goodmis.org
> account. I don't always read my redhat email. That's reserved for
> bugzillas assigned to me ;-)
> 
> > 
> > > OK, having said that, I just got it to happen - listening to audacity
> > > and just logging into Facebook (of all things!! Meh!)
> > > 
> > > This is the contents of the trace file (as per instructions on bug 
> > > #1191603)
> > > 
> > > # tracer: irqsoff
> > > #
> > > # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> > > # 
> > > # latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> > > #-
> > > #| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
> > > #-
> > > #  => started at: perf_event_update_userpage
> > > #  => ended at:   retint_careful
> > > #
> > > #
> > > #  _--=> CPU#
> > > # / _-=> irqs-off
> > > #| / _=> need-resched
> > > #|| / _---=> hardirq/softirq
> > > #||| / _--=> preempt-depth
> > > # / delay
> > > #  cmd pid   | time  |   caller
> > > # \   /  |  \|   /
> > > apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage
> 
> perf_event_update_userpage should not be taking 2ms to complete.
> 
> > This suggests that the IRQ line was disabled or interrupts were
> > disabled on all four CPUs for 7 ms.  However, the irqsoff trace shows
> > that the maximum latency was 2 ms.  Something strange is going on, but
> > I don't know what or how to find it.
> > 
> > Steve, do you have any ideas about this?  Or suggestions for other 
> > people to ask?
> 
> Is there SMIs on this box? Those will not be detected by the latency
> tracers directly. But we do have other tools to detect them.

Right, NMI shouldn't be on all CPUs concurrently, and while its possible
to get very long NMIs with perf (callchains tend to take a while) 7ms
sounds like very long on a regular machine (there's issues with SGI
class NUMA machines).


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 30 Jul 2013, Steven Rostedt wrote:

> On Tue, 2013-07-30 at 11:42 -0400, Alan Stern wrote:
> > On Mon, 29 Jul 2013, James Stone wrote:
> 
> Just an FYI, it is usually better to email my rost...@goodmis.org
> account. I don't always read my redhat email. That's reserved for
> bugzillas assigned to me ;-)

I got the address from the top of Documentation/trace/ftrace.txt (which
I was reading at the time to make sure I understood the trace output
correctly).  Should that file be updated?

> > > # tracer: irqsoff
> > > #
> > > # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> > > # 
> > > # latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> > > #-
> > > #| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
> > > #-
> > > #  => started at: perf_event_update_userpage
> > > #  => ended at:   retint_careful
> > > #
> > > #
> > > #  _--=> CPU#
> > > # / _-=> irqs-off
> > > #| / _=> need-resched
> > > #|| / _---=> hardirq/softirq
> > > #||| / _--=> preempt-depth
> > > # / delay
> > > #  cmd pid   | time  |   caller
> > > # \   /  |  \|   /
> > > apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage
> 
> perf_event_update_userpage should not be taking 2ms to complete.

How can that be chased down?  And even so, 2 ms is a lot smaller than 7 
ms.

> > This suggests that the IRQ line was disabled or interrupts were
> > disabled on all four CPUs for 7 ms.  However, the irqsoff trace shows
> > that the maximum latency was 2 ms.  Something strange is going on, but
> > I don't know what or how to find it.
> > 
> > Steve, do you have any ideas about this?  Or suggestions for other 
> > people to ask?
> 
> Is there SMIs on this box? Those will not be detected by the latency
> tracers directly. But we do have other tools to detect them.

What are they, and how can James try them?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Steven Rostedt]

On Tue, 2013-07-30 at 11:42 -0400, Alan Stern wrote:
> On Mon, 29 Jul 2013, James Stone wrote:

Just an FYI, it is usually better to email my rost...@goodmis.org
account. I don't always read my redhat email. That's reserved for
bugzillas assigned to me ;-)

> 
> > OK, having said that, I just got it to happen - listening to audacity
> > and just logging into Facebook (of all things!! Meh!)
> > 
> > This is the contents of the trace file (as per instructions on bug #1191603)
> > 
> > # tracer: irqsoff
> > #
> > # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> > # 
> > # latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> > #-
> > #| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
> > #-
> > #  => started at: perf_event_update_userpage
> > #  => ended at:   retint_careful
> > #
> > #
> > #  _--=> CPU#
> > # / _-=> irqs-off
> > #| / _=> need-resched
> > #|| / _---=> hardirq/softirq
> > #||| / _--=> preempt-depth
> > # / delay
> > #  cmd pid   | time  |   caller
> > # \   /  |  \|   /
> > apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage

perf_event_update_userpage should not be taking 2ms to complete.

> > apt-chec-36280dN.. 2173us : trace_hardirqs_on_thunk <-retint_careful
> > apt-chec-36280dN.. 2173us+: trace_hardirqs_on_caller <-retint_careful
> > apt-chec-36280dN.. 2177us : 
> >  => trace_hardirqs_on_thunk
> > 
> > I will send the tail of the usbmon trace off-list.
> 
> This irqsoff trace and the usbmon trace were taken at the same time, 
> showing the same events, right?
> 
> Here's the important part of the usbmon trace, right where the errors
> began:
> 
> 8800b5660200 1564937888 C Zo:1:002:1 0:1:3850:0 8 0:0:96 0:96:96 0:192:80 
> 0:272:96 0:368:80 720 >
> 8800b5660200 1564937895 S Zo:1:002:1 -115:1:3850 8 -18:0:80 -18:80:96 
> -18:176:80 -18:256:96 -18:352:80 704 = 00edba02 00371d06 00edba02 00371d06 
> 005079fd 001b1003 005079fd 001b1003
> 8800c9d10c00 1564945487 C Zi:1:002:1 0:8:3863:0 1 0:0:4 4 = 08830500
> 8800c9d10c00 1564945495 S Zi:1:002:1 -115:8:3863 1 -18:0:4 4 <
> 8800c9d10c00 1564945499 E Zi:1:002:1 -18 0
> 
> (The timestamp is the second column, in microseconds.  The last line is
> the first error, caused by the URB submission on the previous line,
> which was too late.)
> 
> This shows that the errors occurred because a period longer than 7 ms
> passed with no URB completions (the interval between the first and
> third lines above).  Everywhere else in the usbmon trace there were at
> least two URBs completing every ms, and there can be no doubt that the
> EHCI controller tried to issue at least one IRQ every ms.
> 
> This suggests that the IRQ line was disabled or interrupts were
> disabled on all four CPUs for 7 ms.  However, the irqsoff trace shows
> that the maximum latency was 2 ms.  Something strange is going on, but
> I don't know what or how to find it.
> 
> Steve, do you have any ideas about this?  Or suggestions for other 
> people to ask?

Is there SMIs on this box? Those will not be detected by the latency
tracers directly. But we do have other tools to detect them.

-- Steve

> 
> I can try to ameliorate the situation.  Although the 7-ms delay will
> inevitably cause an underrun, it doesn't have to cause errors the way
> it does now.  I'll write a patch to handle this.  It may take a few
> days.
> 
> Alan Stern


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Mon, 29 Jul 2013, James Stone wrote:

> OK, having said that, I just got it to happen - listening to audacity
> and just logging into Facebook (of all things!! Meh!)
> 
> This is the contents of the trace file (as per instructions on bug #1191603)
> 
> # tracer: irqsoff
> #
> # irqsoff latency trace v1.1.5 on 3.10.0-ver5
> # 
> # latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> #-
> #| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
> #-
> #  => started at: perf_event_update_userpage
> #  => ended at:   retint_careful
> #
> #
> #  _--=> CPU#
> # / _-=> irqs-off
> #| / _=> need-resched
> #|| / _---=> hardirq/softirq
> #||| / _--=> preempt-depth
> # / delay
> #  cmd pid   | time  |   caller
> # \   /  |  \|   /
> apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage
> apt-chec-36280dN.. 2173us : trace_hardirqs_on_thunk <-retint_careful
> apt-chec-36280dN.. 2173us+: trace_hardirqs_on_caller <-retint_careful
> apt-chec-36280dN.. 2177us : 
>  => trace_hardirqs_on_thunk
> 
> I will send the tail of the usbmon trace off-list.

This irqsoff trace and the usbmon trace were taken at the same time, 
showing the same events, right?

Here's the important part of the usbmon trace, right where the errors
began:

8800b5660200 1564937888 C Zo:1:002:1 0:1:3850:0 8 0:0:96 0:96:96 0:192:80 
0:272:96 0:368:80 720 >
8800b5660200 1564937895 S Zo:1:002:1 -115:1:3850 8 -18:0:80 -18:80:96 
-18:176:80 -18:256:96 -18:352:80 704 = 00edba02 00371d06 00edba02 00371d06 
005079fd 001b1003 005079fd 001b1003
8800c9d10c00 1564945487 C Zi:1:002:1 0:8:3863:0 1 0:0:4 4 = 08830500
8800c9d10c00 1564945495 S Zi:1:002:1 -115:8:3863 1 -18:0:4 4 <
8800c9d10c00 1564945499 E Zi:1:002:1 -18 0

(The timestamp is the second column, in microseconds.  The last line is
the first error, caused by the URB submission on the previous line,
which was too late.)

This shows that the errors occurred because a period longer than 7 ms
passed with no URB completions (the interval between the first and
third lines above).  Everywhere else in the usbmon trace there were at
least two URBs completing every ms, and there can be no doubt that the
EHCI controller tried to issue at least one IRQ every ms.

This suggests that the IRQ line was disabled or interrupts were
disabled on all four CPUs for 7 ms.  However, the irqsoff trace shows
that the maximum latency was 2 ms.  Something strange is going on, but
I don't know what or how to find it.

Steve, do you have any ideas about this?  Or suggestions for other 
people to ask?

I can try to ameliorate the situation.  Although the 7-ms delay will
inevitably cause an underrun, it doesn't have to cause errors the way
it does now.  I'll write a patch to handle this.  It may take a few
days.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Mon, Jul 29, 2013 at 9:41 PM, James Stone  wrote:
> On Mon, Jul 29, 2013 at 4:25 PM, Alan Stern  wrote:
>> On Sun, 28 Jul 2013, James Stone wrote:
>>
>>> On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern  
>>> wrote:
>>> > On Sat, 27 Jul 2013, James Stone wrote:
>>> >
>>> >> OK. So this seems to have solved the starting jack at low latencies
>>> >> problem, but I am still getting sporadic cannot submit urb (err = -18)
>>> >> under normal use. Will try to add some more info to the #1191603
>>> >> report if I can get it to happen while logging IRQ.
>>> >
>>> > Do these errors occur at the start of a session or somewhere in the
>>> > middle?
>>> >
>>> > If they occur in the middle, they indicate possible underruns.  The
>>> > patch below will greatly reduce the number of these errors (probably to
>>> > the point where you don't see any at all), although it won't fix
>>> > possible underruns.
>>> >
>>>
>>> OK - this patch didn't help - still seeing these cannot submit urb
>>> (err = -18) errors  coming up at random times (this time while the
>>> computer was idling).
>>
>> Do you think you can get a usbmon trace showing one of those errors?
>> Or would the trace file end up being hopelessly large?
>>
>
> No - no way to get usbmon trace on this - it happens only every few
> hours at unpredictable times, and I can't work out what triggers it.
>
> J

OK, having said that, I just got it to happen - listening to audacity
and just logging into Facebook (of all things!! Meh!)

This is the contents of the trace file (as per instructions on bug #1191603)

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.10.0-ver5
# 
# latency: 2173 us, #4/4, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
#-
#| task: apt-check-3628 (uid:1000 nice:19 policy:0 rt_prio:0)
#-
#  => started at: perf_event_update_userpage
#  => ended at:   retint_careful
#
#
#  _--=> CPU#
# / _-=> irqs-off
#| / _=> need-resched
#|| / _---=> hardirq/softirq
#||| / _--=> preempt-depth
# / delay
#  cmd pid   | time  |   caller
# \   /  |  \|   /
apt-chec-36280d.h.0us!: local_clock <-perf_event_update_userpage
apt-chec-36280dN.. 2173us : trace_hardirqs_on_thunk <-retint_careful
apt-chec-36280dN.. 2173us+: trace_hardirqs_on_caller <-retint_careful
apt-chec-36280dN.. 2177us : 
 => trace_hardirqs_on_thunk

I will send the tail of the usbmon trace off-list.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Mon, Jul 29, 2013 at 4:25 PM, Alan Stern  wrote:
> On Sun, 28 Jul 2013, James Stone wrote:
>
>> On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern  
>> wrote:
>> > On Sat, 27 Jul 2013, James Stone wrote:
>> >
>> >> OK. So this seems to have solved the starting jack at low latencies
>> >> problem, but I am still getting sporadic cannot submit urb (err = -18)
>> >> under normal use. Will try to add some more info to the #1191603
>> >> report if I can get it to happen while logging IRQ.
>> >
>> > Do these errors occur at the start of a session or somewhere in the
>> > middle?
>> >
>> > If they occur in the middle, they indicate possible underruns.  The
>> > patch below will greatly reduce the number of these errors (probably to
>> > the point where you don't see any at all), although it won't fix
>> > possible underruns.
>> >
>>
>> OK - this patch didn't help - still seeing these cannot submit urb
>> (err = -18) errors  coming up at random times (this time while the
>> computer was idling).
>
> Do you think you can get a usbmon trace showing one of those errors?
> Or would the trace file end up being hopelessly large?
>

No - no way to get usbmon trace on this - it happens only every few
hours at unpredictable times, and I can't work out what triggers it.

J
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Sun, 28 Jul 2013, James Stone wrote:

> On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern  wrote:
> > On Sat, 27 Jul 2013, James Stone wrote:
> >
> >> OK. So this seems to have solved the starting jack at low latencies
> >> problem, but I am still getting sporadic cannot submit urb (err = -18)
> >> under normal use. Will try to add some more info to the #1191603
> >> report if I can get it to happen while logging IRQ.
> >
> > Do these errors occur at the start of a session or somewhere in the
> > middle?
> >
> > If they occur in the middle, they indicate possible underruns.  The
> > patch below will greatly reduce the number of these errors (probably to
> > the point where you don't see any at all), although it won't fix
> > possible underruns.
> >
> 
> OK - this patch didn't help - still seeing these cannot submit urb
> (err = -18) errors  coming up at random times (this time while the
> computer was idling).

Do you think you can get a usbmon trace showing one of those errors?  
Or would the trace file end up being hopelessly large?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern  wrote:
> On Sat, 27 Jul 2013, James Stone wrote:
>
>> OK. So this seems to have solved the starting jack at low latencies
>> problem, but I am still getting sporadic cannot submit urb (err = -18)
>> under normal use. Will try to add some more info to the #1191603
>> report if I can get it to happen while logging IRQ.
>
> Do these errors occur at the start of a session or somewhere in the
> middle?
>
> If they occur in the middle, they indicate possible underruns.  The
> patch below will greatly reduce the number of these errors (probably to
> the point where you don't see any at all), although it won't fix
> possible underruns.
>

OK - this patch didn't help - still seeing these cannot submit urb
(err = -18) errors  coming up at random times (this time while the
computer was idling).

J
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 26 Jul 2013, James Stone wrote:

> >> James, can you try this out and send me the usbmon trace?  At 64
> >> frames/period this should end up using 4 URBs, which is the minimum
> >> requirement if there are no more than 8 packets per URB and an
> >> incompletely filled URB can contain as few as 1 packets.  With this
> >> patch, there should be no difficulty going down to 32 or maybe even 16
> >> frames/period.
> >>
> >>
> >
> > Here you go.. (attached). This is at 64 frames/period.
> >
> > James
> 
> Apologies - that was with 3 periods/buffer. 2 periods/buffer attached.

It doesn't make any difference; the ALSA driver ignores the 
periods/buffer setting when interacting with the USB stack.

One thing that does make a difference, however, is that you changed 
from 44100 Hz to 48000 Hz.  That's okay; it's still a valid test.

Anyway, the traces show that the patch works as desired, but it isn't
optimal.  The optimal number of URBs is actually quite tricky to
calculate.  I'll send out another patch in a few days.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Sat, 27 Jul 2013, James Stone wrote:

> OK. So this seems to have solved the starting jack at low latencies
> problem, but I am still getting sporadic cannot submit urb (err = -18)
> under normal use. Will try to add some more info to the #1191603
> report if I can get it to happen while logging IRQ.

Do these errors occur at the start of a session or somewhere in the 
middle?

If they occur in the middle, they indicate possible underruns.  The
patch below will greatly reduce the number of these errors (probably to
the point where you don't see any at all), although it won't fix
possible underruns.

Alan Stern



Index: usb-3.10/drivers/usb/host/ehci-sched.c
===
--- usb-3.10.orig/drivers/usb/host/ehci-sched.c
+++ usb-3.10/drivers/usb/host/ehci-sched.c
@@ -1388,7 +1388,7 @@ iso_stream_schedule (
struct ehci_iso_stream  *stream
 )
 {
-   u32 now, base, next, start, period, span;
+   u32 now, now2, base, next, start, period, span;
int status;
unsignedmod = ehci->periodic_size << 3;
struct ehci_iso_sched   *sched = urb->hcpriv;
@@ -1422,6 +1422,7 @@ iso_stream_schedule (
base = ehci->last_iso_frame << 3;
next = (next - base) & (mod - 1);
start = (stream->next_uframe - base) & (mod - 1);
+   now2 = (now - base) & (mod - 1);
 
/* Is the schedule already full? */
if (unlikely(start < period)) {
@@ -1441,12 +1442,12 @@ iso_stream_schedule (
 
/*
 * Not ASAP: Use the next slot in the stream.  If
-* the entire URB falls before the threshold, fail.
+* the entire URB falls before the current frame, fail.
 */
-   else if (start + span - period < next) {
+   else if (start + span - period < now2) {
ehci_dbg(ehci, "iso urb late %p (%u+%u < %u)\n",
urb, start + base,
-   span - period, next + base);
+   span - period, now2 + base);
status = -EXDEV;
goto fail;
}

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Jul 26, 2013 at 11:46 PM, James Stone  wrote:
> On Fri, Jul 26, 2013 at 11:43 PM, James Stone  wrote:
>> On Fri, Jul 26, 2013 at 7:54 PM, Alan Stern  
>> wrote:
>>> On Fri, 26 Jul 2013, Clemens Ladisch wrote:
>>>
 Alan Stern wrote:
 > On Thu, 25 Jul 2013, James Stone wrote:
 >> The only slight difference I can see is that maybe the 3.10 uses
 >> slightly higher CPU load than 3.5 at the ridiculously low latency of
 >> 64 frames/period duplex.
 >
 > With the new patch, what you actually get is 44.1 frames/period (on
 > average).

 In ALSA, the number of frames per period is a constant integer, and Jack
 requires it to be a power of two.  (Where "frame" is an audio frame, and
 "period" is the interval between interrupts reported to user space.)

 With a sample rate of 44100 Hz and a packet rate of 8000 Hz, there
 should be about 5.5 samples per packet.  With a period size of 64 audio
 frames, this results in about 11.6 packets per period.

 The driver does not completely fill URBs to ensure that interrupts
 happen at period boundaries.
>>>
>>> Oho!  I missed all that period_elapsed stuff in prepare_playback_urb()!
>>> But you don't do the same thing for recording URBs -- presumably
>>> because you can't tell in advance how many samples the device will
>>> send.
>>>
>>> This makes the calculation of the number of URBs more complicated.
>>> Revised patch below.
>>>
>>> James, can you try this out and send me the usbmon trace?  At 64
>>> frames/period this should end up using 4 URBs, which is the minimum
>>> requirement if there are no more than 8 packets per URB and an
>>> incompletely filled URB can contain as few as 1 packets.  With this
>>> patch, there should be no difficulty going down to 32 or maybe even 16
>>> frames/period.
>>>
>>>
>>
>> Here you go.. (attached). This is at 64 frames/period.
>>
>> James
>
> Apologies - that was with 3 periods/buffer. 2 periods/buffer attached.
>
> James

OK. So this seems to have solved the starting jack at low latencies
problem, but I am still getting sporadic cannot submit urb (err = -18)
under normal use. Will try to add some more info to the #1191603
report if I can get it to happen while logging IRQ.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 26 Jul 2013, Clemens Ladisch wrote:

> Alan Stern wrote:
> > On Thu, 25 Jul 2013, James Stone wrote:
> >> The only slight difference I can see is that maybe the 3.10 uses
> >> slightly higher CPU load than 3.5 at the ridiculously low latency of
> >> 64 frames/period duplex.
> >
> > With the new patch, what you actually get is 44.1 frames/period (on
> > average).
> 
> In ALSA, the number of frames per period is a constant integer, and Jack
> requires it to be a power of two.  (Where "frame" is an audio frame, and
> "period" is the interval between interrupts reported to user space.)
> 
> With a sample rate of 44100 Hz and a packet rate of 8000 Hz, there
> should be about 5.5 samples per packet.  With a period size of 64 audio
> frames, this results in about 11.6 packets per period.
> 
> The driver does not completely fill URBs to ensure that interrupts
> happen at period boundaries.

Oho!  I missed all that period_elapsed stuff in prepare_playback_urb()!
But you don't do the same thing for recording URBs -- presumably
because you can't tell in advance how many samples the device will
send.

This makes the calculation of the number of URBs more complicated.  
Revised patch below.

James, can you try this out and send me the usbmon trace?  At 64
frames/period this should end up using 4 URBs, which is the minimum
requirement if there are no more than 8 packets per URB and an
incompletely filled URB can contain as few as 1 packets.  With this
patch, there should be no difficulty going down to 32 or maybe even 16
frames/period.

One more thing: I don't understand the calculations involving delay,
est_delay, last_delay, and so on in pcm.c.  Regardless, they appear not
to be as good as they could be, because they don't use
urb->start_frame.

> > Another problem, not necessarily a bad one: The feedback data from the
> > sound device indicates that its internal clock is actually running at
> > 45168 Hz, even though it claims to be running at 44100.
> 
> The feedback data is not measured in "real Hz" (wall clock time) but
> relatively to the 8 kHz bus clock.  Furthermore, it does not show the
> device's internal clock but the rate at which the device wants to
> receive frames; this can be higher at the beginning of a stream if the
> device has an empty FIFO and wants to fill it up.

Sorry, this was a miscalculation on my part.  I divided the value from 
the device by 8000 instead of 8192.  The correct calculation shows the 
internal clock is running at 44109 Hz.  Close enough.

Alan Stern



Index: usb-3.10/sound/usb/endpoint.c
===
--- usb-3.10.orig/sound/usb/endpoint.c
+++ usb-3.10/sound/usb/endpoint.c
@@ -575,6 +575,7 @@ static int data_ep_set_params(struct snd
  struct snd_usb_endpoint *sync_ep)
 {
unsigned int maxsize, i, urb_packs, total_packs, packs_per_ms;
+   unsigned int min_queued_packs, max_packs;
int is_playback = usb_pipeout(ep->pipe);
int frame_bits = snd_pcm_format_physical_width(pcm_format) * channels;
 
@@ -608,11 +609,21 @@ static int data_ep_set_params(struct snd
else
ep->curpacksize = maxsize;
 
-   if (snd_usb_get_speed(ep->chip->dev) != USB_SPEED_FULL)
+   if (snd_usb_get_speed(ep->chip->dev) != USB_SPEED_FULL) {
packs_per_ms = 8 >> ep->datainterval;
-   else
+
+   /* high speed needs 10 USB uframes on the queue at all times */
+   min_queued_packs = DIV_ROUND_UP(10, 8 / packs_per_ms);
+   max_packs = MAX_PACKS_HS;
+   } else {
packs_per_ms = 1;
 
+   /* full speed needs one USB frame on the queue at all times */
+   min_queued_packs = 1;
+   max_packs = MAX_PACKS;
+   }
+   max_packs = min(max_packs, MAX_QUEUE * packs_per_ms);
+
if (is_playback && !snd_usb_endpoint_implicit_feedback_sink(ep)) {
urb_packs = max(ep->chip->nrpacks, 1);
urb_packs = min(urb_packs, (unsigned int) MAX_PACKS);
@@ -625,42 +636,46 @@ static int data_ep_set_params(struct snd
if (sync_ep && !snd_usb_endpoint_implicit_feedback_sink(ep))
urb_packs = min(urb_packs, 1U << sync_ep->syncinterval);
 
-   /* decide how many packets to be used */
-   if (is_playback && !snd_usb_endpoint_implicit_feedback_sink(ep)) {
-   unsigned int minsize, maxpacks;
-   /* determine how small a packet can be */
-   minsize = (ep->freqn >> (16 - ep->datainterval))
- * (frame_bits >> 3);
-   /* with sync from device, assume it can be 12% lower */
-   if (sync_ep)
-   minsize -= minsize >> 3;
-   minsize = max(minsize, 1u);
-   total_packs = (period_bytes + minsize - 1) / minsize;
-   /* we need at least two URBs for queueing */
-   if (total_packs < 2) {

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> On Thu, 25 Jul 2013, James Stone wrote:
>> The only slight difference I can see is that maybe the 3.10 uses
>> slightly higher CPU load than 3.5 at the ridiculously low latency of
>> 64 frames/period duplex.
>
> With the new patch, what you actually get is 44.1 frames/period (on
> average).

In ALSA, the number of frames per period is a constant integer, and Jack
requires it to be a power of two.  (Where "frame" is an audio frame, and
"period" is the interval between interrupts reported to user space.)

> However, something's not working right.  The number of packets in each
> playback URB changes each time the URB is reused!  That's not supposed
> to happen.  The number of packets should remain fixed while the number
> of samples in each packet changes, based on the feedback info.
>
> I don't get it.  The usbmon trace shows three URBs, and the number of
> packets goes like this:
>
>   8 8 8   8 4 8   4 8 3   8 4 8   4 8 3   8 4 8   3 8 4   8 4 8

With a sample rate of 44100 Hz and a packet rate of 8000 Hz, there
should be about 5.5 samples per packet.  With a period size of 64 audio
frames, this results in about 11.6 packets per period.

The driver does not completely fill URBs to ensure that interrupts
happen at period boundaries.

> Another problem, not necessarily a bad one: The feedback data from the
> sound device indicates that its internal clock is actually running at
> 45168 Hz, even though it claims to be running at 44100.

The feedback data is not measured in "real Hz" (wall clock time) but
relatively to the 8 kHz bus clock.  Furthermore, it does not show the
device's internal clock but the rate at which the device wants to
receive frames; this can be higher at the beginning of a stream if the
device has an empty FIFO and wants to fill it up.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 25, 2013 at 10:24 PM, Alan Stern  wrote:
> On Thu, 25 Jul 2013, James Stone wrote:
>
>> On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern  
>> wrote:
>> > On Thu, 25 Jul 2013, James Stone wrote:
>> >
>> >> > Please try the patch from here:
>> >> >
>> >> > http://marc.info/?l=linux-usb&m=137476385206265&w=2
>> >> >
>> >> > instead of the one I sent to you yesterday.  I think it will fix this
>> >> > problem.
>> >> >
>> >> > Alan Stern
>> >> >
>> >>
>> >> Perfect! All fixed!
>> >
>> > Can you provide a usbmon trace showing the start of a session using the
>> > new patch?
>> >
>> > Alan Stern
>> >
>>
>> Sure - will send off list. The only slight difference I can see is
>> that maybe the 3.10 uses slightly higher CPU load than 3.5 at the
>> ridiculously low latency of 64 frames/period duplex.
>
> With the new patch, what you actually get is 44.1 frames/period (on
> average).  That's quite sustainable.
>
> However, something's not working right.  The number of packets in each
> playback URB changes each time the URB is reused!  That's not supposed
> to happen.  The number of packets should remain fixed while the number
> of samples in each packet changes, based on the feedback info.
>
> I don't get it.  The usbmon trace shows three URBs, and the number of
> packets goes like this:
>
> 8 8 8   8 4 8   4 8 3   8 4 8   4 8 3   8 4 8   3 8 4   8 4 8
> etc...
>
> I'm at a complete loss.  It's not caused by confusion on the feedback
> endpoint; in fact the driver doesn't change this number anywhere once
> it has been set up.  What's going on?
>
> James, please apply the diagnostic patch below on top of everything
> else.  It will write entries into the kernel log which hopefully will
> pin down where this number gets changed.
>
> Another problem, not necessarily a bad one: The feedback data from the
> sound device indicates that its internal clock is actually running at
> 45168 Hz, even though it claims to be running at 44100.
>

OK - here is the output:


Jul 25 23:58:46 blueberry kernel: [   24.440327] Actions configured
Jul 25 23:59:00 blueberry kernel: [   39.070484] A urb 88002e02ca00 cnt 2
Jul 25 23:59:00 blueberry kernel: [   39.071467] B urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.071473] C urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.071479] A urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.072465] B urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.072471] C urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.072477] A urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.072706] B urb 88002e02ca00 cnt 2
Jul 25 23:59:00 blueberry kernel: [   39.072711] C urb 88002e02ca00 cnt 2
Jul 25 23:59:00 blueberry kernel: [   39.072717] A urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.073700] B urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.073702] C urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.073704] A urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.074754] B urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.074765] C urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.074773] A urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.075703] B urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.075709] C urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.075715] A urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.076702] B urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.076707] C urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.076713] A urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.077711] B urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.077718] C urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.077724] A urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.078700] B urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.078705] C urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.078711] A urb 88002e02ca00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.079700] B urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.079705] C urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.079711] A urb 8800c9758a00 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.080747] B urb 8800c9758400 cnt 8
Jul 25 23:59:00 blueberry kernel: [   39.080759] C urb 8800c9758400 cnt 8


It only wrote this the first time I started jackd. The following
times, I just got this:

Jul 25 23:59:41 blueberry kernel: [   79.775595] ieee80211 phy0:
rt61pci_txdone: Warning - TX status report missed for entry 12
Jul 26 00:01:20 blueberry kernel: [  178.994157] ieee80211 phy0:
rt61pci_txdone: Warning - TX status report missed for entr

Re: Audio I/O parameters

[Alan Stern]

On Thu, 25 Jul 2013, James Stone wrote:

> On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern  wrote:
> > On Thu, 25 Jul 2013, James Stone wrote:
> >
> >> > Please try the patch from here:
> >> >
> >> > http://marc.info/?l=linux-usb&m=137476385206265&w=2
> >> >
> >> > instead of the one I sent to you yesterday.  I think it will fix this
> >> > problem.
> >> >
> >> > Alan Stern
> >> >
> >>
> >> Perfect! All fixed!
> >
> > Can you provide a usbmon trace showing the start of a session using the
> > new patch?
> >
> > Alan Stern
> >
> 
> Sure - will send off list. The only slight difference I can see is
> that maybe the 3.10 uses slightly higher CPU load than 3.5 at the
> ridiculously low latency of 64 frames/period duplex.

With the new patch, what you actually get is 44.1 frames/period (on
average).  That's quite sustainable.

However, something's not working right.  The number of packets in each
playback URB changes each time the URB is reused!  That's not supposed
to happen.  The number of packets should remain fixed while the number
of samples in each packet changes, based on the feedback info.

I don't get it.  The usbmon trace shows three URBs, and the number of 
packets goes like this:

8 8 8   8 4 8   4 8 3   8 4 8   4 8 3   8 4 8   3 8 4   8 4 8
etc...

I'm at a complete loss.  It's not caused by confusion on the feedback
endpoint; in fact the driver doesn't change this number anywhere once
it has been set up.  What's going on?

James, please apply the diagnostic patch below on top of everything 
else.  It will write entries into the kernel log which hopefully will 
pin down where this number gets changed.

Another problem, not necessarily a bad one: The feedback data from the 
sound device indicates that its internal clock is actually running at 
45168 Hz, even though it claims to be running at 44100.

Alan Stern



Index: usb-3.10/sound/usb/endpoint.c
===
--- usb-3.10.orig/sound/usb/endpoint.c
+++ usb-3.10/sound/usb/endpoint.c
@@ -33,6 +33,8 @@
 #include "pcm.h"
 #include "quirks.h"
 
+static int alancnt = -1;
+
 #define EP_FLAG_ACTIVATED  0
 #define EP_FLAG_RUNNING1
 #define EP_FLAG_STOPPING   2
@@ -358,10 +360,16 @@ static void snd_complete_urb(struct urb
goto exit_clear;
 
if (usb_pipeout(ep->pipe)) {
+   if (alancnt > 0)
+   printk(KERN_INFO "B urb %p cnt %d\n",
+   urb, urb->number_of_packets);
retire_outbound_urb(ep, ctx);
/* can be stopped during retire callback */
if (unlikely(!test_bit(EP_FLAG_RUNNING, &ep->flags)))
goto exit_clear;
+   if (alancnt > 0)
+   printk(KERN_INFO "C urb %p cnt %d\n",
+   urb, urb->number_of_packets);
 
if (snd_usb_endpoint_implicit_feedback_sink(ep)) {
unsigned long flags;
@@ -375,6 +383,13 @@ static void snd_complete_urb(struct urb
}
 
prepare_outbound_urb(ep, ctx);
+   if (urb->number_of_packets != 8 && alancnt < 0)
+   alancnt = 20;
+   if (alancnt > 0) {
+   printk(KERN_INFO "A urb %p cnt %d\n",
+   urb, urb->number_of_packets);
+   --alancnt;
+   }
} else {
retire_inbound_urb(ep, ctx);
/* can be stopped during retire callback */

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern  wrote:
> On Thu, 25 Jul 2013, James Stone wrote:
>
>> > Please try the patch from here:
>> >
>> > http://marc.info/?l=linux-usb&m=137476385206265&w=2
>> >
>> > instead of the one I sent to you yesterday.  I think it will fix this
>> > problem.
>> >
>> > Alan Stern
>> >
>>
>> Perfect! All fixed!
>
> Can you provide a usbmon trace showing the start of a session using the
> new patch?
>
> Alan Stern
>

Sure - will send off list. The only slight difference I can see is
that maybe the 3.10 uses slightly higher CPU load than 3.5 at the
ridiculously low latency of 64 frames/period duplex.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 25 Jul 2013, James Stone wrote:

> > Please try the patch from here:
> >
> > http://marc.info/?l=linux-usb&m=137476385206265&w=2
> >
> > instead of the one I sent to you yesterday.  I think it will fix this
> > problem.
> >
> > Alan Stern
> >
> 
> Perfect! All fixed!

Can you provide a usbmon trace showing the start of a session using the 
new patch?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 25, 2013 at 4:29 PM, Alan Stern  wrote:
> On Thu, 25 Jul 2013, James Stone wrote:
>
>> On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch  wrote:
>> > James Stone wrote:
>> >> Ok -from the bisect, the problem of not being able to get to sub
>> >> 64-frames per period starts with:
>> >>
>> >> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=fc600432cd23e35c85de2ff4468d816d6938a112
>> >
>> > This is a merge, which includes this commit: 
>> > .
>> >
>> >> Could this be the offending deletion?
>> >>
>> >> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/diff/sound/usb/endpoint.c?id=fc600432cd23e35c85de2ff4468d816d6938a112
>> >
>> > (There is a corresponding change in pcm.c.)
>> >
>> > The commit that you found by bisection got reverted later:
>> > 
>> >
>> > Please check that the code of "Fix URB cancellation at stream start" is
>> > in your current kernel.
>> >
>>
>> well, in 3.10, it is not exactly the same as the above revertion. For 
>> example:
>>
>> /* just to be sure */
>> deactivate_urbs(ep, false);
>> if (can_sleep)
>
> Please try the patch from here:
>
> http://marc.info/?l=linux-usb&m=137476385206265&w=2
>
> instead of the one I sent to you yesterday.  I think it will fix this
> problem.
>
> Alan Stern
>

Perfect! All fixed!

Thanks!
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 25 Jul 2013, James Stone wrote:

> On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch  wrote:
> > James Stone wrote:
> >> Ok -from the bisect, the problem of not being able to get to sub
> >> 64-frames per period starts with:
> >>
> >> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=fc600432cd23e35c85de2ff4468d816d6938a112
> >
> > This is a merge, which includes this commit: 
> > .
> >
> >> Could this be the offending deletion?
> >>
> >> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/diff/sound/usb/endpoint.c?id=fc600432cd23e35c85de2ff4468d816d6938a112
> >
> > (There is a corresponding change in pcm.c.)
> >
> > The commit that you found by bisection got reverted later:
> > 
> >
> > Please check that the code of "Fix URB cancellation at stream start" is
> > in your current kernel.
> >
> 
> well, in 3.10, it is not exactly the same as the above revertion. For example:
> 
> /* just to be sure */
> deactivate_urbs(ep, false);
> if (can_sleep)

Please try the patch from here:

http://marc.info/?l=linux-usb&m=137476385206265&w=2

instead of the one I sent to you yesterday.  I think it will fix this 
problem.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

James Stone wrote:
> On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch wrote:
>> The commit that you found by bisection got reverted later:
>> 
>>
>> Please check that the code of "Fix URB cancellation at stream start" is
>> in your current kernel.
>
> well, in 3.10, it is not exactly the same as the above revertion. For example:
>
> /* just to be sure */
> deactivate_urbs(ep, false);
> if (can_sleep)

This is exactly the same as in commit 015618b902ae.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch  wrote:
> James Stone wrote:
>> Ok -from the bisect, the problem of not being able to get to sub
>> 64-frames per period starts with:
>>
>> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=fc600432cd23e35c85de2ff4468d816d6938a112
>
> This is a merge, which includes this commit: 
> .
>
>> Could this be the offending deletion?
>>
>> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/diff/sound/usb/endpoint.c?id=fc600432cd23e35c85de2ff4468d816d6938a112
>
> (There is a corresponding change in pcm.c.)
>
> The commit that you found by bisection got reverted later:
> 
>
> Please check that the code of "Fix URB cancellation at stream start" is
> in your current kernel.
>

well, in 3.10, it is not exactly the same as the above revertion. For example:

/* just to be sure */
deactivate_urbs(ep, false);
if (can_sleep)
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

James Stone wrote:
> Ok -from the bisect, the problem of not being able to get to sub
> 64-frames per period starts with:
>
> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=fc600432cd23e35c85de2ff4468d816d6938a112

This is a merge, which includes this commit: 
.

> Could this be the offending deletion?
>
> http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/diff/sound/usb/endpoint.c?id=fc600432cd23e35c85de2ff4468d816d6938a112

(There is a corresponding change in pcm.c.)

The commit that you found by bisection got reverted later:


Please check that the code of "Fix URB cancellation at stream start" is
in your current kernel.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 24, 2013 at 2:42 AM, James Stone  wrote:
> On Wed, Jul 24, 2013 at 12:23 AM, James Stone  wrote:
>> On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge  wrote:
>>> On Tue, Jul 23, 2013 at 21:13:23 +0100, James Stone wrote:
 On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern  
 wrote:
 > On Fri, 19 Jul 2013, James Stone wrote:
 >
 >> > The questions now are:
 >> >
 >> > Why are the same requests sent over and over again?
 >> >
 >> > Why does the ALSA driver attempt to set the clock frequency
 >> > while the clock is actively in use?
 >> >
 >> > Has this behavior changed since the 3.5 kernel?
 >> >
 >>
 >> Well, I think these requests may correspond to the lights flashing on
 >> and off on the front of the device. When starting the device in 3.5 at
 >> 256 frames/period (duplex), the lights flash on and off 2 times, in
 >> the current patched 3.8 version I have been using, the device lights
 >> flash on and off 4 times before starting jack with exactly the same
 >> settings - so it seems for some reason, the requests are going through
 >> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
 >> usbmon trace of a successful start off list (plus the same for 3.8?)
 >> if it would be useful.
 >
 > I don't know -- it's up to Clemens.
 >
 > Alan Stern
 >

 Hi Alan,

 Just tried a few old kernels, and it seems that the bug I am
 experiencing was introduced at the start of 3.7 - kernel 3.6.11 is
 fine, and all the 3.7 series kernels are broken. So it seems it is not
 the updated ehci usb code that is directly responsible for the
 realtime audio problem. I have been trying the kernels from:
 http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
 to further zoom in on the culprit commit?
>>>
>>> Can you reproduce the problem on a 3.10 kernel? I suspect this is
>>> related to the commit 61a70950 "ALSA: usb-audio: Move configuration to
>>> prepare" in kernel 3.7, which introduced calls to set sample
>>> rate in prepare, even if the sample rate is unchanged. It looks like
>>> jackd calls prepare twice when starting, which is consistent with two
>>> get rate/set rate sequences.
>>>
>>> The unnecessary set rate shouldn't happen with kernel 3.10, as it
>>> includes fa92dd77 "ALSA: usb - Avoid unnecessary sample rate changes on
>>> USB 2.0 clock sources", which says in the commit message: "The Scarlett
>>> 2i2 seems to take almost 500 ms to set the sample rate, even if the
>>> clock is currently set to that value. This patch speeds up prepare of
>>> the device, by avoiding setting the clock to something it already is."
>>>
>>>
>>> Torstein
>>
>> Thanks for this info. I just tried it out, and the device starts up
>> much more cleanly - no flashing lights etc. at longer latencies. It
>> will still not start jackd at 256 frames/period, but this might need
>> Clemen's do not trust too-big wMaxPacketSize values patch added.. Will
>> report back.
>>
>> James
>
>
> Ok - this does seem to be a vast improvement over 3.8.x (and even, in
> some ways the 3.6x series) - with the addition of Clemen's patch.
> However, very low realtime latencies (which seemed to be somewhat
> possible - 64 frames/period or lower - in the 3.6x series) will no
> longer work properly. 128 frames/period looks fairly usable. Will
> continue with bisect to see if I can discover anything else.

Ok -from the bisect, the problem of not being able to get to sub
64-frames per period starts with:

http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?id=fc600432cd23e35c85de2ff4468d816d6938a112

Could this be the offending deletion?

http://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/diff/sound/usb/endpoint.c?id=fc600432cd23e35c85de2ff4468d816d6938a112

??

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Wed, 24 Jul 2013, James Stone wrote:

> Ok - this does seem to be a vast improvement over 3.8.x (and even, in
> some ways the 3.6x series) - with the addition of Clemen's patch.
> However, very low realtime latencies (which seemed to be somewhat
> possible - 64 frames/period or lower - in the 3.6x series) will no
> longer work properly. 128 frames/period looks fairly usable. Will
> continue with bisect to see if I can discover anything else.

I suspect this remaining problem is partly caused by the ALSA driver
misinterpreting the parameters.  For example, when you specify 64
frames/period, what you actually get is 41.3 (on average).

The patch below ought to help.  It is certainly not the correct
solution, but try it out anyway with 64 frames/packet to see if it
works.  And collect a usbmon trace, so I can see whether it really does
behave as intended.  (The patch is meant to apply on top of the one
Clemens sent earlier.)

Alan Stern



Index: usb-3.10/sound/usb/endpoint.c
===
--- usb-3.10.orig/sound/usb/endpoint.c
+++ usb-3.10/sound/usb/endpoint.c
@@ -575,6 +575,7 @@ static int data_ep_set_params(struct snd
  struct snd_usb_endpoint *sync_ep)
 {
unsigned int maxsize, i, urb_packs, total_packs, packs_per_ms;
+   unsigned int min_urbs, max_packs;
int is_playback = usb_pipeout(ep->pipe);
int frame_bits = snd_pcm_format_physical_width(pcm_format) * channels;
 
@@ -608,10 +609,15 @@ static int data_ep_set_params(struct snd
else
ep->curpacksize = maxsize;
 
-   if (snd_usb_get_speed(ep->chip->dev) != USB_SPEED_FULL)
+   if (snd_usb_get_speed(ep->chip->dev) != USB_SPEED_FULL) {
packs_per_ms = 8 >> ep->datainterval;
-   else
+   min_urbs = 3;
+   max_packs = MAX_PACKS_HS;
+   } else {
packs_per_ms = 1;
+   min_urbs = 2;
+   max_packs = MAX_PACKS;
+   }
 
if (is_playback && !snd_usb_endpoint_implicit_feedback_sink(ep)) {
urb_packs = max(ep->chip->nrpacks, 1);
@@ -625,42 +631,23 @@ static int data_ep_set_params(struct snd
if (sync_ep && !snd_usb_endpoint_implicit_feedback_sink(ep))
urb_packs = min(urb_packs, 1U << sync_ep->syncinterval);
 
-   /* decide how many packets to be used */
-   if (is_playback && !snd_usb_endpoint_implicit_feedback_sink(ep)) {
-   unsigned int minsize, maxpacks;
-   /* determine how small a packet can be */
-   minsize = (ep->freqn >> (16 - ep->datainterval))
- * (frame_bits >> 3);
-   /* with sync from device, assume it can be 12% lower */
-   if (sync_ep)
-   minsize -= minsize >> 3;
-   minsize = max(minsize, 1u);
-   total_packs = (period_bytes + minsize - 1) / minsize;
-   /* we need at least two URBs for queueing */
-   if (total_packs < 2) {
-   total_packs = 2;
-   } else {
-   /* and we don't want too long a queue either */
-   maxpacks = max(MAX_QUEUE * packs_per_ms, urb_packs * 2);
-   total_packs = min(total_packs, maxpacks);
-   }
-   } else {
-   while (urb_packs > 1 && urb_packs * maxsize >= period_bytes)
-   urb_packs >>= 1;
-   total_packs = MAX_URBS * urb_packs;
-   }
+   /* each URB must fit into one period */
+   urb_packs = min(urb_packs, period_bytes / maxsize);
+   urb_packs = max(1u, urb_packs);
 
-   ep->nurbs = (total_packs + urb_packs - 1) / urb_packs;
+   total_packs = min(MAX_QUEUE * packs_per_ms, max_packs);
+   ep->nurbs = total_packs / urb_packs;
if (ep->nurbs > MAX_URBS) {
/* too much... */
ep->nurbs = MAX_URBS;
-   total_packs = MAX_URBS * urb_packs;
-   } else if (ep->nurbs < 2) {
-   /* too little - we need at least two packets
+   } else if (ep->nurbs < min_urbs) {
+   /* too little - we need at least min_urbs URBs
 * to ensure contiguous playback/capture
 */
-   ep->nurbs = 2;
+   ep->nurbs = min_urbs;
+   urb_packs = total_packs / ep->nurbs;
}
+   total_packs = ep->nurbs * urb_packs;
 
/* allocate and initialize data urbs */
for (i = 0; i < ep->nurbs; i++) {


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 24, 2013 at 12:23 AM, James Stone  wrote:
> On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge  wrote:
>> On Tue, Jul 23, 2013 at 21:13:23 +0100, James Stone wrote:
>>> On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern  
>>> wrote:
>>> > On Fri, 19 Jul 2013, James Stone wrote:
>>> >
>>> >> > The questions now are:
>>> >> >
>>> >> > Why are the same requests sent over and over again?
>>> >> >
>>> >> > Why does the ALSA driver attempt to set the clock frequency
>>> >> > while the clock is actively in use?
>>> >> >
>>> >> > Has this behavior changed since the 3.5 kernel?
>>> >> >
>>> >>
>>> >> Well, I think these requests may correspond to the lights flashing on
>>> >> and off on the front of the device. When starting the device in 3.5 at
>>> >> 256 frames/period (duplex), the lights flash on and off 2 times, in
>>> >> the current patched 3.8 version I have been using, the device lights
>>> >> flash on and off 4 times before starting jack with exactly the same
>>> >> settings - so it seems for some reason, the requests are going through
>>> >> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
>>> >> usbmon trace of a successful start off list (plus the same for 3.8?)
>>> >> if it would be useful.
>>> >
>>> > I don't know -- it's up to Clemens.
>>> >
>>> > Alan Stern
>>> >
>>>
>>> Hi Alan,
>>>
>>> Just tried a few old kernels, and it seems that the bug I am
>>> experiencing was introduced at the start of 3.7 - kernel 3.6.11 is
>>> fine, and all the 3.7 series kernels are broken. So it seems it is not
>>> the updated ehci usb code that is directly responsible for the
>>> realtime audio problem. I have been trying the kernels from:
>>> http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
>>> to further zoom in on the culprit commit?
>>
>> Can you reproduce the problem on a 3.10 kernel? I suspect this is
>> related to the commit 61a70950 "ALSA: usb-audio: Move configuration to
>> prepare" in kernel 3.7, which introduced calls to set sample
>> rate in prepare, even if the sample rate is unchanged. It looks like
>> jackd calls prepare twice when starting, which is consistent with two
>> get rate/set rate sequences.
>>
>> The unnecessary set rate shouldn't happen with kernel 3.10, as it
>> includes fa92dd77 "ALSA: usb - Avoid unnecessary sample rate changes on
>> USB 2.0 clock sources", which says in the commit message: "The Scarlett
>> 2i2 seems to take almost 500 ms to set the sample rate, even if the
>> clock is currently set to that value. This patch speeds up prepare of
>> the device, by avoiding setting the clock to something it already is."
>>
>>
>> Torstein
>
> Thanks for this info. I just tried it out, and the device starts up
> much more cleanly - no flashing lights etc. at longer latencies. It
> will still not start jackd at 256 frames/period, but this might need
> Clemen's do not trust too-big wMaxPacketSize values patch added.. Will
> report back.
>
> James


Ok - this does seem to be a vast improvement over 3.8.x (and even, in
some ways the 3.6x series) - with the addition of Clemen's patch.
However, very low realtime latencies (which seemed to be somewhat
possible - 64 frames/period or lower - in the 3.6x series) will no
longer work properly. 128 frames/period looks fairly usable. Will
continue with bisect to see if I can discover anything else.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge  wrote:
> On Tue, Jul 23, 2013 at 21:13:23 +0100, James Stone wrote:
>> On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern  
>> wrote:
>> > On Fri, 19 Jul 2013, James Stone wrote:
>> >
>> >> > The questions now are:
>> >> >
>> >> > Why are the same requests sent over and over again?
>> >> >
>> >> > Why does the ALSA driver attempt to set the clock frequency
>> >> > while the clock is actively in use?
>> >> >
>> >> > Has this behavior changed since the 3.5 kernel?
>> >> >
>> >>
>> >> Well, I think these requests may correspond to the lights flashing on
>> >> and off on the front of the device. When starting the device in 3.5 at
>> >> 256 frames/period (duplex), the lights flash on and off 2 times, in
>> >> the current patched 3.8 version I have been using, the device lights
>> >> flash on and off 4 times before starting jack with exactly the same
>> >> settings - so it seems for some reason, the requests are going through
>> >> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
>> >> usbmon trace of a successful start off list (plus the same for 3.8?)
>> >> if it would be useful.
>> >
>> > I don't know -- it's up to Clemens.
>> >
>> > Alan Stern
>> >
>>
>> Hi Alan,
>>
>> Just tried a few old kernels, and it seems that the bug I am
>> experiencing was introduced at the start of 3.7 - kernel 3.6.11 is
>> fine, and all the 3.7 series kernels are broken. So it seems it is not
>> the updated ehci usb code that is directly responsible for the
>> realtime audio problem. I have been trying the kernels from:
>> http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
>> to further zoom in on the culprit commit?
>
> Can you reproduce the problem on a 3.10 kernel? I suspect this is
> related to the commit 61a70950 "ALSA: usb-audio: Move configuration to
> prepare" in kernel 3.7, which introduced calls to set sample
> rate in prepare, even if the sample rate is unchanged. It looks like
> jackd calls prepare twice when starting, which is consistent with two
> get rate/set rate sequences.
>
> The unnecessary set rate shouldn't happen with kernel 3.10, as it
> includes fa92dd77 "ALSA: usb - Avoid unnecessary sample rate changes on
> USB 2.0 clock sources", which says in the commit message: "The Scarlett
> 2i2 seems to take almost 500 ms to set the sample rate, even if the
> clock is currently set to that value. This patch speeds up prepare of
> the device, by avoiding setting the clock to something it already is."
>
>
> Torstein

Thanks for this info. I just tried it out, and the device starts up
much more cleanly - no flashing lights etc. at longer latencies. It
will still not start jackd at 256 frames/period, but this might need
Clemen's do not trust too-big wMaxPacketSize values patch added.. Will
report back.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Torstein Hegge]

On Tue, Jul 23, 2013 at 21:13:23 +0100, James Stone wrote:
> On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern  wrote:
> > On Fri, 19 Jul 2013, James Stone wrote:
> >
> >> > The questions now are:
> >> >
> >> > Why are the same requests sent over and over again?
> >> >
> >> > Why does the ALSA driver attempt to set the clock frequency
> >> > while the clock is actively in use?
> >> >
> >> > Has this behavior changed since the 3.5 kernel?
> >> >
> >>
> >> Well, I think these requests may correspond to the lights flashing on
> >> and off on the front of the device. When starting the device in 3.5 at
> >> 256 frames/period (duplex), the lights flash on and off 2 times, in
> >> the current patched 3.8 version I have been using, the device lights
> >> flash on and off 4 times before starting jack with exactly the same
> >> settings - so it seems for some reason, the requests are going through
> >> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
> >> usbmon trace of a successful start off list (plus the same for 3.8?)
> >> if it would be useful.
> >
> > I don't know -- it's up to Clemens.
> >
> > Alan Stern
> >
> 
> Hi Alan,
> 
> Just tried a few old kernels, and it seems that the bug I am
> experiencing was introduced at the start of 3.7 - kernel 3.6.11 is
> fine, and all the 3.7 series kernels are broken. So it seems it is not
> the updated ehci usb code that is directly responsible for the
> realtime audio problem. I have been trying the kernels from:
> http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
> to further zoom in on the culprit commit?

Can you reproduce the problem on a 3.10 kernel? I suspect this is
related to the commit 61a70950 "ALSA: usb-audio: Move configuration to
prepare" in kernel 3.7, which introduced calls to set sample
rate in prepare, even if the sample rate is unchanged. It looks like
jackd calls prepare twice when starting, which is consistent with two
get rate/set rate sequences.

The unnecessary set rate shouldn't happen with kernel 3.10, as it
includes fa92dd77 "ALSA: usb - Avoid unnecessary sample rate changes on
USB 2.0 clock sources", which says in the commit message: "The Scarlett
2i2 seems to take almost 500 ms to set the sample rate, even if the
clock is currently set to that value. This patch speeds up prepare of
the device, by avoiding setting the clock to something it already is."


Torstein
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 23 Jul 2013, James Stone wrote:

> Hi Alan,
> 
> Just tried a few old kernels, and it seems that the bug I am
> experiencing was introduced at the start of 3.7 - kernel 3.6.11 is

Note that 3.6.11 came out _after_ 3.7, not before.

> fine, and all the 3.7 series kernels are broken. So it seems it is not
> the updated ehci usb code that is directly responsible for the
> realtime audio problem. I have been trying the kernels from:
> http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
> to further zoom in on the culprit commit?

The usual approach is git bisection.  You can find plenty of references 
for how to do it on Google, but it is time consuming and needs plenty 
of disk space as well as a reasonably fast machine.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern  wrote:
> On Fri, 19 Jul 2013, James Stone wrote:
>
>> > The questions now are:
>> >
>> > Why are the same requests sent over and over again?
>> >
>> > Why does the ALSA driver attempt to set the clock frequency
>> > while the clock is actively in use?
>> >
>> > Has this behavior changed since the 3.5 kernel?
>> >
>>
>> Well, I think these requests may correspond to the lights flashing on
>> and off on the front of the device. When starting the device in 3.5 at
>> 256 frames/period (duplex), the lights flash on and off 2 times, in
>> the current patched 3.8 version I have been using, the device lights
>> flash on and off 4 times before starting jack with exactly the same
>> settings - so it seems for some reason, the requests are going through
>> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
>> usbmon trace of a successful start off list (plus the same for 3.8?)
>> if it would be useful.
>
> I don't know -- it's up to Clemens.
>
> Alan Stern
>

Hi Alan,

Just tried a few old kernels, and it seems that the bug I am
experiencing was introduced at the start of 3.7 - kernel 3.6.11 is
fine, and all the 3.7 series kernels are broken. So it seems it is not
the updated ehci usb code that is directly responsible for the
realtime audio problem. I have been trying the kernels from:
http://kernel.ubuntu.com/~kernel-ppa/mainline/. Any suggestions on how
to further zoom in on the culprit commit?

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 19 Jul 2013, James Stone wrote:

> > The questions now are:
> >
> > Why are the same requests sent over and over again?
> >
> > Why does the ALSA driver attempt to set the clock frequency
> > while the clock is actively in use?
> >
> > Has this behavior changed since the 3.5 kernel?
> >
> 
> Well, I think these requests may correspond to the lights flashing on
> and off on the front of the device. When starting the device in 3.5 at
> 256 frames/period (duplex), the lights flash on and off 2 times, in
> the current patched 3.8 version I have been using, the device lights
> flash on and off 4 times before starting jack with exactly the same
> settings - so it seems for some reason, the requests are going through
> multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5
> usbmon trace of a successful start off list (plus the same for 3.8?)
> if it would be useful.

I don't know -- it's up to Clemens.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 17, 2013 at 7:48 PM, Alan Stern  wrote:

> The 32-frames/period trace looks just like the 64 frames/period, only
> worse.  Each URB has only 4 packets, and the underrun problem is
> severe.  This won't happen after the minimum pipeline length is fixed.
>
> The 256-frames/period duplex trace is different.  There are 4 output
> URBs, alternating between 8 and 7 packets, so no underruns.  On the
> other hand, the audio-in stream doesn't start up until 900 ms after the
> audio-out, and everything stops almost immediately afterward.
>
> It certainly looks like that delay is causing the problem, so I tracked
> it down.  Before starting each stream, the ALSA driver sends several
> control requests.  I'm not very familiar with the USB audio protocol;
> it looks like the requests are GET_CUR and SET_CUR for various
> clock-related controls.
>
> First there is Set-Interface for the audio-in interface, followed by:
>
> 88010586a3c0 3063689257 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
> 88010586a3c0 3063689324 C Ci:1:004:0 0 1 = 01
> 88010586a3c0 3063689355 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
> 88010586a3c0 3063689448 C Ci:1:004:0 0 1 = 01
> 88010586a3c0 3063689496 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
> 88010586a3c0 3064139502 C Co:1:004:0 0 4 >
> 88010586a3c0 3064139605 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
> 88010586a3c0 3064139706 C Ci:1:004:0 0 4 = 44ac
>
> As far as I can tell, entity 0x28 is a CLOCK_SELECTOR and 0x29 is a
> CLOCK_SOURCE.  The last two requests appear to set the clock frequency
> to 44100 (0x44ac in little-endian hex) and read it back.
>
> Then there is Set-Interface for the audio-out interface, followed by:
>
> 88010586ac00 3064140256 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
> 88010586ac00 3064140495 C Ci:1:004:0 0 1 = 01
> 88010586ac00 3064140593 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
> 88010586ac00 3064140706 C Ci:1:004:0 0 1 = 01
> 88010586ac00 3064140764 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
> 88010586ac00 3064590952 C Co:1:004:0 0 4 >
> 88010586ac00 3064591055 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
> 88010586ac00 3064592201 C Ci:1:004:0 0 4 = 44ac
>
> These are exactly the same as the previous set of requests.  I don't
> know why they are repeated.  (It's worth pointing out that the same
> repeat also occurs in the simplex out-only trace.)
>
> Next, the audio-out URBs (including the synch URBs) begin, followed by
> some more control requests interspersed among them:
>
> 88010586ac00 3064593448 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
> 88010586ac00 3064593885 C Ci:1:004:0 0 1 = 01
> 88010586ac00 3064593964 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
> 88010586ac00 3064594185 C Ci:1:004:0 0 1 = 01
> 8800bd6db180 3064594238 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
> 8800bd6db180 3065044098 C Co:1:004:0 0 4 >
> 88010586a240 3065044188 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
> 88010586a240 3065044350 C Ci:1:004:0 0 4 = 44ac
> 88010586a240 3065044412 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
> 88010586a240 3065044474 C Ci:1:004:0 0 1 = 01
> 88010586a240 3065044510 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
> 88010586a240 3065044598 C Ci:1:004:0 0 1 = 01
> 88010586a240 3065044631 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
> 88010586a240 3065494566 C Co:1:004:0 0 4 >
> 88010586a240 3065494651 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
> 88010586a240 3065494814 C Ci:1:004:0 0 4 = 44ac
>
> after which the audio-in URBs start up.  This is the same four requests
> as before, repeated as before.  But notice the timestamps (second
> column, values are in microseconds).  Each of the SET_CUR requests for
> the clock frequency requires 450 ms to complete!  That accounts for the
> 900 ms delay.
>
> The same 450-ms delay can be seen in the earlier requests too, but
> there they didn't matter.  It appears that the delay in starting up the
> second stream annoys JACK, causing it to abort the session.
>
> After everything stops, another attempt is made.  This time there is
> only one SET_CUR between the start of the audio-out and the start of
> the audio-in.  Even so, a 450-ms delay evidently is enough to cause
> JACK to abort.  Several more attempts were made, each with the same
> result.
>
> The questions now are:
>
> Why are the same requests sent over and over again?
>
> Why does the ALSA driver attempt to set the clock frequency
> while the clock is actively in use?
>
> Has this behavior changed since the 3.5 kernel?
>

Well, I think these requests may correspond to the lights flashing on
and off on the front of the device. When starting the device in 3.5 at
256 frames/period (duplex), the lights flash on and off 2 times, in
the current patched 3.8 version I have been using, the device lights
flash on and off 4 times before starting jack with exactly the same
settings - so it seems for som

Re: Audio I/O parameters

[Alan Stern]

On Wed, 17 Jul 2013, James Stone wrote:

> On Wed, Jul 17, 2013 at 3:59 PM, Alan Stern  wrote:
> > On Tue, 16 Jul 2013, James Stone wrote:
> >
> >> Thanks. The patch allows jack to now start at (playback only) 64
> >> frames/period. It doesn't work with 32 frames/period though (I think
> >> you predicted this). This is still a regression from 3.5.0-28, which
> >> will work with 8 frames/period for playback only. Furthermore, jack
> >> won't start in duplex at 128 frames/period. It doesn't (yet) tempt me
> >> to use the 3.8 series kernels for proper audio work.
> >
> > Usbmon traces, please (for 3.8 only; I'm willing to believe that 3.5
> > works okay).  It's difficult to predict the final effect of the
> > parameters you supply to JACK, because the ALSA layer imposes its own
> > set of requirements on them.
> 
> I will send off list again.

The 32-frames/period trace looks just like the 64 frames/period, only
worse.  Each URB has only 4 packets, and the underrun problem is
severe.  This won't happen after the minimum pipeline length is fixed.

The 256-frames/period duplex trace is different.  There are 4 output
URBs, alternating between 8 and 7 packets, so no underruns.  On the
other hand, the audio-in stream doesn't start up until 900 ms after the
audio-out, and everything stops almost immediately afterward.

It certainly looks like that delay is causing the problem, so I tracked 
it down.  Before starting each stream, the ALSA driver sends several 
control requests.  I'm not very familiar with the USB audio protocol; 
it looks like the requests are GET_CUR and SET_CUR for various 
clock-related controls.

First there is Set-Interface for the audio-in interface, followed by:

88010586a3c0 3063689257 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
88010586a3c0 3063689324 C Ci:1:004:0 0 1 = 01
88010586a3c0 3063689355 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
88010586a3c0 3063689448 C Ci:1:004:0 0 1 = 01
88010586a3c0 3063689496 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
88010586a3c0 3064139502 C Co:1:004:0 0 4 >
88010586a3c0 3064139605 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
88010586a3c0 3064139706 C Ci:1:004:0 0 4 = 44ac

As far as I can tell, entity 0x28 is a CLOCK_SELECTOR and 0x29 is a
CLOCK_SOURCE.  The last two requests appear to set the clock frequency
to 44100 (0x44ac in little-endian hex) and read it back.

Then there is Set-Interface for the audio-out interface, followed by:

88010586ac00 3064140256 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
88010586ac00 3064140495 C Ci:1:004:0 0 1 = 01
88010586ac00 3064140593 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
88010586ac00 3064140706 C Ci:1:004:0 0 1 = 01
88010586ac00 3064140764 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
88010586ac00 3064590952 C Co:1:004:0 0 4 >
88010586ac00 3064591055 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
88010586ac00 3064592201 C Ci:1:004:0 0 4 = 44ac

These are exactly the same as the previous set of requests.  I don't
know why they are repeated.  (It's worth pointing out that the same
repeat also occurs in the simplex out-only trace.)

Next, the audio-out URBs (including the synch URBs) begin, followed by
some more control requests interspersed among them:

88010586ac00 3064593448 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
88010586ac00 3064593885 C Ci:1:004:0 0 1 = 01
88010586ac00 3064593964 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
88010586ac00 3064594185 C Ci:1:004:0 0 1 = 01
8800bd6db180 3064594238 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
8800bd6db180 3065044098 C Co:1:004:0 0 4 >
88010586a240 3065044188 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
88010586a240 3065044350 C Ci:1:004:0 0 4 = 44ac
88010586a240 3065044412 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
88010586a240 3065044474 C Ci:1:004:0 0 1 = 01
88010586a240 3065044510 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
88010586a240 3065044598 C Ci:1:004:0 0 1 = 01
88010586a240 3065044631 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
88010586a240 3065494566 C Co:1:004:0 0 4 >
88010586a240 3065494651 S Ci:1:004:0 s a1 01 0100 2900 0004 4 <
88010586a240 3065494814 C Ci:1:004:0 0 4 = 44ac

after which the audio-in URBs start up.  This is the same four requests
as before, repeated as before.  But notice the timestamps (second
column, values are in microseconds).  Each of the SET_CUR requests for
the clock frequency requires 450 ms to complete!  That accounts for the
900 ms delay.

The same 450-ms delay can be seen in the earlier requests too, but
there they didn't matter.  It appears that the delay in starting up the
second stream annoys JACK, causing it to abort the session.

After everything stops, another attempt is made.  This time there is 
only one SET_CUR between the start of the audio-out and the start of 
the audio-in.  Even so, a 450-ms delay evidently is enough to cause 
JACK to abort.  Several more attempts were made, each with the s

Re: Audio I/O parameters

[James Stone]

On Wed, Jul 17, 2013 at 3:59 PM, Alan Stern  wrote:
> On Tue, 16 Jul 2013, James Stone wrote:
>
>> Thanks. The patch allows jack to now start at (playback only) 64
>> frames/period. It doesn't work with 32 frames/period though (I think
>> you predicted this). This is still a regression from 3.5.0-28, which
>> will work with 8 frames/period for playback only. Furthermore, jack
>> won't start in duplex at 128 frames/period. It doesn't (yet) tempt me
>> to use the 3.8 series kernels for proper audio work.
>
> Usbmon traces, please (for 3.8 only; I'm willing to believe that 3.5
> works okay).  It's difficult to predict the final effect of the
> parameters you supply to JACK, because the ALSA layer imposes its own
> set of requirements on them.

I will send off list again.

>
> Also, changing the ALSA layer to use a larger minimum pipeline length
> might end up fixing all these problems.  I'm sure that with the current
> code at 64 frames/period, the hardware ends up skipping some frames,
> even though the effect may not be audible.

Yes - there are definitely missed frames. It sounds crackly.

>
>> Could there be any other changes to the kernel between 3.5 and 3.8
>> that might be affecting this?
>
> I don't know.  But don't forget also that some of the behaviors you see
> now may be a result of the first patch from Clemens (the one that fixes
> the problem of the ridiculously large maxpacket values).  That patch
> may not apply cleanly to the 3.5 kernel, but if it does, finding out
> what effects it has could be interesting.

OK - I might try this.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 16 Jul 2013, James Stone wrote:

> Thanks. The patch allows jack to now start at (playback only) 64
> frames/period. It doesn't work with 32 frames/period though (I think
> you predicted this). This is still a regression from 3.5.0-28, which
> will work with 8 frames/period for playback only. Furthermore, jack
> won't start in duplex at 128 frames/period. It doesn't (yet) tempt me
> to use the 3.8 series kernels for proper audio work.

Usbmon traces, please (for 3.8 only; I'm willing to believe that 3.5
works okay).  It's difficult to predict the final effect of the
parameters you supply to JACK, because the ALSA layer imposes its own
set of requirements on them.

Also, changing the ALSA layer to use a larger minimum pipeline length
might end up fixing all these problems.  I'm sure that with the current
code at 64 frames/period, the hardware ends up skipping some frames,
even though the effect may not be audible.

> Could there be any other changes to the kernel between 3.5 and 3.8
> that might be affecting this?

I don't know.  But don't forget also that some of the behaviors you see
now may be a result of the first patch from Clemens (the one that fixes
the problem of the ridiculously large maxpacket values).  That patch
may not apply cleanly to the 3.5 kernel, but if it does, finding out
what effects it has could be interesting.

> I was also wondering if it would be worth me trying to pinpoint which
> commit to the kernel caused this regression? If this is worthwhile,
> pls give some approximate instructions as to how to proceed.

No, it's not necessary.  I know where in ehci-hcd the relevant changes 
occurred.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Tue, Jul 16, 2013 at 7:36 PM, Alan Stern  wrote:
> On Mon, 15 Jul 2013, James Stone wrote:
>
>> >> James, did you ever provide a usbmon trace for 3.8 doing playback only
>> >> and using 64 frames/period?  I don't recall seeing any.  It might help.
>> >>
>> >
>> > OK - will send it to you off-list.
>
> I got it.  It explains a lot.
>
> The audio-out stream uses a pipeline of only 2 URBs.  The URBs start
> out alternating between 8 and 7 packets apiece.  This yields a total
> latency around 1.9 ms (equivalent to 2 periods of about 41 frames at
> 44.1 KHz), which is smaller than I would expect (2 periods of 64 frames
> works out to 2.9 ms).
>
> Anyway, this sort of works.  Every so often (roughly at intervals of 15
> ms) there is an underrun.  Evidently the computer's EHCI hardware
> sometimes requires URBs to be submitted more than 7 microframes in
> advance.  This means that the minimum safe pipeline length is 2 ms, and
> a little more would be better.  Indeed, there was one example in the
> usbmon trace with an IRQ latency over 65 us, which is half a
> microframe.  (Alternatively, a pipeline containing 3 URBs with 5
> packets each should be okay, although it would cause increased
> interrupt overhead.)
>
> After a second of this, the URBs suddenly changed.  They began to
> alternate between 7 and 5 packets; one of them had only 4.  I have no
> idea why this happened.  It led to a situation where ehci-hcd refused
> to accept an URB submission because it wasn't far enough in advance,
> and at that point everything came to a halt.
>
> Try the patch below; it should eliminate the "everything stops"
> problem.  But it will not do anything about the ongoing underruns.  To
> fix that, the latency has to be increased.  Or rather, the latency
> between the ALSA and USB stacks needs to increase to match the
> latency expected by JACK.  A pipeline of 2.9 ms (23 packets total)
> ought to be okay, whereas a pipeline of 15 packets -- what you're
> getting now -- is too short.
>
> And if the pipeline was long enough, the patch below wouldn't be
> needed.
>

Thanks. The patch allows jack to now start at (playback only) 64
frames/period. It doesn't work with 32 frames/period though (I think
you predicted this). This is still a regression from 3.5.0-28, which
will work with 8 frames/period for playback only. Furthermore, jack
won't start in duplex at 128 frames/period. It doesn't (yet) tempt me
to use the 3.8 series kernels for proper audio work.

Could there be any other changes to the kernel between 3.5 and 3.8
that might be affecting this?

I was also wondering if it would be worth me trying to pinpoint which
commit to the kernel caused this regression? If this is worthwhile,
pls give some approximate instructions as to how to proceed.

Best wishes,

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 16 Jul 2013, Clemens Ladisch wrote:

> Alan Stern wrote:
> > The audio-out stream uses a pipeline of only 2 URBs.  The URBs start
> > out alternating between 8 and 7 packets apiece.  This yields a total
> > latency around 1.9 ms (equivalent to 2 periods of about 41 frames at
> > 44.1 KHz), which is smaller than I would expect (2 periods of 64 frames
> > works out to 2.9 ms).
> >
> > Anyway, this sort of works.  Every so often (roughly at intervals of 15
> > ms) there is an underrun.  Evidently the computer's EHCI hardware
> > sometimes requires URBs to be submitted more than 7 microframes in
> > advance.
> 
> It would be trivial to make the driver respect these constraints, if
> only there were some mechanism to know about them.

That's a very good point.  We ought to have some way of exporting that 
information from the HCDs, but we don't.

I can tell you this much, if it helps:

For high-speed devices on EHCI, maintaining a minimum pipeline
length of 9 microframes should be sufficient under normal
circumstances.  There were a few examples in James's trace
where 8 was too short.  (xHCI may have lesser requirements for
high-speed devices; I don't know what they are.  For that matter,
some EHCI controllers also may have lesser requirements, but
since we can't export the actual value it would be best to stick
with a 9-uframe minimum.)

For full-speed devices, I think the minimum pipeline length
can be as low as 1 frame.  This is the same as saying that
there should be more than one URB total, so it's not much of
a restriction.

Note that by "minimum pipeline length", I mean the smallest duration of
URBs in the queue at any time.  The minimum occurs when one of the
largest URBs completes (it is not considered to be in the queue until
it gets resubmitted).

For example, a pipeline of three URBs with lengths 8, 8, and 4 packets
should work quite well.  It would have a minimum pipeline length of 12
microframes (when one of the 8-packet URBs was completing).  But 8, 4,
and 4 would not be good.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> The audio-out stream uses a pipeline of only 2 URBs.  The URBs start
> out alternating between 8 and 7 packets apiece.  This yields a total
> latency around 1.9 ms (equivalent to 2 periods of about 41 frames at
> 44.1 KHz), which is smaller than I would expect (2 periods of 64 frames
> works out to 2.9 ms).
>
> Anyway, this sort of works.  Every so often (roughly at intervals of 15
> ms) there is an underrun.  Evidently the computer's EHCI hardware
> sometimes requires URBs to be submitted more than 7 microframes in
> advance.

It would be trivial to make the driver respect these constraints, if
only there were some mechanism to know about them.

> After a second of this, the URBs suddenly changed.  They began to
> alternate between 7 and 5 packets; one of them had only 4.  I have no
> idea why this happened.

On this device, the host's playback rate is controlled by the device's
frequency feedback.

It's possible that all those underruns have confused the device's sample
counter.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Mon, 15 Jul 2013, James Stone wrote:

> >> James, did you ever provide a usbmon trace for 3.8 doing playback only
> >> and using 64 frames/period?  I don't recall seeing any.  It might help.
> >>
> >
> > OK - will send it to you off-list.

I got it.  It explains a lot.

The audio-out stream uses a pipeline of only 2 URBs.  The URBs start
out alternating between 8 and 7 packets apiece.  This yields a total
latency around 1.9 ms (equivalent to 2 periods of about 41 frames at
44.1 KHz), which is smaller than I would expect (2 periods of 64 frames
works out to 2.9 ms).

Anyway, this sort of works.  Every so often (roughly at intervals of 15
ms) there is an underrun.  Evidently the computer's EHCI hardware
sometimes requires URBs to be submitted more than 7 microframes in
advance.  This means that the minimum safe pipeline length is 2 ms, and
a little more would be better.  Indeed, there was one example in the
usbmon trace with an IRQ latency over 65 us, which is half a
microframe.  (Alternatively, a pipeline containing 3 URBs with 5 
packets each should be okay, although it would cause increased 
interrupt overhead.)

After a second of this, the URBs suddenly changed.  They began to
alternate between 7 and 5 packets; one of them had only 4.  I have no
idea why this happened.  It led to a situation where ehci-hcd refused
to accept an URB submission because it wasn't far enough in advance,
and at that point everything came to a halt.

Try the patch below; it should eliminate the "everything stops" 
problem.  But it will not do anything about the ongoing underruns.  To 
fix that, the latency has to be increased.  Or rather, the latency 
between the ALSA and USB stacks needs to increase to match the 
latency expected by JACK.  A pipeline of 2.9 ms (23 packets total) 
ought to be okay, whereas a pipeline of 15 packets -- what you're 
getting now -- is too short.

And if the pipeline was long enough, the patch below wouldn't be 
needed.

Alan Stern



Index: usb-3.10/drivers/usb/host/ehci-sched.c
===
--- usb-3.10.orig/drivers/usb/host/ehci-sched.c
+++ usb-3.10/drivers/usb/host/ehci-sched.c
@@ -1441,14 +1441,13 @@ iso_stream_schedule (
 
/*
 * Not ASAP: Use the next slot in the stream.  If
-* the entire URB falls before the threshold, fail.
+* the URB is too late, some of the packets won't
+* be handled by the hardware.
 */
else if (start + span - period < next) {
ehci_dbg(ehci, "iso urb late %p (%u+%u < %u)\n",
urb, start + base,
span - period, next + base);
-   status = -EXDEV;
-   goto fail;
}
}
 

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Mon, Jul 15, 2013 at 9:42 PM, Alan Stern  wrote:
> On Mon, 15 Jul 2013, Clemens Ladisch wrote:
>
>> > The interrupts shouldn't differ by more than the duration of one URB,
>> > which would be 1 ms.  There is an initial delay when a stream is first
>> > started, which generally lasts 5-10 ms.  But I think that hasn't
>> > changed since the 3.5 kernel.  Would it make any difference?
>>
>> The initial delay does not really matter as long as it's the same for
>> both streams.  (A difference of 1 ms would be significant if the period
>> size is that short.)
>>
>> > Bear in mind that the input and output streams are started at totally
>> > different times.
>>
>> Jack takes great care to start them together.
>
> If both streams are started at the same time then the initial delays
> won't differ by much more than the endpoint periods.  For audio, the
> periods all seem to be 1 (either 1 frame or 1 microframe, depending on
> the device's speed).  So I guess this should not be an issue.
>
> My remark above refers to some of the usbmon traces provided during
> earlier testing.  For example, this one
>
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1191603/+attachment/3714903/+files/1.mon.out
>
> shows the output stream starting at timestamp 3752849102 and the input
> stream starting at timestamp 3753752104, about 900 ms later.  Of
> course, it's possible that James told JACK to start them separately.
>
>> > And anyway, James's latest problem occurs even with playback only.
>>
>> On my machine, 3 x 8 frames works, although Jack often complains that
>> two periods are already completed when it expected only one.  Anything
>> less (2 x 8 frames) does not work; and 8 frames is where even my PCI
>> card begines to make problems.
>>
>> In any case, "poll timeout" would not indicate completion delays but
>> that no data was transferred _at all_.  In theory, this should not be
>> possible.  I'm stumped at the moment.
>
> The odd thing is that that at least one of the usbmon traces showed the
> audio streams getting shut down almost as soon as the audio-in started
> -- after only the first one or two URBs have completed.  That might
> explain why the poll was timing out.  But why were the streams stopped?
>
> James, did you ever provide a usbmon trace for 3.8 doing playback only
> and using 64 frames/period?  I don't recall seeing any.  It might help.
>

OK - will send it to you off-list.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Mon, 15 Jul 2013, Clemens Ladisch wrote:

> > The interrupts shouldn't differ by more than the duration of one URB,
> > which would be 1 ms.  There is an initial delay when a stream is first
> > started, which generally lasts 5-10 ms.  But I think that hasn't
> > changed since the 3.5 kernel.  Would it make any difference?
> 
> The initial delay does not really matter as long as it's the same for
> both streams.  (A difference of 1 ms would be significant if the period
> size is that short.)
> 
> > Bear in mind that the input and output streams are started at totally
> > different times.
> 
> Jack takes great care to start them together.

If both streams are started at the same time then the initial delays
won't differ by much more than the endpoint periods.  For audio, the
periods all seem to be 1 (either 1 frame or 1 microframe, depending on
the device's speed).  So I guess this should not be an issue.

My remark above refers to some of the usbmon traces provided during 
earlier testing.  For example, this one

https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1191603/+attachment/3714903/+files/1.mon.out

shows the output stream starting at timestamp 3752849102 and the input 
stream starting at timestamp 3753752104, about 900 ms later.  Of 
course, it's possible that James told JACK to start them separately.

> > And anyway, James's latest problem occurs even with playback only.
> 
> On my machine, 3 x 8 frames works, although Jack often complains that
> two periods are already completed when it expected only one.  Anything
> less (2 x 8 frames) does not work; and 8 frames is where even my PCI
> card begines to make problems.
> 
> In any case, "poll timeout" would not indicate completion delays but
> that no data was transferred _at all_.  In theory, this should not be
> possible.  I'm stumped at the moment.

The odd thing is that that at least one of the usbmon traces showed the
audio streams getting shut down almost as soon as the audio-in started
-- after only the first one or two URBs have completed.  That might
explain why the poll was timing out.  But why were the streams stopped?

James, did you ever provide a usbmon trace for 3.8 doing playback only
and using 64 frames/period?  I don't recall seeing any.  It might help.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> On Sat, 13 Jul 2013, Clemens Ladisch wrote:
>> James Stone wrote:
>>> On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:
> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
> JackAudioDriver::ProcessAsync: read error, stopping...

 Some further info - on 3.5.0-28, I can start jackd in playback only
 with 8 frames/period, and capture only at 16 frames/period.
>>>
>>> Any thoughts on further investigating this bug with the 3.8.0 kernel
>>> with the Focusrite Scarlett 2i4?
>>
>> Jack assumes that the interrupts for the playback and capture streams
>> happen at more or less the same time.  It might be possible that on the
>> newer kernels, there is a difference between the arrival times of the
>> first completion callback of each stream.
>
> The interrupts shouldn't differ by more than the duration of one URB,
> which would be 1 ms.  There is an initial delay when a stream is first
> started, which generally lasts 5-10 ms.  But I think that hasn't
> changed since the 3.5 kernel.  Would it make any difference?

The initial delay does not really matter as long as it's the same for
both streams.  (A difference of 1 ms would be significant if the period
size is that short.)

> Bear in mind that the input and output streams are started at totally
> different times.

Jack takes great care to start them together.

> And anyway, James's latest problem occurs even with playback only.

On my machine, 3 x 8 frames works, although Jack often complains that
two periods are already completed when it expected only one.  Anything
less (2 x 8 frames) does not work; and 8 frames is where even my PCI
card begines to make problems.

In any case, "poll timeout" would not indicate completion delays but
that no data was transferred _at all_.  In theory, this should not be
possible.  I'm stumped at the moment.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Sat, 13 Jul 2013, Clemens Ladisch wrote:

> James Stone wrote:
> > On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:
> >>> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
> >>> JackAudioDriver::ProcessAsync: read error, stopping...
> >>
> >> Some further info - on 3.5.0-28, I can start jackd in playback only
> >> with 8 frames/period, and capture only at 16 frames/period.
> >
> > Any thoughts on further investigating this bug with the 3.8.0 kernel
> > with the Focusrite Scarlett 2i4?
> 
> Jack assumes that the interrupts for the playback and capture streams
> happen at more or less the same time.  It might be possible that on the
> newer kernels, there is a difference between the arrival times of the
> first completion callback of each stream.

The interrupts shouldn't differ by more than the duration of one URB,
which would be 1 ms.  There is an initial delay when a stream is first
started, which generally lasts 5-10 ms.  But I think that hasn't
changed since the 3.5 kernel.  Would it make any difference?  I could 
write a patch to reduce or eliminate it.

Bear in mind that the input and output streams are started at totally
different times.  There's no reason to expect the first completion
interrupts to be close together.

And anyway, James's latest problem occurs even with playback only.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

James Stone wrote:
> On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:
>>> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
>>> JackAudioDriver::ProcessAsync: read error, stopping...
>>
>> Some further info - on 3.5.0-28, I can start jackd in playback only
>> with 8 frames/period, and capture only at 16 frames/period.
>
> Any thoughts on further investigating this bug with the 3.8.0 kernel
> with the Focusrite Scarlett 2i4?

Jack assumes that the interrupts for the playback and capture streams
happen at more or less the same time.  It might be possible that on the
newer kernels, there is a difference between the arrival times of the
first completion callback of each stream.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

James Stone wrote:
> On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:
>>> ALSA: poll time out, polled for 2176094 usecs
>>> JackAudioDriver::ProcessAsync: read error, stopping...
>>>
>>> This is a definite reduction in performance compared to earlier kernels.

In theory, "poll time out" indicates that the stream does not appear to
be running.  But I doubt this is a driver problem.

>> Some further info - on 3.5.0-28, I can start jackd in playback only
>> with 8 frames/period, and capture only at 16 frames/period.
>
> Any thoughts on further investigating this bug with the 3.8.0 kernel
> with the Focusrite Scarlett 2i4?

I'll see if I can reproduce this with my own async-feedback device.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 11 Jul 2013, James Stone wrote:

> Hi Clemens,
> 
> On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:
> 
> >> Acquire audio card Audio0
> >> creating alsa driver ... hw:USB,0|-|64|2|44100|0|0|nomon|swmeter|-|16bit
> >> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
> >> USB at usb-:00:12.2-3, high speed
> >> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
> >> ALSA: final selected sample format for playback: 32bit integer 
> >> little-endian
> >> ALSA: use 2 periods for playback
> >> ALSA: poll time out, polled for 2176094 usecs
> >> JackAudioDriver::ProcessAsync: read error, stopping...
> >>
> >> This is a definite reduction in performance compared to earlier kernels.
> >>
> >
> > Some further info - on 3.5.0-28, I can start jackd in playback only
> > with 8 frames/period, and capture only at 16 frames/period.
> >
> 
> Any thoughts on further investigating this bug with the 3.8.0 kernel
> with the Focusrite Scarlett 2i4? I'm happy to continue with any
> further testing if it would be helpful..

Clemens, if it's not already clear, I have reached the limit of my
knowledge at this point.  We are both hoping that you can help solve
this new bug.

James, I can offer one suggestion: Try running JACK under strace, with
playback-only at 64 frames/period.  The strace output may indicate why 
JACK thinks an error occurred when in fact the USB transfers worked 
perfectly.

> One thing is that another person affected by the same bug reports that
> it may be hardware-specific: See:
> 
> https://bugs.launchpad.net/ubuntu/+source/linux-lowlatency/+bug/1185563
> 
> Jori Neimi reports: "My laptop can handle jackd with a latency of 32
> samples on my Focusrite Scarlett 2i2 and 3.8.0-25 lowlatency kernel.
> On my desktop jackd won't even start with a latency of less than 512
> samples using the same kernel and same USB audio device. No help from
> the proposed 3.8.0-26, so I'll continue using 3.5.x kernels on my
> desktop."
> 
> Could this mean it is specific to some type of USB hardware on the 
> motherboard??

Yes, with the existing drivers hardware differences can affect the
result.  But with Clemens's new patch applied, the hardware shouldn't
matter.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

Hi Clemens,

On Mon, Jul 8, 2013 at 2:12 PM, James Stone  wrote:

>> Acquire audio card Audio0
>> creating alsa driver ... hw:USB,0|-|64|2|44100|0|0|nomon|swmeter|-|16bit
>> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
>> USB at usb-:00:12.2-3, high speed
>> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
>> ALSA: final selected sample format for playback: 32bit integer little-endian
>> ALSA: use 2 periods for playback
>> ALSA: poll time out, polled for 2176094 usecs
>> JackAudioDriver::ProcessAsync: read error, stopping...
>>
>> This is a definite reduction in performance compared to earlier kernels.
>>
>
> Some further info - on 3.5.0-28, I can start jackd in playback only
> with 8 frames/period, and capture only at 16 frames/period.
>

Any thoughts on further investigating this bug with the 3.8.0 kernel
with the Focusrite Scarlett 2i4? I'm happy to continue with any
further testing if it would be helpful..

One thing is that another person affected by the same bug reports that
it may be hardware-specific: See:

https://bugs.launchpad.net/ubuntu/+source/linux-lowlatency/+bug/1185563

Jori Neimi reports: "My laptop can handle jackd with a latency of 32
samples on my Focusrite Scarlett 2i2 and 3.8.0-25 lowlatency kernel.
On my desktop jackd won't even start with a latency of less than 512
samples using the same kernel and same USB audio device. No help from
the proposed 3.8.0-26, so I'll continue using 3.5.x kernels on my
desktop."

Could this mean it is specific to some type of USB hardware on the motherboard??

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 6, 2013 at 9:39 PM, James Stone  wrote:
> On Sat, Jul 6, 2013 at 9:36 PM, James Stone  wrote:
>> On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern  wrote:
>>> On Sat, 6 Jul 2013, James Stone wrote:
>>>
 The output when I try to start jack with 128 frames/period is:

 /usr/bin/jackd -dalsa -r44100 -p128 -n2 -D -Chw:USB,0 -Phw:USB,0 -I512 
 -O512 -S
 jackdmp 1.9.9.5
 Copyright 2001-2005 Paul Davis and others.
 Copyright 2004-2012 Grame.
 jackdmp comes with ABSOLUTELY NO WARRANTY
 This is free software, and you are welcome to redistribute it
 under certain conditions; see the file COPYING for details
 no message buffer overruns
 no message buffer overruns
 no message buffer overruns
 JACK server starting in realtime mode with priority 10
 audio_reservation_init
 Acquire audio card Audio0
 creating alsa driver ... 
 hw:USB,0|hw:USB,0|128|2|44100|0|0|nomon|swmeter|-|16bit
 Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
 USB at usb-:00:12.2-3, high speed
 configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 2 periods
 ALSA: final selected sample format for capture: 32bit integer little-endian
 ALSA: use 2 periods for capture
 ALSA: final selected sample format for playback: 32bit integer 
 little-endian
 ALSA: use 2 periods for playback
 ^CJack main caught signal 2

 ..the device is unusable with the lights flashing on and off. Jack
 then shuts down as seen above.

 At 256 frames/period it starts OK.
>>>
>>> What happens if you run JACK with input only, no audio out?
>>>
>>> Alan Stern
>>>
>>
>> It works fine with both input only or output only - down to 16
>> frames/period. At 8 frames/period it shows the same behaviour as at
>> 256 frames/period in duplex - but that is a ridiculously low latency
>> of 0.2ms, so hardly surprising it won't work.
>>
>> I have now got an error message when jack fails to start in duplex mode:
>>
>> ALSA: prepare error for playback on "hw:USB,0" (Protocol error)
>> JackAudioDriver::ProcessAsync: read error, stopping...
>>
>> James
>
> Sorry - slight misinformation there. I can go down to 16 frames/period
> for capture only, but for playback only, it will only go down to 128
> frames/period. Anything lower:
>
> /usr/bin/jackd -dalsa -r44100 -p64 -n2 -Phw:USB,0 -I512 -O512 -S
> jackdmp 1.9.9.5
> Copyright 2001-2005 Paul Davis and others.
> Copyright 2004-2012 Grame.
> jackdmp comes with ABSOLUTELY NO WARRANTY
> This is free software, and you are welcome to redistribute it
> under certain conditions; see the file COPYING for details
> no message buffer overruns
> no message buffer overruns
> no message buffer overruns
> JACK server starting in realtime mode with priority 10
> audio_reservation_init
> Acquire audio card Audio0
> creating alsa driver ... hw:USB,0|-|64|2|44100|0|0|nomon|swmeter|-|16bit
> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
> USB at usb-:00:12.2-3, high speed
> configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
> ALSA: final selected sample format for playback: 32bit integer little-endian
> ALSA: use 2 periods for playback
> ALSA: poll time out, polled for 2176094 usecs
> JackAudioDriver::ProcessAsync: read error, stopping...
>
> This is a definite reduction in performance compared to earlier kernels.
>

Some further info - on 3.5.0-28, I can start jackd in playback only
with 8 frames/period, and capture only at 16 frames/period.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 6, 2013 at 9:36 PM, James Stone  wrote:
> On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern  wrote:
>> On Sat, 6 Jul 2013, James Stone wrote:
>>
>>> The output when I try to start jack with 128 frames/period is:
>>>
>>> /usr/bin/jackd -dalsa -r44100 -p128 -n2 -D -Chw:USB,0 -Phw:USB,0 -I512 
>>> -O512 -S
>>> jackdmp 1.9.9.5
>>> Copyright 2001-2005 Paul Davis and others.
>>> Copyright 2004-2012 Grame.
>>> jackdmp comes with ABSOLUTELY NO WARRANTY
>>> This is free software, and you are welcome to redistribute it
>>> under certain conditions; see the file COPYING for details
>>> no message buffer overruns
>>> no message buffer overruns
>>> no message buffer overruns
>>> JACK server starting in realtime mode with priority 10
>>> audio_reservation_init
>>> Acquire audio card Audio0
>>> creating alsa driver ... 
>>> hw:USB,0|hw:USB,0|128|2|44100|0|0|nomon|swmeter|-|16bit
>>> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
>>> USB at usb-:00:12.2-3, high speed
>>> configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 2 periods
>>> ALSA: final selected sample format for capture: 32bit integer little-endian
>>> ALSA: use 2 periods for capture
>>> ALSA: final selected sample format for playback: 32bit integer little-endian
>>> ALSA: use 2 periods for playback
>>> ^CJack main caught signal 2
>>>
>>> ..the device is unusable with the lights flashing on and off. Jack
>>> then shuts down as seen above.
>>>
>>> At 256 frames/period it starts OK.
>>
>> What happens if you run JACK with input only, no audio out?
>>
>> Alan Stern
>>
>
> It works fine with both input only or output only - down to 16
> frames/period. At 8 frames/period it shows the same behaviour as at
> 256 frames/period in duplex - but that is a ridiculously low latency
> of 0.2ms, so hardly surprising it won't work.
>
> I have now got an error message when jack fails to start in duplex mode:
>
> ALSA: prepare error for playback on "hw:USB,0" (Protocol error)
> JackAudioDriver::ProcessAsync: read error, stopping...
>
> James

Sorry - slight misinformation there. I can go down to 16 frames/period
for capture only, but for playback only, it will only go down to 128
frames/period. Anything lower:

/usr/bin/jackd -dalsa -r44100 -p64 -n2 -Phw:USB,0 -I512 -O512 -S
jackdmp 1.9.9.5
Copyright 2001-2005 Paul Davis and others.
Copyright 2004-2012 Grame.
jackdmp comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
no message buffer overruns
no message buffer overruns
no message buffer overruns
JACK server starting in realtime mode with priority 10
audio_reservation_init
Acquire audio card Audio0
creating alsa driver ... hw:USB,0|-|64|2|44100|0|0|nomon|swmeter|-|16bit
Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
USB at usb-:00:12.2-3, high speed
configuring for 44100Hz, period = 64 frames (1.5 ms), buffer = 2 periods
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 2 periods for playback
ALSA: poll time out, polled for 2176094 usecs
JackAudioDriver::ProcessAsync: read error, stopping...

This is a definite reduction in performance compared to earlier kernels.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern  wrote:
> On Sat, 6 Jul 2013, James Stone wrote:
>
>> The output when I try to start jack with 128 frames/period is:
>>
>> /usr/bin/jackd -dalsa -r44100 -p128 -n2 -D -Chw:USB,0 -Phw:USB,0 -I512 -O512 
>> -S
>> jackdmp 1.9.9.5
>> Copyright 2001-2005 Paul Davis and others.
>> Copyright 2004-2012 Grame.
>> jackdmp comes with ABSOLUTELY NO WARRANTY
>> This is free software, and you are welcome to redistribute it
>> under certain conditions; see the file COPYING for details
>> no message buffer overruns
>> no message buffer overruns
>> no message buffer overruns
>> JACK server starting in realtime mode with priority 10
>> audio_reservation_init
>> Acquire audio card Audio0
>> creating alsa driver ... 
>> hw:USB,0|hw:USB,0|128|2|44100|0|0|nomon|swmeter|-|16bit
>> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
>> USB at usb-:00:12.2-3, high speed
>> configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 2 periods
>> ALSA: final selected sample format for capture: 32bit integer little-endian
>> ALSA: use 2 periods for capture
>> ALSA: final selected sample format for playback: 32bit integer little-endian
>> ALSA: use 2 periods for playback
>> ^CJack main caught signal 2
>>
>> ..the device is unusable with the lights flashing on and off. Jack
>> then shuts down as seen above.
>>
>> At 256 frames/period it starts OK.
>
> What happens if you run JACK with input only, no audio out?
>
> Alan Stern
>

It works fine with both input only or output only - down to 16
frames/period. At 8 frames/period it shows the same behaviour as at
256 frames/period in duplex - but that is a ridiculously low latency
of 0.2ms, so hardly surprising it won't work.

I have now got an error message when jack fails to start in duplex mode:

ALSA: prepare error for playback on "hw:USB,0" (Protocol error)
JackAudioDriver::ProcessAsync: read error, stopping...

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Sat, 6 Jul 2013, James Stone wrote:

> The output when I try to start jack with 128 frames/period is:
> 
> /usr/bin/jackd -dalsa -r44100 -p128 -n2 -D -Chw:USB,0 -Phw:USB,0 -I512 -O512 
> -S
> jackdmp 1.9.9.5
> Copyright 2001-2005 Paul Davis and others.
> Copyright 2004-2012 Grame.
> jackdmp comes with ABSOLUTELY NO WARRANTY
> This is free software, and you are welcome to redistribute it
> under certain conditions; see the file COPYING for details
> no message buffer overruns
> no message buffer overruns
> no message buffer overruns
> JACK server starting in realtime mode with priority 10
> audio_reservation_init
> Acquire audio card Audio0
> creating alsa driver ... 
> hw:USB,0|hw:USB,0|128|2|44100|0|0|nomon|swmeter|-|16bit
> Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
> USB at usb-:00:12.2-3, high speed
> configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 2 periods
> ALSA: final selected sample format for capture: 32bit integer little-endian
> ALSA: use 2 periods for capture
> ALSA: final selected sample format for playback: 32bit integer little-endian
> ALSA: use 2 periods for playback
> ^CJack main caught signal 2
> 
> ..the device is unusable with the lights flashing on and off. Jack
> then shuts down as seen above.
> 
> At 256 frames/period it starts OK.

What happens if you run JACK with input only, no audio out?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 6, 2013 at 10:36 AM, James Stone  wrote:
> On Sat, Jul 6, 2013 at 9:57 AM, Clemens Ladisch  wrote:
>> Alan Stern wrote:
>>> The first half is audio-out only.  About 2 seconds after the start, the
>>> audio-in stream starts up.  After 2 URBs (2 ms) of data, everything
>>> is shut down for no apparent reason -- there were no I/O errors.
>>> [...]
>>> I can't tell whether all these starts and stops are caused by JACK or
>>> by the ALSA layer, let alone figure out the reason for them.
>>
>> Two URBs is the Jack buffer size, isn't it?  Does Jack complain?
>>
>> James, pleasy try running aplay and arecord at the same time; something
>> like this:
>>
>> aplay   -D hw:x -t raw -c 4 -f S32_LE -r 44100 --period-size=128 
>> --buffer-size=256 /dev/zero &
>> arecord -D hw:x-c 2 -f S32_LE -r 44100 --period-size=128 
>> --buffer-size=256 test.wav
>>
>
> Yes - this works fine, without issue.

(I assumed you wanted me to run these without jack running?)

The output when I try to start jack with 128 frames/period is:

/usr/bin/jackd -dalsa -r44100 -p128 -n2 -D -Chw:USB,0 -Phw:USB,0 -I512 -O512 -S
jackdmp 1.9.9.5
Copyright 2001-2005 Paul Davis and others.
Copyright 2004-2012 Grame.
jackdmp comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
no message buffer overruns
no message buffer overruns
no message buffer overruns
JACK server starting in realtime mode with priority 10
audio_reservation_init
Acquire audio card Audio0
creating alsa driver ... hw:USB,0|hw:USB,0|128|2|44100|0|0|nomon|swmeter|-|16bit
Using ALSA driver USB-Audio running on card 0 - Focusrite Scarlett 2i4
USB at usb-:00:12.2-3, high speed
configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 2 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 2 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 2 periods for playback
^CJack main caught signal 2

..the device is unusable with the lights flashing on and off. Jack
then shuts down as seen above.

At 256 frames/period it starts OK.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Sat, Jul 6, 2013 at 9:57 AM, Clemens Ladisch  wrote:
> Alan Stern wrote:
>> The first half is audio-out only.  About 2 seconds after the start, the
>> audio-in stream starts up.  After 2 URBs (2 ms) of data, everything
>> is shut down for no apparent reason -- there were no I/O errors.
>> [...]
>> I can't tell whether all these starts and stops are caused by JACK or
>> by the ALSA layer, let alone figure out the reason for them.
>
> Two URBs is the Jack buffer size, isn't it?  Does Jack complain?
>
> James, pleasy try running aplay and arecord at the same time; something
> like this:
>
> aplay   -D hw:x -t raw -c 4 -f S32_LE -r 44100 --period-size=128 
> --buffer-size=256 /dev/zero &
> arecord -D hw:x-c 2 -f S32_LE -r 44100 --period-size=128 
> --buffer-size=256 test.wav
>

Yes - this works fine, without issue.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
> The first half is audio-out only.  About 2 seconds after the start, the
> audio-in stream starts up.  After 2 URBs (2 ms) of data, everything
> is shut down for no apparent reason -- there were no I/O errors.
> [...]
> I can't tell whether all these starts and stops are caused by JACK or
> by the ALSA layer, let alone figure out the reason for them.

Two URBs is the Jack buffer size, isn't it?  Does Jack complain?

James, pleasy try running aplay and arecord at the same time; something
like this:

aplay   -D hw:x -t raw -c 4 -f S32_LE -r 44100 --period-size=128 
--buffer-size=256 /dev/zero &
arecord -D hw:x-c 2 -f S32_LE -r 44100 --period-size=128 
--buffer-size=256 test.wav


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 5 Jul 2013, James Stone wrote:

> On Fri, Jul 5, 2013 at 3:32 PM, Alan Stern  wrote:
> > On Fri, 5 Jul 2013, James Stone wrote:
> >
> >> I agree the original unable to submit urb bug has been fixed. I have
> >> gone through the output trace, but I can't see anything like you were
> >> suggesting.
> >>
> >> I can submit the whole file (700k) somewhere if you like?
> >
> > You can email it to me off-list.
> >
> Thanks!
> 
> Here it is.

The file is clear enough, but I don't understand why things happened 
the way they did.

The first half is audio-out only.  About 2 seconds after the start, the 
audio-in stream starts up.  After 2 URBs (2 ms) of data, everything 
is shut down for no apparent reason -- there were no I/O errors.

1/2 second after that, the audio-out stream starts up again, and a
little less than 1/2 second later, the audio-in stream starts too.  
Once again, everything gets shut down down after only 2 audio-in URBs.

After another 1/2 second, the audio-out stream gets restarted once 
more.  The trace ends a little less than 1/2 second after that, and 
there is no more audio-in.

I can't tell whether all these starts and stops are caused by JACK or
by the ALSA layer, let alone figure out the reason for them.  Perhaps
running JACK under strace would help?  I have no idea -- this is out of
my league now.  Clemens is your best bet at this point.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Fri, 5 Jul 2013, James Stone wrote:

> I agree the original unable to submit urb bug has been fixed. I have
> gone through the output trace, but I can't see anything like you were
> suggesting.
> 
> I can submit the whole file (700k) somewhere if you like?

You can email it to me off-list.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Fri, Jul 5, 2013 at 3:31 AM, Alan Stern  wrote:
> On Thu, 4 Jul 2013, James Stone wrote:
>
>> > Can you post the part of the trace showing where the audio-in Zi lines
>> > first appear?
>> >
>>
>> I think this is the start of the Zi lines:
>>
>> 8800b3585f00 3572683229 C Ci:1:004:0 0 4 = 44ac
>> 8800a4976200 3572683283 S Zi:1:004:2 -115:1:1680 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4976e00 3572683325 S Zi:1:004:2 -115:1:1688 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4976600 3572683330 S Zi:1:004:2 -115:1:1632 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4977a00 3572683331 S Zi:1:004:2 -115:1:1640 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4977c00 3572683334 S Zi:1:004:2 -115:1:1648 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4977e00 3572683336 S Zi:1:004:2 -115:1:1656 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4976400 3572683338 S Zi:1:004:2 -115:1:1664 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a4976a00 3572683342 S Zi:1:004:2 -115:1:1672 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>
> Yep, that looks right.  It shows 8 URBs being submitted, where each URB
> contains 8 packets at intervals of 1 microframe.  Clemens's patch did
> exactly what it was supposed to.
>
>> 8800a49dc000 3572683863 C Zi:1:004:1 0:8:735:0 1 0:0:4 4 = 08830500
>> 8800a49dc000 3572683870 S Zi:1:004:1 -115:8:735 1 -18:0:4 4 <
>> 8800a4977400 3572683875 C Zo:1:004:1 0:1:729:0 8 0:0:96 0:96:80
>> 0:176:96 0:272:80 0:352:96 704 >
>> 8800a4977400 3572683882 S Zo:1:004:1 -115:1:729 8 -18:0:80
>> -18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
>>      
>> 8800a49dc600 3572684861 C Zi:1:004:1 0:8:743:0 1 0:0:4 4 = 08830500
>> 8800a49dc600 3572684868 S Zi:1:004:1 -115:8:743 1 -18:0:4 4 <
>> 8800a4977800 3572684872 C Zo:1:004:1 0:1:737:0 7 0:0:96 0:96:96
>> 0:192:80 0:272:96 0:368:80 624 >
>> 8800a4977800 3572684878 S Zo:1:004:1 -115:1:737 7 -18:0:80
>> -18:80:96 -18:176:80 -18:256:96 -18:352:80 608 =  
>>      
>> 8800a49dcd00 3572685859 C Zi:1:004:1 0:8:751:0 1 0:0:4 4 = 08830500
>> 8800a49dcd00 3572685865 S Zi:1:004:1 -115:8:751 1 -18:0:4 4 <
>> 8800a4977000 3572685869 C Zo:1:004:1 0:1:744:0 8 0:0:96 0:96:80
>> 0:176:96 0:272:80 0:352:96 704 >
>> 8800a4977000 3572685874 S Zo:1:004:1 -115:1:744 8 -18:0:96
>> -18:96:80 -18:176:96 -18:272:80 -18:352:96 720 =  
>>      
>> 8800a49dca00 3572686736 C Zi:1:004:1 0:8:759:0 1 0:0:4 4 = 08830500
>> 8800a49dca00 3572686742 S Zi:1:004:1 -115:8:759 1 -18:0:4 4 <
>> 8800a4976800 3572686746 C Zo:1:004:1 0:1:752:0 7 0:0:96 0:96:80
>> 0:176:96 0:272:80 0:352:96 624 >
>> 8800a4976800 3572686758 S Zo:1:004:1 -115:1:752 1 -18:0:80 80 =
>>       
>> 
>> 8800a49dc000 3572687737 C Zi:1:004:1 0:8:767:0 1 0:0:4 4 = 08830500
>> 8800a49dc000 3572687743 S Zi:1:004:1 -115:8:767 1 -18:0:4 4 <
>> 8800a4977400 3572687747 C Zo:1:004:1 0:1:759:0 8 0:0:80 0:80:96
>> 0:176:80 0:256:96 0:352:80 704 >
>> 8800a4977400 3572687753 S Zo:1:004:1 -115:1:759 8 -18:0:96
>> -18:96:80 -18:176:96 -18:272:80 -18:352:96 704 =  
>>      
>> 8800a4977800 3572688612 C Zo:1:004:1 0:1:767:0 7 0:0:80 0:80:96
>> 0:176:80 0:256:96 0:352:80 608 >
>> 8800a4977800 3572688623 S Zo:1:004:1 -115:1:767 7 -18:0:96
>> -18:96:80 -18:176:96 -18:272:80 -18:352:96 624 =  
>>      
>> 8800a4976200 3572688861 C Zi:1:004:2 0:1:768:0 8 0:0:40 0:63:40
>> 0:126:40 0:189:40 0:252:40 504 =    
>>    
>
> This shows the completion of the first audio-in URB.  It looks normal,
> except perhaps for the fact that the data values are 0.  But there's no
> doubt that these 0 values were actually sent to the computer by the
> device.
>
>> 8800a4976200 3572688872 S Zi:1:004:2 -115:1:768 8 -18:0:63
>> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
>> 8800a49dc600 3572688879 C Zi:1:004:1 0:8:775:0 1 0:0:4 4 = 08830500
>> 8800a49dc600 357260 S Zi:1:004:1 -115:8:775 1 -18:0:4 4 <
>> 8800a4977000 3572689612 C Zo:1:004:1 0:1:774:0 8 0:0:96 0:96:80
>> 0:176:96 0:272:80 0:352:96 720 >
>> 8800a4977000 3572689646 S Zo:1:004:1 -115:1:774 8 -18:0:80
>> -18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
>>      
>> 8800a4976800 3572689657 C Zo:1:004:1 -104:1:782:0 1 0:0:80 80 >
>
> Again, this shows no errors or 

Re: Audio I/O parameters

[Alan Stern]

On Thu, 4 Jul 2013, James Stone wrote:

> > Can you post the part of the trace showing where the audio-in Zi lines
> > first appear?
> >
> 
> I think this is the start of the Zi lines:
> 
> 8800b3585f00 3572683229 C Ci:1:004:0 0 4 = 44ac
> 8800a4976200 3572683283 S Zi:1:004:2 -115:1:1680 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4976e00 3572683325 S Zi:1:004:2 -115:1:1688 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4976600 3572683330 S Zi:1:004:2 -115:1:1632 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4977a00 3572683331 S Zi:1:004:2 -115:1:1640 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4977c00 3572683334 S Zi:1:004:2 -115:1:1648 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4977e00 3572683336 S Zi:1:004:2 -115:1:1656 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4976400 3572683338 S Zi:1:004:2 -115:1:1664 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a4976a00 3572683342 S Zi:1:004:2 -115:1:1672 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <

Yep, that looks right.  It shows 8 URBs being submitted, where each URB
contains 8 packets at intervals of 1 microframe.  Clemens's patch did
exactly what it was supposed to.

> 8800a49dc000 3572683863 C Zi:1:004:1 0:8:735:0 1 0:0:4 4 = 08830500
> 8800a49dc000 3572683870 S Zi:1:004:1 -115:8:735 1 -18:0:4 4 <
> 8800a4977400 3572683875 C Zo:1:004:1 0:1:729:0 8 0:0:96 0:96:80
> 0:176:96 0:272:80 0:352:96 704 >
> 8800a4977400 3572683882 S Zo:1:004:1 -115:1:729 8 -18:0:80
> -18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
>      
> 8800a49dc600 3572684861 C Zi:1:004:1 0:8:743:0 1 0:0:4 4 = 08830500
> 8800a49dc600 3572684868 S Zi:1:004:1 -115:8:743 1 -18:0:4 4 <
> 8800a4977800 3572684872 C Zo:1:004:1 0:1:737:0 7 0:0:96 0:96:96
> 0:192:80 0:272:96 0:368:80 624 >
> 8800a4977800 3572684878 S Zo:1:004:1 -115:1:737 7 -18:0:80
> -18:80:96 -18:176:80 -18:256:96 -18:352:80 608 =  
>      
> 8800a49dcd00 3572685859 C Zi:1:004:1 0:8:751:0 1 0:0:4 4 = 08830500
> 8800a49dcd00 3572685865 S Zi:1:004:1 -115:8:751 1 -18:0:4 4 <
> 8800a4977000 3572685869 C Zo:1:004:1 0:1:744:0 8 0:0:96 0:96:80
> 0:176:96 0:272:80 0:352:96 704 >
> 8800a4977000 3572685874 S Zo:1:004:1 -115:1:744 8 -18:0:96
> -18:96:80 -18:176:96 -18:272:80 -18:352:96 720 =  
>      
> 8800a49dca00 3572686736 C Zi:1:004:1 0:8:759:0 1 0:0:4 4 = 08830500
> 8800a49dca00 3572686742 S Zi:1:004:1 -115:8:759 1 -18:0:4 4 <
> 8800a4976800 3572686746 C Zo:1:004:1 0:1:752:0 7 0:0:96 0:96:80
> 0:176:96 0:272:80 0:352:96 624 >
> 8800a4976800 3572686758 S Zo:1:004:1 -115:1:752 1 -18:0:80 80 =
>       
> 
> 8800a49dc000 3572687737 C Zi:1:004:1 0:8:767:0 1 0:0:4 4 = 08830500
> 8800a49dc000 3572687743 S Zi:1:004:1 -115:8:767 1 -18:0:4 4 <
> 8800a4977400 3572687747 C Zo:1:004:1 0:1:759:0 8 0:0:80 0:80:96
> 0:176:80 0:256:96 0:352:80 704 >
> 8800a4977400 3572687753 S Zo:1:004:1 -115:1:759 8 -18:0:96
> -18:96:80 -18:176:96 -18:272:80 -18:352:96 704 =  
>      
> 8800a4977800 3572688612 C Zo:1:004:1 0:1:767:0 7 0:0:80 0:80:96
> 0:176:80 0:256:96 0:352:80 608 >
> 8800a4977800 3572688623 S Zo:1:004:1 -115:1:767 7 -18:0:96
> -18:96:80 -18:176:96 -18:272:80 -18:352:96 624 =  
>      
> 8800a4976200 3572688861 C Zi:1:004:2 0:1:768:0 8 0:0:40 0:63:40
> 0:126:40 0:189:40 0:252:40 504 =    
>    

This shows the completion of the first audio-in URB.  It looks normal,
except perhaps for the fact that the data values are 0.  But there's no
doubt that these 0 values were actually sent to the computer by the
device.

> 8800a4976200 3572688872 S Zi:1:004:2 -115:1:768 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a49dc600 3572688879 C Zi:1:004:1 0:8:775:0 1 0:0:4 4 = 08830500
> 8800a49dc600 357260 S Zi:1:004:1 -115:8:775 1 -18:0:4 4 <
> 8800a4977000 3572689612 C Zo:1:004:1 0:1:774:0 8 0:0:96 0:96:80
> 0:176:96 0:272:80 0:352:96 720 >
> 8800a4977000 3572689646 S Zo:1:004:1 -115:1:774 8 -18:0:80
> -18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
>      
> 8800a4976800 3572689657 C Zo:1:004:1 -104:1:782:0 1 0:0:80 80 >

Again, this shows no errors or any other problems.  It looks perfect.  
The fact that there are no "unable to submit urb" messages confirms 
this; the original bug is now gone.

Bu

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 4, 2013 at 10:13 PM, Alan Stern  wrote:
> On Thu, 4 Jul 2013, James Stone wrote:
>
>> OK.. How is this:
>>
>> -71:63:0 -71:126:0 -71:189:0 -71:252:0 504 =  
>>      
>
> To all appearances, this shows what happens when you abort or end a
> normal session.  There's no indication that anything went wrong.
>
> Can you post the part of the trace showing where the audio-in Zi lines
> first appear?
>

I think this is the start of the Zi lines:

8800b3585f00 3572683229 C Ci:1:004:0 0 4 = 44ac
8800a4976200 3572683283 S Zi:1:004:2 -115:1:1680 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4976e00 3572683325 S Zi:1:004:2 -115:1:1688 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4976600 3572683330 S Zi:1:004:2 -115:1:1632 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4977a00 3572683331 S Zi:1:004:2 -115:1:1640 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4977c00 3572683334 S Zi:1:004:2 -115:1:1648 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4977e00 3572683336 S Zi:1:004:2 -115:1:1656 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4976400 3572683338 S Zi:1:004:2 -115:1:1664 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a4976a00 3572683342 S Zi:1:004:2 -115:1:1672 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a49dc000 3572683863 C Zi:1:004:1 0:8:735:0 1 0:0:4 4 = 08830500
8800a49dc000 3572683870 S Zi:1:004:1 -115:8:735 1 -18:0:4 4 <
8800a4977400 3572683875 C Zo:1:004:1 0:1:729:0 8 0:0:96 0:96:80
0:176:96 0:272:80 0:352:96 704 >
8800a4977400 3572683882 S Zo:1:004:1 -115:1:729 8 -18:0:80
-18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
     
8800a49dc600 3572684861 C Zi:1:004:1 0:8:743:0 1 0:0:4 4 = 08830500
8800a49dc600 3572684868 S Zi:1:004:1 -115:8:743 1 -18:0:4 4 <
8800a4977800 3572684872 C Zo:1:004:1 0:1:737:0 7 0:0:96 0:96:96
0:192:80 0:272:96 0:368:80 624 >
8800a4977800 3572684878 S Zo:1:004:1 -115:1:737 7 -18:0:80
-18:80:96 -18:176:80 -18:256:96 -18:352:80 608 =  
     
8800a49dcd00 3572685859 C Zi:1:004:1 0:8:751:0 1 0:0:4 4 = 08830500
8800a49dcd00 3572685865 S Zi:1:004:1 -115:8:751 1 -18:0:4 4 <
8800a4977000 3572685869 C Zo:1:004:1 0:1:744:0 8 0:0:96 0:96:80
0:176:96 0:272:80 0:352:96 704 >
8800a4977000 3572685874 S Zo:1:004:1 -115:1:744 8 -18:0:96
-18:96:80 -18:176:96 -18:272:80 -18:352:96 720 =  
     
8800a49dca00 3572686736 C Zi:1:004:1 0:8:759:0 1 0:0:4 4 = 08830500
8800a49dca00 3572686742 S Zi:1:004:1 -115:8:759 1 -18:0:4 4 <
8800a4976800 3572686746 C Zo:1:004:1 0:1:752:0 7 0:0:96 0:96:80
0:176:96 0:272:80 0:352:96 624 >
8800a4976800 3572686758 S Zo:1:004:1 -115:1:752 1 -18:0:80 80 =
      

8800a49dc000 3572687737 C Zi:1:004:1 0:8:767:0 1 0:0:4 4 = 08830500
8800a49dc000 3572687743 S Zi:1:004:1 -115:8:767 1 -18:0:4 4 <
8800a4977400 3572687747 C Zo:1:004:1 0:1:759:0 8 0:0:80 0:80:96
0:176:80 0:256:96 0:352:80 704 >
8800a4977400 3572687753 S Zo:1:004:1 -115:1:759 8 -18:0:96
-18:96:80 -18:176:96 -18:272:80 -18:352:96 704 =  
     
8800a4977800 3572688612 C Zo:1:004:1 0:1:767:0 7 0:0:80 0:80:96
0:176:80 0:256:96 0:352:80 608 >
8800a4977800 3572688623 S Zo:1:004:1 -115:1:767 7 -18:0:96
-18:96:80 -18:176:96 -18:272:80 -18:352:96 624 =  
     
8800a4976200 3572688861 C Zi:1:004:2 0:1:768:0 8 0:0:40 0:63:40
0:126:40 0:189:40 0:252:40 504 =    
   
8800a4976200 3572688872 S Zi:1:004:2 -115:1:768 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a49dc600 3572688879 C Zi:1:004:1 0:8:775:0 1 0:0:4 4 = 08830500
8800a49dc600 357260 S Zi:1:004:1 -115:8:775 1 -18:0:4 4 <
8800a4977000 3572689612 C Zo:1:004:1 0:1:774:0 8 0:0:96 0:96:80
0:176:96 0:272:80 0:352:96 720 >
8800a4977000 3572689646 S Zo:1:004:1 -115:1:774 8 -18:0:80
-18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
     
8800a4976800 3572689657 C Zo:1:004:1 -104:1:782:0 1 0:0:80 80 >


James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 4 Jul 2013, James Stone wrote:

> OK.. How is this:
> 
> 8800a4976200 3574521627 S Zi:1:004:2 -115:1:3144 8 -18:0:63
> -18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
> 8800a49dc600 3574521634 C Zi:1:004:1 0:8:3151:0 1 0:0:4 4 = 08830500
> 8800a49dc600 3574521636 S Zi:1:004:1 -115:8:3151 1 -18:0:4 4 <
> 8800a4977000 3574522365 C Zo:1:004:1 0:1:3150:0 8 0:0:96 0:96:80
> 0:176:96 0:272:80 0:352:96 720 >
> 8800a4977000 3574522400 S Zo:1:004:1 -115:1:3150 8 -18:0:80
> -18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
>      

Up to here it shows the device operating normally, with no errors.
The rest of the trace shows the ongoing transfers being turned off.

> 8800a4976800 3574522413 C Zo:1:004:1 -104:1:3158:0 1 0:0:80 80 >
> 8800a4976e00 3574522618 C Zi:1:004:2 -104:1:3152:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 00f90500 00eb0200 0028fbff
> 0096fdff 00bc0400 006c0200 0027fcff 004efeff
> 8800a49dcd00 3574522625 C Zi:1:004:1 -104:8:3159:0 1 0:0:4 4 = 08830500
> 8800a4976600 3574523493 C Zi:1:004:2 -104:1:3160:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 0048 0047 0024
> 00d3 0022 0013 00e7 00f4
> 8800a49dca00 3574523501 C Zi:1:004:1 -104:8:3167:0 1 0:0:4 4 = 08830500
> 8800a4977400 3574523502 C Zo:1:004:1 -104:1:3159:0 8 0:0:96
> 0:96:80 0:176:96 0:272:80 0:352:96 704 >
> 8800a4977800 3574524441 C Zo:1:004:1 -104:1:3167:0 7 0:0:96
> 0:96:80 0:176:96 0:272:80 0:352:96 624 >
> 8800a4977a00 3574524617 C Zi:1:004:2 -104:1:3168:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 008b 0015 004e
> 00ef 003a 0013 003e 0050
> 8800a49dc000 3574524624 C Zi:1:004:1 -104:8:3175:0 1 0:0:4 4 = 08830500
> 8800a4977000 3574525368 C Zo:1:004:1 0:1:3174:0 8 0:0:80 0:80:96
> 0:176:80 0:256:96 0:352:80 704 >
> 8800a4977c00 3574525616 C Zi:1:004:2 -104:1:3176:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 002f 0045 0030
> 006b 0045 003f 004f 0046
> 8800a49dc600 3574525623 C Zi:1:004:1 -104:8:3183:0 1 0:0:4 4 = 08830500
> 8800a4977e00 3574526616 C Zi:1:004:2 -104:1:3184:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 0033 0016 003d
> 004b 0029 002c 0002 003d
> 8800b3585f00 3574527275 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
> 8800a4976400 3574527618 C Zi:1:004:2 -104:1:3192:0 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 0060 0040 0039
> 006a 0064 0003 002e 006f
> 8800b3585f00 3574527992 C Ci:1:004:0 0 1 = 01
> 8800b3585f00 3574528076 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
> 8800b3585f00 3574528240 C Ci:1:004:0 0 1 = 01
> 8800b3585f00 3574528290 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
> 8800a4976a00 3574528635 C Zi:1:004:2 -104:1:3200:1 8 0:0:40
> 0:63:40 0:126:40 0:189:40 0:252:40 504 = 0025 0039 003e
> 004c 0023 004c 0068 00fc
> 8800a4976200 3574529614 C Zi:1:004:2 -104:1:3208:8 8 -71:0:0
> -71:63:0 -71:126:0 -71:189:0 -71:252:0 504 =  
>      

To all appearances, this shows what happens when you abort or end a
normal session.  There's no indication that anything went wrong.

Can you post the part of the trace showing where the audio-in Zi lines 
first appear?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 4, 2013 at 9:12 PM, Alan Stern  wrote:
> On Thu, 4 Jul 2013, James Stone wrote:
>
>> > Another hint: The important lines are the ones containing "Zi:1:002:2"
>> > -- the actual string may be slightly different, but it will definitely
>> > contain "Zi" and it will match the " E " lines.
>> >
>> >
>>
>> OK. So I think this is something else then. There are no E lines, but
>> the device locks up and becomes unresponsive with the lower (128)
>> frames/period. Also, I think the performance is degraded vs. the 3.5
>> kernel because I am getting xruns with the 256 frames/period setting,
>> with the device just sitting there not processing any audio. This
>> doesn't even happen with 64 frames/period with a generic 3.5 kernel.
>
> In that case, post what you're got and make sure it includes those
> "Zi:1:002:2" lines.  Best would be if you can find a region of the file
> where those lines are present at the start but then disappear by the
> end.
>
> By the way, just to be clear, here is an example of some
> _uninteresting_ "Zi" lines from your recent trace:
>
> 8800a7c9a600 1731873904 C Zi:1:002:1 0:8:1199:0 1 0:0:4 4 = 08830500
> 8800a7c9a600 1731873912 S Zi:1:002:1 -115:8:1199 1 -18:0:4 4 <
>
> These lines are the synch channel for the audio-out stream; they have
> no connection with the audio-in even though the "i" in "Zi" indicates
> an "input" direction of data flow.  The distinguishing feature of the
> synch transfers is the "4" before the "=" and "<" symbols.  The real
> audio-in lines will have much larger numbers there, like 1024 or 2048.
>
> Alan Stern
>

OK.. How is this:

8800a4976200 3574521627 S Zi:1:004:2 -115:1:3144 8 -18:0:63
-18:63:63 -18:126:63 -18:189:63 -18:252:63 504 <
8800a49dc600 3574521634 C Zi:1:004:1 0:8:3151:0 1 0:0:4 4 = 08830500
8800a49dc600 3574521636 S Zi:1:004:1 -115:8:3151 1 -18:0:4 4 <
8800a4977000 3574522365 C Zo:1:004:1 0:1:3150:0 8 0:0:96 0:96:80
0:176:96 0:272:80 0:352:96 720 >
8800a4977000 3574522400 S Zo:1:004:1 -115:1:3150 8 -18:0:80
-18:80:96 -18:176:80 -18:256:96 -18:352:80 704 =  
     
8800a4976800 3574522413 C Zo:1:004:1 -104:1:3158:0 1 0:0:80 80 >
8800a4976e00 3574522618 C Zi:1:004:2 -104:1:3152:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 00f90500 00eb0200 0028fbff
0096fdff 00bc0400 006c0200 0027fcff 004efeff
8800a49dcd00 3574522625 C Zi:1:004:1 -104:8:3159:0 1 0:0:4 4 = 08830500
8800a4976600 3574523493 C Zi:1:004:2 -104:1:3160:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 0048 0047 0024
00d3 0022 0013 00e7 00f4
8800a49dca00 3574523501 C Zi:1:004:1 -104:8:3167:0 1 0:0:4 4 = 08830500
8800a4977400 3574523502 C Zo:1:004:1 -104:1:3159:0 8 0:0:96
0:96:80 0:176:96 0:272:80 0:352:96 704 >
8800a4977800 3574524441 C Zo:1:004:1 -104:1:3167:0 7 0:0:96
0:96:80 0:176:96 0:272:80 0:352:96 624 >
8800a4977a00 3574524617 C Zi:1:004:2 -104:1:3168:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 008b 0015 004e
00ef 003a 0013 003e 0050
8800a49dc000 3574524624 C Zi:1:004:1 -104:8:3175:0 1 0:0:4 4 = 08830500
8800a4977000 3574525368 C Zo:1:004:1 0:1:3174:0 8 0:0:80 0:80:96
0:176:80 0:256:96 0:352:80 704 >
8800a4977c00 3574525616 C Zi:1:004:2 -104:1:3176:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 002f 0045 0030
006b 0045 003f 004f 0046
8800a49dc600 3574525623 C Zi:1:004:1 -104:8:3183:0 1 0:0:4 4 = 08830500
8800a4977e00 3574526616 C Zi:1:004:2 -104:1:3184:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 0033 0016 003d
004b 0029 002c 0002 003d
8800b3585f00 3574527275 S Ci:1:004:0 s a1 01 0100 2800 0001 1 <
8800a4976400 3574527618 C Zi:1:004:2 -104:1:3192:0 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 0060 0040 0039
006a 0064 0003 002e 006f
8800b3585f00 3574527992 C Ci:1:004:0 0 1 = 01
8800b3585f00 3574528076 S Ci:1:004:0 s a1 01 0200 2900 0001 1 <
8800b3585f00 3574528240 C Ci:1:004:0 0 1 = 01
8800b3585f00 3574528290 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac
8800a4976a00 3574528635 C Zi:1:004:2 -104:1:3200:1 8 0:0:40
0:63:40 0:126:40 0:189:40 0:252:40 504 = 0025 0039 003e
004c 0023 004c 0068 00fc
8800a4976200 3574529614 C Zi:1:004:2 -104:1:3208:8 8 -71:0:0
-71:63:0 -71:126:0 -71:189:0 -71:252:0 504 =  
     


James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 4 Jul 2013, James Stone wrote:

> > Another hint: The important lines are the ones containing "Zi:1:002:2"
> > -- the actual string may be slightly different, but it will definitely
> > contain "Zi" and it will match the " E " lines.
> >
> >
> 
> OK. So I think this is something else then. There are no E lines, but
> the device locks up and becomes unresponsive with the lower (128)
> frames/period. Also, I think the performance is degraded vs. the 3.5
> kernel because I am getting xruns with the 256 frames/period setting,
> with the device just sitting there not processing any audio. This
> doesn't even happen with 64 frames/period with a generic 3.5 kernel.

In that case, post what you're got and make sure it includes those 
"Zi:1:002:2" lines.  Best would be if you can find a region of the file 
where those lines are present at the start but then disappear by the 
end.

By the way, just to be clear, here is an example of some 
_uninteresting_ "Zi" lines from your recent trace:

8800a7c9a600 1731873904 C Zi:1:002:1 0:8:1199:0 1 0:0:4 4 = 08830500
8800a7c9a600 1731873912 S Zi:1:002:1 -115:8:1199 1 -18:0:4 4 <

These lines are the synch channel for the audio-out stream; they have
no connection with the audio-in even though the "i" in "Zi" indicates
an "input" direction of data flow.  The distinguishing feature of the
synch transfers is the "4" before the "=" and "<" symbols.  The real
audio-in lines will have much larger numbers there, like 1024 or 2048.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[James Stone]

On Thu, Jul 4, 2013 at 4:19 PM, Alan Stern  wrote:
>
> On Thu, 4 Jul 2013, James Stone wrote:
>
> > Apologies - I realised I hadn't also applied the 1ms usb patch. With that
> > applied, it will start OK at 256, but not at 128 frames/period. (on earlier
> > kernels it can start at 64 frames/period).
> >
> > Output file (for 128 frames/period) attached.
>
> The part of the usbmon trace that you attached doesn't show any audio
> input at all -- no errors, nothing.
>
> Here's a hint: Look through the usbmon file for lines containing " E "
> -- those are the errors.  Extract a portion starting back from there
> about 100 lines, and include some of the " E " lines so we can see
> them.
>
> Another hint: The important lines are the ones containing "Zi:1:002:2"
> -- the actual string may be slightly different, but it will definitely
> contain "Zi" and it will match the " E " lines.
>
>

OK. So I think this is something else then. There are no E lines, but
the device locks up and becomes unresponsive with the lower (128)
frames/period. Also, I think the performance is degraded vs. the 3.5
kernel because I am getting xruns with the 256 frames/period setting,
with the device just sitting there not processing any audio. This
doesn't even happen with 64 frames/period with a generic 3.5 kernel.

James
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 4 Jul 2013, James Stone wrote:

> Apologies - I realised I hadn't also applied the 1ms usb patch. With that
> applied, it will start OK at 256, but not at 128 frames/period. (on earlier
> kernels it can start at 64 frames/period).
> 
> Output file (for 128 frames/period) attached.

The part of the usbmon trace that you attached doesn't show any audio 
input at all -- no errors, nothing.

Here's a hint: Look through the usbmon file for lines containing " E "  
-- those are the errors.  Extract a portion starting back from there
about 100 lines, and include some of the " E " lines so we can see
them.

Another hint: The important lines are the ones containing "Zi:1:002:2" 
-- the actual string may be slightly different, but it will definitely 
contain "Zi" and it will match the " E " lines.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Thu, 4 Jul 2013, James Stone wrote:

> Just tested, and it doesn't seem to work for fixing the problem on my
> system. Device still locks up when trying jack frames/period of less than
> 512.

Can you post a short (a few hundred lines will be enough) usbmon trace
showing what happens with frames/period = 256?

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

I wrote:
> I'll fix this in the driver.

James, please test this patch.


Regards,
Clemens

--8<>8--
ALSA: usb-audio: do not trust too-big wMaxPacketSize values

The driver used to assume that the streaming endpoint's wMaxPacketSize
value would be an indication of how much data the endpoint expects or
sends, and compute the number of packets per URB using this value.

However, the Focusrite Scarlett 2i4 declares a value of 1024 bytes,
while only about 88 or 44 bytes are be actually used.  This discrepancy
would result in URBs with far too few packets, which would not work
correctly on the EHCI driver.

To get correct URBs, use wMaxPacketSize only as an upper limit on the
packet size.

Reported-by: James Stone 
Not-yet-tested-by: James Stone 
Cc:  # 2.6.35+
Signed-off-by: Clemens Ladisch 
---
 sound/usb/endpoint.c |   13 ++---
 1 file changed, 6 insertions(+), 7 deletions(-)

diff --git a/sound/usb/endpoint.c b/sound/usb/endpoint.c
index 7a444b5..659950e 100644
--- a/sound/usb/endpoint.c
+++ b/sound/usb/endpoint.c
@@ -591,17 +591,16 @@ static int data_ep_set_params(struct snd_usb_endpoint *ep,
ep->stride = frame_bits >> 3;
ep->silence_value = pcm_format == SNDRV_PCM_FORMAT_U8 ? 0x80 : 0;

-   /* calculate max. frequency */
-   if (ep->maxpacksize) {
+   /* assume max. frequency is 25% higher than nominal */
+   ep->freqmax = ep->freqn + (ep->freqn >> 2);
+   maxsize = ((ep->freqmax + 0x) * (frame_bits >> 3))
+   >> (16 - ep->datainterval);
+   /* but wMaxPacketSize might reduce this */
+   if (ep->maxpacksize && ep->maxpacksize < maxsize) {
/* whatever fits into a max. size packet */
maxsize = ep->maxpacksize;
ep->freqmax = (maxsize / (frame_bits >> 3))
<< (16 - ep->datainterval);
-   } else {
-   /* no max. packet size: just take 25% higher than nominal */
-   ep->freqmax = ep->freqn + (ep->freqn >> 2);
-   maxsize = ((ep->freqmax + 0x) * (frame_bits >> 3))
-   >> (16 - ep->datainterval);
}

if (ep->fill_max)
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Alan Stern]

On Tue, 2 Jul 2013, Clemens Ladisch wrote:

> Alan Stern wrote:
> >256 samples/period / (44100 samples/second) * 8000 microframes/second
> > = 46.44 microframes/period.
> >
> > Therefore I would expect to see snd-usb-audio submitting isochronous
> > URBs with 46 or 47 packets, with a pipeline depth of 2 URBs.
> >
> > However, that's not what actually happens.  The audio-out stream uses 8
> > URBs each containing about 7 packets on average, for a latency of 7 ms.
> > The audio-in stream uses 8 URBs each containing 1 packet, for a latency
> > of 0.125 ms and a pipeline duration of 1 ms -- which is too small for
> > the current version of ehci-hcd to accept.
> 
> IIRC 8 x 1 frames worked once upon a time.

And it will once again, after the conversion to tasklets.  :-)

> Anyway, the driver attempts to keep a minimum size of 1 ms for each URB,
> but also uses wMaxPacketSize to compute this and assumes that this is
> not too far off from the actual packet size.  This appears to be the
> first device to use a ridiculously large value of 1024 bytes.

I thought this might be related to the problem.  It was quite 
noticeable in the usbmon trace that the input data occupied only 40 or 
48 bytes of a 1024-byte buffer.

> I'll fix this in the driver.

Thank you.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Audio I/O parameters

[Clemens Ladisch]

Alan Stern wrote:
>256 samples/period / (44100 samples/second) * 8000 microframes/second
>   = 46.44 microframes/period.
>
> Therefore I would expect to see snd-usb-audio submitting isochronous
> URBs with 46 or 47 packets, with a pipeline depth of 2 URBs.
>
> However, that's not what actually happens.  The audio-out stream uses 8
> URBs each containing about 7 packets on average, for a latency of 7 ms.
> The audio-in stream uses 8 URBs each containing 1 packet, for a latency
> of 0.125 ms and a pipeline duration of 1 ms -- which is too small for
> the current version of ehci-hcd to accept.

IIRC 8 x 1 frames worked once upon a time.

Anyway, the driver attempts to keep a minimum size of 1 ms for each URB,
but also uses wMaxPacketSize to compute this and assumes that this is
not too far off from the actual packet size.  This appears to be the
first device to use a ridiculously large value of 1024 bytes.

I'll fix this in the driver.


Regards,
Clemens
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Audio I/O parameters

[Alan Stern]

Clemens:

I'm working with James Stone on a bug report, and maybe you can help.  
The main problem seems to be connected with how snd-usb-audio decides
to package its USB transfers.  The details are all available at

https://bugs.launchpad.net/bugs/1191603

Here's the quick summary.

James is using JACK to do audio I/O.  The data values are 24 bits
(transmitted across the USB bus as 4-byte values).  The audio-in stream
has two data values per sample (stereo), the audio-out stream has four,
and the sampling rate is 44100 Hz.

I'm not at all familiar with JACK, but James explained that it uses two
parameters to control the data flow: frames/period and periods/buffer.  
In case you don't already know what these mean, as far as I can tell a
"frame" is a sample, and frames/period is the number of samples that
JACK sends to/from the kernel in each system call.  Periods/buffer
evidently describes the total size of JACK's ring buffer.

James has frames/period set to 256 and periods/buffer set to 2.  This 
means the duration of a period is:

   256 samples/period / (44100 samples/second) * 8000 microframes/second
= 46.44 microframes/period.

The bInterval values for the isochronous OUT and IN endpoints are both
1 (this is a high-speed device, so the intervals are in microframes).  
Therefore I would expect to see snd-usb-audio submitting isochronous
URBs with 46 or 47 packets, with a pipeline depth of 2 URBs.  This
would yield an output latency of 11.6 ms, which is perhaps larger than
James would like, but could be adjusted.

However, that's not what actually happens.  The audio-out stream uses 8
URBs each containing about 7 packets on average, for a latency of 7 ms.  
The audio-in stream uses 8 URBs each containing 1 packet, for a latency
of 0.125 ms and a pipeline duration of 1 ms -- which is too small for
the current version of ehci-hcd to accept.

Why is there such a large discrepancy between the expected URB 
characteristics and the actual ones?

Why are the audio-out URBs so different from the audio-in (7 packets
per URB vs. 1 packet)?

How can James adjust his settings to get something more reasonable?  
For example, URBs containing 11 or 12 packets (64 samples on average)  
would yield an input latency of 1.5 ms, and a pipeline depth of 4 URBs 
would yield an output latency of 5.8 ms.  These numbers would be 
equivalent to 64 frames/period and 4 periods/buffer in JACK's 
terminology.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html