Log profiler: added test suite.
authorPaolo Molaro <lupus@oddwiz.org>
Wed, 1 Dec 2010 14:13:49 +0000 (15:13 +0100)
committerPaolo Molaro <lupus@oddwiz.org>
Wed, 1 Dec 2010 14:16:23 +0000 (15:16 +0100)
mono/profiler/Makefile.am
mono/profiler/ptestrunner.pl [new file with mode: 0755]
mono/profiler/test-alloc.cs [new file with mode: 0644]
mono/profiler/test-busy.cs [new file with mode: 0644]
mono/profiler/test-excleave.cs [new file with mode: 0644]
mono/profiler/test-heapshot.cs [new file with mode: 0644]
mono/profiler/test-monitor.cs [new file with mode: 0644]
mono/profiler/test-traces.cs [new file with mode: 0644]

index 9ca3c20d076b5a6ad1cd36b9f8723611f551c1d0..b6e5cfe4b442d297f07383683e87a80b58d57d82 100644 (file)
@@ -39,5 +39,21 @@ libmono_profiler_log_la_LIBADD = $(top_builddir)/mono/mini/libmono-$(API_VER).la
 mprof_report_SOURCES = decode.c
 mprof_report_LDADD = $(Z_LIBS)
 
-EXTRA_DIST=utils.c utils.h proflog.h log-profiler.txt perf_event.h
+PLOG_TESTS_SRC=test-alloc.cs test-busy.cs test-monitor.cs test-excleave.cs \
+       test-heapshot.cs test-traces.cs
+PLOG_TESTS=$(PLOG_TESTS_SRC:.cs=.exe)
+
+MCS = $(RUNTIME) $(mcs_topdir)/class/lib/net_2_0/gmcs.exe -unsafe -nowarn:0162 -nowarn:0168 -nowarn:0219 -debug
+
+%.exe: %.cs
+       $(MCS) -out:$@ $<
+
+testlog: $(PLOG_TESTS)
+       perl $(srcdir)/ptestrunner.pl $(top_builddir)
+
+check-local: testlog
+
+EXTRA_DIST=utils.c utils.h proflog.h log-profiler.txt perf_event.h \
+       $(PLOG_TESTS_SRC) ptestrunner.pl
+
 
