Steve: Here's another irqsoff trace collected by James. It's not as extreme as before, but I don't know how to interpret the 875-us jump in the time value. Could this be a result of the timer being adjusted? Also, what's the explanation for these two lines: URL Clas-3286 2d... 881us : jiffies_to_timeval <-__acct_update_integrals URL Clas-3286 2d.h. 882us : exit_idle <-smp_apic_timer_interrupt They appear to say that the CPU got a hardirq while interrupts were disabled. How can that be? Alan Stern # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 3.10.0-ver5 # -------------------------------------------------------------------- # latency: 906 us, #93/93, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4) # ----------------- # | task: URL Classifier-3286 (uid:1000 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: perf_event_update_userpage # => ended at: retint_swapgs # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / delay # cmd pid ||||| time | caller # \ / ||||| \ | / URL Clas-3286 2d.h. 1us : local_clock <-perf_event_update_userpage URL Clas-3286 2d.h. 2us : watchdog_overflow_callback <-__perf_event_overflow URL Clas-3286 2d.h. 3us : arch_trigger_all_cpu_backtrace_handler <-nmi_handle.isra.0 URL Clas-3286 2d.h. 3us : perf_ibs_nmi_handler <-nmi_handle.isra.0 URL Clas-3286 2d.h. 3us : perf_ibs_handle_irq <-perf_ibs_nmi_handler URL Clas-3286 2d.h. 4us : perf_ibs_handle_irq <-perf_ibs_nmi_handler URL Clas-3286 2d.h. 4us!: rcu_nmi_exit <-do_nmi URL Clas-3286 2d... 879us : smp_apic_timer_interrupt <-apic_timer_interrupt URL Clas-3286 2d... 879us : irq_enter <-smp_apic_timer_interrupt URL Clas-3286 2d... 879us : rcu_irq_enter <-irq_enter URL Clas-3286 2d... 879us : rcu_eqs_exit_common.isra.45 <-rcu_irq_enter URL Clas-3286 2d... 880us : vtime_account_irq_enter <-irq_enter URL Clas-3286 2d... 880us : vtime_account_user <-vtime_account_irq_enter URL Clas-3286 2d... 880us : get_vtime_delta <-vtime_account_user URL Clas-3286 2d... 880us : _raw_spin_lock <-vtime_account_user URL Clas-3286 2d... 881us : account_user_time <-vtime_account_user URL Clas-3286 2d... 881us : cpuacct_account_field <-account_user_time URL Clas-3286 2d... 881us : acct_account_cputime <-account_user_time URL Clas-3286 2d... 881us : __acct_update_integrals <-acct_account_cputime URL Clas-3286 2d... 881us : jiffies_to_timeval <-__acct_update_integrals URL Clas-3286 2d.h. 882us : exit_idle <-smp_apic_timer_interrupt URL Clas-3286 2d.h. 882us : hrtimer_interrupt <-smp_apic_timer_interrupt URL Clas-3286 2d.h. 882us : _raw_spin_lock <-hrtimer_interrupt URL Clas-3286 2d.h. 883us : ktime_get_update_offsets <-hrtimer_interrupt URL Clas-3286 2d.h. 883us : __run_hrtimer <-hrtimer_interrupt URL Clas-3286 2d.h. 884us : __remove_hrtimer <-__run_hrtimer URL Clas-3286 2d.h. 884us : hrtimer_wakeup <-__run_hrtimer URL Clas-3286 2d.h. 884us : wake_up_process <-hrtimer_wakeup URL Clas-3286 2d.h. 885us : try_to_wake_up <-wake_up_process URL Clas-3286 2d.h. 885us : _raw_spin_lock_irqsave <-try_to_wake_up URL Clas-3286 2d.h. 886us : task_waking_fair <-try_to_wake_up URL Clas-3286 2d.h. 886us : select_task_rq_fair <-try_to_wake_up URL Clas-3286 2d.h. 887us : idle_cpu <-select_task_rq_fair URL Clas-3286 2d.h. 888us : idle_cpu <-select_task_rq_fair URL Clas-3286 2d.h. 889us : set_task_cpu <-try_to_wake_up URL Clas-3286 2d.h. 889us : migrate_task_rq_fair <-set_task_cpu URL Clas-3286 2d.h. 890us : atomic_notifier_call_chain <-set_task_cpu URL Clas-3286 2d.h. 890us : __atomic_notifier_call_chain <-atomic_notifier_call_chain URL Clas-3286 2d.h. 890us : notifier_call_chain <-__atomic_notifier_call_chain URL Clas-3286 2d.h. 891us : _raw_spin_lock <-try_to_wake_up URL Clas-3286 2d.h. 891us : ttwu_do_activate.constprop.76 <-try_to_wake_up URL Clas-3286 2d.h. 892us : activate_task <-ttwu_do_activate.constprop.76 URL Clas-3286 2d.h. 892us : enqueue_task <-activate_task URL Clas-3286 2d.h. 892us : update_rq_clock <-enqueue_task URL Clas-3286 2d.h. 892us : enqueue_task_fair <-enqueue_task URL Clas-3286 2d.h. 892us : enqueue_entity <-enqueue_task_fair URL Clas-3286 2d.h. 893us : update_curr <-enqueue_entity URL Clas-3286 2d.h. 894us : __compute_runnable_contrib <-enqueue_entity URL Clas-3286 2d.h. 894us : __update_entity_load_avg_contrib <-enqueue_entity URL Clas-3286 2d.h. 894us : update_cfs_rq_blocked_load <-enqueue_entity URL Clas-3286 2d.h. 895us : account_entity_enqueue <-enqueue_entity URL Clas-3286 2d.h. 895us : update_cfs_shares <-enqueue_entity URL Clas-3286 2d.h. 895us : place_entity <-enqueue_entity URL Clas-3286 2d.h. 896us : __enqueue_entity <-enqueue_entity URL Clas-3286 2d.h. 897us : enqueue_entity <-enqueue_task_fair URL Clas-3286 2d.h. 897us : update_curr <-enqueue_entity URL Clas-3286 2d.h. 897us : __compute_runnable_contrib <-enqueue_entity URL Clas-3286 2d.h. 897us : __update_entity_load_avg_contrib <-enqueue_entity URL Clas-3286 2d.h. 897us : update_cfs_rq_blocked_load <-enqueue_entity URL Clas-3286 2d.h. 898us : account_entity_enqueue <-enqueue_entity URL Clas-3286 2d.h. 898us : update_cfs_shares <-enqueue_entity URL Clas-3286 2d.h. 898us : place_entity <-enqueue_entity URL Clas-3286 2d.h. 899us : __enqueue_entity <-enqueue_entity URL Clas-3286 2d.h. 899us : hrtick_update <-enqueue_task_fair URL Clas-3286 2d.h. 899us : ttwu_do_wakeup <-ttwu_do_activate.constprop.76 URL Clas-3286 2d.h. 899us : check_preempt_curr <-ttwu_do_wakeup URL Clas-3286 2d.h. 900us : resched_task <-check_preempt_curr URL Clas-3286 2d.h. 900us : native_smp_send_reschedule <-resched_task URL Clas-3286 2d.h. 901us : flat_send_IPI_mask <-native_smp_send_reschedule URL Clas-3286 2d.h. 901us : ttwu_stat <-try_to_wake_up URL Clas-3286 2d.h. 901us : _raw_spin_unlock_irqrestore <-try_to_wake_up URL Clas-3286 2d.h. 902us : _raw_spin_lock <-__run_hrtimer URL Clas-3286 2d.h. 902us : tick_program_event <-hrtimer_interrupt URL Clas-3286 2d.h. 902us : clockevents_program_event <-tick_program_event URL Clas-3286 2d.h. 902us : ktime_get <-clockevents_program_event URL Clas-3286 2d.h. 903us : lapic_next_event <-clockevents_program_event URL Clas-3286 2d.h. 903us : irq_exit <-smp_apic_timer_interrupt URL Clas-3286 2d.h. 903us : vtime_account_irq_exit <-irq_exit URL Clas-3286 2d.h. 903us : _raw_spin_lock <-vtime_account_irq_exit URL Clas-3286 2d.h. 904us : __vtime_account_system <-vtime_account_irq_exit URL Clas-3286 2d.h. 904us : get_vtime_delta <-__vtime_account_system URL Clas-3286 2d.h. 904us : account_system_time <-__vtime_account_system URL Clas-3286 2d.h. 904us : cpuacct_account_field <-account_system_time URL Clas-3286 2d.h. 904us : acct_account_cputime <-account_system_time URL Clas-3286 2d.h. 904us : __acct_update_integrals <-acct_account_cputime URL Clas-3286 2d.h. 905us : jiffies_to_timeval <-__acct_update_integrals URL Clas-3286 2d... 905us : idle_cpu <-irq_exit URL Clas-3286 2d... 905us : tick_nohz_full_cpu <-irq_exit URL Clas-3286 2d... 906us : rcu_irq_exit <-irq_exit URL Clas-3286 2d... 906us : rcu_eqs_enter_common.isra.47 <-rcu_irq_exit URL Clas-3286 2d... 906us : trace_hardirqs_on_thunk <-retint_swapgs URL Clas-3286 2d... 907us+: trace_hardirqs_on_caller <-retint_swapgs URL Clas-3286 2d... 913us : <stack trace> => trace_hardirqs_on_thunk -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
