Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Date:   Wed, 20 May 2020 19:02:16 +0200
From:   Frederic Weisbecker <frederic@kernel.org>
To:     Juri Lelli <juri.lelli@redhat.com>
Cc:     fweisbec@gmail.com, tglx@linutronix.de, mingo@kernel.org,
        linux-rt-users@vger.kernel.org, peterz@infradead.org,
        linux-kernel@vger.kernel.org
Subject: Re: [RFC PATCH] tick/sched: update full_nohz status after SCHED dep
 is cleared
Message-ID: <20200520170215.GB8800@lenoir>
References: <20200520140402.358880-1-juri.lelli@redhat.com>
 <20200520162400.GA8800@lenoir>
 <20200520164925.GM10078@localhost.localdomain>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20200520164925.GM10078@localhost.localdomain>
User-Agent: Mutt/1.9.4 (2018-02-28)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Wed, May 20, 2020 at 06:49:25PM +0200, Juri Lelli wrote:
> On 20/05/20 18:24, Frederic Weisbecker wrote:
> 
> Hummm, so I enabled 'timer:*', anything else you think I should be
> looking at?

Are you sure you also enabled timer_expire_entry?
Because:

> 
> ...
> ksoftirqd/13-117   [013]   148.265945: softirq_entry:        vec=1 [action=TIMER]

...the timer softirq keep triggering without any timer callback executed. If that's the
case, we may be dealing with an interesting issue.

Thanks.

> ksoftirqd/13-117   [013]   148.265947: softirq_exit:         vec=1 [action=TIMER]
> ksoftirqd/13-117   [013]   148.265948: softirq_entry:        vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.265950: softirq_exit:         vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.265952: sched_switch:         ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120]
>    sysjitter-2536  [013]   148.266912: local_timer_entry:    vector=236
>    sysjitter-2536  [013]   148.266914: hrtimer_cancel:       hrtimer=0xffff9807df91bee0
>    sysjitter-2536  [013]   148.266916: hrtimer_expire_entry: hrtimer=0xffff9807df91bee0 now=148249107837 function=tick_sched_timer/0x0
>    sysjitter-2536  [013]   148.266918: softirq_raise:        vec=1 [action=TIMER]
>    sysjitter-2536  [013]   148.266920: softirq_raise:        vec=7 [action=SCHED]
>    sysjitter-2536  [013]   148.266922: hrtimer_expire_exit:  hrtimer=0xffff9807df91bee0
>    sysjitter-2536  [013]   148.266924: hrtimer_start:        hrtimer=0xffff9807df91bee0 function=tick_sched_timer/0x0 expires=148250105422 softexpires=148250105422
>    sysjitter-2536  [013]   148.266926: local_timer_exit:     vector=236
>    sysjitter-2536  [013]   148.266930: sched_wakeup:         ksoftirqd/13:117 [120] success=1 CPU:013
>    sysjitter-2536  [013]   148.266932: tick_stop:            success=0 dependency=SCHED
>    sysjitter-2536  [013]   148.266934: irq_work_entry:       vector=246
>    sysjitter-2536  [013]   148.266936: irq_work_exit:        vector=246
>    sysjitter-2536  [013]   148.266937: tick_stop:            success=0 dependency=SCHED
>    sysjitter-2536  [013]   148.266940: sched_switch:         sysjitter:2536 [120] R ==> ksoftirqd/13:117 [120]
> ksoftirqd/13-117   [013]   148.266943: softirq_entry:        vec=1 [action=TIMER]
> ksoftirqd/13-117   [013]   148.266946: softirq_exit:         vec=1 [action=TIMER]
> ksoftirqd/13-117   [013]   148.266946: softirq_entry:        vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.266948: softirq_exit:         vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.266950: sched_switch:         ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120]
>    sysjitter-2536  [013]   148.267912: local_timer_entry:    vector=236
>    sysjitter-2536  [013]   148.267914: hrtimer_cancel:       hrtimer=0xffff9807df91bee0
>    sysjitter-2536  [013]   148.267916: hrtimer_expire_entry: hrtimer=0xffff9807df91bee0 now=148250107750 function=tick_sched_timer/0x0
>    sysjitter-2536  [013]   148.267918: softirq_raise:        vec=1 [action=TIMER]
>    sysjitter-2536  [013]   148.267920: softirq_raise:        vec=7 [action=SCHED]
>    sysjitter-2536  [013]   148.267922: hrtimer_expire_exit:  hrtimer=0xffff9807df91bee0
>    sysjitter-2536  [013]   148.267924: hrtimer_start:        hrtimer=0xffff9807df91bee0 function=tick_sched_timer/0x0 expires=148251105422 softexpires=148251105422
>    sysjitter-2536  [013]   148.267926: local_timer_exit:     vector=236
>    sysjitter-2536  [013]   148.267929: sched_wakeup:         ksoftirqd/13:117 [120] success=1 CPU:013
>    sysjitter-2536  [013]   148.267931: tick_stop:            success=0 dependency=SCHED
>    sysjitter-2536  [013]   148.267934: irq_work_entry:       vector=246
>    sysjitter-2536  [013]   148.267936: irq_work_exit:        vector=246
>    sysjitter-2536  [013]   148.267937: tick_stop:            success=0 dependency=SCHED
>    sysjitter-2536  [013]   148.267940: sched_switch:         sysjitter:2536 [120] R ==> ksoftirqd/13:117 [120]
> ksoftirqd/13-117   [013]   148.267943: softirq_entry:        vec=1 [action=TIMER]
> ksoftirqd/13-117   [013]   148.267945: softirq_exit:         vec=1 [action=TIMER]
> ksoftirqd/13-117   [013]   148.267946: softirq_entry:        vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.267947: softirq_exit:         vec=7 [action=SCHED]
> ksoftirqd/13-117   [013]   148.267949: sched_switch:         ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120]
>    sysjitter-2536  [013]   148.268865: call_function_single_entry: vector=251
>    sysjitter-2536  [013]   148.268867: call_function_single_exit: vector=251
>    sysjitter-2536  [013]   148.268870: tick_stop:            success=1 dependency=NONE
>    sysjitter-2536  [013]   148.268872: hrtimer_cancel:       hrtimer=0xffff9807df91bee0
>    sysjitter-2536  [013]   148.268876: call_function_single_entry: vector=251
>    sysjitter-2536  [013]   148.268878: call_function_single_exit: vector=251
> ...
> 
> it looks like tick sched timer is kept armed until tick_stop
> succedes (because of the check performed after _single_exit)?
> 
> Thanks for your quick reply!
>