Re: Audio I/O parameters
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
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
On Sat, Aug 3, 2013 at 11:30 PM, James Stone jamesmst...@gmail.com wrote: On Aug 3, 2013 9:28 PM, Alan Stern st...@rowland.harvard.edu 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
On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern st...@rowland.harvard.edu 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
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_entity URL Clas-32862d.h. 895us : place_entity
Re: Audio I/O parameters
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
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
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
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
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
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
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
On Fri, Aug 2, 2013 at 8:49 AM, James Stone jamesmst...@gmail.com wrote: On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern st...@rowland.harvard.edu 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
On Fri, Aug 2, 2013 at 8:02 PM, James Stone jamesmst...@gmail.com wrote: On Fri, Aug 2, 2013 at 8:49 AM, James Stone jamesmst...@gmail.com wrote: On Thu, Aug 1, 2013 at 5:43 PM, Alan Stern st...@rowland.harvard.edu 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
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 pet...@infradead.org --- 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
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
On Fri, Aug 2, 2013 at 8:40 PM, Alan Stern st...@rowland.harvard.edu 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 wrote: On Wed, 31 Jul 2013, James Stone wrote: On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern st...@rowland.harvard.edu 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
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 : stack trace = 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
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
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 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
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
On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern st...@rowland.harvard.edu 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
On Wed, 31 Jul 2013, James Stone wrote: On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern st...@rowland.harvard.edu 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
On Wed, Jul 31, 2013 at 10:07 PM, Alan Stern st...@rowland.harvard.edu wrote: On Wed, 31 Jul 2013, James Stone wrote: On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern st...@rowland.harvard.edu 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_caller -retint_careful cc1-21060
Re: Audio I/O parameters
On Wed, Jul 31, 2013 at 10:07 PM, Alan Stern st...@rowland.harvard.edu wrote: On Wed, 31 Jul 2013, James Stone wrote: On Wed, Jul 31, 2013 at 4:48 PM, Alan Stern st...@rowland.harvard.edu 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 kernel: [ 6233.028443] ehci-pci :00:12.2: iso underrun
Re: Audio I/O parameters
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 : stack trace = 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
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 : stack trace = 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
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
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
On Sun, 28 Jul 2013, James Stone wrote: On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern st...@rowland.harvard.edu 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
On Mon, Jul 29, 2013 at 9:41 PM, James Stone jamesmst...@gmail.com wrote: On Mon, Jul 29, 2013 at 4:25 PM, Alan Stern st...@rowland.harvard.edu wrote: On Sun, 28 Jul 2013, James Stone wrote: On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern st...@rowland.harvard.edu 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 : stack trace = 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
On Sat, Jul 27, 2013 at 6:45 PM, Alan Stern st...@rowland.harvard.edu 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
On Fri, Jul 26, 2013 at 11:46 PM, James Stone jamesmst...@gmail.com wrote: On Fri, Jul 26, 2013 at 11:43 PM, James Stone jamesmst...@gmail.com wrote: On Fri, Jul 26, 2013 at 7:54 PM, Alan Stern st...@rowland.harvard.edu 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
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
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 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
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) {
- total_packs = 2;
- } else {
-
Re: Audio I/O parameters
On Wed, Jul 24, 2013 at 2:42 AM, James Stone jamesmst...@gmail.com wrote: On Wed, Jul 24, 2013 at 12:23 AM, James Stone jamesmst...@gmail.com wrote: On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge he...@resisty.net 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 st...@rowland.harvard.edu 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
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: http://git.kernel.org/linus/e9ba389c5ffc. 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: http://git.kernel.org/linus/015618b902ae 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
On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch clem...@ladisch.de 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: http://git.kernel.org/linus/e9ba389c5ffc. 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: http://git.kernel.org/linus/015618b902ae 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
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: http://git.kernel.org/linus/015618b902ae 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
On Thu, 25 Jul 2013, James Stone wrote: On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch clem...@ladisch.de 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: http://git.kernel.org/linus/e9ba389c5ffc. 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: http://git.kernel.org/linus/015618b902ae 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-usbm=137476385206265w=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
On Thu, Jul 25, 2013 at 4:29 PM, Alan Stern st...@rowland.harvard.edu wrote: On Thu, 25 Jul 2013, James Stone wrote: On Thu, Jul 25, 2013 at 2:12 PM, Clemens Ladisch clem...@ladisch.de 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: http://git.kernel.org/linus/e9ba389c5ffc. 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: http://git.kernel.org/linus/015618b902ae 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-usbm=137476385206265w=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
On Thu, 25 Jul 2013, James Stone wrote: Please try the patch from here: http://marc.info/?l=linux-usbm=137476385206265w=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
On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern st...@rowland.harvard.edu wrote: On Thu, 25 Jul 2013, James Stone wrote: Please try the patch from here: http://marc.info/?l=linux-usbm=137476385206265w=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
On Thu, 25 Jul 2013, James Stone wrote:
On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern st...@rowland.harvard.edu wrote:
On Thu, 25 Jul 2013, James Stone wrote:
Please try the patch from here:
http://marc.info/?l=linux-usbm=137476385206265w=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
On Thu, Jul 25, 2013 at 10:24 PM, Alan Stern st...@rowland.harvard.edu wrote: On Thu, 25 Jul 2013, James Stone wrote: On Thu, Jul 25, 2013 at 7:26 PM, Alan Stern st...@rowland.harvard.edu wrote: On Thu, 25 Jul 2013, James Stone wrote: Please try the patch from here: http://marc.info/?l=linux-usbm=137476385206265w=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 entry 15 Jul 26 00:01:24 blueberry kernel: [ 182.778798] ieee80211 phy0:
Re: Audio I/O parameters
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
On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern st...@rowland.harvard.edu 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
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
On Tue, Jul 23, 2013 at 21:13:23 +0100, James Stone wrote: On Fri, Jul 19, 2013 at 4:17 PM, Alan Stern st...@rowland.harvard.edu 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
On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge he...@resisty.net 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 st...@rowland.harvard.edu 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
On Wed, Jul 24, 2013 at 12:23 AM, James Stone jamesmst...@gmail.com wrote: On Tue, Jul 23, 2013 at 11:50 PM, Torstein Hegge he...@resisty.net 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 st...@rowland.harvard.edu 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
On Wed, Jul 17, 2013 at 7:48 PM, Alan Stern st...@rowland.harvard.edu 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 some reason, the requests are going through multiple times on the 3.8 kernel but
Re: Audio I/O parameters
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
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
On Wed, Jul 17, 2013 at 3:59 PM, Alan Stern st...@rowland.harvard.edu 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
On Wed, 17 Jul 2013, James Stone wrote: On Wed, Jul 17, 2013 at 3:59 PM, Alan Stern st...@rowland.harvard.edu 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 same result. The
Re: Audio I/O parameters
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
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
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
On Tue, Jul 16, 2013 at 7:36 PM, Alan Stern st...@rowland.harvard.edu 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 wrote: On Sat, 13 Jul 2013, Clemens Ladisch wrote: James Stone wrote: On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com 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
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
On Mon, Jul 15, 2013 at 9:42 PM, Alan Stern st...@rowland.harvard.edu 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
James Stone wrote: On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com 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
On Sat, 13 Jul 2013, Clemens Ladisch wrote: James Stone wrote: On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com 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
On Thu, 11 Jul 2013, James Stone wrote: Hi Clemens, On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com wrote: Snip! 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 wrote: On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com 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
Hi Clemens, On Mon, Jul 8, 2013 at 2:12 PM, James Stone jamesmst...@gmail.com wrote: Snip! 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
On Sat, Jul 6, 2013 at 9:39 PM, James Stone jamesmst...@gmail.com wrote: On Sat, Jul 6, 2013 at 9:36 PM, James Stone jamesmst...@gmail.com wrote: On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern st...@rowland.harvard.edu 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
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
On Sat, Jul 6, 2013 at 9:57 AM, Clemens Ladisch clem...@ladisch.de 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
On Sat, Jul 6, 2013 at 10:36 AM, James Stone jamesmst...@gmail.com wrote: On Sat, Jul 6, 2013 at 9:57 AM, Clemens Ladisch clem...@ladisch.de 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
On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern st...@rowland.harvard.edu 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
On Sat, Jul 6, 2013 at 9:36 PM, James Stone jamesmst...@gmail.com wrote: On Sat, Jul 6, 2013 at 3:41 PM, Alan Stern st...@rowland.harvard.edu 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
On Fri, Jul 5, 2013 at 3:31 AM, Alan Stern st...@rowland.harvard.edu 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 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.
But this isn't getting
Re: Audio I/O parameters
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
On Fri, 5 Jul 2013, James Stone wrote: On Fri, Jul 5, 2013 at 3:32 PM, Alan Stern st...@rowland.harvard.edu 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
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
On Thu, Jul 4, 2013 at 4:19 PM, Alan Stern st...@rowland.harvard.edu 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
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
On Thu, Jul 4, 2013 at 9:12 PM, Alan Stern st...@rowland.harvard.edu 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
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
On Thu, Jul 4, 2013 at 10:13 PM, Alan Stern st...@rowland.harvard.edu 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
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.
But this isn't getting us anywhere. Evidently what we need to see is
the part of the trace where the new
Re: Audio I/O parameters
I wrote:
I'll fix this in the driver.
James, please test this patch.
Regards,
Clemens
--88--
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 jamesmst...@gmail.com
Not-yet-tested-by: James Stone jamesmst...@gmail.com
Cc: sta...@vger.kernel.org # 2.6.35+
Signed-off-by: Clemens Ladisch clem...@ladisch.de
---
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
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
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
Re: Audio I/O parameters
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
