Thanks to Austin's suggestion I was able to get a race which looks suspicious.
# tracer: function
#
# entries-in-buffer/entries-written: 39893/219671100 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# ||||/ delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
irq/35-ahci[000-121 [002] ....113 28719.098051: preempt_count_sub <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] .....13 28719.098051: preempt_count_add <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] ....113 28719.098052: preempt_count_sub <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] .....13 28719.098052: preempt_count_add <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] ....113 28719.098052: _raw_spin_lock_irqsave <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] d...113 28719.098052: preempt_count_add <-_raw_spin_lock_irqsave
irq/35-ahci[000-121 [002] d...213 28719.098052: _raw_spin_unlock_irqrestore <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] ....213 28719.098052: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/35-ahci[000-121 [002] ....113 28719.098052: preempt_count_sub <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] .....13 28719.098052: preempt_count_add <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] d..h313 28719.098053: handle_irq <-do_IRQ
irq/35-ahci[000-121 [002] d..h313 28719.098053: handle_fasteoi_irq <-handle_irq
irq/35-ahci[000-121 [002] d..h313 28719.098053: _raw_spin_lock <-handle_fasteoi_irq
irq/35-ahci[000-121 [002] d..h313 28719.098053: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] d..h413 28719.098054: mask_irq.part.36 <-handle_fasteoi_irq
irq/35-ahci[000-121 [002] d..h413 28719.098054: mask_ioapic_irq <-mask_irq.part.36
irq/35-ahci[000-121 [002] d..h413 28719.098054: _raw_spin_lock_irqsave <-mask_ioapic_irq
irq/35-ahci[000-121 [002] d..h413 28719.098054: preempt_count_add <-_raw_spin_lock_irqsave
irq/35-ahci[000-121 [002] d..h513 28719.098054: io_apic_modify_irq <-mask_ioapic_irq
irq/35-ahci[000-121 [002] d..h513 28719.098055: io_apic_sync <-io_apic_modify_irq
irq/35-ahci[000-121 [002] d..h513 28719.098056: _raw_spin_unlock_irqrestore <-mask_irq.part.36
irq/35-ahci[000-121 [002] d..h513 28719.098056: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/35-ahci[000-121 [002] d..h413 28719.098057: handle_irq_event <-handle_fasteoi_irq
irq/35-ahci[000-121 [002] d..h413 28719.098057: preempt_count_sub <-handle_irq_event
irq/35-ahci[000-121 [002] d..h313 28719.098057: handle_irq_event_percpu <-handle_irq_event
irq/35-ahci[000-121 [002] d..h313 28719.098057: __handle_irq_event_percpu <-handle_irq_event_percpu
irq/35-ahci[000-121 [002] d..h313 28719.098057: irq_default_primary_handler <-__handle_irq_event_percpu
irq/35-ahci[000-121 [002] d..h313 28719.098057: __irq_wake_thread <-__handle_irq_event_percpu
irq/35-ahci[000-121 [002] d..h313 28719.098057: wake_up_process <-__handle_irq_event_percpu
irq/35-ahci[000-121 [002] d..h313 28719.098058: try_to_wake_up <-__handle_irq_event_percpu
irq/35-ahci[000-121 [002] d..h313 28719.098058: _raw_spin_lock_irqsave <-try_to_wake_up
irq/35-ahci[000-121 [002] d..h313 28719.098058: preempt_count_add <-_raw_spin_lock_irqsave
irq/35-ahci[000-121 [002] d..h413 28719.098058: _raw_spin_lock <-try_to_wake_up
irq/35-ahci[000-121 [002] d..h413 28719.098058: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] d..h513 28719.098058: update_rq_clock <-try_to_wake_up
irq/35-ahci[000-121 [002] d..h513 28719.098058: update_irq_load_avg <-update_rq_clock
irq/35-ahci[000-121 [002] d..h513 28719.098058: __accumulate_pelt_segments <-update_irq_load_avg
irq/35-ahci[000-121 [002] d..h513 28719.098059: ttwu_do_activate <-try_to_wake_up
irq/35-ahci[000-121 [002] d..h513 28719.098059: activate_task <-ttwu_do_activate
irq/35-ahci[000-121 [002] d..h513 28719.098059: enqueue_task_rt <-activate_task
irq/35-ahci[000-121 [002] d..h513 28719.098059: dequeue_rt_stack <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098059: dequeue_top_rt_rq <-dequeue_rt_stack
irq/35-ahci[000-121 [002] d..h513 28719.098059: cpupri_set <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: update_rt_migration <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: _raw_spin_lock <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] d..h613 28719.098060: preempt_count_sub <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: enqueue_top_rt_rq <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: intel_pstate_update_util <-enqueue_task_rt
irq/35-ahci[000-121 [002] d..h513 28719.098060: ttwu_do_wakeup <-try_to_wake_up
irq/35-ahci[000-121 [002] d..h513 28719.098060: check_preempt_curr <-ttwu_do_wakeup
irq/35-ahci[000-121 [002] d..h513 28719.098061: check_preempt_curr_rt <-check_preempt_curr
irq/35-ahci[000-121 [002] d..h513 28719.098061: resched_curr <-check_preempt_curr
irq/35-ahci[000-121 [002] dN.h513 28719.098061: task_woken_rt <-ttwu_do_wakeup
irq/35-ahci[000-121 [002] dN.h413 28719.098061: _raw_spin_unlock_irqrestore <-try_to_wake_up
irq/35-ahci[000-121 [002] dN.h413 28719.098061: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/35-ahci[000-121 [002] dN.h313 28719.098061: note_interrupt <-handle_irq_event_percpu
irq/35-ahci[000-121 [002] dN.h313 28719.098062: _raw_spin_lock <-handle_irq_event
irq/35-ahci[000-121 [002] dN.h313 28719.098062: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] dN.h413 28719.098062: ioapic_ack_level <-handle_fasteoi_irq
irq/35-ahci[000-121 [002] dN.h413 28719.098062: irqd_cfg <-ioapic_ack_level
irq/35-ahci[000-121 [002] dN.h413 28719.098062: apic_chip_data.part.17 <-ioapic_ack_level
irq/35-ahci[000-121 [002] dN.h413 28719.098062: irq_complete_move <-ioapic_ack_level
irq/35-ahci[000-121 [002] dN.h413 28719.098062: __irq_complete_move <-ioapic_ack_level
irq/35-ahci[000-121 [002] dN.h413 28719.098062: preempt_count_sub <-handle_fasteoi_irq
irq/35-ahci[000-121 [002] dN.h313 28719.098063: irq_exit <-do_IRQ
irq/35-ahci[000-121 [002] dN.h313 28719.098063: irqtime_account_irq <-irq_exit
irq/35-ahci[000-121 [002] dN.h313 28719.098063: preempt_count_sub <-irq_exit
irq/35-ahci[000-121 [002] .N..113 28719.098063: preempt_count_sub <-percpu_counter_add_batch
irq/35-ahci[000-121 [002] dN..113 28719.098064: rcu_note_context_switch <-__schedule
irq/35-ahci[000-121 [002] dN..113 28719.098064: rcu_preempt_deferred_qs <-rcu_note_context_switch
irq/35-ahci[000-121 [002] dN..113 28719.098064: _raw_spin_lock <-__schedule
irq/35-ahci[000-121 [002] dN..113 28719.098064: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] dN..213 28719.098064: update_rq_clock <-__schedule
irq/35-ahci[000-121 [002] dN..213 28719.098064: pick_next_task_stop <-__schedule
irq/35-ahci[000-121 [002] dN..213 28719.098064: pick_next_task_dl <-__schedule
irq/35-ahci[000-121 [002] dN..213 28719.098065: pick_next_task_rt <-__schedule
irq/35-ahci[000-121 [002] dN..213 28719.098065: update_curr_rt <-pick_next_task_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: __rcu_read_lock <-update_curr_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: __rcu_read_unlock <-update_curr_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: _raw_spin_lock <-update_curr_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] dN..313 28719.098065: preempt_count_sub <-update_curr_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: put_prev_task_rt <-pick_next_task_rt
irq/35-ahci[000-121 [002] dN..213 28719.098065: update_curr_rt <-put_prev_task_rt
irq/35-ahci[000-121 [002] dN..213 28719.098066: update_rt_rq_load_avg <-put_prev_task_rt
irq/35-ahci[000-121 [002] d...213 28719.098066: enter_lazy_tlb <-__schedule
irq/21-spec_-292 [002] d...2.. 28719.098067: finish_task_switch <-__schedule
irq/21-spec_-292 [002] d...2.. 28719.098067: _raw_spin_unlock_irq <-finish_task_switch
irq/21-spec_-292 [002] ....2.. 28719.098067: preempt_count_sub <-_raw_spin_unlock_irq
irq/21-spec_-292 [002] ....... 28719.098067: kthread_should_stop <-irq_thread
irq/21-spec_-292 [002] ....... 28719.098068: irq_thread_check_affinity <-irq_thread
irq/21-spec_-292 [002] ....... 28719.098068: irq_forced_thread_fn <-irq_thread
irq/21-spec_-292 [002] ....... 28719.098068: __local_bh_disable_ip <-irq_forced_thread_fn
irq/21-spec_-292 [002] ....... 28719.098068: migrate_disable <-__local_bh_disable_ip
irq/21-spec_-292 [002] ....11. 28719.098068: pin_current_cpu <-migrate_disable
irq/21-spec_-292 [002] ....11. 28719.098068: __read_rt_trylock <-pin_current_cpu
irq/21-spec_-292 [002] ....11. 28719.098068: task_rq_lock <-migrate_disable
irq/21-spec_-292 [002] ....11. 28719.098069: _raw_spin_lock_irqsave <-task_rq_lock
irq/21-spec_-292 [002] d...11. 28719.098069: preempt_count_add <-_raw_spin_lock_irqsave
irq/21-spec_-292 [002] d...21. 28719.098069: _raw_spin_lock <-task_rq_lock
irq/21-spec_-292 [002] d...21. 28719.098069: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...21. 28719.098069: _raw_spin_unlock_irqrestore <-migrate_disable
irq/21-spec_-292 [002] ....21. 28719.098069: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/21-spec_-292 [002] .....11 28719.098069: rt_spin_lock <-__local_bh_disable_ip
irq/21-spec_-292 [002] .....11 28719.098069: migrate_disable <-rt_spin_lock
irq/21-spec_-292 [002] .....12 28719.098070: rt_spin_lock_slowlock <-__local_bh_disable_ip
irq/21-spec_-292 [002] .....12 28719.098070: _raw_spin_lock_irqsave <-rt_spin_lock_slowlock
irq/21-spec_-292 [002] d....12 28719.098070: preempt_count_add <-_raw_spin_lock_irqsave
irq/21-spec_-292 [002] d...112 28719.098070: rt_spin_lock_slowlock_locked <-rt_spin_lock_slowlock
irq/21-spec_-292 [002] d...112 28719.098070: __try_to_take_rt_mutex <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098070: _raw_spin_lock <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098071: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.098071: preempt_count_sub <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098071: task_blocks_on_rt_mutex <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098071: _raw_spin_lock <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...112 28719.098071: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.098071: rt_mutex_enqueue <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...212 28719.098071: preempt_count_sub <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...112 28719.098071: _raw_spin_lock <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...112 28719.098072: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.098072: rt_mutex_enqueue_pi <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...212 28719.098072: rt_mutex_setprio <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...212 28719.098072: __task_rq_lock <-rt_mutex_setprio
irq/21-spec_-292 [002] d...212 28719.098072: _raw_spin_lock <-__task_rq_lock
irq/21-spec_-292 [002] d...212 28719.098072: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...312 28719.098072: update_rq_clock <-rt_mutex_setprio
irq/21-spec_-292 [002] d...312 28719.098072: update_irq_load_avg <-update_rq_clock
irq/21-spec_-292 [002] d...312 28719.098073: dequeue_task_rt <-rt_mutex_setprio
irq/21-spec_-292 [002] d...312 28719.098073: update_curr_rt <-dequeue_task_rt
irq/21-spec_-292 [002] d...312 28719.098073: __rcu_read_lock <-update_curr_rt
irq/21-spec_-292 [002] d...312 28719.098073: __rcu_read_unlock <-update_curr_rt
irq/21-spec_-292 [002] d...312 28719.098073: _raw_spin_lock <-update_curr_rt
irq/21-spec_-292 [002] d...312 28719.098073: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...412 28719.098073: preempt_count_sub <-update_curr_rt
irq/21-spec_-292 [002] d...312 28719.098074: dequeue_rt_stack <-dequeue_task_rt
irq/21-spec_-292 [002] d...312 28719.098074: dequeue_top_rt_rq <-dequeue_rt_stack
irq/21-spec_-292 [002] d...312 28719.098074: update_rt_migration <-dequeue_rt_stack
irq/21-spec_-292 [002] d...312 28719.098074: enqueue_top_rt_rq <-dequeue_task_rt
irq/21-spec_-292 [002] d...312 28719.098074: intel_pstate_update_util <-dequeue_task_rt
irq/21-spec_-292 [002] d...312 28719.098074: enqueue_task_rt <-rt_mutex_setprio
irq/21-spec_-292 [002] d...312 28719.098074: dequeue_rt_stack <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098074: dequeue_top_rt_rq <-dequeue_rt_stack
irq/21-spec_-292 [002] d...312 28719.098075: update_rt_migration <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098075: _raw_spin_lock <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098075: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...412 28719.098075: preempt_count_sub <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098075: enqueue_top_rt_rq <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098075: intel_pstate_update_util <-enqueue_task_rt
irq/21-spec_-292 [002] d...312 28719.098076: prio_changed_rt <-rt_mutex_setprio
irq/21-spec_-292 [002] d...212 28719.098076: preempt_count_sub <-task_blocks_on_rt_mutex
irq/21-spec_-292 [002] d...112 28719.098076: __try_to_take_rt_mutex <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098076: _raw_spin_unlock_irqrestore <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] ....112 28719.098076: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/21-spec_-292 [002] .....12 28719.098076: __rcu_read_lock <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] .....12 28719.098077: __rcu_read_unlock <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] .....12 28719.098077: schedule <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.098077: rcu_note_context_switch <-__schedule
irq/21-spec_-292 [002] d...112 28719.098077: rcu_preempt_deferred_qs <-rcu_note_context_switch
irq/21-spec_-292 [002] d...112 28719.098077: _raw_spin_lock <-__schedule
irq/21-spec_-292 [002] d...112 28719.098077: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.098077: update_rq_clock <-__schedule
irq/21-spec_-292 [002] d...212 28719.098077: deactivate_task <-__schedule
irq/21-spec_-292 [002] d...212 28719.098077: dequeue_task_rt <-__schedule
irq/21-spec_-292 [002] d...212 28719.098078: update_curr_rt <-dequeue_task_rt
irq/21-spec_-292 [002] d...212 28719.098078: __rcu_read_lock <-update_curr_rt
irq/21-spec_-292 [002] d...212 28719.098078: __rcu_read_unlock <-update_curr_rt
irq/21-spec_-292 [002] d...212 28719.098078: _raw_spin_lock <-update_curr_rt
irq/21-spec_-292 [002] d...212 28719.098078: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...312 28719.098078: preempt_count_sub <-update_curr_rt
irq/21-spec_-292 [002] d...212 28719.098078: dequeue_rt_stack <-dequeue_task_rt
irq/21-spec_-292 [002] d...212 28719.098078: dequeue_top_rt_rq <-dequeue_rt_stack
irq/21-spec_-292 [002] d...212 28719.098078: update_rt_migration <-dequeue_rt_stack
irq/21-spec_-292 [002] d...212 28719.098079: enqueue_top_rt_rq <-dequeue_task_rt
irq/21-spec_-292 [002] d...212 28719.098079: intel_pstate_update_util <-dequeue_task_rt
irq/21-spec_-292 [002] d...212 28719.098079: pick_next_task_stop <-__schedule
irq/21-spec_-292 [002] d...212 28719.098079: pick_next_task_dl <-__schedule
irq/21-spec_-292 [002] d...212 28719.098079: pick_next_task_rt <-__schedule
irq/21-spec_-292 [002] d...212 28719.098079: update_curr_rt <-pick_next_task_rt
irq/21-spec_-292 [002] d...212 28719.098079: put_prev_task_rt <-pick_next_task_rt
irq/21-spec_-292 [002] d...212 28719.098079: update_curr_rt <-put_prev_task_rt
irq/21-spec_-292 [002] d...212 28719.098079: update_rt_rq_load_avg <-put_prev_task_rt
irq/21-spec_-292 [002] d...212 28719.098080: enter_lazy_tlb <-__schedule
irq/35-ahci[000-121 [002] d...213 28719.098080: finish_task_switch <-__schedule
irq/35-ahci[000-121 [002] d...213 28719.098080: _raw_spin_unlock_irq <-finish_task_switch
irq/35-ahci[000-121 [002] ....213 28719.098080: preempt_count_sub <-_raw_spin_unlock_irq
irq/35-ahci[000-121 [002] .....13 28719.098080: rt_spin_unlock <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....13 28719.098080: migrate_enable <-rt_spin_unlock
irq/35-ahci[000-121 [002] .....12 28719.098081: mod_node_page_state <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098081: dec_zone_page_state <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098081: inc_node_page_state <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098081: rt_spin_lock <-ext4_finish_bio
irq/35-ahci[000-121 [002] .....12 28719.098081: migrate_disable <-rt_spin_lock
irq/35-ahci[000-121 [002] .....13 28719.098081: rt_spin_unlock <-ext4_finish_bio
irq/35-ahci[000-121 [002] .....13 28719.098082: migrate_enable <-rt_spin_unlock
irq/35-ahci[000-121 [002] .....12 28719.098082: end_page_writeback <-ext4_finish_bio
irq/35-ahci[000-121 [002] .....12 28719.098082: test_clear_page_writeback <-end_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098082: page_mapping <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098082: rt_spin_lock <-test_clear_page_writeback
irq/35-ahci[000-121 [002] .....12 28719.098082: migrate_disable <-rt_spin_lock
With my limited knowledge of kernel internals I interpret it this way:
First the ahci interrupt thread is running. Then the IRQ from the digitizer card (spec_) comes in and the
low level handler runs. But it does not switch to the threaded part of the spec_ handler but continues
with the ahci interrupt thread - despite the higher rt priority of the spec_ handler (52 instead of 50).
The ahci continues for about 2 ms until this happens:
irq/35-ahci[000-121 [002] ....112 28719.100176: __wake_up_q <-rt_mutex_postunlock
irq/35-ahci[000-121 [002] ....112 28719.100176: __wake_up_q <-rt_mutex_postunlock
irq/35-ahci[000-121 [002] ....112 28719.100176: try_to_wake_up <-__wake_up_q
irq/35-ahci[000-121 [002] ....112 28719.100176: _raw_spin_lock_irqsave <-try_to_wake_up
irq/35-ahci[000-121 [002] d...112 28719.100176: preempt_count_add <-_raw_spin_lock_irqsave
irq/35-ahci[000-121 [002] d...212 28719.100176: _raw_spin_lock <-try_to_wake_up
irq/35-ahci[000-121 [002] d...212 28719.100176: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] d...312 28719.100177: update_rq_clock <-try_to_wake_up
irq/35-ahci[000-121 [002] d...312 28719.100177: update_irq_load_avg <-update_rq_clock
irq/35-ahci[000-121 [002] d...312 28719.100177: ttwu_do_activate <-try_to_wake_up
irq/35-ahci[000-121 [002] d...312 28719.100177: activate_task <-ttwu_do_activate
irq/35-ahci[000-121 [002] d...312 28719.100177: enqueue_task_rt <-activate_task
irq/35-ahci[000-121 [002] d...312 28719.100177: dequeue_rt_stack <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100177: dequeue_top_rt_rq <-dequeue_rt_stack
irq/35-ahci[000-121 [002] d...312 28719.100178: cpupri_set <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: update_rt_migration <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: _raw_spin_lock <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] d...412 28719.100178: preempt_count_sub <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: enqueue_top_rt_rq <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: intel_pstate_update_util <-enqueue_task_rt
irq/35-ahci[000-121 [002] d...312 28719.100178: ttwu_do_wakeup <-try_to_wake_up
irq/35-ahci[000-121 [002] d...312 28719.100178: check_preempt_curr <-ttwu_do_wakeup
irq/35-ahci[000-121 [002] d...312 28719.100179: check_preempt_curr_rt <-check_preempt_curr
irq/35-ahci[000-121 [002] d...312 28719.100179: resched_curr <-check_preempt_curr
irq/35-ahci[000-121 [002] dN..312 28719.100179: task_woken_rt <-ttwu_do_wakeup
irq/35-ahci[000-121 [002] dN..212 28719.100179: _raw_spin_unlock_irqrestore <-try_to_wake_up
irq/35-ahci[000-121 [002] .N..212 28719.100179: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/35-ahci[000-121 [002] .N..112 28719.100179: preempt_count_sub <-rt_mutex_postunlock
irq/35-ahci[000-121 [002] dN..112 28719.100179: rcu_note_context_switch <-__schedule
irq/35-ahci[000-121 [002] dN..112 28719.100180: rcu_preempt_deferred_qs <-rcu_note_context_switch
irq/35-ahci[000-121 [002] dN..112 28719.100180: _raw_spin_lock <-__schedule
irq/35-ahci[000-121 [002] dN..112 28719.100180: preempt_count_add <-_raw_spin_lock
irq/35-ahci[000-121 [002] dN..212 28719.100180: update_rq_clock <-__schedule
irq/35-ahci[000-121 [002] dN..212 28719.100180: pick_next_task_stop <-__schedule
irq/35-ahci[000-121 [002] dN..212 28719.100180: pick_next_task_dl <-__schedule
irq/35-ahci[000-121 [002] dN..212 28719.100180: pick_next_task_rt <-__schedule
irq/35-ahci[000-121 [002] dN..212 28719.100180: update_curr_rt <-pick_next_task_rt
irq/35-ahci[000-121 [002] dN..212 28719.100180: put_prev_task_rt <-pick_next_task_rt
irq/35-ahci[000-121 [002] dN..212 28719.100181: update_curr_rt <-put_prev_task_rt
irq/35-ahci[000-121 [002] dN..212 28719.100181: update_rt_rq_load_avg <-put_prev_task_rt
irq/35-ahci[000-121 [002] d...212 28719.100181: enter_lazy_tlb <-__schedule
irq/21-spec_-292 [002] d...212 28719.100181: finish_task_switch <-__schedule
irq/21-spec_-292 [002] d...212 28719.100182: _raw_spin_unlock_irq <-finish_task_switch
irq/21-spec_-292 [002] ....212 28719.100182: preempt_count_sub <-_raw_spin_unlock_irq
irq/21-spec_-292 [002] .....12 28719.100182: _raw_spin_lock_irqsave <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d....12 28719.100182: preempt_count_add <-_raw_spin_lock_irqsave
irq/21-spec_-292 [002] d...112 28719.100182: _raw_spin_lock <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100182: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.100182: preempt_count_sub <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100183: __try_to_take_rt_mutex <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100183: _raw_spin_lock <-__try_to_take_rt_mutex
irq/21-spec_-292 [002] d...112 28719.100183: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.100183: preempt_count_sub <-__try_to_take_rt_mutex
irq/21-spec_-292 [002] d...112 28719.100183: _raw_spin_lock <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100183: preempt_count_add <-_raw_spin_lock
irq/21-spec_-292 [002] d...212 28719.100183: preempt_count_sub <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100183: fixup_rt_mutex_waiters.part.6 <-rt_spin_lock_slowlock_locked
irq/21-spec_-292 [002] d...112 28719.100184: _raw_spin_unlock_irqrestore <-rt_spin_lock_slowlock
irq/21-spec_-292 [002] ....112 28719.100184: preempt_count_sub <-_raw_spin_unlock_irqrestore
irq/21-spec_-292 [002] .....12 28719.100184: vInterruptService <-irq_forced_thread_fn
irq/21-spec_-292 [002] .....12 28719.100185: ktime_get_real_ts64 <-vInterruptService
irq/21-spec_-292 [002] .....12 28719.100189: __wake_up <-vInterruptService
irq/21-spec_-292 [002] .....12 28719.100189: __wake_up_common_lock <-vInterruptService
.....
Now suddenly the spec handler is running again and this time the driver supplied IRQ-routine (vInterruptService)
is called, but with the 2 ms of delay.
Unfortunately I'm not able to interpret the flags correctly. Especially since the ones described in the header
do not match the number of fields in the output...
If I cut away too much to interpret this please let me know. The whole trace is about 3 MB.
Martin
