← Index
NYTProf Performance Profile   « block view • line view • sub view »
For mentat.storage.mongo.pl
  Run on Tue Jun 24 10:04:38 2014
Reported on Tue Jun 24 10:05:19 2014

Filename/usr/local/lib/perl/5.14.2/MongoDB/Cursor.pm
StatementsExecuted 114 statements in 13.4s
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
111840µs4.00msMongoDB::Cursor::::BEGIN@25MongoDB::Cursor::BEGIN@25
433352µs13.4sMongoDB::Cursor::::nextMongoDB::Cursor::next (xsub)
433229µs13.4sMongoDB::Cursor::::_do_queryMongoDB::Cursor::_do_query
11156µs5.85sMongoDB::Cursor::::countMongoDB::Cursor::count
11139µs5.24sMongoDB::Cursor::::explainMongoDB::Cursor::explain
32230µs47µsMongoDB::Cursor::::DESTROYMongoDB::Cursor::DESTROY (xsub)
32230µs49µsMongoDB::Cursor::::_dt_typeMongoDB::Cursor::_dt_type
32223µs63µsMongoDB::Cursor::::limitMongoDB::Cursor::limit
32219µs31µsMongoDB::Cursor::::_inflate_dbrefsMongoDB::Cursor::_inflate_dbrefs
21117µs26µsMongoDB::Cursor::::fieldsMongoDB::Cursor::fields
11115µs27µsMongoDB::Cursor::::_ensure_specialMongoDB::Cursor::_ensure_special
11112µs3.51msMongoDB::Cursor::::BEGIN@24MongoDB::Cursor::BEGIN@24
22111µs19µsMongoDB::Cursor::::resetMongoDB::Cursor::reset (xsub)
1119µs9µsMongoDB::Cursor::::BEGIN@26MongoDB::Cursor::BEGIN@26
3116µs6µsMongoDB::Cursor::::_initMongoDB::Cursor::_init (xsub)
1114µs4µsMongoDB::Cursor::::CORE:matchMongoDB::Cursor::CORE:match (opcode)
0000s0sMongoDB::Cursor::::allMongoDB::Cursor::all
0000s0sMongoDB::Cursor::::hintMongoDB::Cursor::hint
0000s0sMongoDB::Cursor::::skipMongoDB::Cursor::skip
0000s0sMongoDB::Cursor::::snapshotMongoDB::Cursor::snapshot
0000s0sMongoDB::Cursor::::sortMongoDB::Cursor::sort
0000s0sMongoDB::Cursor::::tailableMongoDB::Cursor::tailable
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments
Time
on line
Calls Time
in subs
Code
1#
2# Copyright 2009-2013 MongoDB, Inc.
3#
4# Licensed under the Apache License, Version 2.0 (the "License");
5# you may not use this file except in compliance with the License.
6# You may obtain a copy of the License at
7#
8# http://www.apache.org/licenses/LICENSE-2.0
9#
10# Unless required by applicable law or agreed to in writing, software
11# distributed under the License is distributed on an "AS IS" BASIS,
12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13# See the License for the specific language governing permissions and
14# limitations under the License.
15#
16
17package MongoDB::Cursor;
18{
1921µs $MongoDB::Cursor::VERSION = '0.702.2';
20}
21
22
23# ABSTRACT: A cursor/iterator for Mongo query results
24232µs27.00ms
# spent 3.51ms (12µs+3.50) within MongoDB::Cursor::BEGIN@24 which was called: # once (12µs+3.50ms) by MongoDB::Connection::BEGIN@27 at line 24
use Moose;
# spent 3.51ms making 1 call to MongoDB::Cursor::BEGIN@24 # spent 3.50ms making 1 call to Moose::Exporter::__ANON__[Moose/Exporter.pm:519]
252118µs24.00ms
# spent 4.00ms (840µs+3.16) within MongoDB::Cursor::BEGIN@25 which was called: # once (840µs+3.16ms) by MongoDB::Connection::BEGIN@27 at line 25
use boolean;
# spent 4.00ms making 1 call to MongoDB::Cursor::BEGIN@25 # spent 6µs making 1 call to boolean::import
262953µs19µs
# spent 9µs within MongoDB::Cursor::BEGIN@26 which was called: # once (9µs+0s) by MongoDB::Connection::BEGIN@27 at line 26
use Tie::IxHash;
# spent 9µs making 1 call to MongoDB::Cursor::BEGIN@26
27
28
29120µs$MongoDB::Cursor::_request_id = int(rand(1000000));
30
31
321100ns$MongoDB::Cursor::slave_okay = 0;
33
34
351100ns$MongoDB::Cursor::timeout = 30000;
36
37
3813µs12.55mshas started_iterating => (
# spent 2.55ms making 1 call to Moose::has
39 is => 'rw',
40 isa => 'Bool',
41 required => 1,
42 default => 0,
43);
44
4512µs12.33mshas _client => (
# spent 2.33ms making 1 call to Moose::has
46 is => 'ro',
47 isa => 'MongoDB::MongoClient',
48 required => 1,
49);
50
5111µs11.53mshas _ns => (
# spent 1.53ms making 1 call to Moose::has
52 is => 'ro',
53 isa => 'Str',
54 required => 1,
55);
56
5712µs11.43mshas _query => (
# spent 1.43ms making 1 call to Moose::has
58 is => 'rw',
59 required => 1,
60);
61
6211µs11.33mshas _fields => (
# spent 1.33ms making 1 call to Moose::has
63 is => 'rw',
64 required => 0,
65);
66
6711µs11.76mshas _limit => (
# spent 1.76ms making 1 call to Moose::has
68 is => 'rw',
69 isa => 'Int',
70 required => 0,
71 default => 0,
72);
73
7411µs11.74mshas _skip => (
# spent 1.74ms making 1 call to Moose::has
75 is => 'rw',
76 isa => 'Int',
77 required => 0,
78 default => 0,
79);
80
8111µs11.70mshas _tailable => (
# spent 1.70ms making 1 call to Moose::has
82 is => 'rw',
83 isa => 'Bool',
84 required => 0,
85 default => 0,
86);
87
- -
9311µs11.70mshas immortal => (
# spent 1.70ms making 1 call to Moose::has
94 is => 'rw',
95 isa => 'Bool',
96 required => 0,
97 default => 0,
98);
99
- -
10211µs11.73mshas partial => (
# spent 1.73ms making 1 call to Moose::has
103 is => 'rw',
104 isa => 'Bool',
105 required => 0,
106 default => 0,
107);
108
109
11011µs11.72mshas slave_okay => (
# spent 1.72ms making 1 call to Moose::has
111 is => 'rw',
112 isa => 'Bool',
113 required => 0,
114 default => 0,
115);
116
117
118# stupid hack for inconsistent database handling of queries
11911µs11.80mshas _grrrr => (
# spent 1.80ms making 1 call to Moose::has
120 is => 'rw',
121 isa => 'Bool',
122 default => 0,
123);
124
12512µs11.77mshas _request_id => (
# spent 1.77ms making 1 call to Moose::has
126 is => 'rw',
127 isa => 'Int',
128 default => 0,
129);
130
131
132
# spent 27µs (15+12) within MongoDB::Cursor::_ensure_special which was called: # once (15µs+12µs) by MongoDB::Cursor::explain at line 256
sub _ensure_special {
133411µs my ($self) = @_;
134
13513µs if ($self->_grrrr) {
# spent 3µs making 1 call to MongoDB::Cursor::_grrrr
136 return;
137 }
138
13915µs $self->_grrrr(1);
# spent 5µs making 1 call to MongoDB::Cursor::_grrrr
14025µs $self->_query({'query' => $self->_query})
# spent 5µs making 2 calls to MongoDB::Cursor::_query, avg 2µs/call
141}
142
143# this does the query if it hasn't been done yet
144
# spent 13.4s (229µs+13.4) within MongoDB::Cursor::_do_query which was called 4 times, avg 3.35s/call: # 2 times (129µs+5.85s) by MongoDB::Cursor::next at line 144 of MongoDB/Collection.pm, avg 2.92s/call # once (48µs+5.24s) by MongoDB::Cursor::next at line 259 # once (52µs+2.31s) by MongoDB::Cursor::next at line 40 of mentat.storage.mongo.pl
sub _do_query {
14532378µs my ($self) = @_;
146
147412µs if ($self->started_iterating) {
# spent 12µs making 4 calls to MongoDB::Cursor::started_iterating, avg 3µs/call
148 return;
149 }
150
1511644µs my $opts = ($self->_tailable() << 1) |
# spent 12µs making 4 calls to MongoDB::Cursor::_tailable, avg 3µs/call # spent 11µs making 4 calls to MongoDB::Cursor::partial, avg 3µs/call # spent 11µs making 4 calls to MongoDB::Cursor::slave_okay, avg 3µs/call # spent 10µs making 4 calls to MongoDB::Cursor::immortal, avg 3µs/call
152 (($MongoDB::Cursor::slave_okay | $self->slave_okay) << 2) |
153 ($self->immortal << 4) |
154 ($self->partial << 7);
155
156138µs36241µs my ($query, $info) = MongoDB::write_query($self->_ns, $opts, $self->_skip, $self->_limit, $self->_query, $self->_fields);
# spent 176µs making 4 calls to MongoDB::write_query, avg 44µs/call # spent 15µs making 6 calls to MongoDB::BSON::Binary::subtype, avg 2µs/call # spent 12µs making 6 calls to MongoDB::BSON::Binary::data, avg 2µs/call # spent 11µs making 4 calls to MongoDB::Cursor::_ns, avg 3µs/call # spent 11µs making 4 calls to MongoDB::Cursor::_skip, avg 3µs/call # spent 7µs making 4 calls to MongoDB::Cursor::_query, avg 2µs/call # spent 6µs making 4 calls to MongoDB::Cursor::_fields, avg 2µs/call # spent 4µs making 4 calls to MongoDB::Cursor::_limit, avg 1µs/call
157441µs $self->_request_id($info->{'request_id'});
# spent 41µs making 4 calls to MongoDB::Cursor::_request_id, avg 10µs/call
158
159884µs $self->_client->send($query);
# spent 75µs making 4 calls to MongoDB::MongoClient::send, avg 19µs/call # spent 9µs making 4 calls to MongoDB::Cursor::_client, avg 2µs/call
160113.4s2013.4s $self->_client->recv($self);
# spent 13.4s making 4 calls to MongoDB::MongoClient::recv, avg 3.35s/call # spent 38µs making 4 calls to MongoDB::Cursor::_request_id, avg 10µs/call # spent 26µs making 8 calls to MongoDB::Cursor::_client, avg 3µs/call # spent 11µs making 4 calls to MongoDB::MongoClient::query_timeout, avg 3µs/call
161
162438µs $self->started_iterating(1);
# spent 38µs making 4 calls to MongoDB::Cursor::started_iterating, avg 10µs/call
163}
164
165
166
# spent 26µs (17+9) within MongoDB::Cursor::fields which was called 2 times, avg 13µs/call: # 2 times (17µs+9µs) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 13µs/call
sub fields {
1671015µs my ($self, $f) = @_;
16822µs confess "cannot set fields after querying"
# spent 2µs making 2 calls to MongoDB::Cursor::started_iterating, avg 1µs/call
169 if $self->started_iterating;
170 confess 'not a hash reference'
171 unless ref $f eq 'HASH' || ref $f eq 'Tie::IxHash';
172
17327µs $self->_fields($f);
# spent 7µs making 2 calls to MongoDB::Cursor::_fields, avg 3µs/call
174 return $self;
175}
176
177
178sub sort {
179 my ($self, $order) = @_;
180 confess "cannot set sort after querying"
181 if $self->started_iterating;
182 confess 'not a hash reference'
183 unless ref $order eq 'HASH' || ref $order eq 'Tie::IxHash';
184
185 $self->_ensure_special;
186 $self->_query->{'orderby'} = $order;
187 return $self;
188}
189
- -
192
# spent 63µs (23+40) within MongoDB::Cursor::limit which was called 3 times, avg 21µs/call: # 2 times (15µs+26µs) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 21µs/call # once (8µs+14µs) by MongoDB::Cursor::explain at line 260
sub limit {
1931220µs my ($self, $num) = @_;
19437µs confess "cannot set limit after querying"
# spent 7µs making 3 calls to MongoDB::Cursor::started_iterating, avg 2µs/call
195 if $self->started_iterating;
196
197332µs $self->_limit($num);
# spent 32µs making 3 calls to MongoDB::Cursor::_limit, avg 11µs/call
198 return $self;
199}
200
- -
203sub tailable {
204 my($self, $bool) = @_;
205 confess "cannot set tailable after querying"
206 if $self->started_iterating;
207
208 $self->_tailable($bool);
209 return $self;
210}
211
- -
215sub skip {
216 my ($self, $num) = @_;
217 confess "cannot set skip after querying"
218 if $self->started_iterating;
219
220 $self->_skip($num);
221 return $self;
222}
223
224
225sub snapshot {
226 my ($self) = @_;
227 confess "cannot set snapshot after querying"
228 if $self->started_iterating;
229
230 $self->_ensure_special;
231 $self->_query->{'$snapshot'} = 1;
232 return $self;
233}
234
235
236sub hint {
237 my ($self, $index) = @_;
238 confess "cannot set hint after querying"
239 if $self->started_iterating;
240 confess 'not a hash reference'
241 unless ref $index eq 'HASH' || ref $index eq 'Tie::IxHash';
242
243 $self->_ensure_special;
244 $self->_query->{'$hint'} = $index;
245 return $self;
246}
247
248
249
# spent 5.24s (39µs+5.24) within MongoDB::Cursor::explain which was called: # once (39µs+5.24s) by Mentat::Storage::Mongo::_set_last_index at line 829 of Mentat/Storage/Mongo.pm
sub explain {
250925µs my ($self) = @_;
25112µs my $temp = $self->_limit;
# spent 2µs making 1 call to MongoDB::Cursor::_limit
25211µs if ($self->_limit > 0) {
# spent 1µs making 1 call to MongoDB::Cursor::_limit
253 $self->_limit($self->_limit * -1);
254 }
255
256127µs $self->_ensure_special;
# spent 27µs making 1 call to MongoDB::Cursor::_ensure_special
25723µs $self->_query->{'$explain'} = boolean::true;
# spent 2µs making 1 call to boolean::true # spent 1µs making 1 call to MongoDB::Cursor::_query
258
2591242µs2710.5s my $retval = $self->reset->next;
# spent 5.24s making 1 call to MongoDB::Cursor::next # spent 5.24s making 1 call to MongoDB::Cursor::_do_query # spent 17µs making 19 calls to boolean::false, avg 900ns/call # spent 15µs making 1 call to MongoDB::Cursor::_dt_type # spent 11µs making 1 call to MongoDB::Cursor::_inflate_dbrefs # spent 8µs making 1 call to MongoDB::Cursor::reset # spent 3µs making 1 call to MongoDB::Cursor::started_iterating # spent 3µs making 1 call to MongoDB::Cursor::_limit # spent 1µs making 1 call to MongoDB::Cursor::_client
26015µs337µs $self->reset->limit($temp);
# spent 21µs making 1 call to MongoDB::Cursor::limit # spent 11µs making 1 call to MongoDB::Cursor::reset # spent 5µs making 1 call to MongoDB::Cursor::started_iterating
261
26213µs undef $self->_query->{'$explain'};
# spent 3µs making 1 call to MongoDB::Cursor::_query
263
264 return $retval;
265}
266
267
268
# spent 5.85s (56µs+5.85) within MongoDB::Cursor::count which was called: # once (56µs+5.85s) by Mentat::Storage::Mongo::find_i at line 398 of Mentat/Storage/Mongo.pm
sub count {
269841µs my ($self, $all) = @_;
270
27125µs my ($db, $coll) = $self->_ns =~ m/^([^\.]+)\.(.*)/;
# spent 4µs making 1 call to MongoDB::Cursor::CORE:match # spent 2µs making 1 call to MongoDB::Cursor::_ns
272121µs my $cmd = new Tie::IxHash(count => $coll);
# spent 21µs making 1 call to Tie::IxHash::new
273
27413µs14µs if ($self->_grrrr) {
# spent 4µs making 1 call to MongoDB::Cursor::_grrrr
275 $cmd->Push(query => $self->_query->{'query'});
276 }
277 else {
27829µs $cmd->Push(query => $self->_query);
# spent 8µs making 1 call to Tie::IxHash::Push # spent 1µs making 1 call to MongoDB::Cursor::_query
279 }
280
281 if ($all) {
282 $cmd->Push(limit => $self->_limit) if $self->_limit;
283 $cmd->Push(skip => $self->_skip) if $self->_skip;
284 }
285
28635.85s my $result = $self->_client->get_database($db)->run_command($cmd);
# spent 5.85s making 1 call to MongoDB::Database::run_command # spent 20µs making 1 call to MongoDB::MongoClient::get_database # spent 1µs making 1 call to MongoDB::Cursor::_client
287
288 # returns "ns missing" if collection doesn't exist
28911µs15µs return 0 unless ref $result eq 'HASH';
# spent 5µs making 1 call to MongoDB::Database::DESTROY
290 return $result->{'n'};
291}
292
293
294# shortcut to make some XS code saner
295
# spent 49µs (30+19) within MongoDB::Cursor::_dt_type which was called 3 times, avg 16µs/call: # 2 times (21µs+12µs) by MongoDB::Cursor::next at line 144 of MongoDB/Collection.pm, avg 17µs/call # once (8µs+7µs) by MongoDB::Cursor::next at line 259
sub _dt_type {
296626µs my $self = shift;
297619µs return $self->_client->dt_type;
# spent 12µs making 3 calls to MongoDB::MongoClient::dt_type, avg 4µs/call # spent 7µs making 3 calls to MongoDB::Cursor::_client, avg 2µs/call
298}
299
300
# spent 31µs (19+12) within MongoDB::Cursor::_inflate_dbrefs which was called 3 times, avg 10µs/call: # 2 times (12µs+7µs) by MongoDB::Cursor::next at line 144 of MongoDB/Collection.pm, avg 10µs/call # once (6µs+4µs) by MongoDB::Cursor::next at line 259
sub _inflate_dbrefs {
301617µs my $self = shift;
302612µs return $self->_client->inflate_dbrefs;
# spent 9µs making 3 calls to MongoDB::MongoClient::inflate_dbrefs, avg 3µs/call # spent 3µs making 3 calls to MongoDB::Cursor::_client, avg 1µs/call
303}
304
- -
307sub all {
308 my ($self) = @_;
309 my @ret;
310
311 while (my $entry = $self->next) {
312 push @ret, $entry;
313 }
314
315 return @ret;
316}
317
318
31916µs222.7ms__PACKAGE__->meta->make_immutable (inline_destructor => 0);
# spent 22.6ms making 1 call to Class::MOP::Class::make_immutable # spent 13µs making 1 call to MongoDB::Cursor::meta
320
321118µs1;
322
323__END__
 
