logging.py 16.5 KB
Newer Older
1
2
# -*- coding:utf-8 -*-

Mario Hock's avatar
Mario Hock committed
3
4
5
6
7
8
9
10
11
# Copyright (c) 2014,
# Karlsruhe Institute of Technology, Institute of Telematics
#
# This code is provided under the BSD 2-Clause License.
# Please refer to the LICENSE.txt file for further information.
#
# Author: Mario Hock


12
import json
Mario Hock's avatar
Mario Hock committed
13
14
import time
import os
Mario Hock's avatar
Mario Hock committed
15
import psutil
16

17
18
19
## experimental "tcp_probe"
#import subprocess
#import signal
20

Mario Hock's avatar
Mario Hock committed
21
22
23
from history_store import HistoryStore


24
25
26
27
28
29
30
31
32
33
34
class LoggingClass:
    def __init__(self, name, fields, siblings, description):
        self.name = name

        self.values = dict()
        self.values["Fields"] = fields
        self.values["Siblings"] = siblings
        self.values["Description"] = description



35
class MeasurementLogger:
Mario Hock's avatar
Mario Hock committed
36
37
38
39
40
    """
    Logs the given »Measurements« (derived from two »Readings«) into a JSON-header CSV-body file.
    """

    ## Initialization ##
41

42
    def __init__(self, num_cpus, nics, begin, system_info, environment, comment, filename):
43
44
45
46
47
        ## Attributes
        self.num_cpus = num_cpus
        self.nics = nics
        self.filename = filename

48
        ## Constants / Characteristics
49
        self.class_names = ("Time", "CPU", "NIC", "NICStats", "Memory")
50
51
52
53
54
55
56
57
        self.type_string = "CPUnetLOG:MeasurementLog"

        ## Run "outsourced" init functions.
        self.class_defs = self._init_class_definitions(num_cpus, nics)

        self.json_header = self._create_json_header(self.class_names,
                                                    self.class_defs.values(),
                                                    self.type_string,
Mario Hock's avatar
Mario Hock committed
58
                                                    begin,
59
                                                    system_info,
60
                                                    environment,
61
62
63
64
65
66
                                                    comment)

        self.csv_header = self._create_csv_header(self.json_header)


        ## Register special logging functions.
67
68
69
70
        self.log_functions = dict()
        self.log_functions["Time"] = self._log_time
        self.log_functions["CPU"] = self._log_cpus
        self.log_functions["NIC"] = self._log_nics
71
72
        self.log_functions["NICStats"] = self._log_nic_stats
        self.log_functions["Memory"] = self._log_memory
73
74


Mario Hock's avatar
Mario Hock committed
75
        ## Initialize file writer.
Mario Hock's avatar
Mario Hock committed
76
        self.writer = CNLFileWriter(filename)
Mario Hock's avatar
Mario Hock committed
77
78
79
80
81
82

        # Write header.
        self.writer.write_header(self.json_header)
        self.writer.write_vector(self.csv_header)


83

84
85
    def _init_class_definitions(self, num_cpus, nics):
        class_defs = dict()
86
87
88

        # set up "CPU" class
        cpu = LoggingClass( name        = "CPU",
Mario Hock's avatar
log irq    
Mario Hock committed
89
                            fields      = ("util", "idle", "usr", "system", "irq", "softirq", "other"),
90
                            siblings    = [ "CPU" + str(i) for i in range(0,num_cpus) ],
91
                            description = "CPU utilization in percent" )
92
        class_defs["CPU"] = cpu
93
94
95
96
97
98

        # set up "NIC" class
        nic = LoggingClass( name        = "NIC",
                            fields      = ("send", "receive"),
                            siblings    = nics,
                            description = "Network traffic (Bits/s)" )
99
        class_defs["NIC"] = nic
100

101
102
103
104
105
106
107
        # set up "NICStats" class
        nicstats = LoggingClass( name = "NICStats",
                            fields      = ("errin", "errout", "dropin", "dropout"),
                            siblings    = nics,
                            description = "Network Interface stats (errors and drops)" )
        class_defs["NICStats"] = nicstats

108
109
        # set up "Time" class
        time = LoggingClass( name        = "Time",
110
111
112
113
                            fields      = ("begin", "end", "duration"),
                            siblings    = None,
                            description = "Begin, end, and duration (in seconds) of this measurement." )
        class_defs["Time"] = time
