Branch data Line data Source code
1 : : // $Id: Stats.cc 7008 2010-03-25 02:42:20Z vern $
2 : :
3 : : #include "Conn.h"
4 : : #include "File.h"
5 : : #include "Event.h"
6 : : #include "NetVar.h"
7 : : #include "Sessions.h"
8 : : #include "Stats.h"
9 : : #include "Scope.h"
10 : : #include "cq.h"
11 : : #include "ConnCompressor.h"
12 : :
13 : :
14 : : int killed_by_inactivity = 0;
15 : :
16 : : uint32 tot_ack_events = 0;
17 : : uint32 tot_ack_bytes = 0;
18 : : uint32 tot_gap_events = 0;
19 : : uint32 tot_gap_bytes = 0;
20 : :
21 : :
22 [ # # ][ # # ]: 0 : class ProfileTimer : public Timer {
23 : : public:
24 : 0 : ProfileTimer(double t, ProfileLogger* l, double i)
25 : 0 : : Timer(t, TIMER_PROFILE)
26 : : {
27 : 0 : logger = l;
28 : 0 : interval = i;
29 : 0 : }
30 : :
31 : : void Dispatch(double t, int is_expire);
32 : :
33 : : protected:
34 : : double interval;
35 : : ProfileLogger* logger;
36 : : };
37 : :
38 : 0 : void ProfileTimer::Dispatch(double t, int is_expire)
39 : : {
40 : 0 : logger->Log();
41 : :
42 : : // Reinstall timer.
43 [ # # ]: 0 : if ( ! is_expire )
44 : : timer_mgr->Add(new ProfileTimer(network_time + interval,
45 : 0 : logger, interval));
46 : 0 : }
47 : :
48 : :
49 : 0 : ProfileLogger::ProfileLogger(BroFile* arg_file, double interval)
50 : 0 : : SegmentStatsReporter()
51 : : {
52 : 0 : file = arg_file;
53 : 0 : log_count = 0;
54 : 0 : timer_mgr->Add(new ProfileTimer(1, this, interval));
55 : 0 : }
56 : :
57 : 0 : ProfileLogger::~ProfileLogger()
58 : : {
59 : 0 : file->Close();
60 [ # # ][ # # ]: 0 : }
[ # # ]
61 : :
62 : 0 : void ProfileLogger::Log()
63 : : {
64 [ # # ]: 0 : if ( terminating )
65 : : // Connections have been flushed already.
66 : 0 : return;
67 : :
68 : 0 : file->Write(fmt("%.06f ------------------------\n", network_time));
69 : :
70 : : // Do expensive profiling only occasionally.
71 : 0 : bool expensive = false;
72 : :
73 [ # # ]: 0 : if ( expensive_profiling_multiple )
74 : 0 : expensive = (++log_count) % expensive_profiling_multiple == 0;
75 : :
76 : : // Memory information.
77 : : struct rusage r;
78 : 0 : getrusage(RUSAGE_SELF, &r);
79 : 0 : struct timeval tv_utime = r.ru_utime;
80 : 0 : struct timeval tv_stime = r.ru_stime;
81 : :
82 : : unsigned int total, malloced;
83 : 0 : get_memory_usage(&total, &malloced);
84 : :
85 : : static unsigned int first_total = 0;
86 : : static double first_rtime = 0;
87 : : static double first_utime = 0;
88 : : static double first_stime = 0;
89 : :
90 : 0 : double rtime = current_time();
91 : 0 : double utime = double(tv_utime.tv_sec) + double(tv_utime.tv_usec) / 1e6;
92 : 0 : double stime = double(tv_stime.tv_sec) + double(tv_stime.tv_usec) / 1e6;
93 : :
94 [ # # ]: 0 : if ( first_total == 0 )
95 : : {
96 : 0 : first_total = total;
97 : 0 : first_rtime = rtime;
98 : 0 : first_utime = utime;
99 : 0 : first_stime = stime;
100 : :
101 : 0 : file->Write(fmt("%.06f Command line: ", network_time ));
102 [ # # ]: 0 : for ( int i = 0; i < bro_argc; i++ )
103 : : {
104 : 0 : file->Write(bro_argv[i]);
105 : 0 : file->Write(" ");
106 : : }
107 : 0 : file->Write(fmt("\n%.06f ------------------------\n", network_time));
108 : : }
109 : :
110 : : file->Write(fmt("%.06f Memory: total=%dK total_adj=%dK malloced: %dK\n",
111 : : network_time, total / 1024, (total - first_total) / 1024,
112 : 0 : malloced / 1024));
113 : :
114 : : file->Write(fmt("%.06f Run-time: user+sys=%.1f user=%.1f sys=%.1f real=%.1f\n",
115 : : network_time, (utime + stime) - (first_utime + first_stime),
116 : 0 : utime - first_utime, stime - first_stime, rtime - first_rtime));
117 : :
118 [ # # ]: 0 : int conn_mem_use = expensive ? sessions->ConnectionMemoryUsage() : 0;
119 : :
120 : : file->Write(fmt("%.06f Conns: total=%d current=%d/%d ext=%d mem=%dK avg=%.1f table=%dK connvals=%dK\n",
121 : : network_time,
122 : : Connection::TotalConnections(),
123 : : Connection::CurrentConnections(),
124 : : sessions->CurrentConnections(),
125 : : Connection::CurrentExternalConnections(),
126 : : conn_mem_use,
127 : : expensive ? (conn_mem_use / double(sessions->CurrentConnections())) : 0,
128 : : expensive ? sessions->MemoryAllocation() / 1024 : 0,
129 : : expensive ? sessions->ConnectionMemoryUsageConnVals() / 1024 : 0
130 [ # # ][ # # ]: 0 : ));
[ # # ]
131 : :
132 : 0 : const ConnCompressor::Sizes& cs = conn_compressor->Size();
133 : :
134 : : file->Write(fmt("%.6f ConnCompressor: pending=%d pending_in_mem=%d full_conns=%d pending+real=%d mem=%dK avg=%.1f/%.1f\n",
135 : : network_time,
136 : : cs.pending_valid,
137 : : cs.pending_in_mem,
138 : : cs.connections,
139 : : cs.hash_table_size,
140 : : cs.memory / 1024,
141 : : cs.memory / double(cs.pending_valid),
142 : : cs.memory / double(cs.pending_in_mem)
143 : 0 : ));
144 : :
145 : : SessionStats s;
146 : 0 : sessions->GetStats(s);
147 : :
148 : : file->Write(fmt("%.06f Conns: tcp=%d/%d udp=%d/%d icmp=%d/%d\n",
149 : : network_time,
150 : : s.num_TCP_conns, s.max_TCP_conns,
151 : : s.num_UDP_conns, s.max_UDP_conns,
152 : : s.num_ICMP_conns, s.max_ICMP_conns
153 : 0 : ));
154 : :
155 : : sessions->tcp_stats.PrintStats(file,
156 : 0 : fmt("%.06f TCP-States:", network_time));
157 : :
158 : : // Alternatively, if you prefer more compact output...
159 : : /*
160 : : file->Write(fmt("%.8f TCP-States: I=%d S=%d SA=%d SR=%d E=%d EF=%d ER=%d F=%d P=%d\n",
161 : : network_time,
162 : : sessions->tcp_stats.StateInactive(),
163 : : sessions->tcp_stats.StateRequest(),
164 : : sessions->tcp_stats.StateSuccRequest(),
165 : : sessions->tcp_stats.StateRstRequest(),
166 : : sessions->tcp_stats.StateEstablished(),
167 : : sessions->tcp_stats.StateHalfClose(),
168 : : sessions->tcp_stats.StateHalfRst(),
169 : : sessions->tcp_stats.StateClosed(),
170 : : sessions->tcp_stats.StatePartial()
171 : : ));
172 : : */
173 : :
174 : : file->Write(fmt("%.06f Connections expired due to inactivity: %d\n",
175 : 0 : network_time, killed_by_inactivity));
176 : :
177 : : file->Write(fmt("%.06f Total reassembler data: %dK\n", network_time,
178 : 0 : Reassembler::TotalMemoryAllocation() / 1024));
179 : :
180 : : // Signature engine.
181 [ # # # # ]: 0 : if ( expensive && rule_matcher )
182 : : {
183 : : RuleMatcher::Stats stats;
184 : 0 : rule_matcher->GetStats(&stats);
185 : :
186 : : file->Write(fmt("%06f RuleMatcher: matchers=%d dfa_states=%d ncomputed=%d "
187 : : "mem=%dK avg_nfa_states=%d\n", network_time, stats.matchers,
188 : 0 : stats.dfa_states, stats.computed, stats.mem / 1024, stats.avg_nfa_states));
189 : : }
190 : :
191 : : file->Write(fmt("%.06f Timers: current=%d max=%d mem=%dK lag=%.2fs\n",
192 : : network_time,
193 : : timer_mgr->Size(), timer_mgr->PeakSize(),
194 : : int(cq_memory_allocation() +
195 : : (timer_mgr->Size() * padded_sizeof(ConnectionTimer))) / 1024,
196 : 0 : network_time - timer_mgr->LastTimestamp()));
197 : :
198 : 0 : unsigned int* current_timers = TimerMgr::CurrentTimers();
199 [ # # ]: 0 : for ( int i = 0; i < NUM_TIMER_TYPES; ++i )
200 : : {
201 [ # # ]: 0 : if ( current_timers[i] )
202 : : file->Write(fmt("%.06f %s = %d\n", network_time,
203 : : timer_type_to_string((TimerType) i),
204 : 0 : current_timers[i]));
205 : : }
206 : :
207 : : // Script-level state.
208 : 0 : unsigned int size, mem = 0;
209 : 0 : PDict(ID)* globals = global_scope()->Vars();
210 : :
211 [ # # ]: 0 : if ( expensive )
212 : : {
213 : 0 : int total_table_entries = 0;
214 : 0 : int total_table_rentries = 0;
215 : :
216 : : file->Write(fmt("%.06f Global_sizes > 100k: %dK\n",
217 : 0 : network_time, mem / 1024));
218 : :
219 : : ID* id;
220 : 0 : IterCookie* c = globals->InitForIteration();
221 : :
222 [ # # ]: 0 : while ( (id = globals->NextEntry(c)) )
223 : : // We don't show/count internal globals as they are always
224 : : // contained in some other global user-visible container.
225 [ # # ][ # # ]: 0 : if ( id->HasVal() && ! id->IsInternalGlobal() )
[ # # ]
226 : : {
227 : 0 : Val* v = id->ID_Val();
228 : :
229 : 0 : size = id->ID_Val()->MemoryAllocation();
230 : 0 : mem += size;
231 : :
232 : 0 : bool print = false;
233 : 0 : int entries = -1;
234 : 0 : int rentries = -1;
235 : :
236 [ # # ]: 0 : if ( size > 100 * 1024 )
237 : 0 : print = true;
238 : :
239 [ # # ]: 0 : if ( v->Type()->Tag() == TYPE_TABLE )
240 : : {
241 : 0 : entries = v->AsTable()->Length();
242 : 0 : total_table_entries += entries;
243 : :
244 : : // ### 100 shouldn't be hardwired
245 : : // in here.
246 [ # # ]: 0 : if ( entries >= 100 )
247 : 0 : print = true;
248 : :
249 : 0 : rentries = v->AsTableVal()->RecursiveSize();
250 : 0 : total_table_rentries += rentries;
251 [ # # ]: 0 : if ( rentries >= 100 ) // ### or here
252 : 0 : print = true;
253 : : }
254 : :
255 [ # # ]: 0 : if ( print )
256 : : {
257 : : file->Write(fmt("%.06f %s = %dK",
258 : : network_time, id->Name(),
259 : 0 : size / 1024));
260 : :
261 [ # # ]: 0 : if ( entries >= 0 )
262 : : file->Write(fmt(" (%d/%d entries)\n",
263 : 0 : entries, rentries));
264 : : else
265 : 0 : file->Write("\n");
266 : : }
267 : : }
268 : :
269 : : file->Write(fmt("%.06f Global_sizes total: %dK\n",
270 : 0 : network_time, mem / 1024));
271 : : file->Write(fmt("%.06f Total number of table entries: %d/%d\n",
272 : : network_time,
273 : 0 : total_table_entries, total_table_rentries));
274 : : }
275 : :
276 : : // Create an event so that scripts can log their information, too.
277 : : // (and for consistency we dispatch it *now*)
278 [ # # ]: 0 : if ( profiling_update )
279 : : {
280 : 0 : val_list* vl = new val_list;
281 : 0 : Ref(file);
282 : 0 : vl->append(new Val(file));
283 : 0 : vl->append(new Val(expensive, TYPE_BOOL));
284 : 0 : mgr.Dispatch(new Event(profiling_update, vl));
285 : : }
286 : : }
287 : :
288 : : void ProfileLogger::SegmentProfile(const char* name, const Location* loc,
289 : 0 : double dtime, int dmem)
290 : : {
291 [ # # ]: 0 : if ( name )
292 : : file->Write(fmt("%.06f segment-%s dt=%.06f dmem=%d\n",
293 : 0 : network_time, name, dtime, dmem));
294 [ # # ]: 0 : else if ( loc )
295 : : file->Write(fmt("%.06f segment-%s:%d dt=%.06f dmem=%d\n",
296 : : network_time,
297 : : loc->filename ? loc->filename : "nofile",
298 : : loc->first_line,
299 [ # # ]: 0 : dtime, dmem));
300 : : else
301 : : file->Write(fmt("%.06f segment-XXX dt=%.06f dmem=%d\n",
302 : 0 : network_time, dtime, dmem));
303 : 0 : }
304 : :
305 : :
306 : 0 : SampleLogger::SampleLogger()
307 : : {
308 : : static TableType* load_sample_info = 0;
309 : :
310 [ # # # # ]: 0 : if ( ! load_sample_info )
311 : 0 : load_sample_info = internal_type("load_sample_info")->AsTableType();
312 : :
313 : 0 : load_samples = new TableVal(load_sample_info);
314 : 0 : }
315 : :
316 : 0 : SampleLogger::~SampleLogger()
317 : : {
318 : 0 : Unref(load_samples);
319 [ # # ][ # # ]: 0 : }
[ # # ]
320 : :
321 : 0 : void SampleLogger::FunctionSeen(const Func* func)
322 : : {
323 : 0 : load_samples->Assign(new StringVal(func->GetID()->Name()), 0);
324 : 0 : }
325 : :
326 : 0 : void SampleLogger::LocationSeen(const Location* loc)
327 : : {
328 : 0 : load_samples->Assign(new StringVal(loc->filename), 0);
329 : 0 : }
330 : :
331 : : void SampleLogger::SegmentProfile(const char* /* name */,
332 : : const Location* /* loc */,
333 : 0 : double dtime, int dmem)
334 : : {
335 : 0 : val_list* vl = new val_list(2);
336 : 0 : vl->append(load_samples->Ref());
337 : 0 : vl->append(new IntervalVal(dtime, Seconds));
338 : 0 : vl->append(new Val(dmem, TYPE_INT));
339 : :
340 : 0 : mgr.QueueEvent(load_sample, vl);
341 : 0 : }
342 : :
343 : 0 : void SegmentProfiler::Init()
344 : : {
345 : 0 : getrusage(RUSAGE_SELF, &initial_rusage);
346 : 0 : }
347 : :
348 : 0 : void SegmentProfiler::Report()
349 : : {
350 : : struct rusage final_rusage;
351 : 0 : getrusage(RUSAGE_SELF, &final_rusage);
352 : :
353 : : double start_time =
354 : : double(initial_rusage.ru_utime.tv_sec) +
355 : : double(initial_rusage.ru_utime.tv_usec) / 1e6 +
356 : : double(initial_rusage.ru_stime.tv_sec) +
357 : 0 : double(initial_rusage.ru_stime.tv_usec) / 1e6;
358 : :
359 : : double stop_time =
360 : : double(final_rusage.ru_utime.tv_sec) +
361 : : double(final_rusage.ru_utime.tv_usec) / 1e6 +
362 : : double(final_rusage.ru_stime.tv_sec) +
363 : 0 : double(final_rusage.ru_stime.tv_usec) / 1e6;
364 : :
365 : 0 : int start_mem = initial_rusage.ru_maxrss * 1024;
366 : 0 : int stop_mem = initial_rusage.ru_maxrss * 1024;
367 : :
368 : 0 : double dtime = stop_time - start_time;
369 : 0 : int dmem = stop_mem - start_mem;
370 : :
371 : 0 : reporter->SegmentProfile(name, loc, dtime, dmem);
372 : 0 : }
373 : :
374 : :
375 : 1 : TCPStateStats::TCPStateStats()
376 : : {
377 [ + + ][ # # ]: 8 : for ( int i = 0; i < TCP_ENDPOINT_RESET + 1; ++i )
378 [ + + ][ # # ]: 56 : for ( int j = 0; j < TCP_ENDPOINT_RESET + 1; ++j )
379 : 49 : state_cnt[i][j] = 0;
380 : 1 : }
381 : :
382 : : void TCPStateStats::ChangeState(EndpointState o_prev, EndpointState o_now,
383 : 3029 : EndpointState r_prev, EndpointState r_now)
384 : : {
385 : 3029 : --state_cnt[o_prev][r_prev];
386 : 3029 : ++state_cnt[o_now][r_now];
387 : 3029 : }
388 : :
389 : 0 : void TCPStateStats::FlipState(EndpointState orig, EndpointState resp)
390 : : {
391 : 0 : --state_cnt[orig][resp];
392 : 0 : ++state_cnt[resp][orig];
393 : 0 : }
394 : :
395 : 0 : unsigned int TCPStateStats::NumStatePartial() const
396 : : {
397 : 0 : unsigned int sum = 0;
398 [ # # ]: 0 : for ( int i = 0; i < TCP_ENDPOINT_RESET + 1; ++i )
399 : : {
400 : 0 : sum += state_cnt[TCP_ENDPOINT_PARTIAL][i];
401 : 0 : sum += state_cnt[i][TCP_ENDPOINT_PARTIAL];
402 : : }
403 : :
404 : 0 : return sum;
405 : : }
406 : :
407 : 0 : void TCPStateStats::PrintStats(BroFile* file, const char* prefix)
408 : : {
409 : 0 : file->Write(prefix);
410 : 0 : file->Write(" Inact. Syn. SA Part. Est. Fin. Rst.\n");
411 : :
412 [ # # ]: 0 : for ( int i = 0; i < TCP_ENDPOINT_RESET + 1; ++i )
413 : : {
414 : 0 : file->Write(prefix);
415 : :
416 [ # # # # # : 0 : switch ( i ) {
# # # ]
417 : : #define STATE_STRING(state, str) \
418 : : case state: \
419 : : file->Write(str); \
420 : : break;
421 : :
422 : 0 : STATE_STRING(TCP_ENDPOINT_INACTIVE, "Inact.");
423 : 0 : STATE_STRING(TCP_ENDPOINT_SYN_SENT, "Syn. ");
424 : 0 : STATE_STRING(TCP_ENDPOINT_SYN_ACK_SENT, "SA ");
425 : 0 : STATE_STRING(TCP_ENDPOINT_PARTIAL, "Part. ");
426 : 0 : STATE_STRING(TCP_ENDPOINT_ESTABLISHED, "Est. ");
427 : 0 : STATE_STRING(TCP_ENDPOINT_CLOSED, "Fin. ");
428 : 0 : STATE_STRING(TCP_ENDPOINT_RESET, "Rst. ");
429 : :
430 : : }
431 : :
432 : 0 : file->Write(" ");
433 : :
434 [ # # ]: 0 : for ( int j = 0; j < TCP_ENDPOINT_RESET + 1; ++j )
435 : : {
436 : 0 : unsigned int n = state_cnt[i][j];
437 [ # # ]: 0 : if ( n > 0 )
438 : : {
439 : : char buf[32];
440 : 0 : safe_snprintf(buf, sizeof(buf), "%-8d", state_cnt[i][j]);
441 : 0 : file->Write(buf);
442 : : }
443 : : else
444 : 0 : file->Write(" ");
445 : : }
446 : :
447 : 0 : file->Write("\n");
448 : : }
449 : 0 : }
450 : :
451 : :
452 : : PacketProfiler::PacketProfiler(unsigned int mode, double freq,
453 : 0 : BroFile* arg_file)
454 : : {
455 : 0 : update_mode = mode;
456 : 0 : update_freq = freq;
457 : 0 : file = arg_file;
458 : :
459 : 0 : last_Utime = last_Stime = last_Rtime = 0.0;
460 : 0 : last_timestamp = time = 0.0;
461 : 0 : pkt_cnt = byte_cnt = 0;
462 : :
463 : 0 : file->Write("time dt npkts nbytes dRtime dUtime dStime dmem\n");
464 : 0 : }
465 : :
466 : 0 : PacketProfiler::~PacketProfiler()
467 : : {
468 : 0 : file->Close();
469 : 0 : }
470 : :
471 : 0 : void PacketProfiler::ProfilePkt(double t, unsigned int bytes)
472 : : {
473 [ # # ]: 0 : if ( last_timestamp == 0.0 )
474 : : {
475 : : struct rusage res;
476 : : struct timeval ptimestamp;
477 : 0 : getrusage(RUSAGE_SELF, &res);
478 : 0 : gettimeofday(&ptimestamp, 0);
479 : :
480 : 0 : get_memory_usage(&last_mem, 0);
481 : 0 : last_Utime = res.ru_utime.tv_sec + res.ru_utime.tv_usec / 1e6;
482 : 0 : last_Stime = res.ru_stime.tv_sec + res.ru_stime.tv_usec / 1e6;
483 : 0 : last_Rtime = ptimestamp.tv_sec + ptimestamp.tv_usec / 1e6;
484 : 0 : last_timestamp = t;
485 : : }
486 : :
487 [ # # ][ # # ]: 0 : if ( (update_mode == MODE_TIME && t > last_timestamp+update_freq) ||
[ # # ][ # # ]
[ # # ][ # # ]
488 : : (update_mode == MODE_PACKET && double(pkt_cnt) > update_freq) ||
489 : : (update_mode == MODE_VOLUME && double(pkt_cnt) > update_freq) )
490 : : {
491 : : struct rusage res;
492 : : struct timeval ptimestamp;
493 : 0 : getrusage(RUSAGE_SELF, &res);
494 : 0 : gettimeofday(&ptimestamp, 0);
495 : :
496 : : double curr_Utime =
497 : 0 : res.ru_utime.tv_sec + res.ru_utime.tv_usec / 1e6;
498 : : double curr_Stime =
499 : 0 : res.ru_stime.tv_sec + res.ru_stime.tv_usec / 1e6;
500 : : double curr_Rtime =
501 : 0 : ptimestamp.tv_sec + ptimestamp.tv_usec / 1e6;
502 : :
503 : : unsigned int curr_mem;
504 : 0 : get_memory_usage(&curr_mem, 0);
505 : :
506 : : file->Write(fmt("%.06f %.03f %d %d %.03f %.03f %.03f %d\n",
507 : : t, time-last_timestamp, pkt_cnt, byte_cnt,
508 : : curr_Rtime - last_Rtime,
509 : : curr_Utime - last_Utime,
510 : : curr_Stime - last_Stime,
511 : 0 : curr_mem - last_mem));
512 : :
513 : 0 : last_Utime = curr_Utime;
514 : 0 : last_Stime = curr_Stime;
515 : 0 : last_Rtime = curr_Rtime;
516 : 0 : last_mem = curr_mem;
517 : 0 : last_timestamp = t;
518 : 0 : pkt_cnt = 0;
519 : 0 : byte_cnt = 0;
520 : : }
521 : :
522 : 0 : ++pkt_cnt;
523 : 0 : byte_cnt += bytes;
524 : 0 : time = t;
525 [ + - ][ + - ]: 6 : }
|
