← Index
NYTProf Performance Profile   « block view • line view • sub view »
For /usr/share/koha/opac/cgi-bin/opac/opac-search.pl
  Run on Tue Oct 15 17:10:45 2013
Reported on Tue Oct 15 17:12:10 2013

Filename/usr/lib/perl5/XML/LibXML/SAX/Parser.pm
StatementsExecuted 60591 statements in 275ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
129511159ms425msXML::LibXML::SAX::Parser::::process_elementXML::LibXML::SAX::Parser::process_element (recurses: max depth 2, inclusive time 519ms)
38853147.8ms427msXML::LibXML::SAX::Parser::::process_nodeXML::LibXML::SAX::Parser::process_node (recurses: max depth 4, inclusive time 1.04s)
25113.12ms437msXML::LibXML::SAX::Parser::::generateXML::LibXML::SAX::Parser::generate
1111.91ms5.42msXML::LibXML::SAX::Parser::::BEGIN@16XML::LibXML::SAX::Parser::BEGIN@16
2511902µs449msXML::LibXML::SAX::Parser::::_parse_stringXML::LibXML::SAX::Parser::_parse_string
111500µs527µsXML::LibXML::SAX::Parser::::BEGIN@18XML::LibXML::SAX::Parser::BEGIN@18
11139µs50µsXML::LibXML::SAX::Parser::::BEGIN@12XML::LibXML::SAX::Parser::BEGIN@12
11123µs26µsXML::LibXML::SAX::Parser::::BEGIN@17XML::LibXML::SAX::Parser::BEGIN@17
11122µs124µsXML::LibXML::SAX::Parser::::BEGIN@13XML::LibXML::SAX::Parser::BEGIN@13
11121µs576µsXML::LibXML::SAX::Parser::::BEGIN@15XML::LibXML::SAX::Parser::BEGIN@15
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
12371µs260µs
# spent 50µs (39+11) within XML::LibXML::SAX::Parser::BEGIN@12 which was called: # once (39µs+11µs) by XML::SAX::ParserFactory::parser at line 12
use strict;
# spent 50µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@12 # spent 11µs making 1 call to strict::import
13363µs2226µs
# spent 124µs (22+102) within XML::LibXML::SAX::Parser::BEGIN@13 which was called: # once (22µs+102µs) by XML::SAX::ParserFactory::parser at line 13
use vars qw($VERSION @ISA);
# spent 124µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@13 # spent 102µs making 1 call to vars::import
14
15369µs21.13ms
# spent 576µs (21+555) within XML::LibXML::SAX::Parser::BEGIN@15 which was called: # once (21µs+555µs) by XML::SAX::ParserFactory::parser at line 15
use XML::LibXML;
# spent 576µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@15 # spent 555µs making 1 call to XML::LibXML::import
163208µs26.03ms
# spent 5.42ms (1.91+3.51) within XML::LibXML::SAX::Parser::BEGIN@16 which was called: # once (1.91ms+3.51ms) by XML::SAX::ParserFactory::parser at line 16
use XML::LibXML::Common qw(:libxml);
# spent 5.42ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@16 # spent 606µs making 1 call to Exporter::import
17339µs229µs
# spent 26µs (23+3) within XML::LibXML::SAX::Parser::BEGIN@17 which was called: # once (23µs+3µs) by XML::SAX::ParserFactory::parser at line 17
use XML::SAX::Base;
# spent 26µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@17 # spent 3µs making 1 call to UNIVERSAL::import
1831.15ms2530µs
# spent 527µs (500+27) within XML::LibXML::SAX::Parser::BEGIN@18 which was called: # once (500µs+27µs) by XML::SAX::ParserFactory::parser at line 18
use XML::SAX::DocumentLocator;
# spent 527µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@18 # spent 3µs making 1 call to UNIVERSAL::import
19
20127µs$VERSION = "1.70"; # VERSION TEMPLATE: DO NOT CHANGE
21113µ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 449ms (902µs+449) within XML::LibXML::SAX::Parser::_parse_string which was called 25 times, avg 18.0ms/call: # 25 times (902µs+449ms) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 18.0ms/call
sub _parse_string {
401002.00ms my ($self, $str, $options) = @_;
4125332µs my $parser = XML::LibXML->new();
# spent 332µs making 25 calls to XML::LibXML::new, avg 13µs/call
422510.6ms my $doc = exists($options->{Source}{SystemId}) ? $parser->parse_string($str, $options->{Source}{SystemId}) : $parser->parse_string($str);
# spent 10.6ms making 25 calls to XML::LibXML::parse_string, avg 425µs/call
4350437ms $self->generate($doc);
# spent 437ms making 25 calls to XML::LibXML::SAX::Parser::generate, avg 17.5ms/call # spent 44µs making 25 calls to XML::LibXML::Node::DESTROY, avg 2µ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 437ms (3.12+433) within XML::LibXML::SAX::Parser::generate which was called 25 times, avg 17.5ms/call: # 25 times (3.12ms+433ms) by XML::LibXML::SAX::Parser::_parse_string at line 43, avg 17.5ms/call
sub generate {
541251.30ms my $self = shift;
55 my ($node) = @_;
56
5725211µs my $doc = $node->ownerDocument();
# spent 211µs making 25 calls to XML::LibXML::Node::ownerDocument, avg 8µs/call
58 {
59 # precompute some DocumentLocator values
601251.13ms my %locator = (
61 PublicId => undef,
62 SystemId => undef,
63 Encoding => undef,
64 XMLVersion => undef,
65 );
662568µs my $dtd = defined $doc ? $doc->externalSubset() : undef;
# spent 68µs making 25 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 }
7150383µs if (defined $doc) {
722574µs $locator{Encoding} = $doc->encoding();
# spent 74µs making 25 calls to XML::LibXML::Document::encoding, avg 3µs/call
732554µs $locator{XMLVersion} = $doc->version();
# spent 54µs making 25 calls to XML::LibXML::Document::version, avg 2µ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} },
83502.21ms ),
# spent 1.35ms making 25 calls to XML::SAX::Base::set_document_locator, avg 54µs/call # spent 855µs making 25 calls to XML::SAX::DocumentLocator::new, avg 34µs/call
84 );
85 }
86
871001.12ms25102µs if ( $node->nodeType() == XML_DOCUMENT_NODE
# spent 102µs making 25 calls to XML::LibXML::Node::nodeType, avg 4µs/call
88 || $node->nodeType == XML_HTML_DOCUMENT_NODE ) {
89251.17ms $self->start_document({});
# spent 1.17ms making 25 calls to XML::SAX::Base::start_document, avg 47µs/call
90751.35ms $self->xml_decl({Version => $node->getVersion, Encoding => $node->getEncoding});
# spent 1.22ms making 25 calls to XML::SAX::Base::xml_decl, avg 49µs/call # spent 77µs making 25 calls to XML::LibXML::Document::getVersion, avg 3µs/call # spent 53µs making 25 calls to XML::LibXML::Document::getEncoding, avg 2µs/call
9125427ms $self->process_node($node);
# spent 427ms making 25 calls to XML::LibXML::SAX::Parser::process_node, avg 17.1ms/call
92501.22ms $self->end_document({});
# spent 1.17ms making 25 calls to XML::SAX::Base::end_document, avg 47µs/call # spent 52µs making 25 calls to XML::LibXML::Node::DESTROY, avg 2µs/call
93 }
94}
95
96
# spent 427ms (47.8+379) within XML::LibXML::SAX::Parser::process_node which was called 3885 times, avg 110µs/call: # 3835 times (46.8ms+-46.8ms) by XML::LibXML::SAX::Parser::process_element at line 244, avg 0s/call # 25 times (700µs+426ms) by XML::LibXML::SAX::Parser::generate at line 91, avg 17.1ms/call # 25 times (299µs+-299µs) by XML::LibXML::SAX::Parser::process_node at line 127, avg 0s/call
sub process_node {
971554062.0ms my ($self, $node) = @_;
98
99 local $self->{current_node} = $node;
100
10138857.98ms my $node_type = $node->nodeType();
# spent 7.98ms making 3885 calls to XML::LibXML::Node::nodeType, avg 2µs/call
1026475469ms if ($node_type == XML_COMMENT_NODE) {
# spent 945ms making 1295 calls to XML::LibXML::SAX::Parser::process_element, avg 730µs/call, recursion: max depth 2, sum of overlapping time 519ms # spent 35.7ms making 2565 calls to XML::SAX::Base::characters, avg 14µs/call # spent 7.12ms making 2565 calls to XML::LibXML::Node::nodeValue, avg 3µs/call # spent 389µs making 25 calls to XML::LibXML::Node::childNodes, avg 16µs/call # spent 75µs making 25 calls to XML::LibXML::Namespace::DESTROY, avg 3µ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) {
12725236µs5038µs $self->process_node($kid);
# spent 38µs making 25 calls to XML::LibXML::Namespace::DESTROY, avg 2µs/call # spent 426ms making 25 calls to XML::LibXML::SAX::Parser::process_node, avg 17.0ms/call, recursion: max depth 1, sum of overlapping time 426ms
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 425ms (159+267) within XML::LibXML::SAX::Parser::process_element which was called 1295 times, avg 328µs/call: # 1295 times (159ms+267ms) by XML::LibXML::SAX::Parser::process_node at line 102, avg 328µs/call
sub process_element {
1521554099.7ms my ($self, $element) = @_;
153
154 my $attribs = {};
15512952.16ms my @ns_maps = $element->getNamespaces;
# spent 2.16ms making 1295 calls to XML::LibXML::Node::getNamespaces, avg 2µs/call
156
157 foreach my $ns (@ns_maps) {
15850996µs1751.98ms $self->start_prefix_mapping(
# spent 1.75ms making 50 calls to XML::SAX::Base::start_prefix_mapping, avg 35µs/call # spent 135µs making 50 calls to XML::LibXML::Namespace::href, avg 3µs/call # spent 93µs making 75 calls to XML::LibXML::Namespace::localname, avg 1µs/call
159 {
160 NamespaceURI => $ns->href,
161 Prefix => ( defined $ns->localname ? $ns->localname : ''),
162 }
163 );
164 }
165
166129514.7ms foreach my $attr ($element->attributes) {
# spent 14.7ms making 1295 calls to XML::LibXML::Node::attributes, avg 11µs/call
167456016.2ms my $key;
168 # warn("Attr: $attr -> ", $attr->getName, " = ", $attr->getData, "\n");
169 # this isa dump thing...
1702012072.6ms22805.85ms if ($attr->isa('XML::LibXML::Namespace')) {
# spent 5.85ms making 2280 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.
173300762µs50172µs unless ( defined $attr->name ) {
# spent 172µs making 50 calls to XML::LibXML::Namespace::name, avg 3µs/call
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";
1865069µs my $localname = $attr->localname;
# spent 69µs making 50 calls to XML::LibXML::Namespace::localname, avg 1µs/call
187 my $key = "{http://www.w3.org/2000/xmlns/}";
188 my $name = "xmlns";
189
1905037µs if ( defined $localname ) {
191 $key .= $localname;
192 $name.= ":".$localname;
193 }
194
1955078µs $attribs->{$key} =
# spent 78µs making 50 calls to XML::LibXML::Namespace::href, avg 2µs/call
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 {
20622303.64ms my $ns = $attr->namespaceURI;
# spent 3.64ms making 2230 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call
207
208 $ns = '' unless defined $ns;
20922304.14ms $key = "{$ns}".$attr->localname;
# spent 4.14ms making 2230 calls to XML::LibXML::Node::localname, avg 2µ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.
21222303.28ms my $name = $attr->name;
# spent 3.28ms making 2230 calls to XML::LibXML::Attr::name, avg 1µs/call
213 $name = "" unless defined $name;
214
21522303.04ms my $prefix = $attr->prefix;
# spent 3.04ms making 2230 calls to XML::LibXML::Node::prefix, avg 1µs/call
216 $prefix = "" unless defined $prefix;
217 $name = "$prefix:$name"
218 if index( $name, ":" ) < 0 && length $prefix;
219
22044608.53ms $attribs->{$key} =
# spent 5.31ms making 2230 calls to XML::LibXML::Attr::value, avg 2µs/call # spent 3.21ms making 2230 calls to XML::LibXML::Node::localname, avg 1µ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
233746012.4ms my $node = {
# spent 3.19ms making 1295 calls to XML::LibXML::Node::nodeName, avg 2µs/call # spent 3.11ms making 2230 calls to XML::LibXML::Node::DESTROY, avg 1µs/call # spent 2.45ms making 1295 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call # spent 1.86ms making 1295 calls to XML::LibXML::Node::localname, avg 1µs/call # spent 1.66ms making 1295 calls to XML::LibXML::Node::prefix, avg 1µs/call # spent 93µs making 50 calls to XML::LibXML::Namespace::DESTROY, 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
241129524.6ms $self->start_element($node);
# spent 24.6ms making 1295 calls to XML::SAX::Base::start_element, avg 19µs/call
242
243129517.3ms foreach my $child ($element->childNodes) {
# spent 17.3ms making 1295 calls to XML::LibXML::Node::childNodes, avg 13µs/call
244383513.8ms38350s $self->process_node($child);
# spent 617ms making 3835 calls to XML::LibXML::SAX::Parser::process_node, avg 161µs/call, recursion: max depth 4, sum of overlapping time 617ms
245 }
246
24738355.06ms my $end_node = { %$node };
# spent 5.06ms making 3835 calls to XML::LibXML::Node::DESTROY, avg 1µs/call
248
249 delete $end_node->{Attributes};
250
251129559.6ms $self->end_element($end_node);
# spent 59.6ms making 1295 calls to XML::SAX::Base::end_element, avg 46µs/call
252
253 foreach my $ns (@ns_maps) {
25450897µs1752.05ms $self->end_prefix_mapping(
# spent 1.83ms making 50 calls to XML::SAX::Base::end_prefix_mapping, avg 37µs/call # spent 135µs making 50 calls to XML::LibXML::Namespace::href, avg 3µs/call # spent 85µs making 75 calls to XML::LibXML::Namespace::localname, avg 1µs/call
255 {
256 NamespaceURI => $ns->href,
257 Prefix => ( defined $ns->localname ? $ns->localname : ''),
258 }
259 );
260 }
261}
262
26315µs1;
264
265__END__
Report produced by the NYTProf 4.04 Perl profiler, developed by Tim Bunce and Adam Kaplan.