Profile of conv.pl

Filename	/home/gmc/projects/marcpm/marc-xml/conv.pl
Statements	Executed 20012 statements in 372ms

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
5005	2	1	139ms	139ms	main::::CORE:print main::CORE:print (opcode)
30000	6	1	78.2ms	78.2ms	UNIVERSAL::::can UNIVERSAL::can (xsub)
1	1	1	2.87ms	140ms	main::::BEGIN@3 main::BEGIN@3
1	1	1	1.03ms	1.16ms	main::::BEGIN@5 main::BEGIN@5
1	1	1	288µs	288µs	MARC::Field::::BEGIN@66MARC::Field::BEGIN@66
40	1	1	131µs	131µs	mro::::method_changed_in mro::method_changed_in (xsub)
40	1	1	90µs	90µs	Internals::::SvREADONLY Internals::SvREADONLY (xsub)
9	1	1	35µs	35µs	UNIVERSAL::::isa UNIVERSAL::isa (xsub)
1	1	1	20µs	61µs	main::::BEGIN@4 main::BEGIN@4
1	1	1	14µs	14µs	main::::CORE:binmode main::CORE:binmode (opcode)
1	1	1	10µs	10µs	version::::(cmp version::(cmp (xsub)
1	1	1	9µs	9µs	version::::(bool version::(bool (xsub)
0	0	0	0s	0s	main::::RUNTIME main::RUNTIME

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

Line	State ments	Time on line	Calls	Time in subs	Code
0			2	351µs	Profile data that couldn't be associated with a specific line: # spent 288µs making 1 call to MARC::Field::BEGIN@66 # spent 63µs making 1 call to MARC::File::XML::DESTROY
1	1	21µs			#!/usr/bin/perl
2
3	3	174µs	2	140ms	# spent 140ms (2.87+137) within main::BEGIN@3 which was called: # once (2.87ms+137ms) by main::RUNTIME at line 3 use MARC::File::XML (BinaryEncoding => 'utf8'); # spent 140ms making 1 call to main::BEGIN@3 # spent 10µs making 1 call to MARC::File::XML::import
4	3	41µs	2	102µs	# spent 61µs (20+41) within main::BEGIN@4 which was called: # once (20µs+41µs) by main::RUNTIME at line 4 use MARC::Record; # spent 61µs making 1 call to main::BEGIN@4 # spent 41µs making 1 call to Exporter::import
5	3	598µs	1	1.16ms	# spent 1.16ms (1.03+129µs) within main::BEGIN@5 which was called: # once (1.03ms+129µs) by main::RUNTIME at line 5 use MARC::Batch; # spent 1.16ms making 1 call to main::BEGIN@5
6
7	1	23µs	1	14µs	binmode STDOUT, ':utf8'; # spent 14µs making 1 call to main::CORE:binmode
8
9	1	6µs	1	64µs	my $batch = MARC::Batch->new('XML', $ARGV[0]); # spent 64µs making 1 call to MARC::Batch::new
10	1	157ms	5000	91.0s	while (my $record = $batch->next) { # spent 91.0s making 5000 calls to MARC::Batch::next, avg 18.2ms/call
11	5000	6.28ms			$i++;
12	5000	187ms	10000	8.12s	print $record->as_usmarc(); # spent 7.98s making 5000 calls to MARC::Record::as_usmarc, avg 1.60ms/call # spent 138ms making 5000 calls to main::CORE:print, avg 28µs/call
13	5000	13.9ms	5	1.00ms	if ($i % 1000 == 0) { # spent 1.00ms making 5 calls to main::CORE:print, avg 201µs/call
14					print STDERR "$i ", scalar(localtime), "\n";
15					}
16	5000	6.75ms			last if $i == 5000;
17					}
18
- -

					# spent 90µs within Internals::SvREADONLY which was called 40 times, avg 2µs/call: # 40 times (90µs+0s) by constant::import at line 111 of constant.pm, avg 2µs/call sub Internals::SvREADONLY; # xsub
					# spent 78.2ms within UNIVERSAL::can which was called 30000 times, avg 3µs/call: # 5000 times (14.4ms+0s) by XML::SAX::Base::end_document at line 1428 of XML/SAX/Base.pm, avg 3µs/call # 5000 times (14.2ms+0s) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 3µs/call # 5000 times (12.8ms+0s) by XML::SAX::Base::start_document at line 1244 of XML/SAX/Base.pm, avg 3µs/call # 5000 times (12.6ms+0s) by XML::SAX::Base::start_element at line 278 of XML/SAX/Base.pm, avg 3µs/call # 5000 times (12.1ms+0s) by XML::SAX::Base::end_element at line 2187 of XML/SAX/Base.pm, avg 2µs/call # 5000 times (12.0ms+0s) by XML::SAX::Base::characters at line 186 of XML/SAX/Base.pm, avg 2µs/call sub UNIVERSAL::can; # xsub
					# spent 35µs within UNIVERSAL::isa which was called 9 times, avg 4µs/call: # 9 times (35µs+0s) by base::import at line 80 of base.pm, avg 4µs/call sub UNIVERSAL::isa; # xsub
					# spent 14µs within main::CORE:binmode which was called: # once (14µs+0s) by main::RUNTIME at line 7 sub main::CORE:binmode; # opcode
					# spent 139ms within main::CORE:print which was called 5005 times, avg 28µs/call: # 5000 times (138ms+0s) by main::RUNTIME at line 12, avg 28µs/call # 5 times (1.00ms+0s) by main::RUNTIME at line 13, avg 201µs/call sub main::CORE:print; # opcode
					# spent 131µs within mro::method_changed_in which was called 40 times, avg 3µs/call: # 40 times (131µs+0s) by constant::import at line 113 of constant.pm, avg 3µs/call sub mro::method_changed_in; # xsub
					# spent 9µs within version::(bool which was called: # once (9µs+0s) by DynaLoader::BEGIN@24 at line 47 of Config.pm sub version::(bool; # xsub
					# spent 10µs within version::(cmp which was called: # once (10µs+0s) by DynaLoader::BEGIN@24 at line 50 of Config.pm sub version::(cmp; # xsub