← Index
NYTProf Performance Profile   « block view • line view • sub view »
For mentat.storage.mongo.pl
  Run on Tue Jun 24 09:58:41 2014
Reported on Tue Jun 24 09:59:36 2014

Filename/usr/local/lib/perl/5.14.2/MongoDB/Cursor.pm
StatementsExecuted 119 statements in 12.8s
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
111773µs3.80msMongoDB::Cursor::::BEGIN@25MongoDB::Cursor::BEGIN@25
433343µs12.8sMongoDB::Cursor::::nextMongoDB::Cursor::next (xsub)
433197µs12.8sMongoDB::Cursor::::_do_queryMongoDB::Cursor::_do_query
11149µs4.73sMongoDB::Cursor::::explainMongoDB::Cursor::explain
11147µs5.74sMongoDB::Cursor::::countMongoDB::Cursor::count
32230µs44µsMongoDB::Cursor::::DESTROYMongoDB::Cursor::DESTROY (xsub)
32230µs47µsMongoDB::Cursor::::_dt_typeMongoDB::Cursor::_dt_type
43327µs74µsMongoDB::Cursor::::limitMongoDB::Cursor::limit
32218µs30µsMongoDB::Cursor::::_inflate_dbrefsMongoDB::Cursor::_inflate_dbrefs
11115µs27µsMongoDB::Cursor::::_ensure_specialMongoDB::Cursor::_ensure_special
21114µs22µsMongoDB::Cursor::::fieldsMongoDB::Cursor::fields
11114µs3.41msMongoDB::Cursor::::BEGIN@24MongoDB::Cursor::BEGIN@24
22110µs16µsMongoDB::Cursor::::resetMongoDB::Cursor::reset (xsub)
1117µs7µsMongoDB::Cursor::::BEGIN@26MongoDB::Cursor::BEGIN@26
3116µs6µsMongoDB::Cursor::::_initMongoDB::Cursor::_init (xsub)
1113µs3µ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µs26.81ms
# spent 3.41ms (14µs+3.40) within MongoDB::Cursor::BEGIN@24 which was called: # once (14µs+3.40ms) by MongoDB::Connection::BEGIN@27 at line 24
use Moose;
# spent 3.41ms making 1 call to MongoDB::Cursor::BEGIN@24 # spent 3.40ms making 1 call to Moose::Exporter::__ANON__[Moose/Exporter.pm:519]
25299µs23.80ms
# spent 3.80ms (773µs+3.02) within MongoDB::Cursor::BEGIN@25 which was called: # once (773µs+3.02ms) by MongoDB::Connection::BEGIN@27 at line 25
use boolean;
# spent 3.80ms making 1 call to MongoDB::Cursor::BEGIN@25 # spent 6µs making 1 call to boolean::import
262932µs17µs
# spent 7µs within MongoDB::Cursor::BEGIN@26 which was called: # once (7µs+0s) by MongoDB::Connection::BEGIN@27 at line 26
use Tie::IxHash;
# spent 7µs making 1 call to MongoDB::Cursor::BEGIN@26
27
28
29113µs$MongoDB::Cursor::_request_id = int(rand(1000000));
30
31
321200ns$MongoDB::Cursor::slave_okay = 0;
33
34
351100ns$MongoDB::Cursor::timeout = 30000;
36
37
3812µs12.40mshas started_iterating => (
# spent 2.40ms making 1 call to Moose::has
39 is => 'rw',
40 isa => 'Bool',
41 required => 1,
42 default => 0,
43);
44
4511µs12.21mshas _client => (
# spent 2.21ms making 1 call to Moose::has
46 is => 'ro',
47 isa => 'MongoDB::MongoClient',
48 required => 1,
49);
50
5112µs11.44mshas _ns => (
# spent 1.44ms 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.31mshas _fields => (
# spent 1.31ms making 1 call to Moose::has
63 is => 'rw',
64 required => 0,
65);
66
6711µs11.74mshas _limit => (
# spent 1.74ms making 1 call to Moose::has
68 is => 'rw',
69 isa => 'Int',
70 required => 0,
71 default => 0,
72);
73
7411µs11.71mshas _skip => (
# spent 1.71ms making 1 call to Moose::has
75 is => 'rw',
76 isa => 'Int',
77 required => 0,
78 default => 0,
79);
80
8111µs11.66mshas _tailable => (
# spent 1.66ms making 1 call to Moose::has
82 is => 'rw',
83 isa => 'Bool',
84 required => 0,
85 default => 0,
86);
87
- -
9311µs11.66mshas immortal => (
# spent 1.66ms making 1 call to Moose::has
94 is => 'rw',
95 isa => 'Bool',
96 required => 0,
97 default => 0,
98);
99
- -
10211µs11.68mshas partial => (
# spent 1.68ms making 1 call to Moose::has
103 is => 'rw',
104 isa => 'Bool',
105 required => 0,
106 default => 0,
107);
108
109
11011µs11.66mshas slave_okay => (
# spent 1.66ms 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
11912µs11.67mshas _grrrr => (
# spent 1.67ms making 1 call to Moose::has
120 is => 'rw',
121 isa => 'Bool',
122 default => 0,
123);
124
12512µs11.80mshas _request_id => (
# spent 1.80ms 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 {
1331900ns my ($self) = @_;
134
13512µs13µs if ($self->_grrrr) {
# spent 3µs making 1 call to MongoDB::Cursor::_grrrr
136 return;
137 }
138
13911µs15µs $self->_grrrr(1);
# spent 5µs making 1 call to MongoDB::Cursor::_grrrr
14017µs25µ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 12.8s (197µs+12.8) within MongoDB::Cursor::_do_query which was called 4 times, avg 3.21s/call: # 2 times (100µs+5.74s) by MongoDB::Cursor::next at line 144 of MongoDB/Collection.pm, avg 2.87s/call # once (48µs+4.73s) by MongoDB::Cursor::next at line 259 # once (48µs+2.37s) by MongoDB::Cursor::next at line 458 of Mentat/Storage/Mongo.pm
sub _do_query {
14542µs my ($self) = @_;
146
14744µs46µs if ($self->started_iterating) {
# spent 6µs making 4 calls to MongoDB::Cursor::started_iterating, avg 1µs/call
148 return;
149 }
150
151430µs1636µs my $opts = ($self->_tailable() << 1) |
# spent 10µs making 4 calls to MongoDB::Cursor::_tailable, avg 3µs/call # spent 9µs making 4 calls to MongoDB::Cursor::slave_okay, avg 2µs/call # spent 8µs making 4 calls to MongoDB::Cursor::immortal, avg 2µs/call # spent 8µs making 4 calls to MongoDB::Cursor::partial, avg 2µs/call
152 (($MongoDB::Cursor::slave_okay | $self->slave_okay) << 2) |
153 ($self->immortal << 4) |
154 ($self->partial << 7);
155
1564162µs36216µs my ($query, $info) = MongoDB::write_query($self->_ns, $opts, $self->_skip, $self->_limit, $self->_query, $self->_fields);
# spent 158µs making 4 calls to MongoDB::write_query, avg 39µs/call # spent 13µs making 6 calls to MongoDB::BSON::Binary::subtype, avg 2µs/call # spent 11µs making 6 calls to MongoDB::BSON::Binary::data, avg 2µs/call # spent 10µs making 4 calls to MongoDB::Cursor::_ns, avg 3µs/call # spent 8µs making 4 calls to MongoDB::Cursor::_skip, avg 2µs/call # spent 7µs making 4 calls to MongoDB::Cursor::_fields, avg 2µs/call # spent 5µs making 4 calls to MongoDB::Cursor::_query, avg 1µs/call # spent 4µs making 4 calls to MongoDB::Cursor::_limit, avg 1µs/call
15747µs436µs $self->_request_id($info->{'request_id'});
# spent 36µs making 4 calls to MongoDB::Cursor::_request_id, avg 9µs/call
158
159499µs887µs $self->_client->send($query);
# spent 81µs making 4 calls to MongoDB::MongoClient::send, avg 20µs/call # spent 7µs making 4 calls to MongoDB::Cursor::_client, avg 2µs/call
160412.8s2012.8s $self->_client->recv($self);
# spent 12.8s making 4 calls to MongoDB::MongoClient::recv, avg 3.21s/call # spent 38µs making 4 calls to MongoDB::Cursor::_request_id, avg 9µs/call # spent 13µs making 8 calls to MongoDB::Cursor::_client, avg 2µs/call # spent 9µs making 4 calls to MongoDB::MongoClient::query_timeout, avg 2µs/call
161
162444µs435µs $self->started_iterating(1);
# spent 35µs making 4 calls to MongoDB::Cursor::started_iterating, avg 9µs/call
163}
164
165
166
# spent 22µs (14+8) within MongoDB::Cursor::fields which was called 2 times, avg 11µs/call: # 2 times (14µs+8µs) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 11µs/call
sub fields {
16722µs my ($self, $f) = @_;
16822µs22µ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;
17022µs confess 'not a hash reference'
171 unless ref $f eq 'HASH' || ref $f eq 'Tie::IxHash';
172
17323µs26µs $self->_fields($f);
# spent 6µs making 2 calls to MongoDB::Cursor::_fields, avg 3µs/call
17424µs 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 74µs (27+47) within MongoDB::Cursor::limit which was called 4 times, avg 19µs/call: # 2 times (13µs+21µs) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 17µs/call # once (7µs+13µs) by MongoDB::Cursor::explain at line 260 # once (7µs+13µs) by Mentat::Storage::Mongo::find_i at line 419 of Mentat/Storage/Mongo.pm
sub limit {
19343µs my ($self, $num) = @_;
19445µs47µs confess "cannot set limit after querying"
# spent 7µs making 4 calls to MongoDB::Cursor::started_iterating, avg 2µs/call
195 if $self->started_iterating;
196
19745µs441µs $self->_limit($num);
# spent 41µs making 4 calls to MongoDB::Cursor::_limit, avg 10µs/call
198410µs 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 4.73s (49µs+4.73) within MongoDB::Cursor::explain which was called: # once (49µs+4.73s) by Mentat::Storage::Mongo::_set_last_index at line 829 of Mentat/Storage/Mongo.pm
sub explain {
2501500ns my ($self) = @_;
25111µs11µs my $temp = $self->_limit;
# spent 1µs making 1 call to MongoDB::Cursor::_limit
25211µs11µs if ($self->_limit > 0) {
# spent 1µs making 1 call to MongoDB::Cursor::_limit
25313µs27µs $self->_limit($self->_limit * -1);
# spent 7µs making 2 calls to MongoDB::Cursor::_limit, avg 3µs/call
254 }
255
25612µs127µs $self->_ensure_special;
# spent 27µs making 1 call to MongoDB::Cursor::_ensure_special
25714µs24µ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
2591246µs279.46s my $retval = $self->reset->next;
# spent 4.73s making 1 call to MongoDB::Cursor::next # spent 4.73s making 1 call to MongoDB::Cursor::_do_query # spent 14µs making 1 call to MongoDB::Cursor::_dt_type # spent 14µs making 19 calls to boolean::false, avg 716ns/call # spent 10µs making 1 call to MongoDB::Cursor::_inflate_dbrefs # spent 7µs making 1 call to MongoDB::Cursor::reset # spent 3µs making 1 call to MongoDB::Cursor::_limit # spent 2µs making 1 call to MongoDB::Cursor::started_iterating # spent 1µs making 1 call to MongoDB::Cursor::_client
26019µs334µs $self->reset->limit($temp);
# spent 21µs making 1 call to MongoDB::Cursor::limit # spent 9µs making 1 call to MongoDB::Cursor::reset # spent 4µs making 1 call to MongoDB::Cursor::started_iterating
261
26213µs13µs undef $self->_query->{'$explain'};
# spent 3µs making 1 call to MongoDB::Cursor::_query
263
26414µs return $retval;
265}
266
267
268
# spent 5.74s (47µs+5.74) within MongoDB::Cursor::count which was called: # once (47µs+5.74s) by Mentat::Storage::Mongo::find_i at line 398 of Mentat/Storage/Mongo.pm
sub count {
2691900ns my ($self, $all) = @_;
270
271112µs25µs my ($db, $coll) = $self->_ns =~ m/^([^\.]+)\.(.*)/;
# spent 3µs making 1 call to MongoDB::Cursor::CORE:match # spent 2µs making 1 call to MongoDB::Cursor::_ns
27212µs121µs my $cmd = new Tie::IxHash(count => $coll);
# spent 21µs making 1 call to Tie::IxHash::new
273
27412µs13µs if ($self->_grrrr) {
# spent 3µs making 1 call to MongoDB::Cursor::_grrrr
275 $cmd->Push(query => $self->_query->{'query'});
276 }
277 else {
27812µs29µ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
2811200ns if ($all) {
282 $cmd->Push(limit => $self->_limit) if $self->_limit;
283 $cmd->Push(skip => $self->_skip) if $self->_skip;
284 }
285
28617µs35.74s my $result = $self->_client->get_database($db)->run_command($cmd);
# spent 5.74s making 1 call to MongoDB::Database::run_command # spent 21µ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
28912µs15µs return 0 unless ref $result eq 'HASH';
# spent 5µs making 1 call to MongoDB::Database::DESTROY
29019µs return $result->{'n'};
291}
292
293
294# shortcut to make some XS code saner
295
# spent 47µs (30+17) within MongoDB::Cursor::_dt_type which was called 3 times, avg 16µs/call: # 2 times (22µs+10µs) by MongoDB::Cursor::next at line 144 of MongoDB/Collection.pm, avg 16µs/call # once (8µs+7µs) by MongoDB::Cursor::next at line 259
sub _dt_type {
29632µs my $self = shift;
297320µs617µs return $self->_client->dt_type;
# spent 10µs making 3 calls to MongoDB::MongoClient::dt_type, avg 3µs/call # spent 7µs making 3 calls to MongoDB::Cursor::_client, avg 2µs/call
298}
299
300
# spent 30µs (18+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 {
30131µs my $self = shift;
302314µs612µ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
31915µs222.1ms__PACKAGE__->meta->make_immutable (inline_destructor => 0);
# spent 22.0ms making 1 call to Class::MOP::Class::make_immutable # spent 12µs making 1 call to MongoDB::Cursor::meta
320
321118µs1;
322
323__END__
 
# spent 3µs within MongoDB::Cursor::CORE:match which was called: # once (3µs+0s) by MongoDB::Cursor::count at line 271
sub MongoDB::Cursor::CORE:match; # opcode
# spent 44µs (30+14) within MongoDB::Cursor::DESTROY which was called 3 times, avg 15µs/call: # 2 times (17µs+7µs) by MongoDB::Database::run_command at line 110 of MongoDB/Database.pm, avg 12µs/call # once (13µs+7µs) by Mentat::Storage::Mongo::find at line 33 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 12.8s (343µs+12.8) within MongoDB::Cursor::next which was called 4 times, avg 3.21s/call: # 2 times (72µs+5.74s) by MongoDB::Collection::find_one at line 144 of MongoDB/Collection.pm, avg 2.87s/call # once (250µs+4.73s) by MongoDB::Cursor::explain at line 259 # once (21µs+2.37s) by Mentat::Storage::Mongo::find at line 458 of Mentat/Storage/Mongo.pm
sub MongoDB::Cursor::next; # xsub
# spent 16µs (10+6) within MongoDB::Cursor::reset which was called 2 times, avg 8µs/call: # once (5µs+4µs) by MongoDB::Cursor::explain at line 260 # once (5µs+2µs) by MongoDB::Cursor::explain at line 259
sub MongoDB::Cursor::reset; # xsub