From: Paolo Molaro Date: Wed, 1 Dec 2010 14:13:49 +0000 (+0100) Subject: Log profiler: added test suite. X-Git-Url: http://wien.tomnetworks.com/gitweb/?a=commitdiff_plain;h=0dd2944adc5d1f491d23edb0d3c3c97044bc7fcb;p=mono.git Log profiler: added test suite. --- diff --git a/mono/profiler/Makefile.am b/mono/profiler/Makefile.am index 9ca3c20d076..b6e5cfe4b44 100644 --- a/mono/profiler/Makefile.am +++ b/mono/profiler/Makefile.am @@ -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 index 00000000000..a26ec51d494 --- /dev/null +++ b/mono/profiler/ptestrunner.pl @@ -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 index 00000000000..3eb3509a7bb --- /dev/null +++ b/mono/profiler/test-alloc.cs @@ -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 index 00000000000..76e1a5b2b54 --- /dev/null +++ b/mono/profiler/test-busy.cs @@ -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 index 00000000000..b1d880ddf3b --- /dev/null +++ b/mono/profiler/test-excleave.cs @@ -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 index 00000000000..f0d537f7642 --- /dev/null +++ b/mono/profiler/test-heapshot.cs @@ -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 index 00000000000..8e77b2f0a5e --- /dev/null +++ b/mono/profiler/test-monitor.cs @@ -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 index 00000000000..ee1d0e1af43 --- /dev/null +++ b/mono/profiler/test-traces.cs @@ -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 { + } + } + } +} +