Sorry, now my responce with send to all instead of only to Alan....
2012/5/2 Ivo Sieben <meltedpianoman@xxxxxxxxx>:
> Hi,
>
>> It's a spin lock and its only held across very small numbers of
>> instructions in any normal path so this rather surprises me - in your
>> actual capture data can you see what is holding the lock for long times
>> causing this ?
>
> Indeed the lock is only taken for a very short time. So in most
> situations it works fine, the lock is free, and can be taken quickly.
> But when I stress my system (e.g. by continuously dumpling a lot of
> text data to another serial terminal from the background), my high
> priority task sometimes finds the lock is taken. In that case
> additional lock handling comes in: priority inheritance, a context
> switch to the background task that holds the lock, and a context
> switch back after the lock is released again. This makes a normal read
> that takes about 50us, to increase in execution time to 150us.
>
> The ftrace for a "quick" spin lock:
>
> 0) | tty_ldisc_deref() {
> 0) | put_ldisc() {
> 0) 8.960 us | atomic_dec_and_spin_lock();
> 0) | __wake_up() {
> 0) | rt_spin_lock() {
> 0) | rt_spin_lock_slowlock() {
> 0) 8.720 us | __try_to_take_rt_mutex();
> 0) + 25.360 us | }
> 0) + 41.760 us | }
> 0) 8.400 us | __wake_up_common();
> 0) | rt_spin_unlock() {
> 0) 8.240 us | rt_spin_lock_slowunlock();
> 0) + 24.320 us | }
> 0) ! 107.840 us | }
> 0) ! 146.400 us | }
> 0) ! 163.120 us | }
>
> While the ftrace for a spin lock that is already taken is a lot
> longer, adding a lot of execution time.
>
> 0) | tty_ldisc_deref() {
> 0) | put_ldisc() {
> 0) 8.640 us | atomic_dec_and_spin_lock();
> 0) | __wake_up() {
> 0) | rt_spin_lock() {
> 0) | rt_spin_lock_slowlock() {
> 0) 8.160 us | __try_to_take_rt_mutex();
> 0) | task_blocks_on_rt_mutex() {
> 0) 8.720 us | __rt_mutex_adjust_prio();
> 0) | __rt_mutex_adjust_prio() {
> 0) | task_setprio() {
> 0) | dequeue_task() {
> 0) 9.680 us | update_rq_clock();
> 0) | dequeue_task_rt() {
> 0) 9.200 us | update_curr_rt();
> 0) + 10.400 us | dequeue_rt_stack();
> 0) + 44.560 us | }
> 0) + 80.000 us | }
> 0) | enqueue_task() {
> 0) 9.120 us | update_rq_clock();
> 0) | enqueue_task_rt() {
> 0) 8.400 us | dequeue_rt_stack();
> 0) 9.280 us | __enqueue_rt_entity();
> 0) + 42.240 us | }
> 0) + 75.840 us | }
> 0) 8.560 us | prio_changed_rt();
> 0) 8.000 us | __task_rq_unlock();
> 0) ! 216.240 us | }
> 0) ! 233.280 us | }
> 0) ! 271.360 us | }
> 0) 8.160 us | __try_to_take_rt_mutex();
> 0) | schedule() {
> 0) | __schedule() {
> 0) | rcu_note_context_switch() {
> 0) 9.120 us | rcu_preempt_note_context_switch();
> 0) + 25.920 us | }
> 0) | deactivate_task() {
> 0) | dequeue_task() {
> 0) 9.120 us | update_rq_clock();
> 0) | dequeue_task_rt() {
> 0) 8.400 us | update_curr_rt();
> 0) 8.720 us | dequeue_rt_stack();
> 0) + 40.880 us | }
> 0) + 74.480 us | }
> 0) + 91.200 us | }
> 0) | put_prev_task_rt() {
> 0) 8.480 us | update_curr_rt();
> 0) + 24.560 us | }
> 0) 8.000 us | pick_next_task_stop();
> 0) | pick_next_task_rt() {
> 0) 8.560 us | pick_next_rt_entity();
> 0) + 25.280 us | }
> 0) ==========> |
> 0) | asm_do_IRQ() {
> 0) | irq_enter() {
> 0) 8.320 us | idle_cpu();
> 0) + 24.160 us | }
> 0) | generic_handle_irq() {
> 0) | handle_level_irq() {
> 0) 8.240 us | at91_aic_mask_irq();
> 0) 8.160 us | at91_aic_mask_irq();
> 0) | handle_irq_event() {
> 0) | handle_irq_event_percpu() {
> 0) | periodic_tick_interrupt() {
> 0) | roserts_timer_hook() {
> 0) |
> system_timer_get_highres_time() {
> 0) 10.000 us | __get_fpga_time_64();
> 0) + 26.880 us | }
> 0) + 43.920 us | }
> 0) + 61.520 us | }
> 0) 8.480 us | note_interrupt();
> 0) + 96.320 us | }
> 0) ! 113.200 us | }
> 0) | unmask_irq() {
> 0) 8.160 us | at91_aic_unmask_irq();
> 0) + 24.240 us | }
> 0) ! 195.840 us | }
> 0) ! 212.080 us | }
> 0) 8.800 us | irq_exit();
> 0) ! 278.240 us | }
> 0) <========== |
> 0) | atomic_notifier_call_chain() {
> 0) | __atomic_notifier_call_chain() {
> 0) 8.240 us | __rcu_read_lock();
> 0) 8.400 us | notifier_call_chain();
> 0) 8.480 us | __rcu_read_unlock();
> 0) + 58.080 us | }
> 0) + 75.920 us | }
> ------------------------------------------
> 0) uart_to-493 => ksoftir-3
> ------------------------------------------
>
> 0) + 10.640 us | finish_task_switch();
> 0) | rt_spin_unlock() {
> 0) | rt_spin_lock_slowunlock() {
> 0) | wakeup_next_waiter() {
> 0) | wake_up_lock_sleeper() {
> 0) | try_to_wake_up() {
> 0) | activate_task() {
> 0) | enqueue_task() {
> 0) 9.120 us | update_rq_clock();
> 0) | enqueue_task_rt() {
> 0) 8.240 us | dequeue_rt_stack();
> 0) 8.080 us | __enqueue_rt_entity();
> 0) + 39.360 us | }
> 0) + 71.840 us | }
> 0) + 87.760 us | }
> 0) | ttwu_do_wakeup() {
> 0) | check_preempt_curr() {
> 0) 7.840 us | check_preempt_curr_rt();
> 0) + 24.320 us | }
> 0) + 43.520 us | }
> 0) ! 156.960 us | }
> 0) ! 172.960 us | }
> 0) ! 190.080 us | }
> 0) | rt_mutex_adjust_prio() {
> 0) | __rt_mutex_adjust_prio() {
> 0) | task_setprio() {
> 0) | dequeue_task() {
> 0) 8.480 us | update_rq_clock();
> 0) | dequeue_task_rt() {
> 0) 8.880 us | update_curr_rt();
> 0) 8.080 us | dequeue_rt_stack();
> 0) + 39.920 us | }
> 0) + 72.000 us | }
> 0) | put_prev_task_rt() {
> 0) + 12.800 us | update_curr_rt();
> 0) + 28.000 us | }
> 0) 7.600 us | set_curr_task_rt();
> 0) | enqueue_task() {
> 0) 8.560 us | update_rq_clock();
> 0) | enqueue_task_rt() {
> 0) 7.760 us | dequeue_rt_stack();
> 0) 7.920 us | __enqueue_rt_entity();
> 0) + 38.160 us | }
> 0) + 69.440 us | }
> 0) 7.920 us | prio_changed_rt();
> 0) 8.240 us | __task_rq_unlock();
> 0) ! 249.760 us | }
> 0) ! 265.600 us | }
> 0) | __schedule() {
> 0) | rcu_note_context_switch() {
> 0) 8.800 us | rcu_preempt_note_context_switch();
> 0) + 25.200 us | }
> 0) 9.360 us | update_rq_clock();
> 0) | put_prev_task_rt() {
> 0) 8.560 us | update_curr_rt();
> 0) + 24.720 us | }
> 0) 8.160 us | pick_next_task_stop();
> 0) | pick_next_task_rt() {
> 0) 8.560 us | pick_next_rt_entity();
> 0) + 24.880 us | }
> 0) | atomic_notifier_call_chain() {
> 0) | __atomic_notifier_call_chain() {
> 0) 7.600 us | __rcu_read_lock();
> 0) 7.760 us | notifier_call_chain();
> 0) 7.920 us | __rcu_read_unlock();
> 0) + 53.760 us | }
> 0) + 69.200 us | }
> ------------------------------------------
> 0) ksoftir-3 => uart_to-493
> ------------------------------------------
>
> 0) + 10.080 us | finish_task_switch();
> 0) ! 1381.120 us | }
> 0) ! 1397.680 us | } /* schedule */
> 0) + 10.320 us | __try_to_take_rt_mutex();
> 0) ! 1748.240 us | } /* rt_spin_lock_slowlock */
> 0) ! 1764.320 us | } /* rt_spin_lock */
> 0) 8.400 us | __wake_up_common();
> 0) | rt_spin_unlock() {
> 0) 8.160 us | rt_spin_lock_slowunlock();
> 0) + 24.320 us | }
> 0) ! 1830.720 us | } /* __wake_up */
> 0) ! 1864.960 us | } /* put_ldisc */
> 0) ! 1881.760 us | } /* tty_ldisc_deref */
ÿôèº{.nÇ+?·?®??+%?Ëÿ±éݶ¥?wÿº{.nÇ+?·¥?{±þÇ«?©ÿ?{ayº Ê?Ú?ë,j¢f£¢·h??ï?êÿ?êçz_è®(é???Ý¢j"?ú¶m§ÿÿ¾«þG«?éÿ¢¸??¨èÚ&£ø§~?á
