Re: [PATCH 3/3] Add name fields in shrinker tracepoint definitions

[Tony Jones <tonyj@suse.de>]

On 07/11/2016 07:18 AM, Vlastimil Babka wrote:
> On 07/09/2016 11:05 AM, Janani Ravichandran wrote:
>> Currently, the mm_shrink_slab_start and mm_shrink_slab_end
>> tracepoints tell us how much time was spent in a shrinker, the number of
>> objects scanned, etc. But there is no information about the identity of
>> the shrinker. This patch enables the trace output to display names of
>> shrinkers.
>>
>> ---
>>  include/trace/events/vmscan.h | 10 ++++++++--
>>  1 file changed, 8 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
>> index 0101ef3..be4c5b0 100644
>> --- a/include/trace/events/vmscan.h
>> +++ b/include/trace/events/vmscan.h
>> @@ -189,6 +189,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  		cache_items, delta, total_scan),
>>
>>  	TP_STRUCT__entry(
>> +		__field(char *, name)
>>  		__field(struct shrinker *, shr)
>>  		__field(void *, shrink)
>>  		__field(int, nid)
>> @@ -202,6 +203,7 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  	),
>>
>>  	TP_fast_assign(
>> +		__entry->name = shr->name;
>>  		__entry->shr = shr;
>>  		__entry->shrink = shr->scan_objects;
>>  		__entry->nid = sc->nid;
>> @@ -214,7 +216,8 @@ TRACE_EVENT(mm_shrink_slab_start,
>>  		__entry->total_scan = total_scan;
>>  	),
>>
>> -	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>> +	TP_printk("name: %s %pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
>> +		__entry->name,
> 
> Is this legal to do when printing is not done via the /sys ... file 
> itself, but raw data is collected and then printed by e.g. trace-cmd? 
> How can it possibly interpret the "char *" kernel pointer?

I actually had a similar patch set to this,  I was going to post it but Janani beat me to it ;-)

Vlastimil is correct,  I'll attach my patch below so you can see the difference.  Otherwise you won't get correct behavior passing through perf.   

I also have a patch which adds a similar latency script (python) but interfaces it into the perf script setup.

Tony

---

Pass shrinker name in shrink slab tracepoints

Signed-off-by: Tony Jones <tonyj@suse.de>
---
 include/trace/events/vmscan.h | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/vmscan.h b/include/trace/events/vmscan.h
index 0101ef3..0a15948 100644
--- a/include/trace/events/vmscan.h
+++ b/include/trace/events/vmscan.h
@@ -16,6 +16,8 @@
 #define RECLAIM_WB_SYNC		0x0004u /* Unused, all reclaim async */
 #define RECLAIM_WB_ASYNC	0x0008u
 
+#define SHRINKER_NAME_LEN 	(size_t)32
+
 #define show_reclaim_flags(flags)				\
 	(flags) ? __print_flags(flags, "|",			\
 		{RECLAIM_WB_ANON,	"RECLAIM_WB_ANON"},	\
@@ -190,6 +192,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
+		__array(char, name, SHRINKER_NAME_LEN)
 		__field(void *, shrink)
 		__field(int, nid)
 		__field(long, nr_objects_to_shrink)
@@ -203,6 +206,7 @@ TRACE_EVENT(mm_shrink_slab_start,
 
 	TP_fast_assign(
 		__entry->shr = shr;
+		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
 		__entry->shrink = shr->scan_objects;
 		__entry->nid = sc->nid;
 		__entry->nr_objects_to_shrink = nr_objects_to_shrink;
@@ -214,9 +218,10 @@ TRACE_EVENT(mm_shrink_slab_start,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
+	TP_printk("%pF %p(%s): nid: %d objects to shrink %ld gfp_flags %s pgs_scanned %ld lru_pgs %ld cache items %ld delta %lld total_scan %ld",
 		__entry->shrink,
 		__entry->shr,
+		__entry->name,
 		__entry->nid,
 		__entry->nr_objects_to_shrink,
 		show_gfp_flags(__entry->gfp_flags),
@@ -236,6 +241,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 
 	TP_STRUCT__entry(
 		__field(struct shrinker *, shr)
+		__array(char, name, SHRINKER_NAME_LEN)
 		__field(int, nid)
 		__field(void *, shrink)
 		__field(long, unused_scan)
@@ -246,6 +252,7 @@ TRACE_EVENT(mm_shrink_slab_end,
 
 	TP_fast_assign(
 		__entry->shr = shr;
+		strlcpy(__entry->name, shr->name, SHRINKER_NAME_LEN);
 		__entry->nid = nid;
 		__entry->shrink = shr->scan_objects;
 		__entry->unused_scan = unused_scan_cnt;
@@ -254,9 +261,10 @@ TRACE_EVENT(mm_shrink_slab_end,
 		__entry->total_scan = total_scan;
 	),
 
-	TP_printk("%pF %p: nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
+	TP_printk("%pF %p(%s): nid: %d unused scan count %ld new scan count %ld total_scan %ld last shrinker return val %d",
 		__entry->shrink,
 		__entry->shr,
+		__entry->name,
 		__entry->nid,
 		__entry->unused_scan,
 		__entry->new_scan,