jana2/scripts/jana-plot-utilization.py

0001
0002 import re
0003 import svgwrite
0004 from datetime import datetime, timedelta
0005 from collections import defaultdict
0006
0007
0008 def parse_logfile():
0009
0010     # Parse the logs and store intervals
0011     thread_history = defaultdict(list)  # Key: thread_id, Value: list of (start_time, end_time, processor_name, event_nr, result)
0012     barrier_history = [] # [(released_timestamp, finished_timestamp)]
0013
0014     start_times = {}  # Key: (thread_id, processor_name), Value: start_time
0015
0016     # Define a regular expression to parse the log lines
0017     source_start_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executing arrow (\w+)$")
0018     source_finish_noemit_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executed arrow (\w+) with result (\w+)$")
0019     source_finish_emit_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executed arrow (\w+) with result (\w+), emitting event# (\d+)$")
0020     source_finish_pending_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executed arrow (\w+) with result (\w+), holding back barrier event# (\d+)$")
0021     processor_start_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executing arrow (\w+) for event# (\d+)$")
0022     processor_finish_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) Executed arrow (\w+) for event# (\d+)$")
0023     barrier_inflight_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) JEventSourceArrow: Barrier event is in-flight$")
0024     barrier_finished_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) \[debug\] (\d+) JEventSourceArrow: Barrier event finished, returning to normal operation$")
0025
0026     with open("log.txt", "r") as log_file:
0027         for line in log_file:
0028
0029             match = re.match(source_start_pattern, line.strip())
0030             if match:
0031                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name = match.groups()
0032                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0033                 start_times[(thread_id, processor_name)] = millis
0034                 continue
0035
0036             match = re.match(source_finish_noemit_pattern, line.strip())
0037             if match:
0038                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result = match.groups()
0039                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0040                 start_time = start_times.pop((thread_id, processor_name), None)
0041                 if start_time:
0042                     thread_history[thread_id].append((start_time, millis, processor_name, None, result))
0043                 continue
0044
0045             match = re.match(source_finish_emit_pattern, line.strip())
0046             if match:
0047                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result, event_nr = match.groups()
0048                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0049                 start_time = start_times.pop((thread_id, processor_name), None)
0050                 if start_time:
0051                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0052                 continue
0053
0054             match = re.match(source_finish_pending_pattern, line.strip())
0055             if match:
0056                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result, event_nr = match.groups()
0057                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0058                 start_time = start_times.pop((thread_id, processor_name), None)
0059                 if start_time:
0060                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0061                 continue
0062
0063             match = re.match(processor_start_pattern, line.strip())
0064             if match:
0065                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, event_nr = match.groups()
0066                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0067                 start_times[(thread_id, processor_name)] = millis
0068                 continue
0069
0070             match = re.match(processor_finish_pattern, line.strip())
0071             if match:
0072                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, event_nr = match.groups()
0073                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0074                 start_time = start_times.pop((thread_id, processor_name), None)
0075                 if start_time:
0076                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0077                 continue
0078
0079             match = re.match(barrier_inflight_pattern, line.strip())
0080             if match:
0081                 hours_str, mins_str, secs_str, millis_str, thread_id = match.groups()
0082                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0083                 start_times[()] = millis
0084                 continue
0085
0086             match = re.match(barrier_finished_pattern, line.strip())
0087             if match:
0088                 hours_str, mins_str, secs_str, millis_str, thread_id = match.groups()
0089                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0090                 start_time = start_times.pop((), None)
0091                 if start_time:
0092                     barrier_history.append((start_time, millis))
0093                 continue
0094
0095     return (thread_history, barrier_history)
0096
0097
0098
0099 def create_svg(all_thread_history, barrier_history):
0100     # Assign colors to processors
0101     processor_colors = {}
0102     color_palette = ['#004E64', '#00A5CF', '#9FFFCB', '#25A18E', '#7AE582', '#FF69B4']
0103     color_index = 0
0104
0105     # Figure out drawing coordinate system
0106     overall_start_time = min(start for history in all_thread_history.values() for (start,_,_,_,_) in history)
0107     overall_end_time = max(end for history in all_thread_history.values() for (_,end,_,_,_) in history)
0108     thread_count = len(all_thread_history)
0109     width=1000
0110     x_scale = width/(overall_end_time-overall_start_time)
0111     thread_height=40
0112     thread_y_padding=20
0113     height=thread_count * thread_height + (thread_count+1) * thread_y_padding
0114
0115
0116     # Create the SVG drawing
0117     dwg = svgwrite.Drawing("timeline.svg", profile='tiny', size=(width, height))
0118     #dwg.add(dwg.rect(insert=(0,0),size=(width,height),stroke="red",fill="white"))
0119
0120     # Draw a rectangle for each processor run on each thread's timeline
0121     y_position = thread_y_padding
0122
0123     for barrier_start,barrier_end in barrier_history:
0124         rect_start = (barrier_start-overall_start_time)*x_scale
0125         if (barrier_end == barrier_start):
0126             rect_width=1
0127         else:
0128             rect_width = (barrier_end-barrier_start)*x_scale
0129
0130         rect = dwg.rect(insert=(rect_start, 0),
0131                             size=(rect_width, height),
0132                             fill="red",
0133                             stroke="none",
0134                             stroke_width=1)
0135         dwg.add(rect)
0136
0137     for thread_id, intervals in all_thread_history.items():
0138         dwg.add(dwg.rect(insert=(0,y_position),size=(1000,thread_height),stroke="lightgray",fill="lightgray"))
0139         for start_time, end_time, processor_name, event_nr, result in intervals:
0140             # Calculate the position and width of the rectangle
0141             # Assign a unique color to each processor name
0142             if processor_name not in processor_colors:
0143                 processor_colors[processor_name] = color_palette[color_index % len(color_palette)]
0144                 color_index += 1
0145
0146             # Draw the rectangle
0147             rect_start = (start_time-overall_start_time)*x_scale
0148             if (end_time == start_time):
0149                 rect_width=1
0150             else:
0151                 rect_width = (end_time-start_time)*x_scale
0152
0153             rect_stroke_color = "black"
0154             if (result == "ComeBackLater" and event_nr is None):
0155                 rect_stroke_color = "gray"
0156
0157
0158             rect = dwg.rect(insert=(rect_start, y_position),
0159                              size=(rect_width, thread_height),
0160                              fill=processor_colors[processor_name],
0161                              stroke=rect_stroke_color,
0162                              stroke_width=1)
0163             mouseover = "Arrow: " + processor_name + "\nEvent nr: " + str(event_nr) + "\nResult: " + result + "\nTime: "+ str(end_time-start_time) + "ms"
0164             rect.add(svgwrite.base.Title(mouseover))
0165             dwg.add(rect)
0166             if (event_nr is not None):
0167                 text = dwg.text(str(event_nr), insert=(rect_start+1, y_position+thread_height-1), fill="white", font_size=8)
0168                 dwg.add(text)
0169
0170         # Move the y position for the next thread
0171         y_position += (thread_y_padding + thread_height)
0172
0173
0174     # Save the SVG file
0175     dwg.save()
0176
0177
0178
0179 if __name__ == "__main__":
0180     thread_history,barrier_history = parse_logfile()
0181     #thread_history = {
0182     #    1103:[(0,1,"a"), (2,5,"b"), (6,8,"a")],
0183     #    219:[(0,3,"b"), (3,6,"c"), (9,10,"d")],
0184     #    3:[(2,7,"a")]
0185     #}
0186     create_svg(thread_history, barrier_history)
0187
0188