logging.py 15 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

Michael König's avatar
Michael König committed
21
from cpunetlog.history_store import HistoryStore
Mario Hock's avatar
Mario Hock committed
22 23


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
Mario Hock's avatar
Mario Hock committed
49
        self.class_names = ("Time", "CPU", "NIC")
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 71 72
        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


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

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


81

82 83
    def _init_class_definitions(self, num_cpus, nics):
        class_defs = dict()
84 85 86

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

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

        # set up "Time" class
        time = LoggingClass( name        = "Time",
101 102 103 104
                            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
105

106
        return class_defs
Mario Hock's avatar
Mario Hock committed
107 108


109
    ## TODO Move this outside the class?
110
    def _create_json_header(self, class_names, class_defs, type, begin, system_info, environment, comment):
111 112
        top_level = dict()
        general = dict()
Mario Hock's avatar
Mario Hock committed
113 114 115
        class_definitions = dict()

        ## General
116 117 118
        general["Classes"] = class_names
        general["Type"] = type
        general["Comment"] = comment
Mario Hock's avatar
Mario Hock committed
119
        general["Date"] = begin
120
        general["SystemInfo"] = system_info
121
        general["Environment"] = environment
122 123 124
        #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
125 126

        ## Class definitions
127
        for c in class_defs:
Mario Hock's avatar
Mario Hock committed
128
            class_definitions[c.name] = c.values
129
        top_level["ClassDefinitions"] = class_definitions
Mario Hock's avatar
Mario Hock committed
130

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

133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155
        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

156 157


Mario Hock's avatar
Mario Hock committed
158 159 160

    ## Logging functions ##

Mario Hock's avatar
Mario Hock committed
161 162
    def _log_time(self, measurement, out_vector):
        out_vector.extend( [measurement.r1.timestamp, measurement.r2.timestamp, measurement.timespan] )
163 164


Mario Hock's avatar
Mario Hock committed
165
    def _log_cpus(self, measurement, out_vector):
166
        for cpu in measurement.cpu_times_percent:
167
            cpu_util = 100-cpu.idle
Mario Hock's avatar
log irq  
Mario Hock committed
168
            other = 100 - sum( (cpu.user, cpu.system, cpu.irq, cpu.softirq, cpu.idle) )
169

Mario Hock's avatar
log irq  
Mario Hock committed
170
            out_vector.extend( [cpu_util, cpu.idle, cpu.user, cpu.system, cpu.irq, cpu.softirq, other] )
171 172


Mario Hock's avatar
Mario Hock committed
173
    def _log_nics(self, measurement, out_vector):
174
        for nic in self.nics:
175 176
            try:
                values = measurement.net_io[nic]
177

178 179 180 181 182
                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) )
183 184 185


    def log(self, measurement):
Mario Hock's avatar
Mario Hock committed
186
        out_vector = list()
187 188

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

Mario Hock's avatar
Mario Hock committed
192
        self.writer.write_vector( out_vector )
193 194


Mario Hock's avatar
Mario Hock committed
195 196 197

    ## Close ##

198
    def close(self):
Mario Hock's avatar
Mario Hock committed
199 200 201 202 203 204
        self.writer.close()