diff --git a/mono/profiler/ptestrunner.pl b/mono/profiler/ptestrunner.pl
new file mode 100755 (executable)
index 0000000..a26ec51
--- /dev/null
@@ -0,0 +1,395 @@
+#!/usr/bin/perl -w
+
+use strict;
+
+# run the log profiler test suite
+
+my $builddir = shift || die "Usage: ptestrunner.pl mono_build_dir\n";
+my @errors = ();
+my $total_errors = 0;
+my $report;
+
+my $profbuilddir = $builddir . "/mono/profiler";
+my $minibuilddir = $builddir . "/mono/mini";
+
+# Setup the execution environment
+# for the profiler module
+append_path ("LD_LIBRARY_PATH", $profbuilddir . "/.libs");
+append_path ("DYLD_LIBRARY_PATH", $profbuilddir . "/.libs");
+# for mprof-report
+append_path ("PATH", $profbuilddir);
+
+# first a basic test
+$report = run_test ("test-alloc.exe");
+check_report_basics ($report);
+check_report_calls ($report, "T:Main (string[])" => 1);
+check_report_allocation ($report, "System.Object" => 1000000);
+report_errors ();
+# test additional named threads and method calls
+$report = run_test ("test-busy.exe");
+check_report_basics ($report);
+check_report_calls ($report, "T:Main (string[])" => 1);
+check_report_threads ($report, "BusyHelper");
+check_report_calls ($report, "T:test ()" => 10, "T:test3 ()" => 10, "T:test2 ()" => 1);
+report_errors ();
+# test with the sampling profiler
+$report = run_test ("test-busy.exe", "report,sample");
+check_report_basics ($report);
+check_report_threads ($report, "BusyHelper");
+# at least 40% of the samples should hit each of the two busy methods
+check_report_samples ($report, "T:test ()" => 40, "T:test3 ()" => 40);
+report_errors ();
+# test lock events
+$report = run_test ("test-monitor.exe");
+check_report_basics ($report);
+check_report_calls ($report, "T:Main (string[])" => 1);
+# we hope for at least some contention, this is not entirely reliable
+check_report_locks ($report, 1, 1);
+report_errors ();
+# test exceptions
+$report = run_test ("test-excleave.exe");
+check_report_basics ($report);
+check_report_calls ($report, "T:Main (string[])" => 1, "T:throw_ex ()" => 1000);
+check_report_exceptions ($report, 1000, 1000, 1000);
+report_errors ();
+# test heapshot
+$report = run_test_sgen ("test-heapshot.exe", "report,heapshot");
+if ($report ne "missing binary") {
+       check_report_basics ($report);
+       check_report_heapshot ($report, 0, {"T" => 5000});
+       check_report_heapshot ($report, 1, {"T" => 5023});
+       report_errors ();
+}
+# test heapshot traces
+$report = run_test_sgen ("test-heapshot.exe", "heapshot,output=-traces.mlpd", "--traces traces.mlpd");
+if ($report ne "missing binary") {
+       check_report_basics ($report);
+       check_report_heapshot ($report, 0, {"T" => 5000});
+       check_report_heapshot ($report, 1, {"T" => 5023});
+       check_heapshot_traces ($report, 0,
+               T => [4999, "T"]
+       );
+       check_heapshot_traces ($report, 1,
+               T => [5022, "T"]
+       );
+       report_errors ();
+}
+# test traces
+$report = run_test ("test-traces.exe", "output=-traces.mlpd", "--traces traces.mlpd");
+check_report_basics ($report);
+check_call_traces ($report,
+       "T:level3 (int)" => [2020, "T:Main (string[])"],
+       "T:level2 (int)" => [2020, "T:Main (string[])", "T:level3 (int)"],
+       "T:level1 (int)" => [2020, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)"],
+       "T:level0 (int)" => [2020, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)", "T:level1 (int)"]
+);
+check_exception_traces ($report,
+       [1010, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)", "T:level1 (int)", "T:level0 (int)"]
+);
+check_alloc_traces ($report,
+       T => [1010, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)", "T:level1 (int)", "T:level0 (int)"]
+);
+report_errors ();
+# test traces without enter/leave events
+$report = run_test ("test-traces.exe", "nocalls,output=-traces.mlpd", "--traces traces.mlpd");
+check_report_basics ($report);
+# this has been broken recently
+check_exception_traces ($report,
+       [1010, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)", "T:level1 (int)", "T:level0 (int)"]
+);
+check_alloc_traces ($report,
+       T => [1010, "T:Main (string[])", "T:level3 (int)", "T:level2 (int)", "T:level1 (int)", "T:level0 (int)"]
+);
+report_errors ();
+
+exit ($total_errors? 1: 0);
+
+# utility functions
+sub append_path {
+       my $var = shift;
+       my $value = shift;
+       if (exists $ENV {$var}) {
+               $ENV {$var} = $value . ";" . $ENV {$var};
+       } else {
+               $ENV {$var} = $value;
+       }
+}
+
+sub run_test
+{
+       return run_test_bin ("$minibuilddir/mono", @_);
+}
+
+sub run_test_sgen
+{
+       return run_test_bin ("$minibuilddir/mono-sgen", @_);
+}
+
+sub run_test_bin
+{
+       my $bin = shift;
+       my $test_name = shift;
+       my $option = shift || "report";
+       my $roptions = shift;
+       #clear the errors
+       @errors = ();
+       $total_errors = 0;
+       print "Checking $test_name with $option ...";
+       unless (-x $bin) {
+               print "missing $bin, skipped.\n";
+               return "missing binary";
+       }
+       my $report = `$bin --profile=log:$option $test_name`;
+       print "\n";
+       if (defined $roptions) {
+               return `$profbuilddir/mprof-report $roptions`;
+       }
+       return $report;
+}
+
+sub report_errors
+{
+       foreach my $e (@errors) {
+               print "Error: $e\n";
+               $total_errors++;
+       }
+       print "Total errors: $total_errors\n" if $total_errors;
+       #print $report;
+}
+
+sub get_delim_data
+{
+       my $report = shift;
+       my $start = shift;
+       my $end = shift;
+       my $section = "";
+       my $insection = 0;
+       foreach (split (/\n/, $report)) {
+               if ($insection) {
+                       #print "matching end $end vs $_\n";
+                       last if /$end/;
+                       $section .= $_;
+                       $section .= "\n";
+               } else {
+                       #print "matching $start vs $_\n";
+                       $insection = 1 if (/$start/);
+               }
+       }
+       return $section;
+}
+
+sub get_section
+{
+       my $report = shift;
+       my $name = shift;
+       return get_delim_data ($report, "^\Q$name\E", "^\\w.*summary");
+}
+
+sub get_heap_shot
+{
+       my $section = shift;
+       my $num = shift;
+       return get_delim_data ($report, "Heap shot $num at", "^\$");
+}
+
+sub check_report_basics
+{
+       my $report = shift;
+       check_report_threads ($report, "Finalizer", "Main");
+       check_report_metadata ($report, 2);
+       check_report_jit ($report);
+}
+
+sub check_report_metadata
+{
+       my $report = shift;
+       my $num = shift;
+       my $section = get_section ($report, "Metadata");
+       push @errors, "Wrong loaded images $num." unless $section =~ /Loaded images:\s$num/s;
+}
+
+sub check_report_calls
+{
+       my $report = shift;
+       my %calls = @_;
+       my $section = get_section ($report, "Method");
+       foreach my $method (keys %calls) {
+               push @errors, "Wrong calls to $method." unless $section =~ /\d+\s+\d+\s+($calls{$method})\s+\Q$method\E/s;
+       }
+}
+
+sub check_call_traces
+{
+       my $report = shift;
+       my %calls = @_;
+       my $section = get_section ($report, "Method");
+       foreach my $method (keys %calls) {
+               my @desc = @{$calls{$method}};
+               my $num = shift @desc;
+               my $trace = get_delim_data ($section, "\\s+\\d+\\s+\\d+\\s+\\d+\\s+\Q$method\E", "^\\s*\\d+\\s+\\d");
+               if ($trace =~ s/^\s+(\d+)\s+calls from:$//m) {
+                       my $num_calls = $1;
+                       push @errors, "Wrong calls to $method." unless $num_calls == $num;
+                       my @frames = map {s/^\s+(.*)\s*$/$1/; $_} split (/\n/, $trace);
+                       while (@desc) {
+                               my $dm = pop @desc;
+                               my $fm = pop @frames;
+                               push @errors, "Wrong frame $fm to $method." unless $dm eq $fm;
+                       }
+               } else {
+                       push @errors, "No num calls for $method.";
+               }
+       }
+}
+
+sub check_alloc_traces
+{
+       my $report = shift;
+       my %types = @_;
+       my $section = get_section ($report, "Allocation");
+       foreach my $type (keys %types) {
+               my @desc = @{$types{$type}};
+               my $num = shift @desc;
+               my $trace = get_delim_data ($section, "\\s+\\d+\\s+\\d+\\s+\\d+\\s+\Q$type\E", "^\\s*\\d+\\s+\\d");
+               if ($trace =~ s/^\s+(\d+)\s+bytes from:$//m) {
+                       #my $num_calls = $1;
+                       #push @errors, "Wrong calls to $method." unless $num_calls == $num;
+                       my @frames = map {s/^\s+(.*)\s*$/$1/; $_} split (/\n/, $trace);
+                       while (@desc) {
+                               my $dm = pop @desc;
+                               my $fm = pop @frames;
+                               $fm = pop @frames if $fm =~ /wrapper/;
+                               push @errors, "Wrong frame $fm for alloc of $type." unless $dm eq $fm;
+                       }
+               } else {
+                       push @errors, "No alloc frames for $type.";
+               }
+       }
+}
+
+sub check_heapshot_traces
+{
+       my $report = shift;
+       my $hshot = shift;
+       my %types = @_;
+       my $section = get_section ($report, "Heap");
+       $section = get_heap_shot ($section, $hshot);
+       foreach my $type (keys %types) {
+               my @desc = @{$types{$type}};
+               my $num = shift @desc;
+               my $rtype = shift @desc;
+               my $trace = get_delim_data ($section, "\\s+\\d+\\s+\\d+\\s+\\d+\\s+\Q$type\E", "^\\s*\\d+\\s+\\d");
+               if ($trace =~ s/^\s+(\d+)\s+references from:\s+\Q$rtype\E$//m) {
+                       my $num_refs = $1;
+                       push @errors, "Wrong num refs to $type from $rtype." unless $num_refs == $num;
+               } else {
+                       push @errors, "No refs to $type from $rtype.";
+               }
+       }
+}
+
+sub check_exception_traces
+{
+       my $report = shift;
+       my @etraces = @_;
+       my $section = get_section ($report, "Exception");
+       foreach my $d (@etraces) {
+               my @desc = @{$d};
+               my $num = shift @desc;
+               my $trace = get_delim_data ($section, "^\\s+$num\\s+throws from:\$", "^\\s+(\\d+|Executed)");
+               if (length ($trace)) {
+                       my @frames = map {s/^\s+(.*)\s*$/$1/; $_} split (/\n/, $trace);
+                       while (@desc) {
+                               my $dm = pop @desc;
+                               my $fm = pop @frames;
+                               push @errors, "Wrong frame '$fm' in exceptions (should be '$dm')." unless $dm eq $fm;
+                       }
+               } else {
+                       push @errors, "No exceptions or incorrect number.";
+               }
+       }
+}
+
+sub check_report_samples
+{
+       my $report = shift;
+       my %calls = @_;
+       my $section = get_section ($report, "Statistical");
+       foreach my $method (keys %calls) {
+               push @errors, "Wrong samples for $method." unless ($section =~ /\d+\s+(\d+\.\d+)\s+\Q$method\E/s && $1 >= $calls{$method});
+       }
+}
+
+sub check_report_allocation
+{
+       my $report = shift;
+       my %allocs = @_;
+       my $section = get_section ($report, "Allocation");
+       foreach my $type (keys %allocs) {
+               if ($section =~ /\d+\s+(\d+)\s+\d+\s+\Q$type\E$/m) {
+                       push @errors, "Wrong allocs for type $type." unless $1 >= $allocs{$type};
+               } else {
+                       push @errors, "No allocs for type $type.";
+               }
+       }
+}
+
+sub check_report_heapshot
+{
+       my $report = shift;
+       my $hshot = shift;
+       my $typemap = shift;
+       my %allocs = %{$typemap};
+       my $section = get_section ($report, "Heap");
+       $section = get_heap_shot ($section, $hshot);
+       foreach my $type (keys %allocs) {
+               if ($section =~ /\d+\s+(\d+)\s+\d+\s+\Q$type\E(\s+\(bytes.*\))?$/m) {
+                       push @errors, "Wrong heapshot for type $type." unless $1 >= $allocs{$type};
+               } else {
+                       push @errors, "No heapshot for type $type.";
+               }
+       }
+}
+
+sub check_report_jit
+{
+       my $report = shift;
+       my $min_methods = shift || 1;
+       my $min_code = shift || 16;
+       my $section = get_section ($report, "JIT");
+       push @errors, "Not enough compiled method." unless (($section =~ /Compiled methods:\s(\d+)/s) && ($1 >= $min_methods));
+       push @errors, "Not enough compiled code." unless (($section =~ /Generated code size:\s(\d+)/s) && ($1 >= $min_code));
+}
+
+sub check_report_locks
+{
+       my $report = shift;
+       my $contentions = shift;
+       my $acquired = shift;
+       my $section = get_section ($report, "Monitor");
+       push @errors, "Not enough contentions." unless (($section =~ /Lock contentions:\s(\d+)/s) && ($1 >= $contentions));
+       push @errors, "Not enough acquired locks." unless (($section =~ /Lock acquired:\s(\d+)/s) && ($1 >= $acquired));
+}
+
+sub check_report_exceptions
+{
+       my $report = shift;
+       my $throws = shift;
+       my $catches = shift;
+       my $finallies = shift;
+       my $section = get_section ($report, "Exception");
+       push @errors, "Not enough throws." unless (($section =~ /Throws:\s(\d+)/s) && ($1 >= $throws));
+       push @errors, "Not enough catches." unless (($section =~ /Executed catch clauses:\s(\d+)/s) && ($1 >= $catches));
+       push @errors, "Not enough finallies." unless (($section =~ /Executed finally clauses:\s(\d+)/s) && ($1 >= $finallies));
+}
+
+sub check_report_threads
+{
+       my $report = shift;
+       my @threads = @_;
+       my $section = get_section ($report, "Thread");
+       foreach my $tname (@threads) {
+               push @errors, "Missing thread $tname." unless $section =~ /Thread:.*name:\s"\Q$tname\E"/s;
+       }
+}
+
diff --git a/mono/profiler/test-alloc.cs b/mono/profiler/test-alloc.cs
new file mode 100644 (file)
index 0000000..3eb3509
--- /dev/null
@@ -0,0 +1,14 @@
+using System;
+
+class T {
+
+       static int count = 1000000;
+       static void Main (string[] args) {
+               if (args.Length > 0)
+                       count = int.Parse (args [0]);
+               for (int i = 0; i < count; ++i) {
+                       object o = new object ();
+               }
+       }
+}
+
diff --git a/mono/profiler/test-busy.cs b/mono/profiler/test-busy.cs
new file mode 100644 (file)
index 0000000..76e1a5b
--- /dev/null
@@ -0,0 +1,45 @@
+using System.Threading;
+
+class T {
+
+       static int count = 10;
+       static void test2 () {
+               //Thread.Sleep (500);
+               //return;
+               int v = 0;
+               for (int i = 0; i < count; ++i) {
+                       v += test3 ();
+               }
+       }
+
+       static int test3 () {
+               int v = 33;
+               for (int i = 0; i < 10000000; ++i) {
+                       v += i * 1000;
+                       v /=  (1 + i) * 2;
+               }
+               return v > 0? 0: 1;
+       }
+       static int test () {
+               int v = 33;
+               for (int i = 0; i < 10000000; ++i) {
+                       v += i * 1000;
+                       v /=  (1 + i) * 2;
+               }
+               return v > 0? 0: 1;
+       }
+       static int Main (string[] args) {
+               if (args.Length > 0)
+                       count = int.Parse (args [0]);
+               Thread t = new Thread (test2);
+               t.Name = "BusyHelper";
+               t.Start ();
+               int v = 0;
+               for (int i = 0; i < count; ++i) {
+                       v += test ();
+               }
+               t.Join ();
+               return v > 0? 0: 1;
+       }
+}
+
diff --git a/mono/profiler/test-excleave.cs b/mono/profiler/test-excleave.cs
new file mode 100644 (file)
index 0000000..b1d880d
--- /dev/null
@@ -0,0 +1,24 @@
+using System;
+
+class T {
+
+       static int f = 0;
+       static int c = 0;
+       static void throw_ex () {
+               try {
+                       throw new Exception ();
+               } finally {
+                       f++;
+               }
+       }
+       static void Main (string[] args) {
+               for (int i = 0; i < 1000; ++i) {
+                       try {
+                               throw_ex ();
+                       } catch {
+                               c++;
+                       }
+               }
+       }
+}
+
diff --git a/mono/profiler/test-heapshot.cs b/mono/profiler/test-heapshot.cs
new file mode 100644 (file)
index 0000000..f0d537f
--- /dev/null
@@ -0,0 +1,25 @@
+using System;
+
+class T {
+       T next;
+
+       static void Main (string[] args) {
+               int count = 5000;
+               T list = null;
+               for (int i = 0; i < count; ++i) {
+                       T n = new T ();
+                       n.next = list;
+                       list = n;
+               }
+               // trigger a heapshot
+               GC.Collect ();
+               for (int i = 0; i < 23; ++i) {
+                       T n = new T ();
+                       n.next = list;
+                       list = n;
+               }
+               // trigger another heapshot
+               GC.Collect ();
+       }
+}
+
diff --git a/mono/profiler/test-monitor.cs b/mono/profiler/test-monitor.cs
new file mode 100644 (file)
index 0000000..8e77b2f
--- /dev/null
@@ -0,0 +1,24 @@
+using System;
+using System.Threading;
+
+class T {
+
+       static object mutex = new object ();
+       static int count = 1000000;
+
+       static void dolock ()
+       {
+               for (int i = 0; i < count; ++i) {
+                       lock (mutex) {
+                       }
+               }
+       }
+
+       static void Main (string[] args) {
+               Thread t = new Thread (dolock);
+               t.Start ();
+               dolock ();
+               t.Join ();
+       }
+}
+
diff --git a/mono/profiler/test-traces.cs b/mono/profiler/test-traces.cs
new file mode 100644 (file)
index 0000000..ee1d0e1
--- /dev/null
@@ -0,0 +1,44 @@
+using System;
+using System.Runtime.CompilerServices;
+
+class T {
+
+       static object o = null;
+
+       [MethodImpl (MethodImplOptions.NoInlining)]
+       static void level3 (int op) {
+               level2 (op);
+       }
+
+       [MethodImpl (MethodImplOptions.NoInlining)]
+       static void level2 (int op) {
+               level1 (op);
+       }
+
+       [MethodImpl (MethodImplOptions.NoInlining)]
+       static void level1 (int op) {
+               level0 (op);
+       }
+
+       [MethodImpl (MethodImplOptions.NoInlining)]
+       static void level0 (int op) {
+               switch (op) {
+               case 0: o = new T (); break;
+               case 1: throw new Exception (); break;
+               }
+       }
+
+       static void Main (string[] args) {
+               int count = 1010;
+               for (int i = 0; i < count; ++i) {
+                       level3 (0);
+               }
+               for (int i = 0; i < count; ++i) {
+                       try {
+                               level3 (1);
+                       } catch {
+                       }
+               }
+       }
+}
+