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

Filename/root/mek/mentat.storage.mongo.pl
StatementsExecuted 21 statements in 3.84ms
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
1118.55ms208msmain::::BEGIN@7 main::BEGIN@7
1113.00ms582msmain::::BEGIN@8 main::BEGIN@8
252112.92ms102msClass::MOP::Attribute::::try {...} Class::MOP::Attribute::try {...}
1112.74ms6.17msmain::::BEGIN@6 main::BEGIN@6
218427202.23ms2.23msUNIVERSAL::::isa UNIVERSAL::isa (xsub)
1111.83ms1.86msmain::::BEGIN@4 main::BEGIN@4
981111.82ms17.9msClass::MOP::Class:::::around Class::MOP::Class:::around
180036191.79ms1.79msUNIVERSAL::::can UNIVERSAL::can (xsub)
158111.23ms66.0msClass::MOP::Method::Accessor::::try {...} Class::MOP::Method::Accessor::try {...}
18111967µs115msClass::MOP::Class::::try {...} Class::MOP::Class::try {...}
111335µs366µsmain::::BEGIN@3 main::BEGIN@3
6411334µs20.7msMoose::Meta::Method::Accessor::::try {...} Moose::Meta::Method::Accessor::try {...}
202015244µs244µsUNIVERSAL::::VERSION UNIVERSAL::VERSION (xsub)
3511109µs25.8msClass::MOP::Method::Constructor::::try {...} Class::MOP::Method::Constructor::try {...}
1101160µs60µsInternals::::SvREADONLY Internals::SvREADONLY (xsub)
42142µs5.88msClass::Load::::try {...} Class::Load::try {...}
51132µs78µsMoose::Object::::try {...} Moose::Object::try {...}
22127µs27µsJSON::XS::::encode_json JSON::XS::encode_json
11124µs43µsMoose::Meta::TypeConstraint::::__ANON__ Moose::Meta::TypeConstraint::__ANON__
31115µs482µsMoose::Meta::Method::Destructor::::try {...} Moose::Meta::Method::Destructor::try {...}
31115µs1.52msModule::Implementation::::try {...} Module::Implementation::try {...}
1116µs71µsDateTime::::try {...} DateTime::try {...}
1116µs6µsversion::::(bool version::(bool (xsub)
1115µs5µsversion::::(cmp version::(cmp (xsub)
1114µs15µsClass::Load::::catch {...} Class::Load::catch {...}
1114µs4µsmain::::CORE:print main::CORE:print (opcode)
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
034325µsProfile data that couldn't be associated with a specific line:
# spent 151µs making 1 call to Mentat::Storage::Mongo::DESTROY # spent 80µs making 2 calls to Moose::Object::DESTROY, avg 40µs/call # spent 22µs making 1 call to MongoDB::Cursor::DESTROY # spent 16µs making 4 calls to MongoDB::OID::DESTROY, avg 4µs/call # spent 8µs making 2 calls to MongoDB::Cursor::_client, avg 4µs/call # spent 3µs making 1 call to Mentat::Storage::Mongo::END # spent 3µs making 1 call to Log::Channel::Channel::END # spent 2µs making 1 call to Log::Writer::Email::END # spent 2µs making 1 call to Log::Writer::Handle::END # spent 2µs making 1 call to Log::Filter::Severity::END # spent 2µs making 1 call to Log::Filter::Threshold::END # spent 2µs making 1 call to Log::Writer::Std::END # spent 2µs making 1 call to Mentat::Storage::END # spent 2µs making 1 call to Log::Filter::All::END # spent 2µs making 1 call to Log::Writer::Syslog::END # spent 2µs making 1 call to Value::Convertor::END # spent 2µs making 1 call to Log::Loger::END # spent 2µs making 1 call to Log::Filter::Source::END # spent 2µs making 1 call to Log::Filter::Re::END # spent 2µs making 1 call to Log::Writer::File::END # spent 2µs making 1 call to Mutex::Flock::END # spent 2µs making 1 call to Log::Filter::None::END # spent 2µs making 1 call to Log::Writer::Module::END # spent 2µs making 1 call to Log::Core::Essentials::END # spent 2µs making 1 call to Log::Filter::Message::END # spent 2µs making 1 call to Log::Channel::Module::END # spent 2µs making 1 call to Log::Filter::Set::END # spent 2µs making 1 call to Log::Filter::Module::END # spent 1µs making 1 call to MongoDB::Cursor::_request_id
11145µs#!/usr/bin/perl -T
2
32305µs2370µs
# spent 366µs (335+31) within main::BEGIN@3 which was called: # once (335µs+31µs) by main::RUNTIME at line 3
use strict;
# spent 366µs making 1 call to main::BEGIN@3 # spent 4µs making 1 call to strict::import
421.75ms21.87ms
# spent 1.86ms (1.83+27µs) within main::BEGIN@4 which was called: # once (1.83ms+27µs) by main::RUNTIME at line 4
use warnings;
# spent 1.86ms making 1 call to main::BEGIN@4 # spent 11µs making 1 call to warnings::import
5
62120µs27.80ms
# spent 6.17ms (2.74+3.43) within main::BEGIN@6 which was called: # once (2.74ms+3.43ms) by main::RUNTIME at line 6
use Time::HiRes qw( time );
# spent 6.17ms making 1 call to main::BEGIN@6 # spent 1.63ms making 1 call to Time::HiRes::import
72119µs1208ms
# spent 208ms (8.55+200) within main::BEGIN@7 which was called: # once (8.55ms+200ms) by main::RUNTIME at line 7
use Value::Convertor;
# spent 208ms making 1 call to main::BEGIN@7
821.28ms1582ms
# spent 582ms (3.00+579) within main::BEGIN@8 which was called: # once (3.00ms+579ms) by main::RUNTIME at line 8
use Mentat::Storage::Mongo;
# spent 582ms making 1 call to main::BEGIN@8
9
1017µs187µsmy ($min, $max) = Value::Convertor->ipv4cidr_to_bins("158.196.158.0", 24);
# spent 87µs making 1 call to Value::Convertor::ipv4cidr_to_bins
1118µs1446µs$min = MongoDB::BSON::Binary->new(data => $min, subtype => 0);
# spent 446µs making 1 call to Moose::Object::new
1212µs1269µs$max = MongoDB::BSON::Binary->new(data => $max, subtype => 0);
# spent 269µ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µs19.74msmy $storage = Mentat::Storage::Mongo->new(database => 'mentat', collection => 'alerts');
# spent 9.74ms making 1 call to Mentat::Storage::new
251400nsmy ($results, $count);
26
27110µs16µsmy $start = time;
# spent 6µs making 1 call to Time::HiRes::time
28
29################################################################################
30# OPTION A
31################################################################################
32
33#($results, $count) = $storage->find($filter);
34
35################################################################################
36# OPTION B
37################################################################################
38
3913µs111.1smy ($cursor, $cnta) = $storage->find_i($filter);
# spent 11.1s making 1 call to Mentat::Storage::Mongo::find_i
40119µs34.61swhile (my $doc = $cursor->next) {
# spent 2.31s making 1 call to MongoDB::Cursor::next # spent 2.31s making 1 call to MongoDB::Cursor::_do_query # spent 3µs making 1 call to MongoDB::Cursor::_limit
41 push(@$results, $doc); $count++;;
42}
43
44################################################################################
4517µs13µsmy $end = time;
# spent 3µs making 1 call to Time::HiRes::time
46168µs14µsprint STDERR "DURATION: ".($end-$start).", COUNT: $count\n";
# spent 4µs making 1 call to main::CORE:print
47
 
# spent 60µs within Internals::SvREADONLY which was called 110 times, avg 550ns/call: # 110 times (60µs+0s) by constant::import at line 132 of constant.pm, avg 550ns/call
sub Internals::SvREADONLY; # xsub
# spent 244µs within UNIVERSAL::VERSION which was called 20 times, avg 12µs/call: # once (17µs+0s) by Module::Implementation::BEGIN@12 at line 12 of Module/Implementation.pm # once (17µs+0s) by DateTime::BEGIN@45 at line 45 of DateTime.pm # once (14µs+0s) by DateTime::TimeZone::Europe::Prague::BEGIN@20 at line 20 of DateTime/TimeZone/Europe/Prague.pm # once (14µ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 (13µs+0s) by Data::OptList::BEGIN@11 at line 11 of Data/OptList.pm # once (13µs+0s) by DateTime::BEGIN@46 at line 46 of DateTime.pm # once (12µs+0s) by Moose::Exporter::BEGIN@17 at line 17 of Moose/Exporter.pm # once (12µs+0s) by DateTime::TimeZone::BEGIN@19 at line 19 of DateTime/TimeZone.pm # once (12µs+0s) by Class::Load::BEGIN@9 at line 9 of Class/Load.pm # once (12µs+0s) by DateTime::TimeZone::Local::Unix::BEGIN@12 at line 12 of DateTime/TimeZone/Local/Unix.pm # once (12µs+0s) by JSON::BEGIN@2 at line 2 of (eval 51)[JSON.pm:252] # 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 Class::Load::XS::BEGIN@9 at line 9 of Class/Load/XS.pm # once (11µs+0s) by Package::Stash::BEGIN@15 at line 15 of Package/Stash.pm # once (10µs+0s) by Sub::Exporter::BEGIN@12 at line 12 of Sub/Exporter.pm # once (10µs+0s) by Class::Load::BEGIN@10 at line 15 of Class/Load.pm # once (10µs+0s) by DateTime::BEGIN@47 at line 48 of DateTime.pm # once (9µs+0s) by Sub::Exporter::BEGIN@13 at line 13 of Sub/Exporter.pm
sub UNIVERSAL::VERSION; # xsub
# spent 1.79ms within UNIVERSAL::can which was called 1800 times, avg 993ns/call: # 396 times (331µs+0s) by Math::BigInt::import at line 2785 of Math/BigInt.pm, avg 836ns/call # 347 times (261µs+0s) by Class::MOP::Class::_single_metaclass_can_be_made_compatible at line 354 of Class/MOP/Class.pm, avg 752ns/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 (174µs+0s) by Class::MOP::Mixin::HasAttributes::add_attribute at line 44 of Class/MOP/Mixin/HasAttributes.pm, avg 962ns/call # 134 times (140µ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 749ns/call # 58 times (77µs+0s) by Moose::Meta::Class::add_attribute at line 583 of Moose/Meta/Class.pm, avg 1µs/call # 44 times (113µs+0s) by Moose::Meta::Attribute::install_delegation at line 1121 of Moose/Meta/Attribute.pm, avg 3µs/call # 41 times (40µs+0s) by Moose::Meta::Class::_eval_environment at line 507 of Moose/Meta/Class.pm, avg 980ns/call # 41 times (40µs+0s) by Moose::Meta::Class::_inline_init_attr_from_default at line 429 of Moose/Meta/Class.pm, avg 978ns/call # 41 times (36µs+0s) by Moose::Meta::Class::_inline_check_required_attr at line 387 of Moose/Meta/Class.pm, avg 876ns/call # 41 times (31µs+0s) by Moose::Meta::Class::_inline_triggers at line 471 of Moose/Meta/Class.pm, avg 761ns/call # 41 times (28µs+0s) by Moose::Meta::Class::_eval_environment at line 521 of Moose/Meta/Class.pm, avg 680ns/call # 35 times (36µ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 (34µs+0s) by Moose::Meta::Method::_inline_throw_error at line 39 of Moose/Meta/Method.pm, avg 1µs/call # 27 times (34µs+0s) by Math::BigInt::import at line 2846 of Math/BigInt.pm, avg 1µs/call # 14 times (26µ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 (18µs+0s) by Math::BigInt::import at line 2769 of Math/BigInt.pm, avg 2µs/call # 5 times (10µs+0s) by Moose::Object::DEMOLISHALL at line 70 of Moose/Object.pm, avg 2µ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 (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 (4µs+0s) by DateTime::TimeZone::_init at line 133 of DateTime/TimeZone.pm, avg 875ns/call # 3 times (7µs+0s) by Moose::Meta::Class::new_object at line 288 of Moose/Meta/Class.pm, avg 2µs/call # 3 times (6µs+0s) by Sub::Exporter::default_generator at line 411 of Sub/Exporter.pm, avg 2µs/call # 3 times (5µs+0s) by Moose::Object::BUILDALL at line 56 of Moose/Object.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 3µs/call # 2 times (3µ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 (1µ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 (1µs+0s) by Moose::Object::BEGIN@108 at line 109 of Moose/Object.pm # once (1µs+0s) by DateTime::Locale::_load_class_from_id at line 292 of DateTime/Locale.pm # once (1µs+0s) by DateTime::TimeZone::new at line 75 of DateTime/TimeZone.pm # once (1µs+0s) by DateTime::Locale::_load_class_from_id at line 279 of DateTime/Locale.pm # once (800ns+0s) by DateTime::TimeZone::new at line 100 of DateTime/TimeZone.pm
sub UNIVERSAL::can; # xsub
# spent 2.23ms within UNIVERSAL::isa which was called 2184 times, avg 1µs/call: # 478 times (396µs+0s) by Class::MOP::Mixin::HasMethods::add_method at line 62 of Class/MOP/Mixin/HasMethods.pm, avg 828ns/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 (207µs+0s) by Class::MOP::Method::Accessor::new at line 29 of Class/MOP/Method/Accessor.pm, avg 823ns/call # 181 times (189µs+0s) by Class::MOP::Mixin::HasAttributes::add_attribute at line 23 of Class/MOP/Mixin/HasAttributes.pm, avg 1µs/call # 181 times (118µs+0s) by Class::MOP::Attribute::attach_to_class at line 240 of Class/MOP/Attribute.pm, avg 653ns/call # 133 times (103µs+0s) by Class::MOP::Mixin::HasMethods::get_method at line 122 of Class/MOP/Mixin/HasMethods.pm, avg 776ns/call # 106 times (232µs+0s) by Class::MOP::Class::new_object at line 496 of Class/MOP/Class.pm, avg 2µs/call # 90 times (159µs+0s) by base::import at line 80 of base.pm, avg 2µs/call # 47 times (52µ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 583ns/call # 36 times (70µ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 (23µs+0s) by Moose::Meta::Method::Delegation::new at line 27 of Moose/Meta/Method/Delegation.pm, avg 639ns/call # 35 times (34µs+0s) by Moose::Meta::TypeConstraint::Registry::add_type_constraint at line 51 of Moose/Meta/TypeConstraint/Registry.pm, avg 974ns/call # 30 times (25µs+0s) by Class::MOP::Method::Constructor::new at line 23 of Class/MOP/Method/Constructor.pm, avg 823ns/call # 20 times (39µs+0s) by metaclass::import at line 35 of metaclass.pm, avg 2µs/call # 13 times (14µs+0s) by Moose::Exporter::_apply_metaroles at line 575 of Moose/Exporter.pm, avg 1µs/call # 13 times (14µ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 844ns/call # 3 times (3µs+0s) by Moose::Meta::Method::Destructor::is_needed at line 61 of Moose/Meta/Method/Destructor.pm, avg 867ns/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 (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 (1µs+0s) by Moose::Meta::Attribute::_process_isa_option at line 361 of Moose/Meta/Attribute.pm # once (900ns+0s) by DateTime::TimeZone::offset_as_seconds at line 441 of DateTime/TimeZone.pm # once (700ns+0s) by Moose::Meta::Attribute::_process_accessors at line 1045 of Moose/Meta/Attribute.pm # once (600ns+0s) by Moose::Meta::Attribute::_process_accessors at line 1057 of Moose/Meta/Attribute.pm
sub UNIVERSAL::isa; # xsub
# spent 4µs within main::CORE:print which was called: # once (4µs+0s) by main::RUNTIME at line 46
sub main::CORE:print; # opcode
# spent 6µs within version::(bool which was called: # once (6µs+0s) by DynaLoader::BEGIN@21 at line 57 of Config.pm
sub version::(bool; # xsub
# spent 5µs within version::(cmp which was called: # once (5µs+0s) by DynaLoader::BEGIN@21 at line 60 of Config.pm
sub version::(cmp; # xsub