← 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:26 2014

Filename/root/mek/mentat.storage.mongo.pl
StatementsExecuted 20 statements in 6.18ms
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
11115.8ms453msmain::::BEGIN@7 main::BEGIN@7
1115.88ms13.3msmain::::BEGIN@6 main::BEGIN@6
1114.16ms4.22msmain::::BEGIN@4 main::BEGIN@4
252112.89ms98.9msClass::MOP::Attribute::::try {...} Class::MOP::Attribute::try {...}
1112.80ms570msmain::::BEGIN@8 main::BEGIN@8
218427202.20ms2.20msUNIVERSAL::::isa UNIVERSAL::isa (xsub)
180036191.97ms1.97msUNIVERSAL::::can UNIVERSAL::can (xsub)
981111.78ms16.9msClass::MOP::Class:::::around Class::MOP::Class:::around
158111.19ms64.0msClass::MOP::Method::Accessor::::try {...} Class::MOP::Method::Accessor::try {...}
18111932µs112msClass::MOP::Class::::try {...} Class::MOP::Class::try {...}
111730µs802µsmain::::BEGIN@3 main::BEGIN@3
202015415µs415µsUNIVERSAL::::VERSION UNIVERSAL::VERSION (xsub)
6411322µs20.0msMoose::Meta::Method::Accessor::::try {...} Moose::Meta::Method::Accessor::try {...}
3511107µs25.2msClass::MOP::Method::Constructor::::try {...} Class::MOP::Method::Constructor::try {...}
1101184µs84µsInternals::::SvREADONLY Internals::SvREADONLY (xsub)
42158µs11.5msClass::Load::::try {...} Class::Load::try {...}
11131µs31µsmain::::CORE:print main::CORE:print (opcode)
51129µs72µsMoose::Object::::try {...} Moose::Object::try {...}
22126µs26µsJSON::XS::::encode_json JSON::XS::encode_json
31124µs2.62msModule::Implementation::::try {...} Module::Implementation::try {...}
11122µs39µsMoose::Meta::TypeConstraint::::__ANON__ Moose::Meta::TypeConstraint::__ANON__
11116µs166µsDateTime::::try {...} DateTime::try {...}
31114µs482µsMoose::Meta::Method::Destructor::::try {...} Moose::Meta::Method::Destructor::try {...}
11114µs14µsversion::::(bool version::(bool (xsub)
11113µs13µsversion::::(cmp version::(cmp (xsub)
1119µs34µsClass::Load::::catch {...} Class::Load::catch {...}
0000s0smain::::RUNTIME main::RUNTIME
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments
Time
on line
Calls Time
in subs
Code
030289µsProfile data that couldn't be associated with a specific line:
# spent 149µs making 1 call to Mentat::Storage::Mongo::DESTROY # spent 77µs making 2 calls to Moose::Object::DESTROY, avg 39µs/call # spent 16µs making 4 calls to MongoDB::OID::DESTROY, avg 4µs/call # spent 3µs making 1 call to Log::Writer::Email::END # spent 3µs making 1 call to Log::Writer::Syslog::END # spent 2µs making 1 call to Mentat::Storage::Mongo::END # spent 2µs making 1 call to Log::Channel::Channel::END # spent 2µs making 1 call to Log::Loger::END # spent 2µs making 1 call to Value::Convertor::END # spent 2µs making 1 call to Log::Filter::Source::END # spent 2µs making 1 call to Log::Filter::All::END # spent 2µs making 1 call to Log::Writer::Handle::END # spent 2µs making 1 call to Log::Filter::Message::END # spent 2µs making 1 call to Log::Filter::Set::END # spent 2µs making 1 call to Log::Filter::Module::END # spent 2µs making 1 call to Log::Filter::Re::END # spent 2µs making 1 call to Log::Filter::Severity::END # spent 2µs making 1 call to Log::Writer::File::END # spent 2µs making 1 call to Log::Writer::Module::END # spent 2µs making 1 call to Mutex::Flock::END # spent 2µs making 1 call to Log::Writer::Std::END # spent 2µs making 1 call to Log::Filter::None::END # spent 2µs making 1 call to Log::Filter::Threshold::END # spent 2µs making 1 call to Log::Core::Essentials::END # spent 2µs making 1 call to Mentat::Storage::END # spent 2µs making 1 call to Log::Channel::Module::END
11124µs#!/usr/bin/perl -T
2
32667µs2811µs
# spent 802µs (730+71) within main::BEGIN@3 which was called: # once (730µs+71µs) by main::RUNTIME at line 3
use strict;
# spent 802µs making 1 call to main::BEGIN@3 # spent 9µs making 1 call to strict::import
423.98ms24.24ms
# spent 4.22ms (4.16+58µs) within main::BEGIN@4 which was called: # once (4.16ms+58µs) by main::RUNTIME at line 4
use warnings;
# spent 4.22ms making 1 call to main::BEGIN@4 # spent 22µs making 1 call to warnings::import
5
62252µs216.9ms
# spent 13.3ms (5.88+7.42) within main::BEGIN@6 which was called: # once (5.88ms+7.42ms) by main::RUNTIME at line 6
use Time::HiRes qw( time );
# spent 13.3ms making 1 call to main::BEGIN@6 # spent 3.58ms making 1 call to Time::HiRes::import
72205µs1453ms
# spent 453ms (15.8+437) within main::BEGIN@7 which was called: # once (15.8ms+437ms) by main::RUNTIME at line 7
use Value::Convertor;
# spent 453ms making 1 call to main::BEGIN@7
82843µs1570ms
# spent 570ms (2.80+567) within main::BEGIN@8 which was called: # once (2.80ms+567ms) by main::RUNTIME at line 8
use Mentat::Storage::Mongo;
# spent 570ms making 1 call to main::BEGIN@8
9
1016µs174µsmy ($min, $max) = Value::Convertor->ipv4cidr_to_bins("158.196.158.0", 24);
# spent 74µs making 1 call to Value::Convertor::ipv4cidr_to_bins
1117µs1378µs$min = MongoDB::BSON::Binary->new(data => $min, subtype => 0);
# spent 378µs making 1 call to Moose::Object::new
1212µs1265µs$max = MongoDB::BSON::Binary->new(data => $max, subtype => 0);
# spent 265µs making 1 call to Moose::Object::new
13
1414µsmy $filter = {
15 'Alert.Source.Node.Address.ipv4.min' => {
16 '$gte' => $min,
17 },
18 'Alert.Source.Node.Address.ipv4.max' => {
19 '$lte' => $max,
20 },
21 'Alert.Classification.@text' => 'Webattack',
22 };
23
2414µs18.84msmy $storage = Mentat::Storage::Mongo->new(database => 'mentat', collection => 'alerts');
# spent 8.84ms making 1 call to Mentat::Storage::new
251200nsmy ($results, $count);
26
2718µs14µsmy $start = time;
# spent 4µs making 1 call to Time::HiRes::time
28
29################################################################################
30# OPTION A
31################################################################################
32
33122µs512.8s($results, $count) = $storage->find($filter);
# spent 12.8s making 1 call to Mentat::Storage::Mongo::find # spent 20µs making 1 call to MongoDB::Cursor::DESTROY # spent 6µs making 2 calls to MongoDB::Cursor::_client, avg 3µs/call # spent 1µs making 1 call to MongoDB::Cursor::_request_id
34
35################################################################################
36# OPTION B
37################################################################################
38
39#my $cursor = $storage->find_i($filter);
40#while (my $doc = $cursor->next) {
41# push(@$results, $doc); $count++;;
42#}
43
44################################################################################
4516µs13µsmy $end = time;
# spent 3µs making 1 call to Time::HiRes::time
46155µs131µsprint STDERR "DURATION: ".($end-$start).", COUNT: $count\n";
# spent 31µs making 1 call to main::CORE:print
47
 
# spent 84µs within Internals::SvREADONLY which was called 110 times, avg 765ns/call: # 110 times (84µs+0s) by constant::import at line 132 of constant.pm, avg 765ns/call
sub Internals::SvREADONLY; # xsub
# spent 415µs within UNIVERSAL::VERSION which was called 20 times, avg 21µs/call: # once (36µs+0s) by Module::Implementation::BEGIN@12 at line 12 of Module/Implementation.pm # once (33µs+0s) by DateTime::BEGIN@45 at line 45 of DateTime.pm # once (32µs+0s) by DateTime::TimeZone::Europe::Prague::BEGIN@20 at line 20 of DateTime/TimeZone/Europe/Prague.pm # once (30µs+0s) by DateTime::BEGIN@46 at line 46 of DateTime.pm # once (29µs+0s) by Data::OptList::BEGIN@11 at line 11 of Data/OptList.pm # once (29µs+0s) by DateTime::TimeZone::BEGIN@19 at line 19 of DateTime/TimeZone.pm # once (28µs+0s) by Class::Load::BEGIN@9 at line 9 of Class/Load.pm # once (28µs+0s) by DateTime::TimeZone::Local::Unix::BEGIN@12 at line 12 of DateTime/TimeZone/Local/Unix.pm # once (25µs+0s) by Class::Load::XS::BEGIN@9 at line 9 of Class/Load/XS.pm # once (23µs+0s) by DateTime::BEGIN@47 at line 48 of DateTime.pm # once (23µs+0s) by Class::Load::BEGIN@10 at line 15 of Class/Load.pm # once (13µs+0s) by Moose::Deprecated::BEGIN@12 at line 19 of Moose/Deprecated.pm # once (13µs+0s) by Moose::Util::BEGIN@12 at line 12 of Moose/Util.pm # once (12µs+0s) by Moose::Exporter::BEGIN@17 at line 17 of Moose/Exporter.pm # once (11µs+0s) by Class::MOP::BEGIN@18 at line 18 of Class/MOP.pm # once (11µs+0s) by Sub::Exporter::BEGIN@11 at line 11 of Sub/Exporter.pm # once (11µs+0s) by Package::Stash::BEGIN@15 at line 15 of Package/Stash.pm # once (10µs+0s) by JSON::BEGIN@2 at line 2 of (eval 51)[JSON.pm:252] # once (10µs+0s) by Sub::Exporter::BEGIN@12 at line 12 of Sub/Exporter.pm # once (9µs+0s) by Sub::Exporter::BEGIN@13 at line 13 of Sub/Exporter.pm
sub UNIVERSAL::VERSION; # xsub
# spent 1.97ms within UNIVERSAL::can which was called 1800 times, avg 1µs/call: # 396 times (505µs+0s) by Math::BigInt::import at line 2785 of Math/BigInt.pm, avg 1µs/call # 347 times (256µs+0s) by Class::MOP::Class::_single_metaclass_can_be_made_compatible at line 354 of Class/MOP/Class.pm, avg 739ns/call # 196 times (238µs+0s) by Class::MOP::Method::Generated::_compile_code at line 59 of Class/MOP/Method/Generated.pm, avg 1µs/call # 181 times (168µs+0s) by Class::MOP::Mixin::HasAttributes::add_attribute at line 44 of Class/MOP/Mixin/HasAttributes.pm, avg 926ns/call # 134 times (136µs+0s) by Moose::Meta::Attribute::_inline_throw_error at line 71 of Moose/Meta/Attribute.pm, avg 1µs/call # 77 times (58µs+0s) by Class::MOP::Class::_single_metaclass_is_compatible at line 287 of Class/MOP/Class.pm, avg 752ns/call # 58 times (76µs+0s) by Moose::Meta::Class::add_attribute at line 583 of Moose/Meta/Class.pm, avg 1µs/call # 44 times (110µs+0s) by Moose::Meta::Attribute::install_delegation at line 1121 of Moose/Meta/Attribute.pm, avg 3µs/call # 41 times (39µs+0s) by Moose::Meta::Class::_inline_init_attr_from_default at line 429 of Moose/Meta/Class.pm, avg 959ns/call # 41 times (36µs+0s) by Moose::Meta::Class::_inline_check_required_attr at line 387 of Moose/Meta/Class.pm, avg 878ns/call # 41 times (30µs+0s) by Moose::Meta::Class::_inline_triggers at line 471 of Moose/Meta/Class.pm, avg 737ns/call # 41 times (28µs+0s) by Moose::Meta::Class::_eval_environment at line 521 of Moose/Meta/Class.pm, avg 683ns/call # 41 times (27µs+0s) by Moose::Meta::Class::_eval_environment at line 507 of Moose/Meta/Class.pm, avg 668ns/call # 35 times (35µs+0s) by Class::MOP::Mixin::HasMethods::_add_meta_method at line 28 of Class/MOP/Mixin/HasMethods.pm, avg 1µs/call # 30 times (33µs+0s) by Moose::Meta::Method::_inline_throw_error at line 39 of Moose/Meta/Method.pm, avg 1µs/call # 27 times (54µs+0s) by Math::BigInt::import at line 2846 of Math/BigInt.pm, avg 2µs/call # 14 times (24µs+0s) by Moose::Exporter::__ANON__[/usr/local/lib/perl/5.14.2/Moose/Exporter.pm:519] at line 468 of Moose/Exporter.pm, avg 2µs/call # 9 times (30µs+0s) by Math::BigInt::import at line 2769 of Math/BigInt.pm, avg 3µs/call # 5 times (9µs+0s) by Class::MOP::Method::Inlined::can_be_inlined at line 70 of Class/MOP/Method/Inlined.pm, avg 2µs/call # 5 times (9µs+0s) by Moose::Object::DEMOLISHALL at line 70 of Moose/Object.pm, avg 2µs/call # 5 times (6µs+0s) by Class::MOP::Method::Inlined::can_be_inlined at line 58 of Class/MOP/Method/Inlined.pm, avg 1µs/call # 5 times (5µs+0s) by Moose::Meta::Class::_call_all_triggers at line 298 of Moose/Meta/Class.pm, avg 1µs/call # 4 times (8µs+0s) by DateTime::TimeZone::_init at line 133 of DateTime/TimeZone.pm, avg 2µs/call # 3 times (9µs+0s) by Moose::Object::BUILDALL at line 56 of Moose/Object.pm, avg 3µs/call # 3 times (6µs+0s) by Moose::Meta::Class::new_object at line 288 of Moose/Meta/Class.pm, avg 2µs/call # 3 times (5µs+0s) by Sub::Exporter::default_generator at line 411 of Sub/Exporter.pm, avg 2µs/call # 3 times (3µs+0s) by MongoDB::Collection::full_name at line 11 of (eval 62)[Eval/Closure.pm:144], avg 1µs/call # 2 times (5µs+0s) by Moose::Util::add_method_modifier at line 239 of Moose/Util.pm, avg 2µs/call # 2 times (2µs+0s) by if::work at line 14 of if.pm, avg 1µs/call # once (4µs+0s) by attributes::import at line 50 of attributes.pm # once (4µs+0s) by Sub::Install::__ANON__[/usr/local/share/perl/5.14.2/Sub/Install.pm:57] at line 45 of Sub/Install.pm # once (3µs+0s) by DateTime::TimeZone::new at line 75 of DateTime/TimeZone.pm # once (3µs+0s) by DateTime::Locale::_load_class_from_id at line 292 of DateTime/Locale.pm # once (2µs+0s) by DateTime::Locale::_load_class_from_id at line 279 of DateTime/Locale.pm # once (2µs+0s) by DateTime::TimeZone::new at line 100 of DateTime/TimeZone.pm # once (1µs+0s) by Moose::Object::BEGIN@108 at line 109 of Moose/Object.pm
sub UNIVERSAL::can; # xsub
# spent 2.20ms within UNIVERSAL::isa which was called 2184 times, avg 1µs/call: # 478 times (371µs+0s) by Class::MOP::Mixin::HasMethods::add_method at line 62 of Class/MOP/Mixin/HasMethods.pm, avg 776ns/call # 446 times (483µs+0s) by Class::MOP::Object::_is_compatible_with at line 52 of Class/MOP/Object.pm, avg 1µs/call # 252 times (200µs+0s) by Class::MOP::Method::Accessor::new at line 29 of Class/MOP/Method/Accessor.pm, avg 794ns/call # 181 times (187µs+0s) by Class::MOP::Mixin::HasAttributes::add_attribute at line 23 of Class/MOP/Mixin/HasAttributes.pm, avg 1µs/call # 181 times (107µs+0s) by Class::MOP::Attribute::attach_to_class at line 240 of Class/MOP/Attribute.pm, avg 592ns/call # 133 times (100µs+0s) by Class::MOP::Mixin::HasMethods::get_method at line 122 of Class/MOP/Mixin/HasMethods.pm, avg 751ns/call # 106 times (230µs+0s) by Class::MOP::Class::new_object at line 496 of Class/MOP/Class.pm, avg 2µs/call # 90 times (178µs+0s) by base::import at line 80 of base.pm, avg 2µs/call # 47 times (51µs+0s) by Moose::Meta::Attribute::install_delegation at line 1121 of Moose/Meta/Attribute.pm, avg 1µs/call # 46 times (27µs+0s) by Class::MOP::Method::Wrapped::wrap at line 76 of Class/MOP/Method/Wrapped.pm, avg 596ns/call # 36 times (66µs+0s) by Class::MOP::Method::Inlined::can_be_inlined at line 43 of Class/MOP/Method/Inlined.pm, avg 2µs/call # 36 times (24µs+0s) by Moose::Meta::Method::Delegation::new at line 27 of Moose/Meta/Method/Delegation.pm, avg 667ns/call # 35 times (33µs+0s) by Moose::Meta::TypeConstraint::Registry::add_type_constraint at line 51 of Moose/Meta/TypeConstraint/Registry.pm, avg 954ns/call # 30 times (31µs+0s) by Class::MOP::Method::Constructor::new at line 23 of Class/MOP/Method/Constructor.pm, avg 1µs/call # 20 times (38µs+0s) by metaclass::import at line 35 of metaclass.pm, avg 2µs/call # 13 times (13µs+0s) by Moose::Exporter::_apply_metaroles at line 575 of Moose/Exporter.pm, avg 1µs/call # 13 times (13µs+0s) by Class::MOP::Class::superclasses at line 949 of Class/MOP/Class.pm, avg 1µs/call # 11 times (19µs+0s) by Moose::Meta::Class::superclasses at line 566 of Moose/Meta/Class.pm, avg 2µs/call # 11 times (12µs+0s) by Moose::init_meta at line 161 of Moose.pm, avg 1µs/call # 9 times (8µs+0s) by MongoDB::Collection::new or MongoDB::Cursor::new or MongoDB::Database::new at line 41 of (eval 62)[Eval/Closure.pm:144], avg 856ns/call # 3 times (2µs+0s) by Moose::Meta::Method::Destructor::is_needed at line 61 of Moose/Meta/Method/Destructor.pm, avg 800ns/call # 2 times (3µs+0s) by Class::MOP::Mixin::HasMethods::_add_meta_method at line 31 of Class/MOP/Mixin/HasMethods.pm, avg 1µs/call # once (2µs+0s) by DateTime::TimeZone::offset_as_seconds at line 441 of DateTime/TimeZone.pm # once (1µs+0s) by Eval::Closure::Sandbox_154::__ANON__[(eval 220)[/usr/local/share/perl/5.14.2/Eval/Closure.pm:144]:3] at line 3 of (eval 62)[Eval/Closure.pm:144] # once (900ns+0s) by Moose::Meta::Attribute::_process_isa_option at line 361 of Moose/Meta/Attribute.pm # once (700ns+0s) by Moose::Meta::Attribute::_process_accessors at line 1057 of Moose/Meta/Attribute.pm # once (700ns+0s) by Moose::Meta::Attribute::_process_accessors at line 1045 of Moose/Meta/Attribute.pm
sub UNIVERSAL::isa; # xsub
# spent 31µs within main::CORE:print which was called: # once (31µs+0s) by main::RUNTIME at line 46
sub main::CORE:print; # opcode
# spent 14µs within version::(bool which was called: # once (14µs+0s) by DynaLoader::BEGIN@21 at line 57 of Config.pm
sub version::(bool; # xsub
# spent 13µs within version::(cmp which was called: # once (13µs+0s) by DynaLoader::BEGIN@21 at line 60 of Config.pm
sub version::(cmp; # xsub