class CNLFileWriter:
Mario Hock's avatar
Mario Hock committed
205 206 207 208 209 210 211 212 213 214 215
    """
    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
216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 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

    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
266 267 268 269 270




class LoggingManager:
271
    def __init__(self, num_cpus, nics, system_info, environment, comment, path, autologging, watch_experiment):
Mario Hock's avatar
Mario Hock committed
272 273 274
        self.num_cpus = num_cpus
        self.nics = nics
        self.comment = comment
Mario Hock's avatar
Mario Hock committed
275
        self.auto_comment = None
Mario Hock's avatar
Mario Hock committed
276
        self.path = path
277 278
        self.system_info = system_info
        self.hostname = system_info["hostname"]
279
        self.environment = environment
Mario Hock's avatar
Mario Hock committed
280
        self.watch_experiment = watch_experiment
Mario Hock's avatar
Mario Hock committed
281

Mario Hock's avatar
Mario Hock committed
282
        # auto-logging
283 284
        self.INACTIVITY_THRESHOLD       = 30   # seconds
        self.HISTORY_SIZE               = 5    # samples
Mario Hock's avatar
Mario Hock committed
285 286 287 288 289 290 291 292
        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
293 294 295
        if ( path and not os.path.exists(path) ):
            os.makedirs(path)

Mario Hock's avatar
Mario Hock committed
296 297 298

        ## Logger.
        self.measurement_logger = None
Mario Hock's avatar
Mario Hock committed
299 300 301
        self.measurement_logger_enabled = False


Mario Hock's avatar
Mario Hock committed
302 303 304 305 306 307 308 309 310 311 312 313


    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
314 315 316
        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
317 318 319 320

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

324 325
        ## experimental "tcp_probe"
        #tcpprobe_filename = filename[:-4] + ".tcpprobe"
326 327


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

Mario Hock's avatar
Mario Hock committed
330 331 332 333 334

        # 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)

335 336 337 338 339 340 341 342
        ## 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
343
        # Create Logger.
Mario Hock's avatar
Mario Hock committed
344
        self.measurement_logger = MeasurementLogger(self.num_cpus, self.nics, [date,t],
345
                                                    self.system_info, environment,
Mario Hock's avatar
Mario Hock committed
346 347
                                                    self.auto_comment if self.auto_comment else self.comment,
                                                    filename)
Mario Hock's avatar
Mario Hock committed
348 349


350 351 352 353 354 355 356
        ## 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)
357 358 359 360




Mario Hock's avatar
Mario Hock committed
361 362 363
    def _stop_measurement_logger(self):
        print( "Logging stopped. File: " + self.measurement_logger.filename )
        self.measurement_logger.close()
Mario Hock's avatar
Mario Hock committed
364

Mario Hock's avatar
Mario Hock committed
365
        self.measurement_logger = None
366
        self.auto_comment = None
Mario Hock's avatar
Mario Hock committed
367

368
        ## experimental "tcp_probe"
Mario Hock's avatar
Mario Hock committed
369
        ## kill "cat /proc/net/tcpprobe > file"
370 371
        #if ( self.use_tcpprobe ):
            #os.killpg(self.tcpprobe.pid, signal.SIGTERM)
Mario Hock's avatar
Mario Hock committed
372 373 374 375


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

379 380 381 382
                if ( values.ratio["bytes_sent"] > 0 or values.ratio["bytes_recv"] > 0 ):
                    return True
            except KeyError:
                pass
Mario Hock's avatar
Mario Hock committed
383 384 385 386 387 388 389

        return False



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

Mario Hock's avatar
Mario Hock committed
392 393


Mario Hock's avatar
Mario Hock committed
394 395 396 397 398 399 400 401 402
    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)
403
            #return hits  ## TODO return a list; maybe introduce field "comments"/"watched_experiments"?
Mario Hock's avatar
Mario Hock committed
404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420

        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
421 422 423 424 425 426 427

    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
428
            self._auto_logging_transition_to_active()
Mario Hock's avatar
Mario Hock committed
429 430 431 432 433 434 435

    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) ):
436
            self.inactivity_count += measurement.timespan
Mario Hock's avatar
Mario Hock committed
437 438 439 440 441 442 443 444 445

            ## 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
446
                #return False
Mario Hock's avatar
Mario Hock committed
447 448 449 450 451

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

Mario Hock's avatar
..  
Mario Hock committed
452 453
        return True

Mario Hock's avatar
Mario Hock committed
454

Mario Hock's avatar
Mario Hock committed
455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504
    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 ):
505 506 507 508
                if ( self.inactivity_count > 2 ):
                    return "(Active)"
                else:
                    return "Active"
Mario Hock's avatar
Mario Hock committed
509 510 511 512
            else:
                return "Standby"


Mario Hock's avatar
Mario Hock committed
513 514 515 516
    def get_logging_comment(self):
        return self.auto_comment if self.auto_comment else self.comment


Mario Hock's avatar
Mario Hock committed
517

Mario Hock's avatar
Mario Hock committed
518
    def close(self):
Mario Hock's avatar
Mario Hock committed
519 520
        if ( self.measurement_logger ):
            self._stop_measurement_logger()
Mario Hock's avatar
Mario Hock committed
521