Mario Hock's avatar
Mario Hock committed
114

115
116
117
118
119
120
121
        # set up "Memory" class
        memory = LoggingClass( name = "Memory",
                            fields      = ("used", "active", "inactive", "buffers", "cached"),
                            siblings   = None,
                            description = "Memory utilization" )
        class_defs["Memory"] = memory

122
        return class_defs
Mario Hock's avatar
Mario Hock committed
123
124


125
    ## TODO Move this outside the class?
126
    def _create_json_header(self, class_names, class_defs, type, begin, system_info, environment, comment):
127
128
        top_level = dict()
        general = dict()
Mario Hock's avatar
Mario Hock committed
129
130
131
        class_definitions = dict()

        ## General
132
133
134
        general["Classes"] = class_names
        general["Type"] = type
        general["Comment"] = comment
Mario Hock's avatar
Mario Hock committed
135
        general["Date"] = begin
136
        general["SystemInfo"] = system_info
137
        general["Environment"] = environment
138
139
140
        #general["End"] = 0        ## TODO ... can't be written at the beginning of the file!!
        #general["Duration"] = 0   ## TODO
        top_level["General"] = general
Mario Hock's avatar
Mario Hock committed
141
142

        ## Class definitions
143
        for c in class_defs:
Mario Hock's avatar
Mario Hock committed
144
            class_definitions[c.name] = c.values
145
        top_level["ClassDefinitions"] = class_definitions
Mario Hock's avatar
Mario Hock committed
146

147
        pretty_json = json.dumps(top_level, sort_keys=True, indent=4)
Mario Hock's avatar
Mario Hock committed
148

149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
        return top_level


    ## TODO Move this outside the class?
    def _create_csv_header(self, json_header):
        csv_header = list()

        general = json_header["General"]
        class_definitions = json_header["ClassDefinitions"]

        for _class_name in general["Classes"]:
            _class = class_definitions[_class_name]

            if ( _class["Siblings"] ):
                for sibling in _class["Siblings"]:
                    for field in _class["Fields"]:
                        csv_header.append( ".".join([sibling, field]) )
            else:
                for field in _class["Fields"]:
                    csv_header.append( field )

        return csv_header

172
173


Mario Hock's avatar
Mario Hock committed
174
175
176

    ## Logging functions ##

Mario Hock's avatar
Mario Hock committed
177
178
    def _log_time(self, measurement, out_vector):
        out_vector.extend( [measurement.r1.timestamp, measurement.r2.timestamp, measurement.timespan] )
179
180


Mario Hock's avatar
Mario Hock committed
181
    def _log_cpus(self, measurement, out_vector):
182
        for cpu in measurement.cpu_times_percent:
183
            cpu_util = 100-cpu.idle
Mario Hock's avatar
log irq    
Mario Hock committed
184
            other = 100 - sum( (cpu.user, cpu.system, cpu.irq, cpu.softirq, cpu.idle) )
185

Mario Hock's avatar
log irq    
Mario Hock committed
186
            out_vector.extend( [cpu_util, cpu.idle, cpu.user, cpu.system, cpu.irq, cpu.softirq, other] )
187
188


Mario Hock's avatar
Mario Hock committed
189
    def _log_nics(self, measurement, out_vector):
190
        for nic in self.nics:
191
192
            try:
                values = measurement.net_io[nic]
193

194
195
196
197
198
                out_vector.extend( [values.ratio["bytes_sent"] * 8,    # Bits/s
                                values.ratio["bytes_recv"] * 8] )  # Bits/s
            except KeyError:
                ## TODO: is 0 a good value to log, in this case?
                out_vector.extend( (0, 0) )
199

200
201
202
203
204
205
206
207
    def _log_nic_stats(self, measurement, out_vector):
        for nic in self.nics:
            values = measurement.net_io[nic]
            out_vector.extend( [values.total["errin"], values.total["errout"], values.total["dropin"], values.total["dropout"]] )


    def _log_memory(self, measurement, out_vector):
        out_vector.extend( [measurement.memory.used, measurement.memory.active, measurement.memory.inactive, measurement.memory.buffers, measurement.memory.cached] )
