pagecache tracepoints proposal

This patch adds several tracepoints to track pagecach behavior. These trecepoints would help us monitor pagecache usage with high resolution.

Signed-off-by Keiichi Kii <[email protected]>

Cc Atsushi Tsuji <[email protected]>

---
 include/trace/events/filemap.h |   83 +++++++++++++++++++++++++++++++++++++++++
 mm/filemap.c                   |    5 ++
 mm/truncate.c                  |    2 
 mm/vmscan.c                    |    3 +
 4 files changed, 93 insertions(+)

Index: linux-2.6-tip/include/trace/events/filemap.h
===================================================================

include/trace/events/filemap.h new file +69 -0

@@ -0,0 +1,83 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM filemap
+
+#if !defined(_TRACE_FILEMAP_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_FILEMAP_H
+
+#include <linux/fs.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(find_get_page,
+
+	TP_PROTO(struct address_space *mapping, pgoff_t offset,
+		struct page *page),
+
+	TP_ARGS(mapping, offset, page),
+
+	TP_STRUCT__entry(
+		__field(dev_t, s_dev)
+		__field(ino_t, i_ino)
+		__field(pgoff_t, offset)
+		__field(struct page *, page)
+		),
+
+	TP_fast_assign(
+		__entry->s_dev = mapping->host ? mapping->host->i_sb->s_dev : 0;
+		__entry->i_ino = mapping->host ? mapping->host->i_ino : 0;
+		__entry->offset = offset;
+		__entry->page = page;
+		),
+
+	TP_printk("s_dev=%u:%u i_ino=%lu offset=%lu %s", MAJOR(__entry->s_dev),
+		MINOR(__entry->s_dev), __entry->i_ino, __entry->offset,
+		__entry->page == NULL ? "page_not_found" : "page_found")
+);
+
+TRACE_EVENT(add_to_page_cache,
+
+	TP_PROTO(struct address_space *mapping, pgoff_t offset),
+
+	TP_ARGS(mapping, offset),
+
+	TP_STRUCT__entry(
+		__field(dev_t, s_dev)
+		__field(ino_t, i_ino)
+		__field(pgoff_t, offset)
+		),
+
+	TP_fast_assign(
+		__entry->s_dev = mapping->host->i_sb->s_dev;
+		__entry->i_ino = mapping->host->i_ino;
+		__entry->offset = offset;
+		),
+
+	TP_printk("s_dev=%u:%u i_ino=%lu offset=%lu", MAJOR(__entry->s_dev),
+		MINOR(__entry->s_dev), __entry->i_ino, __entry->offset)
+);
+
+TRACE_EVENT(remove_from_page_cache,
+
+	TP_PROTO(struct address_space *mapping, pgoff_t offset),
+
+	TP_ARGS(mapping, offset),
+
+	TP_STRUCT__entry(
+		__field(dev_t, s_dev)
+		__field(ino_t, i_ino)
+		__field(pgoff_t, offset)
+		),
+

include/trace/events/filemap.h new file +4 -0

+#endif /* _TRACE_FILEMAP_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Index: linux-2.6-tip/mm/filemap.c
===================================================================

mm/filemap.c +5 -0

@@ -34,6 +34,8 @@
 #include <linux/hardirq.h> /* for BUG_ON(!in_atomic()) only */
 #include <linux/memcontrol.h>
 #include <linux/mm_inline.h> /* for page_is_file_cache() */
+#define CREATE_TRACE_POINTS
+#include <trace/events/filemap.h>
 #include "internal.h"
 
 /*

@@ -149,6 +151,7 @@ void remove_from_page_cache(struct page 
 	spin_lock_irq(&mapping->tree_lock);
 	__remove_from_page_cache(page);
 	spin_unlock_irq(&mapping->tree_lock);
+	trace_remove_from_page_cache(mapping, page->index);
 	mem_cgroup_uncharge_cache_page(page);
 }
 

@@ -419,6 +422,7 @@ int add_to_page_cache_locked(struct page
 			if (PageSwapBacked(page))
 				__inc_zone_page_state(page, NR_SHMEM);
 			spin_unlock_irq(&mapping->tree_lock);
+			trace_add_to_page_cache(mapping, offset);
 		} else {
 			page->mapping = NULL;
 			spin_unlock_irq(&mapping->tree_lock);

@@ -642,6 +646,7 @@ repeat:
 	}
 	rcu_read_unlock();
 
+	trace_find_get_page(mapping, offset, page);
 	return page;
 }
 EXPORT_SYMBOL(find_get_page);

Index: linux-2.6-tip/mm/truncate.c
===================================================================

mm/truncate.c +2 -0

@@ -20,6 +20,7 @@
 				   do_invalidatepage */
 #include "internal.h"
 
+#include <trace/events/filemap.h>
 
 /**
  * do_invalidatepage - invalidate part or all of a page

@@ -388,6 +389,7 @@ invalidate_complete_page2(struct address
 	BUG_ON(page_has_private(page));
 	__remove_from_page_cache(page);
 	spin_unlock_irq(&mapping->tree_lock);
+	trace_remove_from_page_cache(mapping, page->index);
 	mem_cgroup_uncharge_cache_page(page);
 	page_cache_release(page);	/* pagecache ref */
 	return 1;

Index: linux-2.6-tip/mm/vmscan.c
===================================================================

mm/vmscan.c +2 -0

@@ -48,6 +48,8 @@
 
 #include "internal.h"
 
+#include <trace/events/filemap.h>
+
 struct scan_control {
 	/* Incremented by the number of inactive pages that were scanned */
 	unsigned long nr_scanned;

Quoted 12 lines

include/trace/events/filemap.h new file +12 -0

+TRACE_EVENT(remove_from_page_cache,
+
+	TP_PROTO(struct address_space *mapping, pgoff_t offset),
+
+	TP_ARGS(mapping, offset),
+
+	TP_STRUCT__entry(
+		__field(dev_t, s_dev)
+		__field(ino_t, i_ino)
+		__field(pgoff_t, offset)
+		),
+

include/trace/events/filemap.h line 79

Quoted 10 lines

include/trace/events/filemap.h new file +10 -0

+	TP_fast_assign(
+		__entry->s_dev = mapping->host->i_sb->s_dev;
+		__entry->i_ino = mapping->host->i_ino;
+		__entry->offset = offset;
+		),
+
+	TP_printk("s_dev=%u:%u i_ino=%lu offset=%lu", MAJOR(__entry->s_dev),
+		MINOR(__entry->s_dev), __entry->i_ino, __entry->offset)
+);
+

The above qualify in converting to templates or DECLACE_TRACE_CLASS, and DEFINE_EVENT, That is, rename the above TRACE_EVENT into DECLARE_TRACE_CLASS, and then have the other one be a DEFINE_EVENT(). See the trace/event/sched.h for examples.

The TRACE_EVENT can add a bit of code, so use DECLARE_TRACE_CLASS when possible and it will save on the size overhead.

From the output, we can know some information like:

The scripts are implemented based on the trace stream scripting support. And the scripts implement the following.
- how many pagecaches each process has per each file
- how many pages are cached per each file
- how many pagecaches each process shares

To monitor pagecache usage per a process, run "pagecache-usage-record" to record perf data for "pagecache-usage.pl" and run "pagecache-usage-report" to display.

The below outputs show execution sample.

[file list]
device inode caches
--------------------------------

         253:0    1051413      130
         253:0    1051399        2
         253:0    1051414       44
         253:0    1051417      154

[process list]
o postmaster-2330
cached added removed indirect
device inode pages pages pages removed pages
----------------------------------------------------------------

         253:0    1051399        0        2        0             0
         253:0    1051417      154        0        0             0
         253:0    1051413      130        0        0             0
         253:0    1051414       44        0        0             0

----------------------------------------------------------------
total: 337 2 0 0

Quoted 1 line

From the output, we can know some information like:

- if "added pages" > "cached pages" on process list then It means repeating add/remove pagecache many times. => Bad case for pagecache usage

- if "added pages" <= "cached pages" on process list then It means no unnecessary I/O operations.
=> Good case for pagecache usage.

- if "caches" on file list >
sum "cached pages" per each file on process list then
It means there are unneccessary pagecaches in the memory.
=> Bad case for pagecache usage

Signed-off-by Keiichi Kii <[email protected]>

Cc Atsushi Tsuji <[email protected]>

---
 tools/perf/scripts/perl/bin/pagecache-usage-record |    7 
 tools/perf/scripts/perl/bin/pagecache-usage-report |    6 
 tools/perf/scripts/perl/pagecache-usage.pl         |  160 +++++++++++++++++++++
 3 files changed, 173 insertions(+)

Index: linux-2.6-tip/tools/perf/scripts/perl/bin/pagecache-usage-record
===================================================================

tools/perf/scripts/perl/bin/pagecache-usage-record new file +7 -0

@@ -0,0 +1,7 @@
+#!/bin/bash
+perf record -c 1 -f -a -M -R -e filemap:add_to_page_cache -e filemap:find_get_page -e filemap:remove_from_page_cache
+
+
+
+
+

Index: linux-2.6-tip/tools/perf/scripts/perl/bin/pagecache-usage-report
===================================================================

tools/perf/scripts/perl/bin/pagecache-usage-report new file +6 -0

@@ -0,0 +1,6 @@
+#!/bin/bash
+# description: pagecache usage per process
+perf trace -s ~/libexec/perf-core/scripts/perl/pagecache-usage.pl
+
+
+

Index: linux-2.6-tip/tools/perf/scripts/perl/pagecache-usage.pl
===================================================================

tools/perf/scripts/perl/pagecache-usage.pl new file +70 -0

+use lib "$ENV{'PERF_EXEC_PATH'}/scripts/perl/Perf-Trace-Util/lib";
+use lib "./Perf-Trace-Util/lib";
+use Perf::Trace::Core;
+use Perf::Trace::Context;
+use Perf::Trace::Util;
+use List::Util qw/sum/;
+my %files;
+my %processes;
+my %records;
+
+sub trace_end
+{
+	print_pagecache_usage_per_file();
+	print "\n";
+	print_pagecache_usage_per_process();
+	print_unhandled();
+}
+
+sub filemap::remove_from_page_cache
+{
+	my ($event_name, $context, $common_cpu, $common_secs, $common_nsecs,
+	    $common_pid, $common_comm,
+	    $s_dev, $i_ino, $offset) = @_;
+	my $f = \%{$files{$s_dev}{$i_ino}};
+	my $r = \%{$records{$common_comm."-".$common_pid}{$f}};
+
+	delete $$f{$offset};
+	$$r{inode} = $i_ino;
+	$$r{dev} = $s_dev;
+	if (exists $$r{added}{$offset}) {
+	    $$r{removed}++;
+	} else {
+	    $$r{indirect_removed}++;
+	}
+}
+
+sub filemap::add_to_page_cache
+{
+	my ($event_name, $context, $common_cpu, $common_secs, $common_nsecs,
+	    $common_pid, $common_comm,
+	    $s_dev, $i_ino, $offset) = @_;
+	my $f = \%{$files{$s_dev}{$i_ino}};
+	my $r = \%{$records{$common_comm."-".$common_pid}{$f}};
+
+	$$f{$offset}++;
+	$$r{added}{$offset}++;
+	$$r{inode} = $i_ino;
+	$$r{dev} = $s_dev;
+}
+
+sub filemap::find_get_page
+{
+	my ($event_name, $context, $common_cpu, $common_secs, $common_nsecs,
+	    $common_pid, $common_comm,
+	    $s_dev, $i_ino, $offset, $page) = @_;
+	my $f = \%{$files{$s_dev}{$i_ino}};
+	my $r = \%{$records{$common_comm."-".$common_pid}{$f}};
+
+	if ($page != 0) {
+	    $$f{$offset}++;
+	    $$r{cached}++;
+	    $$r{inode} = $i_ino;
+	    $$r{dev} = $s_dev;
+	}
+}
+
+my %unhandled;
+
+sub trace_unhandled
+{

tools/perf/scripts/perl/pagecache-usage.pl new file +61 -0

+	    return;
+	}
+
+	print "\nunhandled events:\n\n";
+
+	printf("%-40s  %10s\n", "event", "count");
+	printf("%-40s  %10s\n", "----------------------------------------",
+	       "-----------");
+
+	foreach my $event_name (keys %unhandled) {
+	    printf("%-40s  %10d\n", $event_name, $unhandled{$event_name});
+	}
+}
+
+sub minor
+{
+	my $dev = shift;
+	return $dev & ((1 << 20) - 1);
+}
+
+sub major
+{
+	my $dev = shift;
+	return $dev >> 20;
+}
+
+sub print_pagecache_usage_per_file
+{
+	print "[file list]\n";
+	printf("  %12s %10s %8s\n", "", "", "cached");
+	printf("  %12s %10s %8s\n", "device", "inode", "pages");
+	printf("  %s\n", '-' x 32);
+	while(my($dev, $file) = each(%files)) {
+	    while(my($inode, $r) = each(%$file)) {
+		my $count = values %$r;
+		next if $count == 0;
+		printf("  %12s %10d %8d\n",
+		       major($dev).":".minor($dev), $inode, $count);
+	    }
+	}
+}
+
+sub print_pagecache_usage_per_process
+{
+	print "[process list]\n";
+	while(my ($pid, $v) = each(%records)) {
+	    my ($sum_cached, $sum_added, $sum_removed, $sum_indirect_removed);
+
+	    print "o $pid\n";
+	    printf("  %12s %10s %8s %8s %8s %13s\n", "", "",
+		   "cached", "added", "removed", "indirect");
+	    printf("  %12s %10s %8s %8s %8s %13s\n", "device", "inode",
+		   "pages", "pages", "pages", "removed pages");
+	    printf("  %s\n", '-' x 64);
+	    while(my ($file, $r) = each(%$v)) {
+		my $added_num = List::Util::sum(values %{$$r{added}});
+		$sum_cached += $$r{cached};
+		$sum_added += $added_num;
+		$sum_removed += $$r{removed};
+		$sum_indirect_removed += $$r{indirect_removed};
+		printf("  %12s %10d %8d %8d %8d %13d\n",

Hi,

Quoted 6 lines · Keiichi KII

The scripts are implemented based on the trace stream scripting support. And the scripts implement the following.
- how many pagecaches each process has per each file
- how many pages are cached per each file
- how many pagecaches each process shares

Nice, it looks like a very useful script - I gave it a quick try and it seems to work well...

The only problem I see, nothing to do with your script and nothing you can do anything about at the moment, is that the record step generates a huge amount of data, which of course makes the event processing take awhile. A lot of it appears to be due to perf itself - being able to filter out the perf-generated events in the kernel would make a big difference, I think; you normally don't want to see those anyway...

BTW, I see that you did your first version in Python - not that you'd want to redo it again, but just FYI I now have working Python support that I'll be posting soon - I still have some small details to hammer out, but if you have any other scripts in the pipeline, in a couple days you'll be able to use Python instead if you want.

Quoted 3 lines

To monitor pagecache usage per a process, run "pagecache-usage-record" to record perf data for "pagecache-usage.pl" and run "pagecache-usage-report" to display.

Another way of course would be to use 'perf trace record/report' and the script name as shown by perf trace -l:

$ perf trace record pagecache-usage
$ perf trace report pagecache-usage

tools/perf/scripts/perl/pagecache-usage.pl line 1

Quoted 6 lines

Index: linux-2.6-tip/tools/perf/scripts/perl/pagecache-usage.pl
===================================================================

tools/perf/scripts/perl/pagecache-usage.pl new file +1 -0

@@ -0,0 +1,160 @@
+# perf trace event handlers, generated by perf trace -g perl

You might want to get rid of this and add a short description and your name, if you want to take credit for it. ;-)

Quoted 2 lines

tools/perf/scripts/perl/pagecache-usage.pl new file +2 -0

+# Licensed under the terms of the GNU GPL License version 2
+

tools/perf/scripts/perl/pagecache-usage.pl line 9

Quoted 6 lines

tools/perf/scripts/perl/pagecache-usage.pl new file +6 -0

+# The common_* event handler fields are the most useful fields common to
+# all events.  They don't necessarily correspond to the 'common_*' fields
+# in the format files.  Those fields not available as handler params can
+# be retrieved using Perl functions of the form common_*($context).
+# See Context.pm for the list of available functions.
+

You can get rid of this part too - it's just meant to be helpful information generated when starting a script.

Quoted 12 lines

tools/perf/scripts/perl/pagecache-usage.pl new file +12 -0

+my %unhandled;
+
+sub trace_unhandled
+{
+	my ($event_name, $context, $common_cpu, $common_secs, $common_nsecs,
+	    $common_pid, $common_comm) = @_;
+
+	$unhandled{$event_name}++;
+}
+
+sub print_unhandled
+{

tools/perf/scripts/perl/pagecache-usage.pl line 89

Quoted 2 lines

tools/perf/scripts/perl/pagecache-usage.pl new file +2 -0

+	if ((scalar keys %unhandled) == 0) {
+	    print "unhandled events nothing\n";

This is kind of distracting - it's not too useful to know that you don't have unhandled events, but if you do have some, it is useful to print those as you do below - it points out that some event type are being unnecessarily recorded or the script is being run on the wrong trace data.

Quoted 13 lines · Tom Zanussi

Hi,

Quoted 6 lines · Keiichi KII

The scripts are implemented based on the trace stream scripting support. And the scripts implement the following.
- how many pagecaches each process has per each file
- how many pages are cached per each file
- how many pagecaches each process shares

Nice, it looks like a very useful script - I gave it a quick try and it seems to work well...

Quoted 6 lines

The only problem I see, nothing to do with your script and nothing you can do anything about at the moment, is that the record step generates a huge amount of data, which of course makes the event processing take awhile. A lot of it appears to be due to perf itself - being able to filter out the perf-generated events in the kernel would make a big difference, I think; you normally don't want to see those anyway...

Yes, right. I don't want to process the data of perf itself. I will try to find any way to solve this problem.

Here's one way, using the tracepoint filters - it does make a big difference in this case.

Before (using the new -P option, which includes perf in the trace data):

root@tropicana:~# perf record -c 1 -f -a -M -R -e filemap:add_to_page_cache -e filemap:find_get_page -e filemap:remove_from_page_cache -P sleep 5
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 71.201 MB perf.data (~3110815 samples) ]

After (filters out events generated by perf):

root@tropicana:~# perf record -c 1 -f -a -M -R -e filemap:add_to_page_cache -e filemap:find_get_page -e filemap:remove_from_page_cache sleep 5
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.309 MB perf.data (~13479 samples) ]

Here's one way, using the tracepoint filters - it does make a big difference in this case.

Before (using the new -P option, which includes perf in the trace data):

root@tropicana:~# perf record -c 1 -f -a -M -R -e filemap:add_to_page_cache -e filemap:find_get_page -e filemap:remove_from_page_cache -P sleep 5
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 71.201 MB perf.data (~3110815 samples) ]

After (filters out events generated by perf):

root@tropicana:~# perf record -c 1 -f -a -M -R -e filemap:add_to_page_cache -e filemap:find_get_page -e filemap:remove_from_page_cache sleep 5
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.309 MB perf.data (~13479 samples) ]

Tom

[PATCH] perf record: filter out perf process tracepoint events

The perf process itself can generate a lot of trace data, which most of the time isn't of any interest. This patch adds a predicate to the kernel tracepoint filter of each recorded event type which effectively screens out any event generated by perf.

Assuming the common case would be to ignore perf, this makes it the default; the old behavior can be selected by using 'perf record -P'.

Quoted 9 lines

[PATCH] perf record: filter out perf process tracepoint events

The perf process itself can generate a lot of trace data, which most of the time isn't of any interest. This patch adds a predicate to the kernel tracepoint filter of each recorded event type which effectively screens out any event generated by perf.

Assuming the common case would be to ignore perf, this makes it the default; the old behavior can be selected by using 'perf record -P'.

I think filtering out perf from the instrumentation is a very desirable features.

But I see two drawbacks with this patch.
First of all, we want to keep perf as a part of the instrumentation as a default behaviour I think, as it is a true part of the system wide load. So I would rather suggest to keep it as a default and have an exclude_perf option instead of include_perf.