On Thu, 2017-10-05 at 17:54 +0200, Sebastian Andrzej Siewior wrote: > On 2017-10-04 18:07:59 [+0200], Mike Galbraith wrote: > > Seems combo-patch induced some ltp posix conformance test grumbling. > > > > +clock_settime_8_1 ... ... FAILED > > +clock_settime_4_2 ... ... FAILED > > +clock_settime_speculative_4_3 ... ... FAILED > > +timer_settime_5_2 ... ... FAILED > > +timer_settime_5_1 ... ... FAILED > > +timer_settime_5_3 ... ... FAILED > > > > rtbox:/root # > > /usr/local/ltp/conformance/interfaces/clock_settime/clock_settime_8-1.run-test > > Ended too late. 1507131910 >> 1507131908 > > Test FAILED > > rtbox:/root # > > /usr/local/ltp/conformance/interfaces/clock_settime/clock_settime_4-2.run-test > > timer should have expired _immediately_ > > rtbox:/root # > > /usr/local/ltp/conformance/interfaces/clock_settime/speculative/clock_settime_speculative_4-3.run-test > > Overrun count =0, not # of repeating timer expirys > > FAIL: Caught 0 signals, not 1 > > Test FAILED > > rtbox:/root # > > /opt/ltp/conformance/interfaces/timer_settime/timer_settime_5-2.run-test > > signal was not sent > > So the last triggers here, too and I have an idea.
I ran a trace of clock_settime_4-2.run-test, which arms a timer for now+9 seconds, then clock_settime to advance 4 seconds past timer expiration, which should cause the timer to fire. Going through SyS_clock_settime..retrigger_next_event..lapic_next_deadline does not trigger interrupt, but does without the culprit patch applied. clock_settime_4-6453 [003] ....... 384.288883: SyS_clock_settime <-entry_SYSCALL_64_fastpath clock_settime_4-6453 [003] ....... 384.288883: __might_fault <-SyS_clock_settime clock_settime_4-6453 [003] ....... 384.288883: __might_sleep <-__might_fault clock_settime_4-6453 [003] ....... 384.288883: ___might_sleep <-__might_fault clock_settime_4-6453 [003] ....... 384.288883: _copy_from_user <-SyS_clock_settime clock_settime_4-6453 [003] ....... 384.288884: __might_fault <-_copy_from_user clock_settime_4-6453 [003] ....... 384.288884: __might_sleep <-__might_fault clock_settime_4-6453 [003] ....... 384.288884: ___might_sleep <-__might_fault clock_settime_4-6453 [003] ....... 384.288884: posix_clock_realtime_set <-SyS_clock_settime clock_settime_4-6453 [003] ....... 384.288884: do_sys_settimeofday64 <-posix_clock_realtime_set clock_settime_4-6453 [003] ....... 384.288884: security_settime64 <-do_sys_settimeofday64 clock_settime_4-6453 [003] ....... 384.288884: cap_settime <-security_settime64 clock_settime_4-6453 [003] ....... 384.288885: capable <-cap_settime clock_settime_4-6453 [003] ....... 384.288885: ns_capable_common <-cap_settime clock_settime_4-6453 [003] ....... 384.288885: security_capable <-ns_capable_common clock_settime_4-6453 [003] ....... 384.288885: cap_capable <-security_capable clock_settime_4-6453 [003] ....... 384.288885: apparmor_capable <-security_capable clock_settime_4-6453 [003] ....... 384.288885: do_settimeofday64 <-do_sys_settimeofday64 clock_settime_4-6453 [003] ....... 384.288886: _raw_spin_lock_irqsave <-do_settimeofday64 clock_settime_4-6453 [003] d...... 384.288886: preempt_count_add <-_raw_spin_lock_irqsave clock_settime_4-6453 [003] d...1.. 384.288886: preempt_count_add <-do_settimeofday64 clock_settime_4-6453 [003] d...2.. 384.288886: timekeeping_forward_now.constprop.12 <-do_settimeofday64 clock_settime_4-6453 [003] d...2.. 384.288886: set_normalized_timespec <-do_settimeofday64 clock_settime_4-6453 [003] d...2.. 384.288886: tk_set_wall_to_mono <-do_settimeofday64 clock_settime_4-6453 [003] d...2.. 384.288886: set_normalized_timespec <-tk_set_wall_to_mono clock_settime_4-6453 [003] d...2.. 384.288886: set_normalized_timespec <-tk_set_wall_to_mono clock_settime_4-6453 [003] d...2.. 384.288886: timekeeping_update <-do_settimeofday64 clock_settime_4-6453 [003] d...2.. 384.288887: ntp_clear <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288887: ntp_update_frequency <-ntp_clear clock_settime_4-6453 [003] d...2.. 384.288887: ntp_get_next_leap <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288887: update_vsyscall <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288887: raw_notifier_call_chain <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288887: notifier_call_chain <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288887: pvclock_gtod_notify <-notifier_call_chain clock_settime_4-6453 [003] d...2.. 384.288888: preempt_count_add <-pvclock_gtod_notify clock_settime_4-6453 [003] d...3.. 384.288888: preempt_count_sub <-pvclock_gtod_notify clock_settime_4-6453 [003] d...2.. 384.288888: update_fast_timekeeper <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288888: update_fast_timekeeper <-timekeeping_update clock_settime_4-6453 [003] d...2.. 384.288888: preempt_count_sub <-do_settimeofday64 clock_settime_4-6453 [003] d...1.. 384.288888: _raw_spin_unlock_irqrestore <-do_settimeofday64 clock_settime_4-6453 [003] ....1.. 384.288888: preempt_count_sub <-_raw_spin_unlock_irqrestore clock_settime_4-6453 [003] ....... 384.288888: clock_was_set <-do_settimeofday64 clock_settime_4-6453 [003] ....... 384.288888: on_each_cpu <-clock_was_set clock_settime_4-6453 [003] ....... 384.288889: preempt_count_add <-on_each_cpu clock_settime_4-6453 [003] ....1.. 384.288889: smp_call_function <-on_each_cpu clock_settime_4-6453 [003] ....1.. 384.288889: preempt_count_add <-smp_call_function clock_settime_4-6453 [003] ....2.. 384.288889: smp_call_function_many <-smp_call_function clock_settime_4-6453 [003] ....2.. 384.288890: native_send_call_func_ipi <-smp_call_function_many clock_settime_4-6453 [003] ....2.. 384.288890: x2apic_send_IPI_allbutself <-native_send_call_func_ipi clock_settime_4-6453 [003] ....2.. 384.288890: __x2apic_send_IPI_mask <-native_send_call_func_ipi clock_settime_4-6453 [003] ....2.. 384.288914: preempt_count_sub <-smp_call_function clock_settime_4-6453 [003] d...1.. 384.288914: retrigger_next_event <-on_each_cpu clock_settime_4-6453 [003] d...1.. 384.288915: _raw_spin_lock <-retrigger_next_event clock_settime_4-6453 [003] d...1.. 384.288915: preempt_count_add <-_raw_spin_lock clock_settime_4-6453 [003] d...2.. 384.288915: ktime_get_update_offsets_now <-retrigger_next_event clock_settime_4-6453 [003] d...2.. 384.288915: __hrtimer_get_next_event <-retrigger_next_event clock_settime_4-6453 [003] d...2.. 384.288915: __hrtimer_next_event_base <-__hrtimer_get_next_event clock_settime_4-6453 [003] d...2.. 384.288915: __hrtimer_next_event_base <-retrigger_next_event clock_settime_4-6453 [003] d...2.. 384.288915: tick_program_event <-retrigger_next_event clock_settime_4-6453 [003] d...2.. 384.288915: clockevents_program_event <-retrigger_next_event clock_settime_4-6453 [003] d...2.. 384.288915: ktime_get <-clockevents_program_event clock_settime_4-6453 [003] d...2.. 384.288916: lapic_next_deadline <-clockevents_program_event clock_settime_4-6453 [003] d...2.. 384.288916: preempt_count_sub <-retrigger_next_event
