Re: [PATCH] hrtimer: CPU and entry_time is added to a warning message in hrtimer_interrupt()

[Rei Yamamoto]

On Fri, 24 Jun 2022 16:00:11, Rei Yamamoto wrote:
> dmesg
> :
> [ 1462.836971] start repro_hrtimer_interrupt
> [ 1462.836976] test_handler = test_handler [repro] 0xffff9788f7bb3048
> :
> [ 1462.879117] hrtimer: CPU 7, entry_time = 1462807264840, interrupt took
> 60048886 ns             ^^^^^               ^^^^^^^^^^^^^
> 
> cat /sys/kernel/debug/tracing/trace
> :
>           <idle>-0       [007] d.h1.  1462.838075: hrtimer_expire_entry:
>                          ^^^^^
> hrtimer=0000000041fcee42 function=test_handler [repro] now=1462807264840
>                                                            ^^^^^^^^^^^^^

test_handler() keeps running for 20 milliseconds due to a loop,
and it leads to exceed next_expire.

# grep -A 21 "hrtimer_restart test_handler" repro.c
static enum hrtimer_restart test_handler(struct hrtimer *hrtimer)
{
        ktime_t start, end;
        printk(KERN_INFO "start test_handler %d times\n", count);

        hrtimer_forward_now(hrtimer, ns_to_ktime(TICK_NSEC));

        start = ktime_get();

        for(;;){
                end = ktime_get();
                if((ktime_sub(end, start)) > 20000000)
                        break;
        }

        if(count < 20){
                count++;
                return HRTIMER_RESTART;
        }else{
                return HRTIMER_NORESTART;
        }
}

Thanks,
Rei