208
209

    def log(self, measurement):
Mario Hock's avatar
Mario Hock committed
210
        out_vector = list()
211
212

        ## Call the specific log-function for each class (in the proper order).
Mario Hock's avatar
Mario Hock committed
213
        for c in self.class_names:
Mario Hock's avatar
Mario Hock committed
214
            self.log_functions[c](measurement, out_vector)
215

Mario Hock's avatar
Mario Hock committed
216
        self.writer.write_vector( out_vector )
217
218


Mario Hock's avatar
Mario Hock committed
219
220
221

    ## Close ##

222
    def close(self):
Mario Hock's avatar
Mario Hock committed
223
224
225
226
227
228
        self.writer.close()




class CNLFileWriter:
Mario Hock's avatar
Mario Hock committed
229
230
231
232
233
234
235
236
237
238
239
    """
    This class produces files in the »CNL« format.

    Usage:
      - Constructor( filename )
      - write_header( »Dictionary that gets converted into JSON.« )
      - write_vector( »Vector specifying the CSV-header« )
      - Loop:
          - write_vector( »Vector holding one line of data.« )
      - close()
    """
Mario Hock's avatar
Mario Hock committed
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289

    def __init__(self, filename):
        self.filename = filename

        self.file = None
        self.header_written = False

        self._open_file()


    def _write(self, line):
        self.file.write(line)

    def _writeln(self):
        self.file.write("\n")


    def _open_file(self):
        self.file = open(self.filename, "w")
        self._write("%% CPUnetLOGv1\n")

    def write_header(self, header_dict):
        pretty_json = json.dumps(header_dict, sort_keys=True, indent=4)

        self._write( "%% Begin_Header\n" )
        self._write( pretty_json )
        self._writeln()
        self._write( "%% End_Header\n" )
        self._writeln()
        self._write( "%% Begin_Body\n" )

        self.header_written = True


    #def write_line(self, line):
        #self._write( line + "\n" )

    def write_vector(self, out_vector):
        line = ", ".join( map(str, out_vector) ) + "\n"

        self._write( line )


    def close(self):
        if ( self.header_written ):
            self._write( "%% End_Body\n" )

        if ( self.file ):
            self._writeln()
            self.file.close()
Mario Hock's avatar
Mario Hock committed
290
291
292
293
294




class LoggingManager:
295
    def __init__(self, num_cpus, nics, system_info, environment, comment, path, autologging, watch_experiment, killswitch):
Mario Hock's avatar
Mario Hock committed
296
297
298
        self.num_cpus = num_cpus
        self.nics = nics
        self.comment = comment
Mario Hock's avatar
Mario Hock committed
299
        self.auto_comment = None
Mario Hock's avatar
Mario Hock committed
300
        self.path = path
301
302
        self.system_info = system_info
        self.hostname = system_info["hostname"]
303
        self.environment = environment
Mario Hock's avatar
Mario Hock committed
304
        self.watch_experiment = watch_experiment
305
306
        self.killswitch = killswitch
        self.killstate = False
Mario Hock's avatar
Mario Hock committed
307

Mario Hock's avatar
Mario Hock committed
308
        # auto-logging
309
310
        self.INACTIVITY_THRESHOLD       = 10   # seconds
#        self.INACTIVITY_THRESHOLD       = 30   # seconds
311
        self.HISTORY_SIZE               = 5    # samples
Mario Hock's avatar
Mario Hock committed
312
313
314
315
316
317
318
319
        self.auto_logging = autologging
        if ( autologging ):
            self.log_history = HistoryStore(self.HISTORY_SIZE)
            self.logging_active = False
            self.inactivity_count = 0


        # "mkdir" on path, if necessary.
Mario Hock's avatar
Mario Hock committed
320
321
322
        if ( path and not os.path.exists(path) ):
            os.makedirs(path)

Mario Hock's avatar
Mario Hock committed
323
324
325

        ## Logger.
        self.measurement_logger = None
Mario Hock's avatar
Mario Hock committed
326
327
328
        self.measurement_logger_enabled = False


Mario Hock's avatar
Mario Hock committed
329
330
331
332
333
334
335
336
337
338
339
340


    def _start_new_measurement_logger(self, measurement=None):
        assert( not self.measurement_logger )

        # find start time
        if ( measurement ):
            t = measurement.get_begin()
        else:
            t = time.time()

        # Create filename from start time.
