Filename | /root/mek/mentat.storage.mongo.pl |
Statements | Executed 20 statements in 6.18ms |
Calls | P | F | Exclusive Time |
Inclusive Time |
Subroutine |
---|---|---|---|---|---|
1 | 1 | 1 | 15.8ms | 453ms | BEGIN@7 | main::
1 | 1 | 1 | 5.88ms | 13.3ms | BEGIN@6 | main::
1 | 1 | 1 | 4.16ms | 4.22ms | BEGIN@4 | main::
252 | 1 | 1 | 2.89ms | 98.9ms | try {...} | Class::MOP::Attribute::
1 | 1 | 1 | 2.80ms | 570ms | BEGIN@8 | main::
2184 | 27 | 20 | 2.20ms | 2.20ms | isa (xsub) | UNIVERSAL::
1800 | 36 | 19 | 1.97ms | 1.97ms | can (xsub) | UNIVERSAL::
981 | 1 | 1 | 1.78ms | 16.9ms | around | Class::MOP::Class:::
158 | 1 | 1 | 1.19ms | 64.0ms | try {...} | Class::MOP::Method::Accessor::
181 | 1 | 1 | 932µs | 112ms | try {...} | Class::MOP::Class::
1 | 1 | 1 | 730µs | 802µs | BEGIN@3 | main::
20 | 20 | 15 | 415µs | 415µs | VERSION (xsub) | UNIVERSAL::
64 | 1 | 1 | 322µs | 20.0ms | try {...} | Moose::Meta::Method::Accessor::
35 | 1 | 1 | 107µs | 25.2ms | try {...} | Class::MOP::Method::Constructor::
110 | 1 | 1 | 84µs | 84µs | SvREADONLY (xsub) | Internals::
4 | 2 | 1 | 58µs | 11.5ms | try {...} | Class::Load::
1 | 1 | 1 | 31µs | 31µs | CORE:print (opcode) | main::
5 | 1 | 1 | 29µs | 72µs | try {...} | Moose::Object::
2 | 2 | 1 | 26µs | 26µs | encode_json | JSON::XS::
3 | 1 | 1 | 24µs | 2.62ms | try {...} | Module::Implementation::
1 | 1 | 1 | 22µs | 39µs | __ANON__ | Moose::Meta::TypeConstraint::
1 | 1 | 1 | 16µs | 166µs | try {...} | DateTime::
3 | 1 | 1 | 14µs | 482µs | try {...} | Moose::Meta::Method::Destructor::
1 | 1 | 1 | 14µs | 14µs | (bool (xsub) | version::
1 | 1 | 1 | 13µs | 13µs | (cmp (xsub) | version::
1 | 1 | 1 | 9µs | 34µs | catch {...} | Class::Load::
0 | 0 | 0 | 0s | 0s | RUNTIME | main::
Line | State ments |
Time on line |
Calls | Time in subs |
Code |
---|---|---|---|---|---|
0 | 30 | 289µs | Profile 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 | ||
1 | 1 | 124µs | #!/usr/bin/perl -T | ||
2 | |||||
3 | 2 | 667µs | 2 | 811µs | # spent 802µs (730+71) within main::BEGIN@3 which was called:
# once (730µs+71µs) by main::RUNTIME at line 3 # spent 802µs making 1 call to main::BEGIN@3
# spent 9µs making 1 call to strict::import |
4 | 2 | 3.98ms | 2 | 4.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 # spent 4.22ms making 1 call to main::BEGIN@4
# spent 22µs making 1 call to warnings::import |
5 | |||||
6 | 2 | 252µs | 2 | 16.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 # spent 13.3ms making 1 call to main::BEGIN@6
# spent 3.58ms making 1 call to Time::HiRes::import |
7 | 2 | 205µs | 1 | 453ms | # spent 453ms (15.8+437) within main::BEGIN@7 which was called:
# once (15.8ms+437ms) by main::RUNTIME at line 7 # spent 453ms making 1 call to main::BEGIN@7 |
8 | 2 | 843µs | 1 | 570ms | # spent 570ms (2.80+567) within main::BEGIN@8 which was called:
# once (2.80ms+567ms) by main::RUNTIME at line 8 # spent 570ms making 1 call to main::BEGIN@8 |
9 | |||||
10 | 1 | 6µs | 1 | 74µs | my ($min, $max) = Value::Convertor->ipv4cidr_to_bins("158.196.158.0", 24); # spent 74µs making 1 call to Value::Convertor::ipv4cidr_to_bins |
11 | 1 | 7µs | 1 | 378µs | $min = MongoDB::BSON::Binary->new(data => $min, subtype => 0); # spent 378µs making 1 call to Moose::Object::new |
12 | 1 | 2µs | 1 | 265µs | $max = MongoDB::BSON::Binary->new(data => $max, subtype => 0); # spent 265µs making 1 call to Moose::Object::new |
13 | |||||
14 | 1 | 4µs | my $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 | |||||
24 | 1 | 4µs | 1 | 8.84ms | my $storage = Mentat::Storage::Mongo->new(database => 'mentat', collection => 'alerts'); # spent 8.84ms making 1 call to Mentat::Storage::new |
25 | 1 | 200ns | my ($results, $count); | ||
26 | |||||
27 | 1 | 8µs | 1 | 4µs | my $start = time; # spent 4µs making 1 call to Time::HiRes::time |
28 | |||||
29 | ################################################################################ | ||||
30 | # OPTION A | ||||
31 | ################################################################################ | ||||
32 | |||||
33 | 1 | 22µs | 5 | 12.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 | ################################################################################ | ||||
45 | 1 | 6µs | 1 | 3µs | my $end = time; # spent 3µs making 1 call to Time::HiRes::time |
46 | 1 | 55µs | 1 | 31µs | print 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 | |||||
# 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 | |||||
# 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 | |||||
# 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 | |||||
# spent 31µs within main::CORE:print which was called:
# once (31µs+0s) by main::RUNTIME at line 46 | |||||
# spent 14µs within version::(bool which was called:
# once (14µs+0s) by DynaLoader::BEGIN@21 at line 57 of Config.pm | |||||
# spent 13µs within version::(cmp which was called:
# once (13µs+0s) by DynaLoader::BEGIN@21 at line 60 of Config.pm |