Profile of testnewboardincnply

Filename	/homes/dcw/src/perl/coloroids_solver/testnewboardincnply
Statements	Executed 29 statements in 7.64ms

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1	1	1	5.91ms	9.00ms	main::::BEGIN@10 main::BEGIN@10
1	1	1	3.94ms	4.43ms	main::::BEGIN@9 main::BEGIN@9
1	1	1	3.61ms	37.3ms	main::::BEGIN@12 main::BEGIN@12
1	1	1	2.67ms	2.95ms	main::::BEGIN@13 main::BEGIN@13
1	1	1	1.87ms	2.12ms	main::::BEGIN@14.7 main::BEGIN@14.7
1	1	1	998µs	9.46ms	main::::BEGIN@8 main::BEGIN@8
1	1	1	971µs	1.06ms	main::::BEGIN@7.1 main::BEGIN@7.1
1	1	1	43µs	43µs	main::::BEGIN@7 main::BEGIN@7
14	1	1	13µs	13µs	mro::::method_changed_in mro::method_changed_in (xsub)
17	1	1	9µs	9µs	Internals::::SvREADONLYInternals::SvREADONLY (xsub)
1	1	1	4µs	4µs	version::::(bool version::(bool (xsub)
1	1	1	4µs	4µs	version::::(cmp version::(cmp (xsub)

Call graph for these subroutines as a Graphviz dot language file.

Line	State ments	Time on line	Calls	Time in subs	Code
1					#!/usr/bin/perl
2
3					#
4					# test NewIncNPlyPicker, NewSolver and NewBoard...
5					#
6
7	4	1.07ms	3	1.20ms	# spent 43µs within main::BEGIN@7 which was called: # once (43µs+0s) by main::RUNTIME at line 7 # spent 1.06ms (971µs+93µs) within main::BEGIN@7.1 which was called: # once (971µs+93µs) by main::RUNTIME at line 7 use v5.12; # spent 1.06ms making 1 call to main::BEGIN@7.1 # spent 93µs making 1 call to feature::import # spent 43µs making 1 call to main::BEGIN@7
8	2	144µs	2	9.57ms	# spent 9.46ms (998µs+8.46) within main::BEGIN@8 which was called: # once (998µs+8.46ms) by main::RUNTIME at line 8 use Function::Parameters; # spent 9.46ms making 1 call to main::BEGIN@8 # spent 110µs making 1 call to Function::Parameters::import
9	2	90µs	2	4.45ms	# spent 4.43ms (3.94+492µs) within main::BEGIN@9 which was called: # once (3.94ms+492µs) by main::RUNTIME at line 9 use Data::Dumper; # spent 4.43ms making 1 call to main::BEGIN@9 # spent 18µs making 1 call to Exporter::import
10	2	85µs	2	10.2ms	# spent 9.00ms (5.91+3.09) within main::BEGIN@10 which was called: # once (5.91ms+3.09ms) by main::RUNTIME at line 10 use Getopt::Long; # spent 9.00ms making 1 call to main::BEGIN@10 # spent 1.19ms making 1 call to Getopt::Long::import
11
12	2	2.72ms	2	37.3ms	# spent 37.3ms (3.61+33.7) within main::BEGIN@12 which was called: # once (3.61ms+33.7ms) by main::RUNTIME at line 12 use NewBoard; # spent 37.3ms making 1 call to main::BEGIN@12 # spent 14µs making 1 call to Exporter::import
13	2	1.67ms	1	2.95ms	# spent 2.95ms (2.67+287µs) within main::BEGIN@13 which was called: # once (2.67ms+287µs) by main::RUNTIME at line 13 use NewIncNPlyPicker; # spent 2.95ms making 1 call to main::BEGIN@13
14	2	1.76ms	1	2.12ms	# spent 2.12ms (1.87+242µs) within main::BEGIN@14.7 which was called: # once (1.87ms+242µs) by main::RUNTIME at line 14 use NewSolveGame; # spent 2.12ms making 1 call to main::BEGIN@14.7
15
16	1	26µs	1	19µs	print "running: $0 @ARGV\n"; # spent 19µs making 1 call to main::CORE:print
17
18	1	400ns			my $nply;
19	1	300ns			my $seed = 1;
20	1	2µs	1	4µs	my $result = GetOptions( # spent 4µs making 1 call to Getopt::Long::GetOptions
21					"nply=i" => \$nply,
22					"seed=i" => \$seed,
23					);
24
25	1	100ns			die "Usage: testnewboardincnply [--nply N] [--seed S] [filename\|W H colours]\n"
26					unless $result;
27
28	1	200ns			srand( $seed );
29
30	1	0s			my $board;
31	1	400ns			if( @ARGV < 2 )
32					{
33	1	400ns			my $filename = shift // "boards/4x4";
34	1	2µs	1	7.36ms	$board = NewBoard->newfromfile( $filename ); # spent 7.36ms making 1 call to NewBoard::newfromfile
35					}
36					else
37					{
38					my( $w, $h, @colours ) = @ARGV;
39					$board = NewBoard->newrandom( $w, $h, @colours );
40					}
41
42	1	2µs	1	2µs	set_nply( $nply ) if $nply; # spent 2µs making 1 call to main::set_nply
43
44					#print "initial board =\n$board\n";
45	1	2µs	1	58.1s	my $nmoves = solve_game( $board, \&incnply_pick_best, \&incnply_makenm1ply ); # spent 58.1s making 1 call to main::solve_game
46	1	57µs	1	6µs	print "\nsolved in $nmoves moves\n"; # spent 6µs making 1 call to main::CORE:print

					# spent 9µs within Internals::SvREADONLY which was called 17 times, avg 547ns/call: # 17 times (9µs+0s) by constant::import at line 132 of constant.pm, avg 547ns/call sub Internals::SvREADONLY; # xsub
					# spent 13µs within mro::method_changed_in which was called 14 times, avg 929ns/call: # 14 times (13µs+0s) by constant::import at line 147 of constant.pm, avg 929ns/call sub mro::method_changed_in; # xsub
					# spent 4µs within version::(bool which was called: # once (4µs+0s) by DynaLoader::BEGIN@21 at line 57 of Config.pm sub version::(bool; # xsub
					# spent 4µs within version::(cmp which was called: # once (4µs+0s) by DynaLoader::BEGIN@21 at line 60 of Config.pm sub version::(cmp; # xsub