← 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 11:58:52 2013
Reported on Tue Oct 15 12:01:03 2013

Filename/usr/lib/perl5/XML/LibXML/SAX/Parser.pm
StatementsExecuted 73176 statements in 335ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
161911189ms529msXML::LibXML::SAX::Parser::::process_elementXML::LibXML::SAX::Parser::process_element (recurses: max depth 7, inclusive time 818ms)
48333162.0ms531msXML::LibXML::SAX::Parser::::process_nodeXML::LibXML::SAX::Parser::process_node (recurses: max depth 8, inclusive time 1.48s)
11117.7ms17.8msXML::LibXML::SAX::Parser::::BEGIN@17XML::LibXML::SAX::Parser::BEGIN@17
11111.9ms29.0msXML::LibXML::SAX::Parser::::BEGIN@15XML::LibXML::SAX::Parser::BEGIN@15
28213.67ms542msXML::LibXML::SAX::Parser::::generateXML::LibXML::SAX::Parser::generate
1112.13ms5.38msXML::LibXML::SAX::Parser::::BEGIN@16XML::LibXML::SAX::Parser::BEGIN@16
25111.08ms467msXML::LibXML::SAX::Parser::::_parse_stringXML::LibXML::SAX::Parser::_parse_string
111754µs785µsXML::LibXML::SAX::Parser::::BEGIN@18XML::LibXML::SAX::Parser::BEGIN@18
311112µs91.8msXML::LibXML::SAX::Parser::::_parse_systemidXML::LibXML::SAX::Parser::_parse_systemid
11121µs28µsXML::LibXML::SAX::Parser::::BEGIN@12XML::LibXML::SAX::Parser::BEGIN@12
11112µs66µsXML::LibXML::SAX::Parser::::BEGIN@13XML::LibXML::SAX::Parser::BEGIN@13
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
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
12337µs235µs
# spent 28µs (21+7) within XML::LibXML::SAX::Parser::BEGIN@12 which was called: # once (21µs+7µs) by XML::SAX::ParserFactory::parser at line 12
use strict;
# spent 28µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@12 # spent 7µs making 1 call to strict::import
13340µs2120µs
# spent 66µs (12+54) within XML::LibXML::SAX::Parser::BEGIN@13 which was called: # once (12µs+54µs) by XML::SAX::ParserFactory::parser at line 13
use vars qw($VERSION @ISA);
# spent 66µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@13 # spent 54µs making 1 call to vars::import
14
153185µs229.3ms
# spent 29.0ms (11.9+17.1) within XML::LibXML::SAX::Parser::BEGIN@15 which was called: # once (11.9ms+17.1ms) by XML::SAX::ParserFactory::parser at line 15
use XML::LibXML;
# spent 29.0ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@15 # spent 335µs making 1 call to XML::LibXML::import
163225µs26.05ms
# spent 5.38ms (2.13+3.25) within XML::LibXML::SAX::Parser::BEGIN@16 which was called: # once (2.13ms+3.25ms) by XML::SAX::ParserFactory::parser at line 16
use XML::LibXML::Common qw(:libxml);
# spent 5.38ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@16 # spent 675µs making 1 call to Exporter::import
173267µs117.8ms
# spent 17.8ms (17.7+92µs) within XML::LibXML::SAX::Parser::BEGIN@17 which was called: # once (17.7ms+92µs) by XML::SAX::ParserFactory::parser at line 17
use XML::SAX::Base;
# spent 17.8ms making 1 call to XML::LibXML::SAX::Parser::BEGIN@17
1831.61ms1785µs
# spent 785µs (754+30) within XML::LibXML::SAX::Parser::BEGIN@18 which was called: # once (754µs+30µs) by XML::SAX::ParserFactory::parser at line 18
use XML::SAX::DocumentLocator;
# spent 785µs making 1 call to XML::LibXML::SAX::Parser::BEGIN@18
19
2012µs$VERSION = "1.70"; # VERSION TEMPLATE: DO NOT CHANGE
21116µ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 467ms (1.08+466) within XML::LibXML::SAX::Parser::_parse_string which was called 25 times, avg 18.7ms/call: # 25 times (1.08ms+466ms) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 18.7ms/call
sub _parse_string {
401002.38ms my ($self, $str, $options) = @_;
4125310µs my $parser = XML::LibXML->new();
# spent 310µs making 25 calls to XML::LibXML::new, avg 12µs/call
422510.9ms my $doc = exists($options->{Source}{SystemId}) ? $parser->parse_string($str, $options->{Source}{SystemId}) : $parser->parse_string($str);
# spent 10.9ms making 25 calls to XML::LibXML::parse_string, avg 436µs/call
4350453ms $self->generate($doc);
# spent 453ms making 25 calls to XML::LibXML::SAX::Parser::generate, avg 18.1ms/call # spent 50µs making 25 calls to XML::LibXML::Node::DESTROY, avg 2µs/call
44}
45
46
# spent 91.8ms (112µs+91.7) within XML::LibXML::SAX::Parser::_parse_systemid which was called 3 times, avg 30.6ms/call: # 3 times (112µs+91.7ms) by XML::SAX::Base::parse at line 2602 of XML/SAX/Base.pm, avg 30.6ms/call
sub _parse_systemid {
4712305µs my ($self, $sysid, $options) = @_;
48368µs my $parser = XML::LibXML->new();
# spent 68µs making 3 calls to XML::LibXML::new, avg 23µs/call
4932.13ms my $doc = $parser->parse_file($sysid);
# spent 2.13ms making 3 calls to XML::LibXML::parse_file, avg 711µs/call
50689.3ms $self->generate($doc);
# spent 89.3ms making 3 calls to XML::LibXML::SAX::Parser::generate, avg 29.8ms/call # spent 6µs making 3 calls to XML::LibXML::Node::DESTROY, avg 2µs/call
51}
52
53
# spent 542ms (3.67+539) within XML::LibXML::SAX::Parser::generate which was called 28 times, avg 19.4ms/call: # 25 times (3.21ms+450ms) by XML::LibXML::SAX::Parser::_parse_string at line 43, avg 18.1ms/call # 3 times (460µs+88.8ms) by XML::LibXML::SAX::Parser::_parse_systemid at line 50, avg 29.8ms/call
sub generate {
544484.66ms my $self = shift;
55 my ($node) = @_;
56
5728246µs my $doc = $node->ownerDocument();
# spent 246µs making 28 calls to XML::LibXML::Node::ownerDocument, avg 9µs/call
58 {
59 # precompute some DocumentLocator values
60 my %locator = (
61 PublicId => undef,
62 SystemId => undef,
63 Encoding => undef,
64 XMLVersion => undef,
65 );
662886µs my $dtd = defined $doc ? $doc->externalSubset() : undef;
# spent 86µs making 28 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 }
71 if (defined $doc) {
722880µs $locator{Encoding} = $doc->encoding();
# spent 80µs making 28 calls to XML::LibXML::Document::encoding, avg 3µs/call
732870µs $locator{XMLVersion} = $doc->version();
# spent 70µs making 28 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} },
83562.75ms ),
# spent 1.46ms making 28 calls to XML::SAX::Base::set_document_locator, avg 52µs/call # spent 1.30ms making 28 calls to XML::SAX::DocumentLocator::new, avg 46µs/call
84 );
85 }
86
8728124µs if ( $node->nodeType() == XML_DOCUMENT_NODE
# spent 124µs making 28 calls to XML::LibXML::Node::nodeType, avg 4µs/call
88 || $node->nodeType == XML_HTML_DOCUMENT_NODE ) {
89281.36ms $self->start_document({});
# spent 1.36ms making 28 calls to XML::SAX::Base::start_document, avg 48µs/call
90841.37ms $self->xml_decl({Version => $node->getVersion, Encoding => $node->getEncoding});
# spent 1.24ms making 28 calls to XML::SAX::Base::xml_decl, avg 44µs/call # spent 86µs making 28 calls to XML::LibXML::Document::getVersion, avg 3µs/call # spent 51µs making 28 calls to XML::LibXML::Document::getEncoding, avg 2µs/call
9128531ms $self->process_node($node);
# spent 531ms making 28 calls to XML::LibXML::SAX::Parser::process_node, avg 19.0ms/call
92561.69ms $self->end_document({});
# spent 1.64ms making 28 calls to XML::SAX::Base::end_document, avg 59µs/call # spent 54µs making 28 calls to XML::LibXML::Node::DESTROY, avg 2µs/call
93 }
94}
95
96
# spent 531ms (62.0+469) within XML::LibXML::SAX::Parser::process_node which was called 4833 times, avg 110µs/call: # 4777 times (60.8ms+-60.8ms) by XML::LibXML::SAX::Parser::process_element at line 244, avg 0s/call # 28 times (849µs+530ms) by XML::LibXML::SAX::Parser::generate at line 91, avg 19.0ms/call # 28 times (387µs+-387µs) by XML::LibXML::SAX::Parser::process_node at line 127, avg 0s/call
sub process_node {
971936081.0ms my ($self, $node) = @_;
98
99 local $self->{current_node} = $node;
100
101483310.6ms my $node_type = $node->nodeType();
# spent 10.6ms making 4833 calls to XML::LibXML::Node::nodeType, avg 2µs/call
1028044589ms if ($node_type == XML_COMMENT_NODE) {
# spent 1.35s making 1619 calls to XML::LibXML::SAX::Parser::process_element, avg 832µs/call, recursion: max depth 7, sum of overlapping time 818ms # spent 49.8ms making 3147 calls to XML::SAX::Base::characters, avg 16µs/call # spent 8.75ms making 3147 calls to XML::LibXML::Node::nodeValue, avg 3µs/call # spent 502µs making 28 calls to XML::LibXML::Node::childNodes, avg 18µs/call # spent 493µs making 39 calls to XML::SAX::Base::comment, avg 13µs/call # spent 206µs making 39 calls to XML::LibXML::Node::getData, avg 5µs/call # spent 68µ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) {
1275334µs $self->process_node($kid);
# spent 34µs making 25 calls to XML::LibXML::Namespace::DESTROY, avg 1µs/call # spent 529ms making 28 calls to XML::LibXML::SAX::Parser::process_node, avg 18.9ms/call, recursion: max depth 1, sum of overlapping time 529ms
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 529ms (189+340) within XML::LibXML::SAX::Parser::process_element which was called 1619 times, avg 327µs/call: # 1619 times (189ms+340ms) by XML::LibXML::SAX::Parser::process_node at line 102, avg 327µs/call
sub process_element {
15253235244ms my ($self, $element) = @_;
153
154 my $attribs = {};
15516192.80ms my @ns_maps = $element->getNamespaces;
# spent 2.80ms making 1619 calls to XML::LibXML::Node::getNamespaces, avg 2µs/call
156
157 foreach my $ns (@ns_maps) {
1581872.24ms $self->start_prefix_mapping(
# spent 1.99ms making 53 calls to XML::SAX::Base::start_prefix_mapping, avg 38µs/call # spent 139µs making 53 calls to XML::LibXML::Namespace::href, avg 3µs/call # spent 115µs making 81 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
166161918.3ms foreach my $attr ($element->attributes) {
# spent 18.3ms making 1619 calls to XML::LibXML::Node::attributes, avg 11µs/call
167 my $key;
168 # warn("Attr: $attr -> ", $attr->getName, " = ", $attr->getData, "\n");
169 # this isa dump thing...
17026346.71ms if ($attr->isa('XML::LibXML::Namespace')) {
# spent 6.71ms making 2634 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.
17353206µs unless ( defined $attr->name ) {
# spent 206µs making 53 calls to XML::LibXML::Namespace::name, avg 4µ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";
1865384µs my $localname = $attr->localname;
# spent 84µs making 53 calls to XML::LibXML::Namespace::localname, avg 2µs/call
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
1955399µs $attribs->{$key} =
# spent 99µs making 53 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 {
20625814.42ms my $ns = $attr->namespaceURI;
# spent 4.42ms making 2581 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call
207
208 $ns = '' unless defined $ns;
20925814.94ms $key = "{$ns}".$attr->localname;
# spent 4.94ms making 2581 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.
21225813.74ms my $name = $attr->name;
# spent 3.74ms making 2581 calls to XML::LibXML::Attr::name, avg 1µs/call
213 $name = "" unless defined $name;
214
21525813.66ms my $prefix = $attr->prefix;
# spent 3.66ms making 2581 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
220516210.2ms $attribs->{$key} =
# spent 6.47ms making 2581 calls to XML::LibXML::Attr::value, avg 3µs/call # spent 3.75ms making 2581 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
233911015.5ms my $node = {
# spent 3.92ms making 1619 calls to XML::LibXML::Node::nodeName, avg 2µs/call # spent 3.60ms making 2581 calls to XML::LibXML::Node::DESTROY, avg 1µs/call # spent 3.06ms making 1619 calls to XML::LibXML::Node::namespaceURI, avg 2µs/call # spent 2.40ms making 1619 calls to XML::LibXML::Node::localname, avg 1µs/call # spent 2.18ms making 1619 calls to XML::LibXML::Node::prefix, avg 1µs/call # spent 302µs making 53 calls to XML::LibXML::Namespace::DESTROY, avg 6µs/call
234 Name => $element->nodeName,
235 Attributes => $attribs,
236 NamespaceURI => $element->namespaceURI,
237 Prefix => $element->prefix || "",
238 LocalName => $element->localname,
239 };
240
241161935.0ms $self->start_element($node);
# spent 35.0ms making 1619 calls to XML::SAX::Base::start_element, avg 22µs/call
242
243161922.9ms foreach my $child ($element->childNodes) {
# spent 22.9ms making 1619 calls to XML::LibXML::Node::childNodes, avg 14µs/call
24447807µs $self->process_node($child);
# spent 7µs making 3 calls to XML::LibXML::Namespace::DESTROY, avg 2µs/call # spent 949ms making 4777 calls to XML::LibXML::SAX::Parser::process_node, avg 199µs/call, recursion: max depth 8, sum of overlapping time 949ms
245 }
246
24747776.28ms my $end_node = { %$node };
# spent 6.28ms making 4777 calls to XML::LibXML::Node::DESTROY, avg 1µs/call
248
249 delete $end_node->{Attributes};
250
251161968.8ms $self->end_element($end_node);
# spent 68.8ms making 1619 calls to XML::SAX::Base::end_element, avg 42µs/call
252
253 foreach my $ns (@ns_maps) {
2541872.51ms $self->end_prefix_mapping(
# spent 2.24ms making 53 calls to XML::SAX::Base::end_prefix_mapping, avg 42µs/call # spent 161µs making 53 calls to XML::LibXML::Namespace::href, avg 3µs/call # spent 107µs making 81 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
26316µs1;
264
265__END__
Report produced by the NYTProf 4.04 Perl profiler, developed by Tim Bunce and Adam Kaplan.