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