← Index
NYTProf Performance Profile   « line view »
For flows_to_es.pl
  Run on Mon May 9 23:27:59 2016
Reported on Mon May 9 23:28:08 2016

Filename/data/flows/bin/flows_to_es.pl
StatementsExecuted 92 statements in 32.5ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
43116.6ms16.6msmain::::CORE:backtick main::CORE:backtick (opcode)
1116.30ms8.78msmain::::BEGIN@9 main::BEGIN@9
1115.02ms22.8msmain::::BEGIN@7 main::BEGIN@7
1113.31ms3.67msmain::::BEGIN@124 main::BEGIN@124
1113.30ms17.3msmain::::BEGIN@5 main::BEGIN@5
111182.77ms81.8msMoo::::with Moo::with
1112.36ms2.39msmain::::BEGIN@4 main::BEGIN@4
1112.33ms6.45msmain::::BEGIN@123 main::BEGIN@123
1112.16ms3.44msmain::::BEGIN@207 main::BEGIN@207
2211.38ms1.65msMoo::Role::::before Moo::Role::before
1111.31ms2.90msmain::::BEGIN@10 main::BEGIN@10
1111.03ms10.3msmain::::BEGIN@8 main::BEGIN@8
69699949µs15.9msMoo::Role::::has Moo::Role::has
111921µs4.81msmain::::BEGIN@11 main::BEGIN@11
111769µs34.2msmain::::BEGIN@147 main::BEGIN@147
3122413615µs615µsUNIVERSAL::::can UNIVERSAL::can (xsub)
111386µs424µsmain::::BEGIN@3 main::BEGIN@3
111337µs337µsmain::::CORE:unlink main::CORE:unlink (opcode)
322217304µs304µsUNIVERSAL::::VERSION UNIVERSAL::VERSION (xsub)
552102µs17.8msMoo::::has Moo::has
11183µs38.7msmain::::load_storable_file main::load_storable_file
99976µs93µsMoo::Role::::requires Moo::Role::requires
11164µs64µsmain::::return_mapping main::return_mapping
11160µs6.46msSearch::Elasticsearch::Transport::::try {...} Search::Elasticsearch::Transport::try {...}
22159µs6.48msmain::::clear_flows main::clear_flows
11156µs5.92msmain::::retrieve_flows main::retrieve_flows
11153µs4.35msmain::::retrieve_flow_duration main::retrieve_flow_duration
11150µs183msmain::::create_es_bulk main::create_es_bulk
11144µs1.91msSearch::Elasticsearch::Role::Cxn::::try {...} Search::Elasticsearch::Role::Cxn::try {...}
163231µs31µsUNIVERSAL::::isa UNIVERSAL::isa (xsub)
22130µs30µsmain::::CORE:ftis main::CORE:ftis (opcode)
22126µs39µsmain::::return_estimestamp main::return_estimestamp
11124µs92µsSearch::Elasticsearch::Role::Client::Direct::::try {...} Search::Elasticsearch::Role::Client::Direct::try {...}
22124µs65µsmain::::return_esdate main::return_esdate
241122µs22µsInternals::::SvREADONLY Internals::SvREADONLY (xsub)
33322µs8.37msMoo::Role::::with Moo::Role::with
11112µs49µsmain::::BEGIN@125 main::BEGIN@125
22211µs14µsMoo::Role::::around Moo::Role::around
21110µs2.49msModule::Implementation::::try {...} Module::Implementation::try {...}
11110µs1.28msmain::::BEGIN@230 main::BEGIN@230
1119µs42µsmain::::BEGIN@381 main::BEGIN@381
1118µs48µsmain::::BEGIN@235 main::BEGIN@235
1118µs15.9msmain::::create_bulk main::create_bulk
6337µs7µsutf8::::downgrade utf8::downgrade (xsub)
1115µs5µsversion::::(bool version::(bool (xsub)
1115µs5µsversion::::(cmp version::(cmp (xsub)
1114µs4µsmain::::CORE:pack main::CORE:pack (opcode)
1112µs2µsmain::::CORE:match main::CORE:match (opcode)
1111µs1µsutf8::::encode utf8::encode (xsub)
0000s0smain::::RUNTIME main::RUNTIME
0000s0smain::::__ANON__[flows_to_es.pl:159] main::__ANON__[flows_to_es.pl:159]
0000s0smain::::__ANON__[flows_to_es.pl:162] main::__ANON__[flows_to_es.pl:162]
0000s0smain::::__ANON__[flows_to_es.pl:393] main::__ANON__[flows_to_es.pl:393]
0000s0smain::::__ANON__[flows_to_es.pl:395] main::__ANON__[flows_to_es.pl:395]
0000s0smain::::__ANON__[flows_to_es.pl:58] main::__ANON__[flows_to_es.pl:58]
0000s0smain::::__ANON__[flows_to_es.pl:61] main::__ANON__[flows_to_es.pl:61]
0000s0smain::::create_es_index main::create_es_index
0000s0smain::::send_to_influxdb main::send_to_influxdb
0000s0smain::::transform_tags main::transform_tags
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
0211µsProfile data that couldn't be associated with a specific line:
# spent 7µs making 1 call to Class::XSAccessor::END # spent 4µs making 1 call to JSON::XS::DESTROY
1#!/usr/bin/perl
2
32365µs2440µs
# spent 424µs (386+38) within main::BEGIN@3 which was called: # once (386µs+38µs) by main::RUNTIME at line 3
use strict;
# spent 424µs making 1 call to main::BEGIN@3 # spent 16µs making 1 call to strict::import
422.27ms22.40ms
# spent 2.39ms (2.36+26µs) within main::BEGIN@4 which was called: # once (2.36ms+26µs) by main::RUNTIME at line 4
use warnings;
# spent 2.39ms making 1 call to main::BEGIN@4 # spent 7µs making 1 call to warnings::import
5295µs218.0ms
# spent 17.3ms (3.30+14.0) within main::BEGIN@5 which was called: # once (3.30ms+14.0ms) by main::RUNTIME at line 5
use local::lib '/opt/flows/lib';
# spent 17.3ms making 1 call to main::BEGIN@5 # spent 610µs making 1 call to local::lib::import
6
72145µs223.5ms
# spent 22.8ms (5.02+17.8) within main::BEGIN@7 which was called: # once (5.02ms+17.8ms) by main::RUNTIME at line 7
use IO::Socket;
# spent 22.8ms making 1 call to main::BEGIN@7 # spent 716µs making 1 call to IO::Socket::import
82132µs210.3ms
# spent 10.3ms (1.03+9.25) within main::BEGIN@8 which was called: # once (1.03ms+9.25ms) by main::RUNTIME at line 8
use Math::Round qw(round);
# spent 10.3ms making 1 call to main::BEGIN@8 # spent 58µs making 1 call to Exporter::import
92139µs28.81ms
# spent 8.78ms (6.30+2.49) within main::BEGIN@9 which was called: # once (6.30ms+2.49ms) by main::RUNTIME at line 9
use Data::Dumper;
# spent 8.78ms making 1 call to main::BEGIN@9 # spent 29µs making 1 call to Exporter::import
102161µs22.94ms
# spent 2.90ms (1.31+1.58) within main::BEGIN@10 which was called: # once (1.31ms+1.58ms) by main::RUNTIME at line 10
use JSON::XS;
# spent 2.90ms making 1 call to main::BEGIN@10 # spent 41µs making 1 call to Exporter::import
112731µs24.84ms
# spent 4.81ms (921µs+3.89) within main::BEGIN@11 which was called: # once (921µs+3.89ms) by main::RUNTIME at line 11
use Try::Tiny;
# spent 4.81ms making 1 call to main::BEGIN@11 # spent 36µs making 1 call to Exporter::import
12
13#
14# This uses the pmacct pipe at $pipe to pull in, process, and store netflow
15# data into InfluxDB. Also a few subs exist for reading cached Storable files
16# for adding more info into InfluxDB. This could easily be expanded to store
17# into ElasticSearch or any other DB as well. This is designed to run fast from
18# cron at every X minutes depending on the resolution you want/need.
19#
20# Also important to note that this uses the InfluxDB UDP "Line Protocol" not
21# the graphite input. The database to insert into is determined by the InfluxDB
22# configuration and each port will go into a different database.
23#
24
25# TODO:
26# Finish the transform_tags sub so we can re-use this and just pass multiple
27# hashes into it whenever we need to add/re-write tags into data.
28# Add support for ElasticSearch? Should be trivial, just another sub that takes
29# both %values and %tags.
30
31# Global shit
3211µsmy $pipe = '/opt/flows/cache/full.pipe';
331300nsmy $influxdb_host = '127.0.0.1';
341300nsmy $influxdb_port = '9999';
351300nsmy $storage_name = 'netflow';
361300nsmy $mapping_name = 'netflowdata';
3712µsmy @es_nodes = [ '127.0.0.1:9200' ];
381200nsmy $influx_enabled = 0;
3916µs1298µsmy $sock = IO::Socket::INET->new( Proto => 'udp', PeerPort => $influxdb_port, PeerAddr => $influxdb_host) or die "Could not create socket $!\n";
# spent 298µs making 1 call to IO::Socket::INET::new
40#
41
4213µs14.35msmy $duration = retrieve_flow_duration($pipe);
# spent 4.35ms making 1 call to main::retrieve_flow_duration
4315µs15.92msmy @flows = retrieve_flows($pipe);
# spent 5.92ms making 1 call to main::retrieve_flows
44114µs13.02msclear_flows($pipe);
# spent 3.02ms making 1 call to main::clear_flows
45
4617µs138.7msmy $librenms = load_storable_file('/opt/flows/cache/librenms.stor');
# spent 38.7ms making 1 call to main::load_storable_file
47
4817µs1183msmy $bulk = create_es_bulk($storage_name);
# spent 183ms making 1 call to main::create_es_bulk
49
5013µs123µsmy $estime = return_estimestamp();
# spent 23µs making 1 call to main::return_estimestamp
5112µs111µsmy $esdate = return_esdate();
# spent 11µs making 1 call to main::return_esdate
52
5311µsforeach my $line (@flows) {
54 chomp($line);
55 my $obj;
56 try {
57 $obj = decode_json($line);
58 } catch {
59 print "Error, Malformed JSON: $line\n";
60 next;
61 };
62 my %values;
63 $values{pps} = eval { round((($obj->{packets}) / $duration)) } || 0;
64 # 368 bits assumes Ethernet Header, IFG, and 2 dot1q tags
65 $values{bps} = eval { round((($obj->{bytes} * 8) + ($values{pps} * 368)) / $duration) } || 0;
66 $values{bytes} = $obj->{bytes};
67 $values{packets} = $obj->{packets};
68 $values{avg_size} = eval{ round(($obj->{bytes}) / $values{packets}) } || 0;
69 if ($obj->{as_path}) {
70 my @aspath = split(' ', $obj->{as_path});
71 my $i = 1;
72 foreach my $as (@aspath) {
73 $values{as_path}{"as_path_" . $i} = $as;
74 $i++;
75 }
76 }
77
78 my %librenms_info;
79 if ($librenms->{devices}{$obj->{tag}}) {
80 my $device = $librenms->{devices}{$obj->{tag}};
81 $librenms_info{device_name} = $device->{info}{hostname} || '';
82 $librenms_info{device_location} = $device->{info}{location} || '';
83 $librenms_info{iface_in_descr} = $device->{ports_by_ifIndex}{$obj->{in_iface}}{port_descr_descr} || '';
84 $librenms_info{iface_out_descr} = $device->{ports_by_ifIndex}{$obj->{out_iface}}{port_descr_descr} || '';
85 $librenms_info{iface_in_type} = $device->{ports_by_ifIndex}{$obj->{in_iface}}{port_descr_type} || '';
86 $librenms_info{iface_out_type} = $device->{ports_by_ifIndex}{$obj->{out_iface}}{port_descr_type} || '';
87 }
88
89 $bulk->index ({
90 index => "$storage_name-$esdate",
91 type => "$mapping_name",
92 source => {
93 '_timestamp' => $estime,
94 'bps' => $values{bps},
95 'pps' => $values{pps},
96 'avg_size' => $values{avg_size},
97 'as_path' => \%{$values{as_path}},
98 'flow_stats' => $obj,
99 'librenms_info' => \%librenms_info,
100 },
101 });
102
103 if ($influx_enabled == 1) {
104 my %tags;
105 foreach my $key (keys %{$obj}) {
106 next if $key =~ /bytes/;
107 next if $key =~ /packets/;
108 next if $obj->{$key} =~ /^$/;
109 next if $obj->{$key} =~ /^0$/;
110 $tags{$key} = $obj->{$key};
111 }
112 send_to_influxdb($sock, 'netflow', \%values, \%tags) || print "Error sending to InfluxDB\n";
113 }
114}
115
11613µs114µs$bulk->flush();
# spent 14µs making 1 call to Search::Elasticsearch::Bulk::flush
11718.82ms13.46msclear_flows($pipe);
# spent 3.46ms making 1 call to main::clear_flows
118
119#
120# Copies the file, locks, retreives, then deletes. Avoids any concurrency issues.
121#
122
# spent 38.7ms (83µs+38.6) within main::load_storable_file which was called: # once (83µs+38.6ms) by main::RUNTIME at line 46
sub load_storable_file {
1232182µs210.2ms
# spent 6.45ms (2.33+4.12) within main::BEGIN@123 which was called: # once (2.33ms+4.12ms) by main::RUNTIME at line 123
use Storable qw(lock_retrieve);
# spent 6.45ms making 1 call to main::BEGIN@123 # spent 3.73ms making 1 call to Exporter::import
1242144µs23.71ms
# spent 3.67ms (3.31+362µs) within main::BEGIN@124 which was called: # once (3.31ms+362µs) by main::RUNTIME at line 124
use File::Copy qw(copy);
# spent 3.67ms making 1 call to main::BEGIN@124 # spent 40µs making 1 call to Exporter::import
1252162µs286µs
# spent 49µs (12+37) within main::BEGIN@125 which was called: # once (12µs+37µs) by main::RUNTIME at line 125
use File::Basename qw(dirname);
# spent 49µs making 1 call to main::BEGIN@125 # spent 37µs making 1 call to Exporter::import
12611µs my $file = shift;
1271400ns my $thawed;
128121µs110µs if (-e $file) {
# spent 10µs making 1 call to main::CORE:ftis
12915µs1109µs my $dir = dirname($file);
# spent 109µs making 1 call to File::Basename::dirname
130114µs12.63ms copy($file, "$dir/$$\.tmp") || return 0;
# spent 2.63ms making 1 call to File::Copy::copy
131139µs120µs if (-e "$dir/$$\.tmp") {
# spent 20µs making 1 call to main::CORE:ftis
132110µs135.5ms $thawed = lock_retrieve("$dir/$$\.tmp");
# spent 35.5ms making 1 call to Storable::lock_retrieve
1331351µs1337µs unlink("$dir/$$\.tmp");
# spent 337µs making 1 call to main::CORE:unlink
13412µs if (!$thawed) {
135 return 0;
136 }
137 } else {
138 return 0;
139 }
140 } else {
141 return 0;
142 }
14316µs return $thawed;
144}
145
146
# spent 183ms (50µs+183) within main::create_es_bulk which was called: # once (50µs+183ms) by main::RUNTIME at line 48
sub create_es_bulk {
1472431µs134.2ms
# spent 34.2ms (769µs+33.5) within main::BEGIN@147 which was called: # once (769µs+33.5ms) by main::RUNTIME at line 147
use Search::Elasticsearch;
# spent 34.2ms making 1 call to main::BEGIN@147
14812µs my $dbname = shift;
149
150
151111µs1155ms my $es = Search::Elasticsearch->new(nodes => @es_nodes);
# spent 155ms making 1 call to Search::Elasticsearch::new
15215µs154µs my $esdate = return_esdate();
# spent 54µs making 1 call to main::return_esdate
15314µs116µs my $estime = return_estimestamp();
# spent 16µs making 1 call to main::return_estimestamp
15413µs164µs my ($mapping, $datatype) = return_mapping($dbname);
# spent 64µs making 1 call to main::return_mapping
155
15616µs27.02ms if (!($es->indices->exists(index => "$dbname-$esdate"))) {
# spent 6.72ms making 1 call to Search::Elasticsearch::Role::Client::Direct::__ANON__[/opt/flows/lib/lib/perl5/Search/Elasticsearch/Role/Client/Direct.pm:102] # spent 298µs making 1 call to Search::Elasticsearch::Role::Client::Direct::Main::indices
157 try {
158 $es->indices->create( index => "$dbname-$esdate", body => { mappings => $mapping, } );
159 } catch {
160 print "Create mapping for index $dbname-$esdate failed\n";
161 return 0;
162 };
163 }
16418µs115.9ms return create_bulk($es, "$dbname-$esdate", 'datatype');
# spent 15.9ms making 1 call to main::create_bulk
165}
166
167# I think this covers us for most use-cases:
168#
169# $tags = (
170# key => {
171# operation => 'replace'
172# value => {
173# 100 => 'somename',
174# },
175# key2 => {
176# operation => 'add',
177# newtag => 'key3'
178# value => {
179# 101 => 'Transit'
180# },
181# },
182# );
183
184#
185# Danger, this doesn't do what you think.
186#
187sub transform_tags {
188 my $tags = shift;
189 my $input_transform = shift;
190
191 return $tags unless $input_transform;
192
193 foreach my $key (keys %{$input_transform}) {
194 next unless $tags->{$key};
195 if ($input_transform->{$key}{operation} =~ /replace/i) {
196 $tags->{$key} = $input_transform->{$key}{value}
197 } elsif ($input_transform->{$key}{operation} =~ /add/i) {
198 $tags->{$input_transform->{$key}{addkey}} = $input_transform->{$key}{addvalue};
199 } else {
200 next;
201 }
202 }
203 return $tags;
204}
205
206sub send_to_influxdb {
2072254µs23.47ms
# spent 3.44ms (2.16+1.29) within main::BEGIN@207 which was called: # once (2.16ms+1.29ms) by main::RUNTIME at line 207
use InfluxDB::LineProtocol qw(data2line);
# spent 3.44ms making 1 call to main::BEGIN@207 # spent 20µs making 1 call to InfluxDB::LineProtocol::import
208 my $sock = shift;
209 my $metric = shift;
210 my $values = shift;
211 my $tags = shift;
212 my $timestamp = shift || time * 1000000000;
213 my $influxline = data2line($metric, $values, $tags, $timestamp) . "\n" || return 0;
214 #print $influxline;
215 $sock->send($influxline) || return 0;
216 return 1;
217}
218
219### Start ES
220
221
# spent 15.9ms (8µs+15.9) within main::create_bulk which was called: # once (8µs+15.9ms) by main::create_es_bulk at line 164
sub create_bulk {
2221500ns my $es = shift;
2231400ns my $index = shift;
2241900ns my $mapping = shift;
225
22616µs115.9ms return $es->bulk_helper('index' => $index, 'type' => $mapping) || return 0;
# spent 15.9ms making 1 call to Search::Elasticsearch::Role::Client::Direct::Main::bulk_helper
227}
228
229
# spent 65µs (24+40) within main::return_esdate which was called 2 times, avg 32µs/call: # once (20µs+34µs) by main::create_es_bulk at line 152 # once (5µs+7µs) by main::RUNTIME at line 51
sub return_esdate {
230269µs22.55ms
# spent 1.28ms (10µs+1.27) within main::BEGIN@230 which was called: # once (10µs+1.27ms) by main::RUNTIME at line 230
use POSIX qw(strftime);
# spent 1.28ms making 1 call to main::BEGIN@230 # spent 1.27ms making 1 call to POSIX::import
231266µs240µs return strftime("%Y-%m-%d-%H", gmtime);
# spent 40µs making 2 calls to POSIX::strftime, avg 20µs/call
232}
233
234
# spent 39µs (26+13) within main::return_estimestamp which was called 2 times, avg 20µs/call: # once (14µs+9µs) by main::RUNTIME at line 50 # once (12µs+4µs) by main::create_es_bulk at line 153
sub return_estimestamp {
2352323µs288µs
# spent 48µs (8+40) within main::BEGIN@235 which was called: # once (8µs+40µs) by main::RUNTIME at line 235
use POSIX qw(strftime);
# spent 48µs making 1 call to main::BEGIN@235 # spent 40µs making 1 call to POSIX::import
236239µs213µs return strftime("%Y-%m-%d %H:%M:%S.000", localtime);
# spent 13µs making 2 calls to POSIX::strftime, avg 6µs/call
237}
238
239
# spent 64µs within main::return_mapping which was called: # once (64µs+0s) by main::create_es_bulk at line 154
sub return_mapping {
24011µs my $dbname = shift;
241149µs my %mapping = (
242 '_default_' => {
243 '_timestamp' => {
244 enabled => 'true',
245 store => 'true',
246 format => 'date_hour_minute_second_fraction',
247 index => 'analyzed',
248 },
249 dynamic_templates => {
250 as_path => {
251 path_match => 'as_path.as_path_*',
252 mapping => {
253 type => 'integer',
254 store => 'true',
255 },
256 },
257 },
258 properties => {
259 pps => {
260 type => 'long',
261 store => 'true',
262 },
263 bps => {
264 type => 'long',
265 store => 'true',
266 },
267 avg_size => {
268 type => 'long',
269 store => 'true',
270 },
271 bytes => {
272 type => 'long',
273 store => 'true',
274 },
275 flow_stats => {
276 type => 'object',
277 properties => {
278 bytes => {
279 type => 'long',
280 store => 'true',
281 },
282 packets => {
283 type => 'long',
284 store => 'true',
285 },
286 mac_dst => {
287 type => 'string',
288 index => =>'not_analyzed',
289 },
290 ip_proto => {
291 type => 'string',
292 index => 'not_analyzed',
293 },
294 ip_src => {
295 type => 'ip',
296 },
297 ip_dst => {
298 type => 'ip',
299 },
300 iface_in => {
301 type => 'long',
302 index => 'not_analyzed',
303 },
304 iface_out => {
305 type => 'long',
306 store => 'true',
307 },
308 port_src => {
309 type => 'integer',
310 store => 'true',
311 },
312 port_dst => {
313 type => 'integer',
314 store => 'true',
315 },
316 tos => {
317 type => 'integer',
318 store => 'true',
319 },
320 tcp_flags => {
321 type => 'integer',
322 store => 'true'
323 },
324 as_path => {
325 type => 'string',
326 index => 'not_analyzed',
327 },
328 local_pref => {
329 type => 'integer',
330 store => 'true',
331 },
332 med => {
333 type => 'integer',
334 store => 'true',
335 },
336 tag => {
337 type => 'integer',
338 store => 'true',
339 },
340 tag2 => {
341 type => 'integer',
342 store => 'true',
343 },
344 },
345 },
346 librenms_info => {
347 type => 'object',
348 properties => {
349 iface_in_descr => {
350 type => 'string',
351 index => 'not_analyzed',
352 },
353 iface_in_type => {
354 type => 'string',
355 index => 'not_analyzed',
356 },
357 iface_out_descr => {
358 type => 'string',
359 index => 'not_analyzed',
360 },
361 iface_out_type => {
362 type => 'string',
363 index => 'not_analyzed',
364 },
365 device_name => {
366 type => 'string',
367 index => 'not_analyzed',
368 },
369 device_location => {
370 type => 'string',
371 index => 'not_analyzed',
372 },
373 }
374 }
375 },
376 });
377114µs return \%{$mapping{$dbname}};
378}
379
380sub create_es_index {
3812596µs274µs
# spent 42µs (9+32) within main::BEGIN@381 which was called: # once (9µs+32µs) by main::RUNTIME at line 381
use Try::Tiny;
# spent 42µs making 1 call to main::BEGIN@381 # spent 32µs making 1 call to Exporter::import
382 my $es = shift;
383 my $index = shift;
384 my $mapping = shift;
385
386 return 1 if $es->indices->exists(index => $index);
387 try {
388 $es->index->create(index => $index,
389 body => {
390 mappings => $mapping,
391 }
392 );
393 } catch {
394 return 0;
395 };
396 return 1;
397}
398
399### End ES
400
401#
402
# spent 6.48ms (59µs+6.42) within main::clear_flows which was called 2 times, avg 3.24ms/call: # once (17µs+3.44ms) by main::RUNTIME at line 117 # once (41µs+2.98ms) by main::RUNTIME at line 44
sub clear_flows {
40323µs my $pipe = shift;
40426.46ms26.42ms my $cleared = `pmacct -p $pipe -l -e`;
# spent 6.42ms making 2 calls to main::CORE:backtick, avg 3.21ms/call
405228µs return 1;
406}
407
408#
409
# spent 5.92ms (56µs+5.87) within main::retrieve_flows which was called: # once (56µs+5.87ms) by main::RUNTIME at line 43
sub retrieve_flows {
4101500ns my $pipe = shift;
41115.91ms15.87ms my @flows = `pmacct -p $pipe -l -O json -s`;
# spent 5.87ms making 1 call to main::CORE:backtick
412122µs return @flows;
413}
414
415#
416# This could probably be done better.
417#
418
# spent 4.35ms (53µs+4.30) within main::retrieve_flow_duration which was called: # once (53µs+4.30ms) by main::RUNTIME at line 42
sub retrieve_flow_duration {
4191300ns my $pipe = shift;
42014.34ms14.30ms my $duration = `pmacct -p $pipe -i`;
# spent 4.30ms making 1 call to main::CORE:backtick
42111µs chomp($duration);
422112µs12µs if ($duration =~ /never/i) {
# spent 2µs making 1 call to main::CORE:match
423 $duration = 3600;
424 } elsif ($duration > 3600) {
425 $duration = 3600;
426 }
42718µs return $duration;
428}
 
# spent 22µs within Internals::SvREADONLY which was called 24 times, avg 908ns/call: # 24 times (22µs+0s) by constant::import at line 136 of constant.pm, avg 908ns/call
sub Internals::SvREADONLY; # xsub
# spent 304µs within UNIVERSAL::VERSION which was called 32 times, avg 10µs/call: # 11 times (92µs+0s) by strictures::VERSION at line 23 of strictures.pm, avg 8µs/call # once (19µs+0s) by Search::Elasticsearch::Serializer::JSON::BEGIN@4 at line 4 of /opt/flows/lib/lib/perl5/Search/Elasticsearch/Serializer/JSON.pm # once (14µs+0s) by Search::Elasticsearch::Cxn::HTTPTiny::BEGIN@8 at line 8 of /opt/flows/lib/lib/perl5/Search/Elasticsearch/Cxn/HTTPTiny.pm # once (12µs+0s) by Search::Elasticsearch::Role::Client::Direct::BEGIN@7 at line 7 of /opt/flows/lib/lib/perl5/Search/Elasticsearch/Role/Client/Direct.pm # once (11µs+0s) by Search::Elasticsearch::BEGIN@3 at line 3 of /opt/flows/lib/lib/perl5/Search/Elasticsearch.pm # once (11µs+0s) by IO::Socket::BEGIN@12 at line 12 of IO/Socket.pm # once (11µs+0s) by B::Hooks::EndOfScope::BEGIN@23 at line 26 of /opt/flows/lib/lib/perl5/B/Hooks/EndOfScope.pm # once (11µs+0s) by B::Hooks::EndOfScope::XS::BEGIN@9 at line 9 of /opt/flows/lib/lib/perl5/B/Hooks/EndOfScope/XS.pm # once (11µs+0s) by B::Hooks::EndOfScope::BEGIN@16 at line 16 of /opt/flows/lib/lib/perl5/B/Hooks/EndOfScope.pm # once (11µs+0s) by Sub::Exporter::BEGIN@11 at line 11 of /opt/flows/lib/lib/perl5/Sub/Exporter.pm # once (11µs+0s) by Data::OptList::BEGIN@8 at line 8 of /opt/flows/lib/lib/perl5/Data/OptList.pm # once (10µs+0s) by Module::Implementation::BEGIN@12 at line 12 of Module/Implementation.pm # once (10µs+0s) by Encode::BEGIN@12 at line 12 of Encode.pm # once (10µs+0s) by B::Hooks::EndOfScope::XS::BEGIN@10 at line 13 of /opt/flows/lib/lib/perl5/B/Hooks/EndOfScope/XS.pm # once (10µs+0s) by Search::Elasticsearch::Logger::LogAny::BEGIN@8 at line 8 of /opt/flows/lib/lib/perl5/Search/Elasticsearch/Logger/LogAny.pm # once (10µs+0s) by Package::Stash::BEGIN@15 at line 15 of Package/Stash.pm # once (9µs+0s) by Sub::Exporter::BEGIN@12 at line 12 of /opt/flows/lib/lib/perl5/Sub/Exporter.pm # once (9µs+0s) by Try::Tiny::BEGIN@12 at line 12 of Try/Tiny.pm # once (8µs+0s) by Sub::Exporter::BEGIN@13 at line 13 of /opt/flows/lib/lib/perl5/Sub/Exporter.pm # once (6µs+0s) by Method::Generate::Accessor::BEGIN@11 at line 17 of Method/Generate/Accessor.pm # once (5µs+0s) by HTTP::Tiny::_agent at line 580 of /opt/flows/lib/lib/perl5/HTTP/Tiny.pm # once (4µs+0s) by Method::Generate::Accessor::BEGIN@11 at line 21 of Method/Generate/Accessor.pm
sub UNIVERSAL::VERSION; # xsub
# spent 615µs within UNIVERSAL::can which was called 312 times, avg 2µs/call: # 64 times (123µs+0s) by Method::Generate::Accessor::_generate_xs at line 624 of Method/Generate/Accessor.pm, avg 2µs/call # 48 times (62µs+0s) by Role::Tiny::_install_does at line 395 of Role/Tiny.pm, avg 1µs/call # 29 times (57µs+0s) by Moo::Role::_inhale_if_moose at line 118 of Moo/Role.pm, avg 2µs/call # 29 times (55µs+0s) by Sub::Exporter::default_generator at line 411 of /opt/flows/lib/lib/perl5/Sub/Exporter.pm, avg 2µs/call # 18 times (25µs+0s) by Role::Tiny::_check_requires at line 301 of Role/Tiny.pm, avg 1µs/call # 16 times (42µs+0s) by Role::Tiny::_install_does at line 393 of Role/Tiny.pm, avg 3µs/call # 14 times (26µs+0s) by Moo::Role::import at line 73 of Moo/Role.pm, avg 2µs/call # 10 times (44µs+0s) by Method::Generate::Constructor::generate_method at line 98 of Method/Generate/Constructor.pm, avg 4µs/call # 10 times (33µs+0s) by Method::Generate::Constructor::generate_method at line 89 of Method/Generate/Constructor.pm, avg 3µs/call # 10 times (29µs+0s) by Method::Generate::Constructor::generate_method at line 104 of Method/Generate/Constructor.pm, avg 3µs/call # 10 times (24µs+0s) by Moo::_constructor_maker_for at line 160 of Moo.pm, avg 2µs/call # 10 times (15µs+0s) by Moo::_accessor_maker_for at line 129 of Moo.pm, avg 1µs/call # 10 times (10µs+0s) by Moo::_constructor_maker_for at line 162 of Moo.pm, avg 950ns/call # 8 times (9µs+0s) by Role::Tiny::_install_does at line 397 of Role/Tiny.pm, avg 1µs/call # 4 times (9µs+0s) by Role::Tiny::apply_roles_to_package at line 223 of Role/Tiny.pm, avg 2µs/call # 4 times (8µs+0s) by Moo::_Utils::_install_modifier at line 31 of Moo/_Utils.pm, avg 2µs/call # 4 times (6µs+0s) by Class::Method::Modifiers::install_modifier at line 44 of Class/Method/Modifiers.pm, avg 2µs/call # 3 times (10µs+0s) by Moo::Object::new at line 13 of Moo/Object.pm, avg 3µs/call # 3 times (9µs+0s) by Moo::Object::new at line 22 of Moo/Object.pm, avg 3µs/call # 2 times (5µs+0s) by Log::Any::Manager::_require_dynamic at line 181 of /opt/flows/lib/lib/perl5/Log/Any/Manager.pm, avg 3µs/call # 2 times (4µs+0s) by HTTP::Tiny::Handle::_get_tid at line 1595 of /opt/flows/lib/lib/perl5/HTTP/Tiny.pm, avg 2µs/call # 2 times (3µs+0s) by Log::Any::Adapter::Util::require_dynamic at line 182 of /opt/flows/lib/lib/perl5/Log/Any/Adapter/Util.pm, avg 2µs/call # once (4µs+0s) by attributes::import at line 59 of attributes.pm # once (4µs+0s) by HTTP::Tiny::Handle::timeout at line 1024 of /opt/flows/lib/lib/perl5/HTTP/Tiny.pm
sub UNIVERSAL::can; # xsub
# spent 31µs within UNIVERSAL::isa which was called 16 times, avg 2µs/call: # 14 times (28µs+0s) by base::import at line 73 of base.pm, avg 2µs/call # once (2µs+0s) by File::Path::mkpath at line 67 of File/Path.pm # once (1µs+0s) by File::Path::mkpath at line 75 of File/Path.pm
sub UNIVERSAL::isa; # xsub
# spent 16.6ms within main::CORE:backtick which was called 4 times, avg 4.15ms/call: # 2 times (6.42ms+0s) by main::clear_flows at line 404, avg 3.21ms/call # once (5.87ms+0s) by main::retrieve_flows at line 411 # once (4.30ms+0s) by main::retrieve_flow_duration at line 420
sub main::CORE:backtick; # opcode
# spent 30µs within main::CORE:ftis which was called 2 times, avg 15µs/call: # once (20µs+0s) by main::load_storable_file at line 131 # once (10µs+0s) by main::load_storable_file at line 128
sub main::CORE:ftis; # opcode
# spent 2µs within main::CORE:match which was called: # once (2µs+0s) by main::retrieve_flow_duration at line 422
sub main::CORE:match; # opcode
# spent 4µs within main::CORE:pack which was called: # once (4µs+0s) by main::BEGIN@7 at line 315 of IO/Socket.pm
sub main::CORE:pack; # opcode
# spent 337µs within main::CORE:unlink which was called: # once (337µs+0s) by main::load_storable_file at line 133
sub main::CORE:unlink; # opcode
# spent 7µs within utf8::downgrade which was called 6 times, avg 1µs/call: # 2 times (3µs+0s) by URI::_generic::path at line 46 of URI/_generic.pm, avg 1µs/call # 2 times (2µs+0s) by URI::_uric_escape at line 93 of URI.pm, avg 1µs/call # 2 times (2µs+0s) by HTTP::Tiny::Handle::write at line 1114 of /opt/flows/lib/lib/perl5/HTTP/Tiny.pm, avg 750ns/call
sub utf8::downgrade; # xsub
# spent 1µs within utf8::encode which was called: # once (1µs+0s) by Search::Elasticsearch::Util::API::Path::path_handler at line 31 of /opt/flows/lib/lib/perl5/Search/Elasticsearch/Util/API/Path.pm
sub utf8::encode; # xsub
# spent 5µs within version::(bool which was called: # once (5µs+0s) by local::lib::BEGIN@11 at line 59 of Config.pm
sub version::(bool; # xsub
# spent 5µs within version::(cmp which was called: # once (5µs+0s) by local::lib::BEGIN@11 at line 62 of Config.pm
sub version::(cmp; # xsub
Report produced by the NYTProf 5.06 Perl profiler, developed by Tim Bunce and Adam Kaplan.