Profile of conv.pl

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

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
40000	8	2	90.0ms	90.0ms	UNIVERSAL::::can UNIVERSAL::can (xsub)
5005	2	1	42.5ms	42.5ms	main::::CORE:print main::CORE:print (opcode)
1	1	1	2.88ms	138ms	main::::BEGIN@3 main::BEGIN@3
1	1	1	1.03ms	1.16ms	main::::BEGIN@5 main::BEGIN@5
1	1	1	310µs	310µs	MARC::Field::::BEGIN@66MARC::Field::BEGIN@66
32	1	1	96µs	96µs	mro::::method_changed_in mro::method_changed_in (xsub)
32	1	1	71µs	71µs	Internals::::SvREADONLY Internals::SvREADONLY (xsub)
8	1	1	29µs	29µs	UNIVERSAL::::isa UNIVERSAL::isa (xsub)
1	1	1	20µs	59µs	main::::BEGIN@4 main::BEGIN@4
1	1	1	14µs	14µs	main::::CORE:binmode main::CORE:binmode (opcode)
1	1	1	9µs	9µs	version::::(bool version::(bool (xsub)
1	1	1	9µs	9µs	version::::(cmp version::(cmp (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	362µs	Profile data that couldn't be associated with a specific line: # spent 310µs making 1 call to MARC::Field::BEGIN@66 # spent 52µs making 1 call to MARC::File::XML::DESTROY
1	1	23µs			#!/usr/bin/perl
2
3	3	175µs	2	138ms	# spent 138ms (2.88+135) within main::BEGIN@3 which was called: # once (2.88ms+135ms) by main::RUNTIME at line 3 use MARC::File::XML (BinaryEncoding => 'utf8'); # spent 138ms making 1 call to main::BEGIN@3 # spent 10µs making 1 call to MARC::File::XML::import
4	3	42µs	2	98µs	# spent 59µs (20+39) within main::BEGIN@4 which was called: # once (20µs+39µs) by main::RUNTIME at line 4 use MARC::Record; # spent 59µs making 1 call to main::BEGIN@4 # spent 39µs making 1 call to Exporter::import
5	3	599µ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	7µs	1	60µs	my $batch = MARC::Batch->new('XML', $ARGV[0]); # spent 60µs making 1 call to MARC::Batch::new
10	20001	239ms	5000	31.1s	while (my $record = $batch->next) { # spent 31.1s making 5000 calls to MARC::Batch::next, avg 6.22ms/call
11					$i++;
12			10000	7.79s	print $record->as_usmarc(); # spent 7.75s making 5000 calls to MARC::Record::as_usmarc, avg 1.55ms/call # spent 41.3ms making 5000 calls to main::CORE:print, avg 8µs/call
13			5	1.13ms	if ($i % 1000 == 0) { # spent 1.13ms making 5 calls to main::CORE:print, avg 225µs/call
14					print STDERR "$i ", scalar(localtime), "\n";
15					}
16					last if $i == 5000;
17					}
18
- -

					# spent 71µs within Internals::SvREADONLY which was called 32 times, avg 2µs/call: # 32 times (71µs+0s) by constant::import at line 111 of constant.pm, avg 2µs/call sub Internals::SvREADONLY; # xsub
					# spent 90.0ms within UNIVERSAL::can which was called 40000 times, avg 2µs/call: # 5000 times (13.5ms+0s) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 3µs/call # 5000 times (12.3ms+0s) by XML::SAX::Base::end_document at line 1428 of XML/SAX/Base.pm, avg 2µs/call # 5000 times (11.6ms+0s) by XML::SAX::ExpatXS::Preload::get_start_element at line 218 of XML/SAX/ExpatXS/Preload.pm, avg 2µs/call # 5000 times (11.0ms+0s) by XML::SAX::Base::set_document_locator at line 1612 of XML/SAX/Base.pm, avg 2µs/call # 5000 times (10.8ms+0s) by XML::SAX::Base::start_document at line 1244 of XML/SAX/Base.pm, avg 2µs/call # 5000 times (10.3ms+0s) by XML::SAX::ExpatXS::Preload::get_end_element at line 29 of XML/SAX/ExpatXS/Preload.pm, avg 2µs/call # 5000 times (10.3ms+0s) by XML::SAX::ExpatXS::Preload::get_characters at line 155 of XML/SAX/ExpatXS/Preload.pm, avg 2µs/call # 5000 times (10.2ms+0s) by XML::SAX::ExpatXS::Preload::get_comment at line 92 of XML/SAX/ExpatXS/Preload.pm, avg 2µs/call sub UNIVERSAL::can; # xsub
					# spent 29µs within UNIVERSAL::isa which was called 8 times, avg 4µs/call: # 8 times (29µ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 42.5ms within main::CORE:print which was called 5005 times, avg 8µs/call: # 5000 times (41.3ms+0s) by main::RUNTIME at line 12, avg 8µs/call # 5 times (1.13ms+0s) by main::RUNTIME at line 13, avg 225µs/call sub main::CORE:print; # opcode
					# spent 96µs within mro::method_changed_in which was called 32 times, avg 3µs/call: # 32 times (96µ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 9µs within version::(cmp which was called: # once (9µs+0s) by DynaLoader::BEGIN@24 at line 50 of Config.pm sub version::(cmp; # xsub