Mario Hock's avatar
Mario Hock committed
341
342
343
        date = time.strftime("%Y-%m-%d_%H:%M:%S", time.localtime(t))
        filename_prefix = self.path + "/" + date + "-" + self.hostname
        filename = filename_prefix + ".cnl"
Mario Hock's avatar
Mario Hock committed
344
345
346
347

        # Make sure the filename is unique.
        i = 0
        while ( os.path.exists(filename) ):
Mario Hock's avatar
Mario Hock committed
348
            filename = filename_prefix + "-" + str(i) + ".cnl"
Mario Hock's avatar
Mario Hock committed
349
            i += 1
Mario Hock's avatar
Mario Hock committed
350

351
352
        ## experimental "tcp_probe"
        #tcpprobe_filename = filename[:-4] + ".tcpprobe"
353
354


Mario Hock's avatar
Mario Hock committed
355
        print( "Logging to file: " + filename )
Mario Hock's avatar
Mario Hock committed
356

Mario Hock's avatar
Mario Hock committed
357
358
359
360
361

        # Auto-comment: Store the command line of the observed tool/experiment.
        if ( self.watch_experiment ):
            self.auto_comment = self._find_cmd_line_of(self.watch_experiment)

362
363
364
365
366
367
368
369
        ## Read environment file (if given).
        if ( self.environment ):
            with open(self.environment) as f:
                environment = json.load(f)
        else:
            environment = None


Mario Hock's avatar
Mario Hock committed
370
        # Create Logger.
Mario Hock's avatar
Mario Hock committed
371
        self.measurement_logger = MeasurementLogger(self.num_cpus, self.nics, [date,t],
372
                                                    self.system_info, environment,
Mario Hock's avatar
Mario Hock committed
373
374
                                                    self.auto_comment if self.auto_comment else self.comment,
                                                    filename)
Mario Hock's avatar
Mario Hock committed
375
376


377
378
379
380
381
382
383
        ## experimental "tcp_probe"
        ## test if tcp_probe file is readable
        #PATH_TO_TCP_PROBE = "/proc/net/tcpprobe"
        #self.use_tcpprobe = os.access(PATH_TO_TCP_PROBE, os.R_OK)
        #if ( self.use_tcpprobe ):
            ### start "cat /proc/net/tcpprobe > file" in parallel (and send quit signal, when logging is stopped)
            #self.tcpprobe = subprocess.Popen("cat " + PATH_TO_TCP_PROBE + " > " + tcpprobe_filename, shell=True, preexec_fn=os.setsid)
384
385
386
387




Mario Hock's avatar
Mario Hock committed
388
389
390
    def _stop_measurement_logger(self):
        print( "Logging stopped. File: " + self.measurement_logger.filename )
        self.measurement_logger.close()
Mario Hock's avatar
Mario Hock committed
391

Mario Hock's avatar
Mario Hock committed
392
        self.measurement_logger = None
393
        self.auto_comment = None
Mario Hock's avatar
Mario Hock committed
394

395
396
397
        if(self.killswitch):
            self.killstate = True

398
        ## experimental "tcp_probe"
Mario Hock's avatar
Mario Hock committed
399
        ## kill "cat /proc/net/tcpprobe > file"
400
401
        #if ( self.use_tcpprobe ):
            #os.killpg(self.tcpprobe.pid, signal.SIGTERM)
Mario Hock's avatar
Mario Hock committed
402
403
404
405


    def _is_activity_on_nics(self, measurement):
        for nic in self.nics:
406
407
            try:
                values = measurement.net_io[nic]
Mario Hock's avatar
Mario Hock committed
408

409
410
411
412
                if ( values.ratio["bytes_sent"] > 0 or values.ratio["bytes_recv"] > 0 ):
                    return True
            except KeyError:
                pass
Mario Hock's avatar
Mario Hock committed
413
414
415
416
417
418
419

        return False



    def _log(self, measurement):
        if ( self.measurement_logger ):
Mario Hock's avatar
Mario Hock committed
420
421
            self.measurement_logger.log(measurement)

Mario Hock's avatar
Mario Hock committed
422
423


