[prev in list] [next in list] [prev in thread] [next in thread] 

List:       linux-kernel
Subject:    Re: [patch] voluntary-preempt-2.6.8.1-P4
From:       karl.vogel () seagha ! com
Date:       2004-08-19 20:37:57
Message-ID: m3brh6g8yi.fsf () seagha ! com
[Download RAW message or body]

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/


[prev in list] [next in list] [prev in thread] [next in thread]