From linux-kernel Thu Aug 19 20:37:57 2004 From: karl.vogel () seagha ! com Date: Thu, 19 Aug 2004 20:37:57 +0000 To: linux-kernel Subject: Re: [patch] voluntary-preempt-2.6.8.1-P4 Message-Id: X-MARC-Message: https://marc.info/?l=linux-kernel&m=109294792517277 The following latency trace is generated each time the sound driver is opened by an application on my box. # lspci -s 00:06.0 00:06.0 Multimedia audio controller: nVidia Corporation nForce3 Audio (rev a2) Audio driver: # lsmod|grep snd snd_seq 51856 0 snd_intel8x0 30600 0 snd_ac97_codec 66820 1 snd_intel8x0 snd_pcm 88264 1 snd_intel8x0 snd_timer 22596 2 snd_seq,snd_pcm snd_page_alloc 9288 2 snd_intel8x0,snd_pcm snd_mpu401_uart 6656 1 snd_intel8x0 snd_rawmidi 21156 1 snd_mpu401_uart snd_seq_device 7176 2 snd_seq,snd_rawmidi snd 48804 8 snd_seq,snd_intel8x0,snd_ac97_codec,snd_pcm,snd_timer,snd_mpu401_uart,snd_rawmidi,snd_seq_device soundcore 7840 1 snd preemption latency trace v1.0.1 ------------------------------- latency: 50752 us, entries: 267 (267) ----------------- | task: artsd/2502, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: voluntary_resched+0x31/0x60 => ended at: sys_ioctl+0xf4/0x2b0 =======> 0.000ms (+0.000ms): touch_preempt_timing (voluntary_resched) 0.000ms (+0.000ms): snd_power_wait (snd_pcm_prepare) 0.000ms (+0.000ms): snd_pcm_action_lock_irq (snd_pcm_prepare) 0.001ms (+0.000ms): snd_pcm_action_single (snd_pcm_action_lock_irq) 0.001ms (+0.000ms): snd_pcm_pre_prepare (snd_pcm_action_single) 0.001ms (+0.000ms): snd_pcm_do_prepare (snd_pcm_action_single) 0.001ms (+0.000ms): snd_intel8x0_pcm_prepare (snd_pcm_do_prepare) 0.002ms (+0.000ms): snd_intel8x0_setup_pcm_out (snd_intel8x0_pcm_prepare) 0.002ms (+0.000ms): igetdword (snd_intel8x0_setup_pcm_out) 0.002ms (+0.000ms): iputdword (snd_intel8x0_setup_pcm_out) 0.003ms (+0.000ms): __const_udelay (snd_intel8x0_setup_pcm_out) 0.003ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 0.003ms (+0.000ms): delay_pmtmr (__delay) 0.995ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 0.995ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 0.995ms (+0.000ms): delay_pmtmr (__delay) 1.986ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 1.986ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 1.986ms (+0.000ms): delay_pmtmr (__delay) 2.978ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 2.978ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 2.978ms (+0.000ms): delay_pmtmr (__delay) 3.969ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 3.969ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 3.970ms (+0.000ms): delay_pmtmr (__delay) 4.961ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 4.961ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 4.961ms (+0.000ms): delay_pmtmr (__delay) 5.953ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 5.953ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 5.953ms (+0.000ms): delay_pmtmr (__delay) 6.944ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 6.944ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 6.944ms (+0.000ms): delay_pmtmr (__delay) 7.936ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 7.936ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 7.936ms (+0.000ms): delay_pmtmr (__delay) 8.927ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 8.927ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 8.927ms (+0.000ms): delay_pmtmr (__delay) 9.919ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 9.919ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 9.919ms (+0.000ms): delay_pmtmr (__delay) 10.910ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 10.910ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 10.911ms (+0.000ms): delay_pmtmr (__delay) 11.902ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 11.902ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 11.902ms (+0.000ms): delay_pmtmr (__delay) 12.893ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 12.894ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 12.894ms (+0.000ms): delay_pmtmr (__delay) 13.885ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 13.885ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 13.885ms (+0.000ms): delay_pmtmr (__delay) 14.877ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 14.877ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 14.877ms (+0.000ms): delay_pmtmr (__delay) 15.868ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 15.868ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 15.868ms (+0.000ms): delay_pmtmr (__delay) 16.860ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 16.860ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 16.860ms (+0.000ms): delay_pmtmr (__delay) 17.851ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 17.851ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 17.851ms (+0.000ms): delay_pmtmr (__delay) 18.843ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 18.843ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 18.843ms (+0.000ms): delay_pmtmr (__delay) 19.834ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 19.835ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 19.835ms (+0.000ms): delay_pmtmr (__delay) 20.826ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 20.826ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 20.826ms (+0.000ms): delay_pmtmr (__delay) 21.818ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 21.818ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 21.818ms (+0.000ms): delay_pmtmr (__delay) 22.809ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 22.809ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 22.809ms (+0.000ms): delay_pmtmr (__delay) 23.801ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 23.801ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 23.801ms (+0.000ms): delay_pmtmr (__delay) 24.792ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 24.792ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 24.792ms (+0.000ms): delay_pmtmr (__delay) 25.784ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 25.784ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 25.784ms (+0.000ms): delay_pmtmr (__delay) 26.775ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 26.775ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 26.776ms (+0.000ms): delay_pmtmr (__delay) 27.767ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 27.767ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 27.767ms (+0.000ms): delay_pmtmr (__delay) 28.759ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 28.759ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 28.759ms (+0.000ms): delay_pmtmr (__delay) 29.750ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 29.750ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 29.750ms (+0.000ms): delay_pmtmr (__delay) 30.742ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 30.742ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 30.742ms (+0.000ms): delay_pmtmr (__delay) 31.733ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 31.733ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 31.733ms (+0.000ms): delay_pmtmr (__delay) 32.725ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 32.725ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 32.725ms (+0.000ms): delay_pmtmr (__delay) 33.716ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 33.716ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 33.717ms (+0.000ms): delay_pmtmr (__delay) 34.708ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 34.708ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 34.708ms (+0.000ms): delay_pmtmr (__delay) 35.700ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 35.700ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 35.700ms (+0.000ms): delay_pmtmr (__delay) 36.691ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 36.691ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 36.691ms (+0.000ms): delay_pmtmr (__delay) 37.683ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 37.683ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 37.683ms (+0.000ms): delay_pmtmr (__delay) 38.674ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 38.674ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 38.674ms (+0.000ms): delay_pmtmr (__delay) 39.666ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 39.666ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 39.666ms (+0.000ms): delay_pmtmr (__delay) 40.657ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 40.657ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 40.657ms (+0.000ms): delay_pmtmr (__delay) 41.649ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 41.649ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 41.649ms (+0.000ms): delay_pmtmr (__delay) 42.640ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 42.641ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 42.641ms (+0.000ms): delay_pmtmr (__delay) 43.632ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 43.632ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 43.632ms (+0.000ms): delay_pmtmr (__delay) 44.624ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 44.624ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 44.624ms (+0.000ms): delay_pmtmr (__delay) 45.615ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 45.615ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 45.615ms (+0.000ms): delay_pmtmr (__delay) 46.607ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 46.607ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 46.607ms (+0.000ms): delay_pmtmr (__delay) 47.598ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 47.598ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 47.598ms (+0.000ms): delay_pmtmr (__delay) 48.590ms (+0.991ms): __const_udelay (snd_intel8x0_setup_pcm_out) 48.590ms (+0.000ms): __delay (snd_intel8x0_setup_pcm_out) 48.590ms (+0.000ms): delay_pmtmr (__delay) 49.581ms (+0.991ms): iputdword (snd_intel8x0_setup_pcm_out) 49.582ms (+0.000ms): snd_intel8x0_setup_periods (snd_intel8x0_pcm_prepare) 49.582ms (+0.000ms): iputdword (snd_intel8x0_setup_periods) 49.585ms (+0.002ms): iputbyte (snd_intel8x0_setup_periods) 49.585ms (+0.000ms): iputbyte (snd_intel8x0_setup_periods) 49.586ms (+0.000ms): iputbyte (snd_intel8x0_setup_periods) 49.586ms (+0.000ms): snd_pcm_do_reset (snd_pcm_action_single) 49.586ms (+0.000ms): snd_pcm_lib_ioctl (snd_pcm_do_reset) 49.586ms (+0.000ms): snd_pcm_lib_ioctl_reset (snd_pcm_do_reset) 49.587ms (+0.000ms): snd_pcm_post_prepare (snd_pcm_action_single) 49.587ms (+0.000ms): smp_apic_timer_interrupt (snd_pcm_action_lock_irq) 49.587ms (+0.000ms): profile_hook (smp_apic_timer_interrupt) 49.588ms (+0.000ms): notifier_call_chain (profile_hook) 49.588ms (+0.000ms): do_IRQ (snd_pcm_action_lock_irq) 49.589ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ) 49.589ms (+0.000ms): generic_redirect_hardirq (do_IRQ) 49.589ms (+0.000ms): wake_up_process (generic_redirect_hardirq) 49.589ms (+0.000ms): try_to_wake_up (wake_up_process) 49.589ms (+0.000ms): task_rq_lock (try_to_wake_up) 49.589ms (+0.000ms): activate_task (try_to_wake_up) 49.589ms (+0.000ms): sched_clock (activate_task) 49.590ms (+0.000ms): recalc_task_prio (activate_task) 49.590ms (+0.000ms): effective_prio (recalc_task_prio) 49.590ms (+0.000ms): enqueue_task (activate_task) 49.590ms (+0.000ms): preempt_schedule (try_to_wake_up) 49.590ms (+0.000ms): preempt_schedule (do_IRQ) 49.591ms (+0.000ms): do_IRQ (snd_pcm_action_lock_irq) 49.591ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ) 49.591ms (+0.000ms): generic_redirect_hardirq (do_IRQ) 49.591ms (+0.000ms): preempt_schedule (do_IRQ) 49.591ms (+0.000ms): generic_handle_IRQ_event (do_IRQ) 49.591ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event) 49.592ms (+0.000ms): mark_offset_pmtmr (timer_interrupt) 49.598ms (+0.006ms): do_timer (timer_interrupt) 49.598ms (+0.000ms): update_process_times (do_timer) 49.598ms (+0.000ms): update_one_process (update_process_times) 49.598ms (+0.000ms): run_local_timers (update_process_times) 49.598ms (+0.000ms): raise_softirq (update_process_times) 49.598ms (+0.000ms): scheduler_tick (update_process_times) 49.598ms (+0.000ms): sched_clock (scheduler_tick) 49.599ms (+0.000ms): task_timeslice (scheduler_tick) 49.599ms (+0.000ms): update_wall_time (do_timer) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.599ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.600ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.601ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.602ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 49.603ms (+0.000ms): generic_note_interrupt (do_IRQ) 49.604ms (+0.000ms): end_edge_ioapic_irq (do_IRQ) 49.604ms (+0.000ms): preempt_schedule (do_IRQ) 49.604ms (+0.000ms): do_softirq (do_IRQ) 49.604ms (+0.000ms): __do_softirq (do_softirq) 49.604ms (+0.000ms): wake_up_process (do_softirq) 49.604ms (+0.000ms): try_to_wake_up (wake_up_process) 49.604ms (+0.000ms): task_rq_lock (try_to_wake_up) 49.604ms (+0.000ms): activate_task (try_to_wake_up) 49.604ms (+0.000ms): sched_clock (activate_task) 49.604ms (+0.000ms): recalc_task_prio (activate_task) 49.605ms (+0.000ms): effective_prio (recalc_task_prio) 49.605ms (+0.000ms): enqueue_task (activate_task) 49.605ms (+0.000ms): preempt_schedule (snd_pcm_action_lock_irq) 49.605ms (+0.000ms): sub_preempt_count (sys_ioctl) sound/pci/intel8x0.c contains: if (chip->device_type == DEVICE_NFORCE) { /* reset to 2ch once to keep the 6 channel data in alignment, * to start from Front Left always */ iputdword(chip, ICHREG(GLOB_CNT), (cnt & 0xcfffff)); mdelay(50); /* grrr... */ } else if (chip->device_type == DEVICE_INTEL_ICH4) { So I guess it's that mdelay(50) which is generating these (each time the device is opened). - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/