Re: [PATCH RESEND v2 2/2] perf/core: Fix incorrected time diff in tick adjust period
From: Luo Gengkun
Date: Sat Aug 10 2024 - 05:27:06 EST
On 2024/7/29 22:18, Luo Gengkun wrote:
On 2024/6/17 21:42, Adrian Hunter wrote:
On 17/04/24 14:54, Luo Gengkun wrote:
Adrian found that there is a probability that the number of samples
is small, which is caused by the unreasonable large sampling period.
# taskset --cpu 0 perf record -F 1000 -e cs -- taskset --cpu 1 ./test
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.010 MB perf.data (204 samples) ]
# perf script
...
test 865 265.377846: 16 cs: ffffffff832e927b
schedule+0x2b
test 865 265.378900: 15 cs: ffffffff832e927b
schedule+0x2b
test 865 265.379845: 14 cs: ffffffff832e927b
schedule+0x2b
test 865 265.380770: 14 cs: ffffffff832e927b
schedule+0x2b
test 865 265.381647: 15 cs: ffffffff832e927b
schedule+0x2b
test 865 265.382638: 16 cs: ffffffff832e927b
schedule+0x2b
test 865 265.383647: 16 cs: ffffffff832e927b
schedule+0x2b
test 865 265.384704: 15 cs: ffffffff832e927b
schedule+0x2b
test 865 265.385649: 14 cs: ffffffff832e927b
schedule+0x2b
test 865 265.386578: 152 cs: ffffffff832e927b
schedule+0x2b
test 865 265.396383: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.406183: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.415839: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.425445: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.435052: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.444708: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.454314: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.463970: 154 cs: ffffffff832e927b
schedule+0x2b
test 865 265.473577: 154 cs: ffffffff832e927b
schedule+0x2b
...
It seems that the Timer Interrupts is not coming every TICK_NSEC when
No, the period is not adjusted unless the event is active i.e.
scheduled in.
So an event in a task context where the task sleeps a lot will
likely not be adjusted every tick.
Yes, your explanation makes sense.
system is idle. For example, counter increase n during 2 * TICK_NSEC,
and it call perf_adjust_period using n and TICK_NSEC, so the final
period
we calculated will be bigger than expected one. What's more, if the
the overflow time is larger than 2 * TICK_NSEC we cannot tune the
period
using __perf_event_account_interrupt. To fix this problem, perf can
calculate the tick interval by itself.
Yes, the period can get stuck being too big:
perf_adjust_freq_unthr_events() calculates a value that is
too big because it incorrectly assumes the count has
accumulated only since the last tick, whereas it can have
been much longer.
__perf_event_account_interrupt() has an unexplained limit
(2*TICK_NSEC) on the count delta, and won't adjust the
period if that is exceeded.
Signed-off-by: Luo Gengkun <luogengkun@xxxxxxxxxxxxxxx>
---
include/linux/perf_event.h | 1 +
kernel/events/core.c | 15 ++++++++++++---
2 files changed, 13 insertions(+), 3 deletions(-)
diff --git a/include/linux/perf_event.h b/include/linux/perf_event.h
index afb028c54f33..2708f1d0692c 100644
--- a/include/linux/perf_event.h
+++ b/include/linux/perf_event.h
@@ -265,6 +265,7 @@ struct hw_perf_event {
* State for freq target events, see __perf_event_overflow() and
* perf_adjust_freq_unthr_context().
*/
+ u64 freq_tick_stamp;
u64 freq_time_stamp;
u64 freq_count_stamp;
#endif
diff --git a/kernel/events/core.c b/kernel/events/core.c
index cad50d3439f1..0f2025d631aa 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -4112,7 +4112,7 @@ perf_adjust_freq_unthr_context(struct
perf_event_context *ctx, bool unthrottle)
{
struct perf_event *event;
struct hw_perf_event *hwc;
- u64 now, period = TICK_NSEC;
+ u64 now, period, tick_stamp;
s64 delta;
/*
@@ -4151,6 +4151,10 @@ perf_adjust_freq_unthr_context(struct
perf_event_context *ctx, bool unthrottle)
*/
event->pmu->stop(event, PERF_EF_UPDATE);
+ tick_stamp = perf_clock();
Perhaps jiffies would work just as well, but be
more efficient.
I tried to use jiffies as shown below.
tick_stamp = perf_clock();
+ printk("debug jiffies64:%llu, clock:%llu\n",
jiffies64_to_nsecs(get_jiffies_64()), perf_clock());
period = tick_stamp - hwc->freq_tick_stamp;
But the result is odd and I don't know why, the result is pasted below.
[ 423.646990] debug jiffies64:4295090788000000, clock:423646990256
[ 423.685989] debug jiffies64:4295090827000000, clock:423685989583
[ 423.719989] debug jiffies64:4295090861000000, clock:423719989830
[ 423.755990] debug jiffies64:4295090897000000, clock:423755990128
[ 423.766990] debug jiffies64:4295090908000000, clock:423766989901
[ 423.777990] debug jiffies64:4295090918000000, clock:423777989972
[ 423.787989] debug jiffies64:4295090929000000, clock:423787989835
[ 423.798989] debug jiffies64:4295090940000000, clock:423798989359
[ 423.833990] debug jiffies64:4295090975000000, clock:423833990057
[ 423.878989] debug jiffies64:4295091020000000, clock:423878989503
[ 423.898990] debug jiffies64:4295091040000000, clock:423898990201
[ 423.921989] debug jiffies64:4295091063000000, clock:423921989762
[ 423.967989] debug jiffies64:4295091109000000, clock:423967989325
[ 424.011989] debug jiffies64:4295091153000000, clock:424011989387
[ 424.099989] debug jiffies64:4295091241000000, clock:424099989730
[ 424.169989] debug jiffies64:4295091311000000, clock:424169989577
perf_clock gets the right answer and jiffies make me confuse.
Looking forward to your reply, sincerely.
Please ignore the previous problem. I try to replace perf_clock with
jiffies, and
it still work well. The result is pasted below:
root@lgk:~# time ./a.out
real 0m3.459s
user 0m0.144s
sys 0m1.508s
root@lgk:~# perf record -e cs -F 1000 ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.132 MB perf.data (3421 samples) ]
root@lgk:~# perf record -e cs -F 1000 ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.128 MB perf.data (3336 samples) ]
root@lgk:~# perf record -e cs -F 1000 ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.128 MB perf.data (3315 samples) ]
root@lgk:~# perf record -e cs -F 1000 ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.125 MB perf.data (3262 samples) ]
root@lgk:~# perf record -e cs -F 1000 ./a.out
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.129 MB perf.data (3344 samples) ]
In addition, it looks like perf_clock is using everywhere in perf. So i
replace
local_clock with jiffies, as shown below:
+#include <linux/jiffies.h>
#include "internal.h"
@@ -578,7 +579,7 @@ void __weak perf_event_print_debug(void) { }
static inline u64 perf_clock(void)
{
- return local_clock();
+ return jiffies64_to_nsecs(get_jiffies_64());
}
+ period = tick_stamp - hwc->freq_tick_stamp;
+ hwc->freq_tick_stamp = tick_stamp;
+
now = local64_read(&event->count);
delta = now - hwc->freq_count_stamp;
hwc->freq_count_stamp = now;
@@ -4162,8 +4166,13 @@ perf_adjust_freq_unthr_context(struct
perf_event_context *ctx, bool unthrottle)
* to perf_adjust_period() to avoid stopping it
* twice.
*/
- if (delta > 0)
- perf_adjust_period(event, period, delta, false);
+ if (delta > 0) {
+ /*
+ * we skip first tick adjust period
+ */
+ if (likely(period != tick_stamp))
+ perf_adjust_period(event, period, delta, false);
+ }
event->pmu->start(event, delta > 0 ? PERF_EF_RELOAD : 0);
next: