[Devel] [PATCH vz9 07/20] mm/page_alloc: add latency to the page_alloc tracepoint

[Nikita Yushchenko]

From: Andrey Ryabinin <aryabinin at virtuozzo.com>

Add 'lat' field to the mm_page_alloc tracepoint. It shows allocation
latency in microseconds (0.000001 second).

Signed-off-by: Andrey Ryabinin <aryabinin at virtuozzo.com>
Reviewed-by: Cyrill Gorcunov <gorcunov at virtuozzo.com>

++++++++++++
mm/page_alloc: fix latency in tracepoint.

Since transition from jiffies to sched_clock(), mm_page_alloc
garbadge since we substract from jiffies nanoseconds.
Fix this.

mFixes: e9e7602565ab ("mm/page_alloc: use sched_clock() instead of jiffies to
measure latency")
Signed-off-by: Andrey Ryabinin <aryabinin at virtuozzo.com>

++++++++++++
mm/page_alloc: fix latency in tracepoint - addon

Compilation warning fixed: use proper type.

mFixes: 7eff199a7a9e ("mm/page_alloc: fix latency in tracepoint.")
Signed-off-by: Andrey Ryabinin <aryabinin at virtuozzo.com>

++++++++++++
mm/trace: fix always 0 latency in page_alloc tracepoint

Since __entry->time wasn't assigned, mm_page_alloc trace point
shows always 0 lat.

mFixes: fc8961c87c00 ("mm/page_alloc: add latency to the page_alloc tracepoint")
Signed-off-by: Andrey Ryabinin <aryabinin at virtuozzo.com>

Rebased to vz8 and merged following vz7 patches:
 - b3e2b2367630 ("mm/page_alloc: add latency to the page_alloc tracepoint")
 - 5ae153305c03 ("mm/page_alloc: fix latency in tracepoint.")
 - b6be69d05fd4 ("mm/page_alloc: fix latency in tracepoint - addon")
 - 0662cba1feed ("mm/trace: fix always 0 latency in page_alloc tracepoint")
Signed-off-by: Andrey Zhadchenko <andrey.zhadchenko at virtuozzo.com>

(cherry-picked from vz8 commit a625b5a00a03 ("mm/page_alloc: add latency to
the page_alloc tracepoint"))

Signed-off-by: Nikita Yushchenko <nikita.yushchenko at virtuozzo.com>
---
 include/trace/events/kmem.h | 11 +++++++----
 mm/page_alloc.c             | 13 +++++++------
 2 files changed, 14 insertions(+), 10 deletions(-)

diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index ddc8c944f417..dc07c9811432 100644
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -201,15 +201,16 @@ TRACE_EVENT(mm_page_free_batched,
 TRACE_EVENT(mm_page_alloc,
 
 	TP_PROTO(struct page *page, unsigned int order,
-			gfp_t gfp_flags, int migratetype),
+			gfp_t gfp_flags, int migratetype, u64 time),
 
-	TP_ARGS(page, order, gfp_flags, migratetype),
+	TP_ARGS(page, order, gfp_flags, migratetype, time),
 
 	TP_STRUCT__entry(
 		__field(	unsigned long,	pfn		)
 		__field(	unsigned int,	order		)
 		__field(	gfp_t,		gfp_flags	)
 		__field(	int,		migratetype	)
+		__field(	u64,		time		)
 	),
 
 	TP_fast_assign(
@@ -217,14 +218,16 @@ TRACE_EVENT(mm_page_alloc,
 		__entry->order		= order;
 		__entry->gfp_flags	= gfp_flags;
 		__entry->migratetype	= migratetype;
+		__entry->time		= time;
 	),
 
-	TP_printk("page=%p pfn=0x%lx order=%d migratetype=%d gfp_flags=%s",
+	TP_printk("page=%p pfn=0x%lx order=%d migratetype=%d gfp_flags=%s lat=%llu",
 		__entry->pfn != -1UL ? pfn_to_page(__entry->pfn) : NULL,
 		__entry->pfn != -1UL ? __entry->pfn : 0,
 		__entry->order,
 		__entry->migratetype,
-		show_gfp_flags(__entry->gfp_flags))
+		show_gfp_flags(__entry->gfp_flags),
+		__entry->time)
 );
 
 DECLARE_EVENT_CLASS(mm_page,
diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index cdc719098dbb..ccefc210fdb1 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -5440,14 +5440,13 @@ void update_maxlat(struct kstat_lat_snap_struct *alloc_lat,
 }
 
 static void __alloc_collect_stats(gfp_t gfp_mask, unsigned int order,
-		struct page *page, u64 time)
+		struct page *page, u64 time, u64 current_clock)
 {
 #ifdef CONFIG_VE
 	unsigned long flags;
-	u64 current_clock, delta;
+	u64 delta;
 	int ind, cpu;
 
-	current_clock = sched_clock();
 	delta = current_clock - time;
 	if (!(gfp_mask & __GFP_RECLAIM)) {
 		if (in_task())
@@ -5487,7 +5486,7 @@ struct page *__alloc_pages(gfp_t gfp, unsigned int order, int preferred_nid,
 	unsigned int alloc_flags = ALLOC_WMARK_LOW;
 	gfp_t alloc_gfp; /* The gfp_t that was actually used for allocation */
 	struct alloc_context ac = { };
-	u64 start;
+	u64 start, current_clock;
 
 	/*
 	 * There are several places where we assume that the order value is sane
@@ -5545,8 +5544,10 @@ struct page *__alloc_pages(gfp_t gfp, unsigned int order, int preferred_nid,
 		page = NULL;
 	}
 
-	__alloc_collect_stats(alloc_gfp, order, page, start);
-	trace_mm_page_alloc(page, order, alloc_gfp, ac.migratetype);
+	current_clock = sched_clock();
+	__alloc_collect_stats(alloc_gfp, order, page, start, current_clock);
+	trace_mm_page_alloc(page, order, alloc_gfp, ac.migratetype,
+			(current_clock - start));
 
 	return page;
 }
-- 
2.30.2