Re: How how latent should non-preemptive scheduling be?
From: Sitsofe Wheeler
Date: Tue Sep 30 2008 - 09:18:22 EST
Ingo Molnar wrote:
* Sitsofe Wheeler <sitsofe@xxxxxxxxx> wrote:
cat-7717 [000] 1392.941867: __tasklet_schedule <-ath5k_intr
cat-7717 [000] 1393.005963: __tasklet_schedule <-ath5k_intr
cat-7717 [000] 1393.033222: __switch_to <-schedule
Here a schedule seemingly doesn't happen for a few hundredths of a second...
that's about 60 msecs. ath5k_intr IRQ handling overhead? IRQ handlers
are non-preemptible. (even under CONFIG_PREEMPT=y)
What about the piece leading up to that:
cat-7717 [000] 1392.752092: del_timer <-schedule_timeout
cat-7717 [000] 1392.772263: account_scheduler_latency
<-enqueue_task_fair
cat-7717 [000] 1392.773224: __tasklet_schedule <-kbd_event
cat-7717 [000] 1392.773225: schedule_console_callback
<-kbd_event
cat-7717 [000] 1392.773225: schedule_work
<-schedule_console_callback
cat-7717 [000] 1392.773226: queue_work <-schedule_work
cat-7717 [000] 1392.773232: account_scheduler_latency
<-enqueue_task_fair
cat-7717 [000] 1392.773240: account_scheduler_latency
<-enqueue_task_fair
cat-7717 [000] 1392.773251: schedule_delayed_work
<-put_queue
cat-7717 [000] 1392.773251: queue_delayed_work
<-schedule_delayed_work
cat-7717 [000] 1392.773258: schedule_console_callback
<-kbd_event
cat-7717 [000] 1392.773258: schedule_work
<-schedule_console_callback
cat-7717 [000] 1392.773259: queue_work <-schedule_work
cat-7717 [000] 1392.773267: schedule_console_callback
<-kbd_event
cat-7717 [000] 1392.773268: schedule_work
<-schedule_console_callback
cat-7717 [000] 1392.773268: queue_work <-schedule_work
cat-7717 [000] 1392.807931: account_scheduler_latency
<-enqueue_task_fair
cat-7717 [000] 1392.839464: __tasklet_schedule <-ath5k_intr
Here's a snippet from
http://sucs.org/~sits/test/eeepc-debug/20080929/trace-on-battery.txt.bz2 :
cat-7717 [000] 1392.752092: del_timer <-schedule_timeout
cat-7717 [000] 1392.752092: acpi_ec_check_status
<-acpi_ec_wait
cat-7717 [000] 1392.752093: constant_test_bit
<-acpi_ec_check_status
cat-7717 [000] 1392.752095: mutex_unlock
<-acpi_ec_transaction
cat-7717 [000] 1392.752096: acpi_ex_enter_interpreter
<-acpi_ev_address_space_dispatch
cat-7717 [000] 1392.752097: acpi_os_wait_semaphore
<-acpi_ut_acquire_mutex
cat-7717 [000] 1392.752097: down_timeout
<-acpi_os_wait_semaphore
cat-7717 [000] 1392.752098: acpi_ex_release_global_lock
<-acpi_ex_read_data_from_field
cat-7717 [000] 1392.752099: acpi_ex_release_mutex_object
<-acpi_ex_release_global_lock
cat-7717 [000] 1392.752100: acpi_ev_release_global_lock
<-acpi_ex_release_mutex_object
cat-7717 [000] 1392.752100: __acpi_release_global_lock
<-acpi_ev_release_global_lock
cat-7717 [000] 1392.752101: acpi_os_signal_semaphore
<-acpi_ev_release_global_lock
cat-7717 [000] 1392.752102: up <-acpi_os_signal_semaphore
...
cat-7717 [000] 1392.839447:
acpi_ex_truncate_for32bit_table <-acpi_ds_exec_end_op
cat-7717 [000] 1392.839447: acpi_ps_next_parse_state
<-acpi_ps_parse_loop
cat-7717 [000] 1392.839448: acpi_ps_complete_op
<-acpi_ps_parse_loop
cat-7717 [000] 1392.839448: acpi_ps_complete_this_op
<-acpi_ps_complete_op
cat-7717 [000] 1392.839449: acpi_ps_delete_parse_tree
<-acpi_ps_complete_this_op
cat-7717 [000] 1392.839449: acpi_ps_get_arg
<-acpi_ps_delete_parse_tree
cat-7717 [000] 1392.839450: acpi_ps_get_opcode_info
<-acpi_ps_get_arg
cat-7717 [000] 1392.839450: acpi_ps_get_arg
<-acpi_ps_delete_parse_tree
cat-7717 [000] 1392.839451: acpi_ps_get_opcode_info
<-acpi_ps_get_arg
cat-7717 [000] 1392.839452: do_IRQ <-common_interrupt
cat-7717 [000] 1392.839453: irq_enter <-do_IRQ
cat-7717 [000] 1392.839453: irq_to_desc <-do_IRQ
cat-7717 [000] 1392.839454: handle_fasteoi_irq <-do_IRQ
cat-7717 [000] 1392.839455: handle_IRQ_event
<-handle_fasteoi_irq
cat-7717 [000] 1392.839455: usb_hcd_irq <-handle_IRQ_event
cat-7717 [000] 1392.839456: uhci_irq <-usb_hcd_irq
cat-7717 [000] 1392.839458: ath5k_intr <-handle_IRQ_event
cat-7717 [000] 1392.839459: ath5k_hw_is_intr_pending
<-ath5k_intr
cat-7717 [000] 1392.839461: ath5k_hw_get_isr <-ath5k_intr
cat-7717 [000] 1392.839464: __tasklet_schedule <-ath5k_intr
Why didn't another process cut in from 1392.752092 to 1392.839464? In
the schedule grep normally runs for cat are half as long e.g.:
<idle>-0 [000] 1392.747102: __switch_to <-schedule
cat-7717 [000] 1392.747103: del_timer <-schedule_timeout
cat-7717 [000] 1392.747107:
schedule_timeout_uninterruptible <-msleep
cat-7717 [000] 1392.747107: schedule_timeout
<-schedule_timeout_uninterruptible
cat-7717 [000] 1392.747108: init_timer <-schedule_timeout
cat-7717 [000] 1392.747108: __mod_timer <-schedule_timeout
cat-7717 [000] 1392.747111: __switch_to <-schedule
<idle>-0 [000] 1392.749067: account_scheduler_latency
<-enqueue_task_fair
Further why (after taking a break to process the ath5k interrupt) did it
not schedule another process other than cat until 1393.033226:
cat-7717 [000] 1393.033215: set_normalized_timespec
<-ktime_get_ts
cat-7717 [000] 1393.033216: ktime_add_safe
<-hrtimer_start_range_ns
cat-7717 [000] 1393.033217: ktime_add_safe
<-hrtimer_start_range_ns
cat-7717 [000] 1393.033217: enqueue_hrtimer
<-hrtimer_start_range_ns
cat-7717 [000] 1393.033222: __switch_to <-schedule
hald-addon-inpu-3237 [000] 1393.033226: fget_light <-do_sys_poll
--
Sitsofe | http://sucs.org/~sits/
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/