> -----Ursprüngliche Nachricht----- > Von: Thomas Gleixner [mailto:tglx@xxxxxxxxxxxxx] > Gesendet: Dienstag, 1. März 2016 11:08 > An: Wirth, Martin > Cc: bigeasy@xxxxxxxxxxxxx > Betreff: Re: AW: AW: AW: Large latencies with 4.4.1-rt6 > > Can you try to gather a trace: > > cyclictest -Sp99 -m -i200 -f -b500 > > You might need to up the interval a bit, but that should give us the reason for > this hickup. > I finally found the reason for the ms range latencies. When we bought the cpu -card about 2 years ago we had problems with the built-in DP to VGA bridge in combination with a KVM switch. To solve this I added, as suggested on a linux forum, the kernel parameter i915.disable_power_well=0. With former kernels this did no harm, but with 4.4 it causes the large latencies. The i915 driver even warns that disable_power_well is deprecated and dangerous now but I overlooked this in the kernel log. So now that this is gone, I still see a lot of 100 µs range latencies with 4.4.3-rt9. Interestingly I get even larger ones of up to 200 µs when tracing is not enabled (over 12 h runs). The traces around such a 100 µs hickup look like this: cc1-17437 0....2.. 195934546us : preempt_count_sub <-_raw_spin_unlock_irq cc1-17437 0....1.. 195934546us : preempt_count_sub <-schedule cc1-17437 0d...... 195934546us : do_IRQ <-ret_from_intr cc1-17437 0d...... 195934546us : irq_enter <-do_IRQ cc1-17437 0d...... 195934547us : rcu_irq_enter <-irq_enter cc1-17437 0d...... 195934547us : irqtime_account_irq <-irq_enter cc1-17437 0d...... 195934547us : in_serving_softirq <-irqtime_account_irq cc1-17437 0d...... 195934547us : preempt_count_add <-irq_enter cc1-17437 0d..h... 195934547us : exit_idle <-do_IRQ cc1-17437 0d..h... 195934547us : handle_irq <-do_IRQ cc1-17437 0d..h... 195934547us : handle_edge_irq <-handle_irq cc1-17437 0d..h... 195934547us : _raw_spin_lock <-handle_edge_irq cc1-17437 0d..h... 195934547us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h1.. 195934547us : irq_chip_ack_parent <-handle_edge_irq cc1-17437 0d..h1.. 195934548us : apic_ack_edge <-irq_chip_ack_parent cc1-17437 0d..h1.. 195934548us : irq_complete_move <-apic_ack_edge cc1-17437 0d..h1.. 195934548us : irq_move_irq <-apic_ack_edge cc1-17437 0d..h1.. 195934548us : handle_irq_event <-handle_edge_irq cc1-17437 0d..h1.. 195934548us : preempt_count_sub <-handle_irq_event cc1-17437 0d..h... 195934548us : handle_irq_event_percpu <-handle_irq_event cc1-17437 0d..h... 195934548us : irq_default_primary_handler <-handle_irq_event_percpu cc1-17437 0d..h... 195934548us : __irq_wake_thread <-handle_irq_event_percpu cc1-17437 0d..h... 195934549us : wake_up_process <-__irq_wake_thread cc1-17437 0d..h... 195934549us : try_to_wake_up <-wake_up_process cc1-17437 0d..h... 195934549us : _raw_spin_lock_irqsave <-try_to_wake_up cc1-17437 0d..h... 195934549us : preempt_count_add <-_raw_spin_lock_irqsave cc1-17437 0d..h1.. 195934549us : select_task_rq_rt <-try_to_wake_up cc1-17437 0d..h1.. 195934549us : __rcu_read_lock <-select_task_rq_rt cc1-17437 0d..h1.. 195934549us : __rcu_read_unlock <-select_task_rq_rt cc1-17437 0d..h1.. 195934549us : _raw_spin_lock <-try_to_wake_up cc1-17437 0d..h1.. 195934549us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h2.. 195934549us : ttwu_do_activate.constprop.100 <-try_to_wake_up cc1-17437 0d..h2.. 195934550us : activate_task <-ttwu_do_activate.constprop.100 cc1-17437 0d..h2.. 195934550us : update_rq_clock.part.89 <-activate_task cc1-17437 0d..h2.. 195934550us : enqueue_task_rt <-activate_task cc1-17437 0d..h2.. 195934550us : dequeue_rt_stack <-enqueue_task_rt cc1-17437 0d..h2.. 195934550us : dequeue_top_rt_rq <-dequeue_rt_stack cc1-17437 0d..h2.. 195934550us : cpupri_set <-enqueue_task_rt cc1-17437 0d..h2.. 195934550us : update_rt_migration <-enqueue_task_rt cc1-17437 0d..h2.. 195934551us : _raw_spin_lock <-enqueue_task_rt cc1-17437 0d..h2.. 195934551us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h3.. 195934551us : preempt_count_sub <-enqueue_task_rt cc1-17437 0d..h2.. 195934551us : enqueue_top_rt_rq <-enqueue_task_rt cc1-17437 0d..h2.. 195934551us : ttwu_do_wakeup <-ttwu_do_activate.constprop.100 cc1-17437 0d..h2.. 195934551us : check_preempt_curr <-ttwu_do_wakeup cc1-17437 0d..h2.. 195934551us : resched_curr <-check_preempt_curr cc1-17437 0d..h2.. 195934551us : native_smp_send_reschedule <-resched_curr cc1-17437 0d..h2.. 195934551us : flat_send_IPI_mask <-native_smp_send_reschedule cc1-17437 0d..h2.. 195934552us : task_woken_rt <-ttwu_do_wakeup cc1-17437 0d..h2.. 195934552us : preempt_count_sub <-try_to_wake_up cc1-17437 0d..h1.. 195934552us : __rcu_read_lock <-try_to_wake_up cc1-17437 0d..h1.. 195934552us : __rcu_read_unlock <-try_to_wake_up cc1-17437 0d..h1.. 195934552us : _raw_spin_unlock_irqrestore <-try_to_wake_up cc1-17437 0d..h1.. 195934552us : preempt_count_sub <-_raw_spin_unlock_irqrestore cc1-17437 0d..h... 195934552us : note_interrupt <-handle_irq_event_percpu cc1-17437 0d..h... 195934552us : _raw_spin_lock <-handle_irq_event cc1-17437 0d..h... 195934552us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h1.. 195934553us : preempt_count_sub <-handle_edge_irq cc1-17437 0d..h... 195934553us : irq_exit <-do_IRQ cc1-17437 0d..h... 195934553us : irqtime_account_irq <-irq_exit cc1-17437 0d..h... 195934553us : preempt_count_sub <-irq_exit cc1-17437 0d...... 195934553us!: rcu_irq_exit <-irq_exit cc1-17437 0d...... 195934680us : do_IRQ <-ret_from_intr cc1-17437 0d...... 195934681us : irq_enter <-do_IRQ cc1-17437 0d...... 195934681us : rcu_irq_enter <-irq_enter cc1-17437 0d...... 195934681us : irqtime_account_irq <-irq_enter cc1-17437 0d...... 195934681us : in_serving_softirq <-irqtime_account_irq cc1-17437 0d...... 195934681us : preempt_count_add <-irq_enter cc1-17437 0d..h... 195934681us : exit_idle <-do_IRQ cc1-17437 0d..h... 195934682us : handle_irq <-do_IRQ cc1-17437 0d..h... 195934682us : handle_edge_irq <-handle_irq cc1-17437 0d..h... 195934682us : _raw_spin_lock <-handle_edge_irq cc1-17437 0d..h... 195934682us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h1.. 195934682us : irq_chip_ack_parent <-handle_edge_irq cc1-17437 0d..h1.. 195934682us : apic_ack_edge <-irq_chip_ack_parent cc1-17437 0d..h1.. 195934682us : irq_complete_move <-apic_ack_edge cc1-17437 0d..h1.. 195934682us : irq_move_irq <-apic_ack_edge cc1-17437 0d..h1.. 195934682us : handle_irq_event <-handle_edge_irq cc1-17437 0d..h1.. 195934683us : preempt_count_sub <-handle_irq_event cc1-17437 0d..h... 195934683us : handle_irq_event_percpu <-handle_irq_event cc1-17437 0d..h... 195934683us : irq_default_primary_handler <-handle_irq_event_percpu cc1-17437 0d..h... 195934683us : __irq_wake_thread <-handle_irq_event_percpu cc1-17437 0d..h... 195934683us : wake_up_process <-__irq_wake_thread cc1-17437 0d..h... 195934683us : try_to_wake_up <-wake_up_process cc1-17437 0d..h... 195934683us : _raw_spin_lock_irqsave <-try_to_wake_up cc1-17437 0d..h... 195934683us : preempt_count_add <-_raw_spin_lock_irqsave cc1-17437 0d..h1.. 195934683us : select_task_rq_rt <-try_to_wake_up cc1-17437 0d..h1.. 195934684us : __rcu_read_lock <-select_task_rq_rt cc1-17437 0d..h1.. 195934684us : __rcu_read_unlock <-select_task_rq_rt cc1-17437 0d..h1.. 195934684us : _raw_spin_lock <-try_to_wake_up cc1-17437 0d..h1.. 195934684us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h2.. 195934684us : ttwu_do_activate.constprop.100 <-try_to_wake_up cc1-17437 0d..h2.. 195934684us : activate_task <-ttwu_do_activate.constprop.100 cc1-17437 0d..h2.. 195934684us : update_rq_clock.part.89 <-activate_task cc1-17437 0d..h2.. 195934684us : enqueue_task_rt <-activate_task cc1-17437 0d..h2.. 195934684us : dequeue_rt_stack <-enqueue_task_rt cc1-17437 0d..h2.. 195934684us : dequeue_top_rt_rq <-dequeue_rt_stack cc1-17437 0d..h2.. 195934685us : cpupri_set <-enqueue_task_rt cc1-17437 0d..h2.. 195934685us : update_rt_migration <-enqueue_task_rt cc1-17437 0d..h2.. 195934685us : _raw_spin_lock <-enqueue_task_rt cc1-17437 0d..h2.. 195934685us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h3.. 195934685us : preempt_count_sub <-enqueue_task_rt cc1-17437 0d..h2.. 195934685us : enqueue_top_rt_rq <-enqueue_task_rt cc1-17437 0d..h2.. 195934685us : ttwu_do_wakeup <-ttwu_do_activate.constprop.100 cc1-17437 0d..h2.. 195934686us : check_preempt_curr <-ttwu_do_wakeup cc1-17437 0d..h2.. 195934686us : resched_curr <-check_preempt_curr cc1-17437 0d..h2.. 195934686us : native_smp_send_reschedule <-resched_curr cc1-17437 0d..h2.. 195934686us : flat_send_IPI_mask <-native_smp_send_reschedule cc1-17437 0d..h2.. 195934687us : task_woken_rt <-ttwu_do_wakeup cc1-17437 0d..h2.. 195934687us : preempt_count_sub <-try_to_wake_up cc1-17437 0d..h1.. 195934687us : __rcu_read_lock <-try_to_wake_up cc1-17437 0d..h1.. 195934687us : __rcu_read_unlock <-try_to_wake_up cc1-17437 0d..h1.. 195934687us : _raw_spin_unlock_irqrestore <-try_to_wake_up cc1-17437 0d..h1.. 195934687us : preempt_count_sub <-_raw_spin_unlock_irqrestore cc1-17437 0d..h... 195934687us : note_interrupt <-handle_irq_event_percpu cc1-17437 0d..h... 195934687us : _raw_spin_lock <-handle_irq_event cc1-17437 0d..h... 195934688us : preempt_count_add <-_raw_spin_lock cc1-17437 0d..h1.. 195934688us : preempt_count_sub <-handle_edge_irq cc1-17437 0d..h... 195934688us : irq_exit <-do_IRQ So for the time being I'm back to 4.1.15-rt17 which shows max latencies below 28 µs even under heavy load. Martin ��.n��������+%������w��{.n�����{�����ǫ���ܨ}���Ơz�j:+v�����w����ޙ��&�)ߡ�a����z�ޗ���ݢj��w�f