# spent 4µs within MongoDB::Cursor::CORE:match which was called: # once (4µs+0s) by MongoDB::Cursor::count at line 271
sub MongoDB::Cursor::CORE:match; # opcode
# spent 47µs (30+17) within MongoDB::Cursor::DESTROY which was called 3 times, avg 16µs/call: # 2 times (18µs+8µs) by MongoDB::Database::run_command at line 110 of MongoDB/Database.pm, avg 13µs/call # once (13µs+9µs) by main::NULL at line 0 of mentat.storage.mongo.pl
sub MongoDB::Cursor::DESTROY; # xsub
# spent 6µs within MongoDB::Cursor::_init which was called 3 times, avg 2µs/call: # 3 times (6µs+0s) by MongoDB::Collection::find at line 125 of MongoDB/Collection.pm, avg 2µs/call
sub MongoDB::Cursor::_init; # xsub
# spent 13.4s (352µs+13.4) within MongoDB::Cursor::next which was called 4 times, avg 3.35s/call: # 2 times (76µs+5.85s) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 2.92s/call # once (256µs+5.24s) by MongoDB::Cursor::explain at line 259 # once (20µs+2.31s) by main::RUNTIME at line 40 of mentat.storage.mongo.pl
sub MongoDB::Cursor::next; # xsub
# spent 19µs (11+8) within MongoDB::Cursor::reset which was called 2 times, avg 9µs/call: # once (6µs+5µs) by MongoDB::Cursor::explain at line 260 # once (5µs+3µs) by MongoDB::Cursor::explain at line 259
sub MongoDB::Cursor::reset; # xsub