1#!/usr/bin/env python 2 3import sys 4import os 5import re 6 7TRACE_SUBSYS_NNET = 0x9000 8TRACE_SUBSYS_NET = 0x6000 9TRACE_SUBSYS_LLNET = 0x6000 10valid_cores = ["3 ", "2 "] 11core_map = {2: "DRV", 3:"APP"} 12 13# Following constans are used for profiling modified stack 14event_map = { 15 0x0001 : "Start", 16 0x0002 : "Stop", 17 0x0003 : "Driver saw pkg (RX)", 18 0x0004 : "Ethersrv saw pkg", 19 0x0005 : "Ethersrv checked frag", 20 0x0006 : "Ethersrv app filtered", 21 0x0007 : "Ethersrv app c2u started", 22 0x0008 : "Ethersrv copied pkg", 23 0x000D : "Ethersrv spp produce done", 24 0x0009 : "Ethersrv app notify", 25 0x000A : "LWIP handle_incoming_", 26 0x000B : "LWIP call rec_handler", 27 0x000C : "APP received", 28 29 0x0020 : "APP sent", 30 0x0021 : "LWIP idc_send_packet", 31 0x0029 : "LWIP before mfence", 32 0x002A : "LWIP after mfence", 33 0x002B : "LWIP payload flushed", 34 0x002C : "LWIP bufferdesc fetched", 35 0x0022 : "LWIP spp produced", 36 0x0023 : "LWIP update spp index", 37 0x002D : "LWIP pending TX work", 38 0x0024 : "LWIP notify driver", 39 0x0025 : "Ethersrv notify recieved", 40 0x002E : "Ethersrv send_pkt_on_w..", 41 0x0026 : "Ethersrv send_sng_pkt..", 42 0x0027 : "Driver add pkg (TX)", 43 0x0028 : "Driver saw pkg done (TX)" 44 } 45 46 47event_map1 = { 480X0001: "NET_START", 490X0002: "NET_STOP", 500X0003: "New_packet_came", 510X0004: "pkt_processed", 520X0005: "pkt_uploaded", 530X0006: "pkt_entered_app", 540X0007: "pkt_processed_app", 550X0008: "reply_prepared_app", 560X0009: "reply_queued_app", 570X000A: "reply_sent_app", 580X000B: "reply_into_NIC", 590X000C: "reply_sent_by_NIC", 600x000D: "app_done_with_pbuf", 610x000E: "app_recved_TX_done", 620x0010: "interrupt_came", 630x0011: "ARP_packet_incoming", 640x0012: "physical_interrupt_came", 650x0013: "TX_Done_by_NIC", 660x0014: "register_pbuf_in_NIC", 670x0015: "filters_executed_1", 680x0016: "filters_executed_2", 690x0017: "packet_copied", 700x0018: "filter_frag", 710x0019: "packet_copy_started", 720x001A: "packet_copied_src_read", 730x001B: "packet_copied_dst_read", 740x001C: "packet_copy_copied", 75 76 77} 78 79kmap = { 0xcccc: 'Context switch', 80 0xed00: 'Sched make runnable', 81 0xed01: 'Sched remove', 82 0xed02: 'Sched yield', 83 0xed02: 'Sched schedule', 84 0xed04: 'Sched current', 85 } 86 87tmap = { 0x0400: 'Sem wait enter', 88 0x0401: 'Sem wait leave', 89 0x0402: 'Sem try wait', 90 0x0403: 'Sem post', 91 } 92 93netmap = { 0x0001: 'Start', 94 0x0002: 'Stop', 95 96 0x0003: 'Driver saw pkg (RX)', 97 0x0004: 'Ethersrv saw pkg', 98 0x0005: 'Ethersrv checked frag', 99 0x0006: 'Ethersrv app filtered', 100 0x0007: 'Ethersrv app c2u started', 101 0x0008: 'Ethersrv copied pkg', 102 0x0009: 'Ethersrv app notify', 103 0x000A: 'LWIP handle_incoming_', 104 0x000B: 'LWIP call rec_handler', 105 0x000C: 'APP recieved', 106 0x000D: 'Ethersrv spp produce done', 107 108 0x0020: 'APP sent', 109 0x0021: 'LWIP idc_send_packet', 110 0x0029: 'LWIP before mfence', 111 0x002A: 'LWIP after mfence', 112 0x002B: 'LWIP payload flushed', 113 0x002C: 'LWIP bufferdesc fetched', 114 0x0022: 'LWIP spp produced', 115 0x0023: 'LWIP update spp index', 116 0x002D: 'LWIP pending TX work', 117 0x0024: 'LWIP notify driver', 118 0x0025: 'Ethersrv notify recieved', 119 0x002E: 'Ethersrv send_pkt_on_w..', 120 0x0026: 'Ethersrv send_sng_pkt..', 121 0x0027: 'Driver add pkg (TX)', 122 0x0028: 'Driver saw pkg done (TX)', 123 124 0x0030: 'tcp_write done', 125 0x0031: 'tcp_output done', 126 0x0032: 'tcp_recved done', 127 0x0033: 'tx pbuf freed', 128 0x0034: 'tx pbuf memp start', 129 0x0035: 'tx pbuf memp done', 130 } 131 132 133 134llmap = { 0x0001: 'LLNET_START', 135 0x0002: 'LLNET_STOP', 136 0x0003: 'LLNET_IRQ', 137 138 0x0010: 'LLNET_DRVIRQ', 139 0x0011: 'LLNET_DRVRX', 140 0x0012: 'LLNET_DRVTXADD', 141 0x0013: 'LLNET_DRVTXDONE', 142 143 0x0020: 'LLNET_LWIPPBA1', 144 0x0021: 'LLNET_LWIPPBA2', 145 0x0022: 'LLNET_LWIPPBF1', 146 0x0023: 'LLNET_LWIPPBF2', 147 0x0024: 'LLNET_LWIPRX', 148 0x0025: 'LLNET_LWIPTX', 149 150 0x0030: 'LLNET_APPRX', 151 0x0031: 'LLNET_APPTX', 152 } 153 154 155def default_info(ev): 156 return ("%-15x" % ev['INFO']) 157 158def kern_info(ev): 159 if ev['EVENT'] == 0xcccc: 160 return DCB[ev['CID']][ev['INFO']] 161 return default_info(ev) 162 163ssmap = { 0xffff: ('KERN', kmap, kern_info), 164 0xeeee: ('THREAD', tmap, default_info), 165 0x9000: ('NET', netmap, default_info), 166 0xd000: ('LLNET', llmap, default_info), 167 0xea00: ('UMP TX', {}, default_info), 168 0xeb00: ('UMP RX', {}, default_info), 169 } 170 171 172NIC_IN_EVENTS = { 1730x0012: "physical interrupt came", 1740x0010: "interrupt came", 1750X0003: "New packet came", 1760X0004: "pkt processed", 1770X0005: "pkt uploaded" 178} 179 180APP_IN_EVENTS = { 1810X0006: "pkt entered app", 1820X0007: "pkt processed app" 183} 184 185APP_OUT_EVENTS = { 1860X0008: "reply prepared app", 1870X0009: "reply queued app", 1880X000A: "reply sent app" 189} 190 191NIC_OUT_EVENTS = { 1920X000B: "reply into NIC", 1930X000C: "reply sent by NIC" 194} 195 196machine_speeds = { 197 'nos6' : 2799.877, 198 'sbrinz1' : 2511.0, 199 'ziger1' : 2400.367, 200 'gottardo' : 1866.0, 201 } 202#packet_boundries = [0X0012] 203#LOGICAL_ORDER = [0x012, 0x0010, 0x0003, 0x0004, 0x0005, 0x0006, 0x0007, 204# 0x0008, 0x0009, 0x000A, 0x000b, 0x000c] 205 206packet_boundries = [0x0031] 207LOGICAL_ORDER = [0x0010, 0x0003, 0x0015, 0x0016, # 0x0019, 0x001a, 0x001b, 0x001c, 208 0x0017, 0x0004, 0x0005, 0x0006, 0x0007, 0x0008, 0x0009, 0x000A, 209 0x000b, 0x000c] 210 211#LOGICAL_ORDER = [0x0010, 0x0003, 0x0015, 0x0016, 0x0019, 0x001a, 0x001b, 0x001c, 212# 0x0017, 0x0004, 0x0005, 0x0006, 0x0007, 0x0008, 0x0009, 0x000A, 213# 0x000b, 0x000c] 214 215 216 217# Maps core to (map of context id -> name) 218DCB = {} 219 220 221MAX_EVENT_NOREPLY = 9 222MAX_EVENTS = 0x00FF 223 224DEBUG = False 225DEBUG = True 226 227MACHINE = 'sbrinz1' 228 229def dprint (args): 230 if DEBUG: 231 print args 232 233def c2t (cycles): 234# return (cycles) # cycles 235 return ( cycles / (machine_speeds[MACHINE])) # micro seconds 236 237def print_event(event): 238 ss = ssmap[event['SYS']] 239 ev = event['EVENT'] 240 info = ss[2](event) 241 if not ev in ss[1]: 242 print "%-15f %-12f %-10s %-45s %-4s %s" % (c2t(event['TS']), 243 c2t(event['DIFF']), ss[0], ev, core_map[event['CID']], info) 244 else: 245 print "%-15f %-12f %-10s %-45s %-4s %s" % (c2t(event['TS']), 246 c2t(event['DIFF']), ss[0], ss[1][ev], 247 core_map[event['CID']], info) 248 #print event['DIFF_S'], event_map[event['EVENT']],\ 249 #core_map[event['CID']], event['INFO'] 250 251def show_event_list(event_list): 252 for e in event_list: 253 print_event(e) 254 255def extract_events(in_f): 256 splitter = re.compile(r'[\ ]') 257 event_list = [] 258 line_count = 0 259 for line in in_f: 260 if line[0] == '#' : 261 if line[1:6] == ' DCB ': 262 c = int(line[6:8]) 263 i = int(line[8:24], 16) & 0xffffffff 264 name = line[25:-1] 265 if not c in DCB: 266 DCB[c] = {} 267 DCB[c][i] = name 268 continue 269 270 if line[0:2] not in valid_cores : 271 continue 272 273 tokens = splitter.split(line.strip()) 274 if len(tokens) != 3 : 275 print "Error: Cant process line " + line 276 continue 277 c_event = {} 278# print "Processing line " + str(tokens) 279 try: 280 c_event['CID'] = int(tokens[0]) 281 c_event['TS'] = int(tokens[1]) 282 c_event['SYS'] = int(tokens[2][0:4],16) 283 c_event['EVENT'] = int(tokens[2][4:8],16) 284 c_event['INFO'] = int(tokens[2][8:],16) 285 except Exception as inst: 286 print type(inst) # the exception instance 287 print inst.args # arguments stored in args 288 print "exception for line " + line 289 continue 290# raise 291 292 293 # Lets ignore non-networking events 294# if c_event['SYS'] != TRACE_SUBSYS_NNET : 295# print "Non network event, ignoring " + \ 296# str(c_event['SYS']) + " " + line 297# continue 298 299 # Lets ignore start and stop events 300 if c_event['EVENT'] in [0x1, 0x2]: 301 continue 302 303 if(len(event_list) == 0): 304 c_event['DIFF_S'] = 0 305 else: 306 prev_c_event = event_list[-1] 307 c_event['DIFF_S'] = c_event['TS'] - prev_c_event['TS'] 308 # For time being making DIFF = DIFF_S to show interesting prints 309 c_event['DIFF'] = c_event['DIFF_S'] 310 c_event['DIFF'] = 0 311 event_list.append(c_event) 312 return event_list 313 314 315def diff_events(event_list): 316 # now sort the event list based on timestamp 317 sorted_events = sorted(event_list, key=lambda dd: dd['TS']) 318 319 packet_list = [] 320 i = 0 321 for e in sorted_events: 322 if i == 0: 323 e['DIFF'] = 0 324 else: 325 e['DIFF'] = e['TS'] - sorted_events[i-1]['TS'] 326 i = i + 1 327 return sorted_events 328 329def print_packet(pkt): 330 print "" 331 print "######################" 332 print "Time after last packet %f" % ( 333 c2t(pkt['PDIFF'])) 334 start = pkt['EL'][0]['TS'] 335 for e in pkt['EL']: 336 a = e['TS'] 337 e['TS'] = a - start 338 print_event(e) 339 e['TS'] = a 340 print "Packet Lifetime = %f, no. of events = %d" % ( 341 c2t(pkt['STOP'] - pkt['START']), len(pkt['EL'])) 342 343 344def show_packet_list(plist, only_answered=False): 345 for pkt in plist: 346 if (only_answered): 347 if(len(pkt['EL'])<= MAX_EVENT_NOREPLY): 348 continue 349 print_packet(pkt) 350 351def find_event_in_pkt(event_id, pkt): 352 for e in pkt['EL']: 353 if event_id == e['EVENT']: 354 return e 355 return None 356 357def add_packet_stat(pkt, stat): 358 stat['PKTS'] = stat['PKTS'] + 1 359 360 # calculate packet lifetime 361 lifetime = pkt['EL'][-1]['TS'] - pkt['EL'][0]['TS'] 362 if stat['PKTS'] == 1 : 363 stat['PLIFE_SUM'] = lifetime 364 stat['PLIFE_MAX'] = lifetime 365 stat['PLIFE_MIN'] = lifetime 366 else: 367 stat['PLIFE_SUM'] = stat['PLIFE_SUM'] + lifetime 368 if lifetime < stat['PLIFE_MIN']: 369 stat['PLIFE_MIN'] = lifetime 370 if lifetime > stat['PLIFE_MAX']: 371 stat['PLIFE_MAX'] = lifetime 372 373# stat['PLIFE'] = stat['PLIFE'] + ( pkt['EL'][-1]['TS'] - pkt['EL'][0]['TS']) 374 375 prev = None 376 for i in LOGICAL_ORDER: 377 e = find_event_in_pkt(i, pkt) 378 if e == None: 379 print "event does not exist in packet!!!!" 380 print "event it %d " % (i) 381 print "pkt event list is " + str(pkt['EL']) 382 sys.exit(1) #continue 383 stat['COUNT'][i] = stat['COUNT'][i] + 1 384 if prev == None: 385 # This is the first event in the packet 386 diff = 0 387 else: 388 diff = e['TS'] - prev['TS'] 389 390 391 if stat['PKTS'] == 1 : 392 # This is the first packet 393 stat['MAX'][i] = diff 394 stat['MIN'][i] = diff 395 stat['SUM'][i] = diff 396 else: 397 stat['SUM'][i] = stat['SUM'][i] + diff 398 if (diff < stat['MIN'][i]): 399 stat['MIN'][i] = diff 400 if (diff > stat['MAX'][i]): 401 stat['MAX'][i] = diff 402 prev = e 403 404 405# for e in pkt['EL']: 406# print "event is %d " %(e['EVENT']) 407# stat['COUNT'][e['EVENT']] = stat['COUNT'][e['EVENT']] + 1 408# stat['SUM'][e['EVENT']] = stat['SUM'][e['EVENT']] + e['DIFF'] 409 410def print_stats(stat): 411 print "#################################" 412 print "######## AVERAGE of pkts %d #####" % (stat['PKTS']) 413 print "#################################" 414 if stat['PKTS'] == 0 : 415 print "No answered packets!!" 416 return 417 418 for i in LOGICAL_ORDER: 419 if stat['COUNT'][i] == 0 : 420 continue 421 avg = stat['SUM'][i] / stat['COUNT'][i] 422 423 print "e %-25s %5d %10f %10f %10f" % (event_map[i], stat['COUNT'][i], 424 c2t(stat['MIN'][i]), c2t(avg), c2t(stat['MAX'][i])) 425 426# print "e %s %d %f %f %f" % (event_map[i], stat['COUNT'][i], 427# c2t(stat['MIN'][i]), c2t(avg), c2t(stat['MAX'][i])) 428 429 print "Packet lifespan %f/%f/%f" % (c2t(stat['PLIFE_MIN']), 430 c2t(stat['PLIFE_SUM']/stat['PKTS']), c2t(stat['PLIFE_MAX'])) 431 432 print "######################" 433 print "######################" 434 435def create_packet_list_stat(): 436 plist_stat = {} 437 plist_stat['PKTS'] = 0 438 plist_stat['PDIFF'] = 0 439 plist_stat['PLIFE'] = 0 440 plist_stat['COUNT'] = [] 441 plist_stat['SUM'] = [] 442 plist_stat['MAX'] = [] 443 plist_stat['MIN'] = [] 444 445 446 for i in range(0x0001,MAX_EVENTS+1): 447 plist_stat['SUM'].append(0) #[i] = 0 448 plist_stat['COUNT'].append(0) #[i] = 0 449 plist_stat['MAX'].append(0) #[i] = 0 450 plist_stat['MIN'].append(0) #[i] = 0 451 return plist_stat 452 453def is_answered_packet(pkt): 454 if len(pkt['EL']) < len(LOGICAL_ORDER): 455 dprint("not answered pkt as len %d is smaller than %d" % ( 456 len(pkt['EL']), len(LOGICAL_ORDER)) ) 457 return False 458 counter = 0 459 for e in pkt['EL']: 460 if e['EVENT'] in LOGICAL_ORDER : 461 counter = counter + 1 462 if counter == len(LOGICAL_ORDER): 463 dprint("Answered..!!!!") 464 return True 465 466 dprint("Not answered as common events are %d instead of %d"%(counter, 467 len(LOGICAL_ORDER))) 468 return False 469 470def show_answered_packets_list(plist): 471 if plist == None: 472 print "No packets.." 473 return 474 if len(plist) == 0: 475 print "No packets..." 476 return 477 stat = create_packet_list_stat() 478 for pkt in plist: 479 if is_answered_packet(pkt): 480 dprint("there are answered packets!!!") 481 add_packet_stat(pkt, stat) 482 print_stats(stat) 483 484 485def create_empty_packet(starting_event, last_stop): 486 starting_event['DIFF'] = 0 487 pkt = {'EL': [starting_event], 488 'START': starting_event['TS'], 489 } 490 if last_stop == 0: 491 pkt['PDIFF'] = 0 492 else: 493 pkt['PDIFF'] = pkt['START'] - last_stop 494 495 return pkt 496 497def group_events(event_list): 498 packet_list = [] 499 i = 0 500 for e in event_list: 501 is_appended = False 502 if i == 0: 503 packet_list.append(create_empty_packet(e, 0)) 504 is_appended = True 505 else: 506 if e['EVENT'] in packet_boundries : 507 packet_list.append(create_empty_packet(e, 508 packet_list[-1]['STOP'])) 509 is_appended = True 510 511 packet_list[-1]['STOP'] = e['TS'] 512 e['PDIFF'] = e['TS'] - packet_list[-1]['EL'][-1]['TS'] 513 if not is_appended : 514 packet_list[-1]['EL'].append(e) 515 i = i + 1 516 517 return packet_list 518 519def process_trace(in_f): 520 elist = diff_events(extract_events(in_f)) 521 dprint("no. of events detected is " + str(len(elist))) 522# show_event_list(elist) 523 524 plist = group_events(elist) 525# dprint("no. of packets detected is " + str(len(plist))) 526 527 show_packet_list(plist) 528# show_packet_list(plist, True) 529# show_answered_packets_list(plist) 530 531def show_usage(): 532 print "Usage: " + sys.argv[0] + " <traceFile>" 533 534 535def main(): 536 if len(sys.argv) != 2: 537 show_usage() 538 sys.exit(1) 539 inputFile = open(sys.argv[1], 'r') 540 #outputFile = open(sys.argv[2], 'w') 541 process_trace(inputFile) 542 543if __name__ == '__main__' : 544 main() 545