Mario Hock's avatar
Mario Hock committed
424
425
426
427
428
429
430
431
432
    def _find_cmd_line_of(self, name):
        hits = list()

        for p in psutil.process_iter():
            if ( p.name == name ):
                hits.append( " ".join(p.cmdline) )

        if ( len(hits) > 0 ):
            return "; ".join(hits)
433
            #return hits  ## TODO return a list; maybe introduce field "comments"/"watched_experiments"?
Mario Hock's avatar
Mario Hock committed
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450

        return None


    def _auto_logging_transition_to_active(self):
        self.logging_active = True
        self.inactivity_count = 0

        ## Create a new measurement logger (if enabled).
        if ( self.measurement_logger_enabled ):
            self._start_new_measurement_logger()

        ## Log the new measurement, but also some history.
        for m in self.log_history.flush():
            self._log(m)


Mario Hock's avatar
Mario Hock committed
451
452
453
454
455
456
457

    def _auto_logging_process_in_inactive_state(self, measurement):
        ## Store measurement.
        self.log_history.push(measurement)

        ## If activity detected, start logging.
        if ( self._is_activity_on_nics(measurement) ):
Mario Hock's avatar
Mario Hock committed
458
            self._auto_logging_transition_to_active()
Mario Hock's avatar
Mario Hock committed
459
460
461
462
463
464
465

    def _auto_logging_process_in_active_state(self, measurement):
        ## Log measurement.
        self._log(measurement)

        ## Branch: Inactive sample.
        if ( not self._is_activity_on_nics(measurement) ):
466
            self.inactivity_count += measurement.timespan
Mario Hock's avatar
Mario Hock committed
467
468
469
470
471
472
473
474
475

            ## Inactivity phase too long: Stop logging.
            if ( self.inactivity_count >= self.INACTIVITY_THRESHOLD ):
                if ( self.measurement_logger_enabled ):
                    self._stop_measurement_logger()

                self.logging_active = False

                ## Stop everything!!  (XXX)
Mario Hock's avatar
Mario Hock committed
476
                #return False
Mario Hock's avatar
Mario Hock committed
477
478
479
480
481

        ## Branch: Active sample.
        else:
            self.inactivity_count = 0

Mario Hock's avatar
..    
Mario Hock committed
482
483
        return True

Mario Hock's avatar
Mario Hock committed
484

Mario Hock's avatar
Mario Hock committed
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
    def _auto_logging(self, measurement):
        ## BRANCH: Logging inactive,
        #    wait for activity on observed nics.
        if ( not self.logging_active ):
            self._auto_logging_process_in_inactive_state(measurement)

            return True

        ## BRANCH: Logging active,
        #    log until observed nics get inactive.
        else:
            return self._auto_logging_process_in_active_state(measurement)

        ## Should be never reached.
        assert( False )


    def enable_measurement_logger(self):
        self.measurement_logger_enabled = True

        if ( not self.auto_logging ):
            self._start_new_measurement_logger()



    def log(self, measurement):

        ## BRANCH: no auto-logging, just call _log() directly.
        if ( not self.auto_logging ):
            self._log(measurement)

            return True

        ## BRANCH: Auto-logging
        else:
            return self._auto_logging(measurement)



    def get_logging_state(self):
        if ( not self.measurement_logger_enabled ):
            return "Disabled"

        # BRANCH: no auto-logging
        if ( not self.auto_logging ):
            return "Enabled"

        # BRANCH: auto-logging
        else:
            if ( self.logging_active ):
535
536
537
538
                if ( self.inactivity_count > 2 ):
                    return "(Active)"
                else:
                    return "Active"
Mario Hock's avatar
Mario Hock committed
539
540
541
542
            else:
                return "Standby"


Mario Hock's avatar
Mario Hock committed
543
544
545
    def get_logging_comment(self):
        return self.auto_comment if self.auto_comment else self.comment

546
547
    def get_killstate(self):
        return self.killstate
Mario Hock's avatar
Mario Hock committed
548

Mario Hock's avatar
Mario Hock committed
549

Mario Hock's avatar
Mario Hock committed
550
    def close(self):
Mario Hock's avatar
Mario Hock committed
551
552
        if ( self.measurement_logger ):
            self._stop_measurement_logger()
Mario Hock's avatar
Mario Hock committed
553