← Index
NYTProf Performance Profile   « block view • line view • sub view »
For conv.pl
  Run on Sun Nov 14 21:09:12 2010
Reported on Sun Nov 14 21:13:15 2010

Filename/usr/lib/perl5/XML/LibXML/SAX/Parser.pm
StatementsExecuted 8336285 statements in 55.5s
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
1852991131.9s87.1sXML::LibXML::SAX::Parser::::process_elementXML::LibXML::SAX::Parser::process_element (recurses: max depth 2, inclusive time 106s)
5558973110.5s87.4sXML::LibXML::SAX::Parser::::process_nodeXML::LibXML::SAX::Parser::process_node (recurses: max depth 4, inclusive time 215s)
500011599ms89.4sXML::LibXML::SAX::Parser::::generateXML::LibXML::SAX::Parser::generate
500011166ms91.6sXML::LibXML::SAX::Parser::::_parse_stringXML::LibXML::SAX::Parser::_parse_string
11114.7ms33.1msXML::LibXML::SAX::Parser::::BEGIN@15XML::LibXML::SAX::Parser::BEGIN@15
11110.8ms10.8msXML::LibXML::SAX::Parser::::BEGIN@18XML::LibXML::SAX::Parser::BEGIN@18
1119.79ms14.9msXML::LibXML::SAX::Parser::::BEGIN@16XML::LibXML::SAX::Parser::BEGIN@16
11157µs72µsXML::LibXML::SAX::Parser::::BEGIN@12XML::LibXML::SAX::Parser::BEGIN@12
11126µs131µsXML::LibXML::SAX::Parser::::BEGIN@13XML::LibXML::SAX::Parser::BEGIN@13
11115µs15µsXML::LibXML::SAX::Parser::::BEGIN@17XML::LibXML::SAX::Parser::BEGIN@17
0000s0sXML::LibXML::SAX::Parser::::CLONE_SKIPXML::LibXML::SAX::Parser::CLONE_SKIP
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:77]XML::LibXML::SAX::Parser::__ANON__[:77]
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:78]XML::LibXML::SAX::Parser::__ANON__[:78]
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:79]XML::LibXML::SAX::Parser::__ANON__[:79]
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:80]XML::LibXML::SAX::Parser::__ANON__[:80]
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:81]XML::LibXML::SAX::Parser::__ANON__[:81]
0000s0sXML::LibXML::SAX::Parser::::__ANON__[:82]XML::LibXML::SAX::Parser::__ANON__[:82]
0000s0sXML::LibXML::SAX::Parser::::_parse_bytestreamXML::LibXML::SAX::Parser::_parse_bytestream
0000s0sXML::LibXML::SAX::Parser::::_parse_characterstreamXML::LibXML::SAX::Parser::_parse_characterstream
0000s0sXML::LibXML::SAX::Parser::::_parse_systemidXML::LibXML::SAX::Parser::_parse_systemid
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1# $Id: Parser.pm 785 2009-07-16 14:17:46Z pajas $
2#
3# This is free software, you may use it and distribute it under the same terms as
4# Perl itself.
5#
6# Copyright 2001-2003 AxKit.com Ltd., 2002-2006 Christian Glahn, 2006-2009 Petr Pajas
7#
8#
9
10package XML::LibXML::SAX::Parser;
11
12369µs287µs
# spent 72µs (57+15) within XML::LibXML::SAX::Parser::BEGIN@12 which was called: # once (57µs+15µs) by XML::SAX::ParserFactory::BEGIN@1 at line 12
use strict;
# spent 72µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@12 # spent 15µs making 1 call to strict::import
13346µs2236µs
# spent 131µs (26+105) within XML::LibXML::SAX::Parser::BEGIN@13 which was called: # once (26µs+105µs) by XML::SAX::ParserFactory::BEGIN@1 at line 13
use vars qw($VERSION @ISA);
# spent 131µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@13 # spent 105µs making 1 call to vars::import
14
153211µs233.5ms
# spent 33.1ms (14.7+18.5) within XML::LibXML::SAX::Parser::BEGIN@15 which was called: # once (14.7ms+18.5ms) by XML::SAX::ParserFactory::BEGIN@1 at line 15
use XML::LibXML;
# spent 33.1ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@15 # spent 392µs making 1 call to XML::LibXML::import
1633.20ms215.9ms
# spent 14.9ms (9.79+5.09) within XML::LibXML::SAX::Parser::BEGIN@16 which was called: # once (9.79ms+5.09ms) by XML::SAX::ParserFactory::BEGIN@1 at line 16
use XML::LibXML::Common qw(:libxml);
# spent 14.9ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@16 # spent 1.02ms making 1 call to Exporter::import
17341µs115µs
# spent 15µs within XML::LibXML::SAX::Parser::BEGIN@17 which was called: # once (15µs+0s) by XML::SAX::ParserFactory::BEGIN@1 at line 17
use XML::SAX::Base;
# spent 15µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@17
18311.7ms110.8ms
# spent 10.8ms (10.8+31µs) within XML::LibXML::SAX::Parser::BEGIN@18 which was called: # once (10.8ms+31µs) by XML::SAX::ParserFactory::BEGIN@1 at line 18
use XML::SAX::DocumentLocator;
# spent 10.8ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@18
19
2012µs$VERSION = "1.70"; # VERSION TEMPLATE: DO NOT CHANGE
21115µs@ISA = ('XML::SAX::Base');
22
23sub CLONE_SKIP {
24 return $XML::LibXML::__threads_shared ? 0 : 1;
25}
26
27sub _parse_characterstream {
28 my ($self, $fh, $options) = @_;
29 die "parsing a characterstream is not supported at this time";
30}
31
32sub _parse_bytestream {
33 my ($self, $fh, $options) = @_;
34 my $parser = XML::LibXML->new();
35 my $doc = exists($options->{Source}{SystemId}) ? $parser->parse_fh($fh, $options->{Source}{SystemId}) : $parser->parse_fh($fh);
36 $self->generate($doc);
37}
38
39
# spent 91.6s (166ms+91.5) within XML::LibXML::SAX::Parser::_parse_string which was called 5000 times, avg 18.3ms/call: # 5000 times (166ms+91.5s) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 18.3ms/call
sub _parse_string {
4020000319ms my ($self, $str, $options) = @_;
41500073.7ms my $parser = XML::LibXML->new();
# spent 73.7ms making 5000 calls to XML::LibXML::new, avg 15µs/call
4250001.87s my $doc = exists($options->{Source}{SystemId}) ? $parser->parse_string($str, $options->{Source}{SystemId}) : $parser->parse_string($str);
# spent 1.87s making 5000 calls to XML::LibXML::parse_string, avg 375µs/call
431000089.4s $self->generate($doc);
# spent 89.4s making 5000 calls to XML::LibXML::SAX::Parser::generate, avg 17.9ms/call # spent 12.5ms making 5000 calls to XML::LibXML::Node::DESTROY, avg 3µs/call
44}
45
46sub _parse_systemid {
47 my ($self, $sysid, $options) = @_;
48 my $parser = XML::LibXML->new();
49 my $doc = $parser->parse_file($sysid);
50 $self->generate($doc);
51}
52
53
# spent 89.4s (599ms+88.8) within XML::LibXML::SAX::Parser::generate which was called 5000 times, avg 17.9ms/call: # 5000 times (599ms+88.8s) by XML::LibXML::SAX::Parser::_parse_string at line 43, avg 17.9ms/call
sub generate {
5425000232ms my $self = shift;
55 my ($node) = @_;
56
57500026.5ms my $doc = $node->ownerDocument();
# spent 26.5ms making 5000 calls to XML::LibXML::Node::ownerDocument, avg 5µs/call
58 {
59 # precompute some DocumentLocator values
6025000206ms my %locator = (
61 PublicId => undef,
62 SystemId => undef,
63 Encoding => undef,
64 XMLVersion => undef,
65 );
66500015.8ms my $dtd = defined $doc ? $doc->externalSubset() : undef;
# spent 15.8ms making 5000 calls to XML::LibXML::Document::externalSubset, avg 3µs/call
67 if (defined $dtd) {
68 $locator{PublicId} = $dtd->publicId();
69 $locator{SystemId} = $dtd->systemId();
70 }
711000082.9ms if (defined $doc) {
72500015.2ms $locator{Encoding} = $doc->encoding();
# spent 15.2ms making 5000 calls to XML::LibXML::Document::encoding, avg 3µs/call
73500015.7ms $locator{XMLVersion} = $doc->version();
# spent 15.7ms making 5000 calls to XML::LibXML::Document::version, avg 3µs/call
74 }
75 $self->set_document_locator(
76 XML::SAX::DocumentLocator->new(
77 sub { $locator{PublicId} },
78 sub { $locator{SystemId} },
79 sub { defined($self->{current_node}) ? $self->{current_node}->line_number() : undef },
80 sub { 1 },
81 sub { $locator{Encoding} },
82 sub { $locator{XMLVersion} },
8310000430ms ),
# spent 273ms making 5000 calls to XML::SAX::Base::set_document_locator, avg 55µs/call # spent 158ms making 5000 calls to XML::SAX::DocumentLocator::new, avg 32µs/call
84 );
85 }
86
8720000217ms500016.4ms if ( $node->nodeType() == XML_DOCUMENT_NODE
# spent 16.4ms making 5000 calls to XML::LibXML::Node::nodeType, avg 3µs/call
88 || $node->nodeType == XML_HTML_DOCUMENT_NODE ) {
895000253ms $self->start_document({});
# spent 253ms making 5000 calls to XML::SAX::Base::start_document, avg 51µs/call
9015000279ms $self->xml_decl({Version => $node->getVersion, Encoding => $node->getEncoding});
# spent 251ms making 5000 calls to XML::SAX::Base::xml_decl, avg 50µs/call # spent 15.9ms making 5000 calls to XML::LibXML::Document::getVersion, avg 3µs/call # spent 12.3ms making 5000 calls to XML::LibXML::Document::getEncoding, avg 2µs/call
91500087.4s $self->process_node($node);
# spent 87.4s making 5000 calls to XML::LibXML::SAX::Parser::process_node, avg 17.5ms/call
9210000286ms $self->end_document({});
# spent 273ms making 5000 calls to XML::SAX::Base::end_document, avg 55µs/call # spent 13.1ms making 5000 calls to XML::LibXML::Node::DESTROY, avg 3µs/call
93 }
94}
95
96
# spent 87.4s (10.5+76.9) within XML::LibXML::SAX::Parser::process_node which was called 555897 times, avg 157µs/call: # 545897 times (10.3s+-10.3s) by XML::LibXML::SAX::Parser::process_element at line 244, avg 0s/call # 5000 times (135ms+87.3s) by XML::LibXML::SAX::Parser::generate at line 91, avg 17.5ms/call # 5000 times (83.8ms+-83.8ms) by XML::LibXML::SAX::Parser::process_node at line 127, avg 0s/call
sub process_node {
97222358813.3s my ($self, $node) = @_;
98
99 local $self->{current_node} = $node;
100
1015558971.50s my $node_type = $node->nodeType();
# spent 1.50s making 555897 calls to XML::LibXML::Node::nodeType, avg 3µs/call
10292149596.9s if ($node_type == XML_COMMENT_NODE) {
# spent 193s making 185299 calls to XML::LibXML::SAX::Parser::process_element, avg 1.04ms/call, recursion: max depth 2, sum of overlapping time 106s # spent 8.44s making 365598 calls to XML::SAX::Base::characters, avg 23µs/call # spent 1.30s making 365598 calls to XML::LibXML::Node::nodeValue, avg 4µs/call # spent 79.3ms making 5000 calls to XML::LibXML::Node::childNodes, avg 16µs/call
103 $self->comment( { Data => $node->getData } );
104 }
105 elsif ($node_type == XML_TEXT_NODE
106 || $node_type == XML_CDATA_SECTION_NODE) {
107 # warn($node->getData . "\n");
108 $self->characters( { Data => $node->nodeValue } );
109 }
110 elsif ($node_type == XML_ELEMENT_NODE) {
111 # warn("<" . $node->getName . ">\n");
112 $self->process_element($node);
113 # warn("</" . $node->getName . ">\n");
114 }
115 elsif ($node_type == XML_ENTITY_REF_NODE) {
116 foreach my $kid ($node->childNodes) {
117 # warn("child of entity ref: " . $kid->getType() . " called: " . $kid->getName . "\n");
118 $self->process_node($kid);
119 }
120 }
121 elsif ($node_type == XML_DOCUMENT_NODE
122 || $node_type == XML_HTML_DOCUMENT_NODE
123 || $node_type == XML_DOCUMENT_FRAG_NODE) {
124 # some times it is just usefull to generate SAX events from
125 # a document fragment (very good with filters).
126 foreach my $kid ($node->childNodes) {
127500032.0ms50000s $self->process_node($kid);
# spent 87.2s making 5000 calls to XML::LibXML::SAX::Parser::process_node, avg 17.4ms/call, recursion: max depth 1, sum of overlapping time 87.2s
128 }
129 }
130 elsif ($node_type == XML_PI_NODE) {
131 $self->processing_instruction( { Target => $node->getName, Data => $node->getData } );
132 }
133 elsif ($node_type == XML_COMMENT_NODE) {
134 $self->comment( { Data => $node->getData } );
135 }
136 elsif ( $node_type == XML_XINCLUDE_START
137 || $node_type == XML_XINCLUDE_END ) {
138 # ignore!
139 # i may want to handle this one day, dunno yet
140 }
141 elsif ($node_type == XML_DTD_NODE ) {
142 # ignore!
143 # i will support DTDs, but had no time yet.
144 }
145 else {
146 # warn("unsupported node type: $node_type");
147 }
148
149}
150
151
# spent 87.1s (31.9+55.2) within XML::LibXML::SAX::Parser::process_element which was called 185299 times, avg 470µs/call: # 185299 times (31.9s+55.2s) by XML::LibXML::SAX::Parser::process_node at line 102, avg 470µs/call
sub process_element {
152222358819.1s my ($self, $element) = @_;
153
154 my $attribs = {};
155185299420ms my @ns_maps = $element->getNamespaces;
# spent 420ms making 185299 calls to XML::LibXML::Node::getNamespaces, avg 2µs/call
156
157 foreach my $ns (@ns_maps) {
158 $self->start_prefix_mapping(
159 {
160 NamespaceURI => $ns->href,
161 Prefix => ( defined $ns->localname ? $ns->localname : ''),
162 }
163 );
164 }
165
1661852992.74s foreach my $attr ($element->attributes) {
# spent 2.74s making 185299 calls to XML::LibXML::Node::attributes, avg 15µs/call
1675887623.43s my $key;
168 # warn("Attr: $attr -> ", $attr->getName, " = ", $attr->getData, "\n");
169 # this isa dump thing...
170264942915.1s2943811.00s if ($attr->isa('XML::LibXML::Namespace')) {
# spent 1.00s making 294381 calls to UNIVERSAL::isa, avg 3µs/call
171 # TODO This needs fixing modulo agreeing on what
172 # is the right thing to do here.
173 unless ( defined $attr->name ) {
174 ## It's an atter like "xmlns='foo'"
175 $attribs->{"{}xmlns"} =
176 {
177 Name => "xmlns",
178 LocalName => "xmlns",
179 Prefix => "",
180 Value => $attr->href,
181 NamespaceURI => "",
182 };
183 }
184 else {
185 my $prefix = "xmlns";
186 my $localname = $attr->localname;
187 my $key = "{http://www.w3.org/2000/xmlns/}";
188 my $name = "xmlns";
189
190 if ( defined $localname ) {
191 $key .= $localname;
192 $name.= ":".$localname;
193 }
194
195 $attribs->{$key} =
196 {
197 Name => $name,
198 Value => $attr->href,
199 NamespaceURI => "http://www.w3.org/2000/xmlns/",
200 Prefix => $prefix,
201 LocalName => $localname,
202 };
203 }
204 }
205 else {
206294381727ms my $ns = $attr->namespaceURI;
# spent 727ms making 294381 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call
207
208 $ns = '' unless defined $ns;
209294381820ms $key = "{$ns}".$attr->localname;
# spent 820ms making 294381 calls to XML::LibXML::Node::localname, avg 3µs/call
210 ## Not sure why, but $attr->name is coming through stripped
211 ## of its prefix, so we need to hand-assemble a real name.
212294381758ms my $name = $attr->name;
# spent 758ms making 294381 calls to XML::LibXML::Attr::name, avg 3µs/call
213 $name = "" unless defined $name;
214
215294381696ms my $prefix = $attr->prefix;
# spent 696ms making 294381 calls to XML::LibXML::Node::prefix, avg 2µs/call
216 $prefix = "" unless defined $prefix;
217 $name = "$prefix:$name"
218 if index( $name, ":" ) < 0 && length $prefix;
219
2205887621.76s $attribs->{$key} =
# spent 1.01s making 294381 calls to XML::LibXML::Attr::value, avg 3µs/call # spent 749ms making 294381 calls to XML::LibXML::Node::localname, avg 3µs/call
221 {
222 Name => $name,
223 Value => $attr->value,
224 NamespaceURI => $ns,
225 Prefix => $prefix,
226 LocalName => $attr->localname,
227 };
228 }
229 # use Data::Dumper;
230 # warn("Attr made: ", Dumper($attribs->{$key}), "\n");
231 }
232
23310355772.58s my $node = {
# spent 672ms making 294381 calls to XML::LibXML::Node::DESTROY, avg 2µs/call # spent 621ms making 185299 calls to XML::LibXML::Node::nodeName, avg 3µs/call # spent 465ms making 185299 calls to XML::LibXML::Node::localname, avg 3µs/call # spent 416ms making 185299 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call # spent 403ms making 185299 calls to XML::LibXML::Node::prefix, avg 2µs/call
234 Name => $element->nodeName,
235 Attributes => $attribs,
236 NamespaceURI => $element->namespaceURI,
237 Prefix => $element->prefix || "",
238 LocalName => $element->localname,
239 };
240
2411852995.36s $self->start_element($node);
# spent 5.36s making 185299 calls to XML::SAX::Base::start_element, avg 29µs/call
242
2431852993.15s foreach my $child ($element->childNodes) {
# spent 3.15s making 185299 calls to XML::LibXML::Node::childNodes, avg 17µs/call
2445458973.40s5458970s $self->process_node($child);
# spent 128s making 545897 calls to XML::LibXML::SAX::Parser::process_node, avg 234µs/call, recursion: max depth 4, sum of overlapping time 128s
245 }
246
2475458971.18s my $end_node = { %$node };
# spent 1.18s making 545897 calls to XML::LibXML::Node::DESTROY, avg 2µs/call
248
249 delete $end_node->{Attributes};
250
25118529912.5s $self->end_element($end_node);
# spent 12.5s making 185299 calls to XML::SAX::Base::end_element, avg 67µs/call
252
253 foreach my $ns (@ns_maps) {
254 $self->end_prefix_mapping(
255 {
256 NamespaceURI => $ns->href,
257 Prefix => ( defined $ns->localname ? $ns->localname : ''),
258 }
259 );
260 }
261}
262
26316µs1;
264
265__END__
Report produced by the NYTProf 4.04 Perl profiler, developed by Tim Bunce and Adam Kaplan.