jana2/scripts/jana-plot-utilization.py

0001 #!/usr/bin/env python3
0002
0003 import sys
0004 import re
0005 from datetime import datetime, timedelta
0006 from collections import defaultdict
0007
0008
0009 class Drawing:
0010     def __init__(self, width, height, profile="tiny"):
0011         self.lines = [
0012             f"""<?xml version="1.0" encoding="utf-8" ?>\n""",
0013             f"""<svg baseProfile="{profile}" width="{width}" height="{height}" version="1.2" xmlns="http://www.w3.org/2000/svg" xmlns:ev="http://www.w3.org/2001/xml-events" xmlns:xlink="http://www.w3.org/1999/xlink"><defs />"""
0014         ]
0015
0016     def write(self, output_filename="timeline.svg"):
0017         self.lines.append("</svg>")
0018         output_file = open(output_filename, 'w')
0019         output_file.writelines(self.lines)
0020         output_file.close()
0021
0022     def add_rect(self, x, y, width, height, fill="lightgray", stroke="darkgray", stroke_width=1, mouseover_text=""):
0023         if not mouseover_text:
0024             self.lines.append(f"""<rect fill="{fill}" height="{height}" stroke="{stroke}" stroke-width="{stroke_width}" width="{width}" x="{x}" y="{y}" />\n""")
0025         else:
0026             self.lines.append(f"""<rect fill="{fill}" height="{height}" stroke="{stroke}" stroke-width="{stroke_width}" width="{width}" x="{x}" y="{y}">\n""")
0027             self.lines.append(f"""    <title>{mouseover_text}</title>\n""")
0028             self.lines.append(f"""</rect>\n\n""")
0029
0030     def add_text(self, text, x, y, fill="black", font_size=8):
0031         self.lines.append(f"""<text fill="{fill}" font-size="{font_size}" x="{x}" y="{y}">{text}</text>\n\n""")
0032
0033
0034 def parse_logfile(input_filename="log.txt"):
0035
0036     # Parse the logs and store intervals
0037     thread_history = defaultdict(list)  # Key: thread_id, Value: list of (start_time, end_time, processor_name, event_nr, result)
0038     region_history = defaultdict(list)  # Key: thread_id, Value: list of (start_time, end_time, region_name, event_nr)
0039     barrier_history = [] # [(released_timestamp, finished_timestamp)]
0040
0041     start_times = {}  # Key: (thread_id, processor_name), Value: start_time
0042
0043     # Define a regular expression to parse the log lines
0044     source_start_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executing arrow (\w+)$")
0045     source_finish_noemit_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executed arrow (\w+) with result (\w+)$")
0046     source_finish_emit_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executed arrow (\w+) with result (\w+), emitting event# (\d+)$")
0047     source_finish_pending_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executed arrow (\w+) with result (\w+), holding back barrier event# (\d+)$")
0048     processor_start_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executing arrow (\w+) for event# (\d+)$")
0049     processor_finish_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] Executed arrow (\w+) for event# (\d+)$")
0050     barrier_inflight_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] JEventSourceArrow: Barrier event is in-flight$")
0051     barrier_finished_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+) \[debug\] JEventSourceArrow: Barrier event finished, returning to normal operation$")
0052     region_start_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+)  \[info\] Entering region ([\w:]+) for event# (\d+)$")
0053     region_finish_pattern = re.compile(r"^(\d{2}):(\d{2}):(\d{2})\.(\d{3}) #(\d+)  \[info\] Exited region ([\w:]+) for event# (\d+)$")
0054
0055     with open(input_filename, "r") as log_file:
0056         for line in log_file:
0057
0058             match = re.match(source_start_pattern, line.strip())
0059             if match:
0060                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name = match.groups()
0061                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0062                 start_times[(thread_id, processor_name)] = millis
0063                 continue
0064
0065             match = re.match(source_finish_noemit_pattern, line.strip())
0066             if match:
0067                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result = match.groups()
0068                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0069                 start_time = start_times.pop((thread_id, processor_name), None)
0070                 if start_time:
0071                     thread_history[thread_id].append((start_time, millis, processor_name, None, result))
0072                 continue
0073
0074             match = re.match(source_finish_emit_pattern, line.strip())
0075             if match:
0076                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result, event_nr = match.groups()
0077                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0078                 start_time = start_times.pop((thread_id, processor_name), None)
0079                 if start_time:
0080                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0081                 continue
0082
0083             match = re.match(source_finish_pending_pattern, line.strip())
0084             if match:
0085                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, result, event_nr = match.groups()
0086                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0087                 start_time = start_times.pop((thread_id, processor_name), None)
0088                 if start_time:
0089                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0090                 continue
0091
0092             match = re.match(processor_start_pattern, line.strip())
0093             if match:
0094                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, event_nr = match.groups()
0095                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0096                 start_times[(thread_id, processor_name)] = millis
0097                 continue
0098
0099             match = re.match(processor_finish_pattern, line.strip())
0100             if match:
0101                 hours_str, mins_str, secs_str, millis_str, thread_id, processor_name, event_nr = match.groups()
0102                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0103                 start_time = start_times.pop((thread_id, processor_name), None)
0104                 if start_time:
0105                     thread_history[thread_id].append((start_time, millis, processor_name, event_nr, result))
0106                 continue
0107
0108             match = re.match(region_start_pattern, line.strip())
0109             if match:
0110                 hours_str, mins_str, secs_str, millis_str, thread_id, region_name, event_nr = match.groups()
0111                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0112                 start_times[(thread_id, region_name)] = millis
0113                 continue
0114
0115             match = re.match(region_finish_pattern, line.strip())
0116             if match:
0117                 hours_str, mins_str, secs_str, millis_str, thread_id, region_name, event_nr = match.groups()
0118                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0119                 start_time = start_times.pop((thread_id, region_name), None)
0120                 if start_time:
0121                     region_history[thread_id].append((start_time, millis, region_name, event_nr))
0122                 else:
0123                     print("No matching enter region")
0124                 continue
0125
0126             match = re.match(barrier_inflight_pattern, line.strip())
0127             if match:
0128                 hours_str, mins_str, secs_str, millis_str, thread_id = match.groups()
0129                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0130                 start_times[()] = millis
0131                 continue
0132
0133             match = re.match(barrier_finished_pattern, line.strip())
0134             if match:
0135                 hours_str, mins_str, secs_str, millis_str, thread_id = match.groups()
0136                 millis = (((int(hours_str) * 60) + int(mins_str) * 60) + int(secs_str)) * 1000 + int(millis_str)
0137                 start_time = start_times.pop((), None)
0138                 if start_time:
0139                     barrier_history.append((start_time, millis))
0140                 continue
0141
0142     return (thread_history, region_history, barrier_history)
0143
0144
0145
0146 def create_svg(output_filename, all_thread_history, region_history, barrier_history):
0147
0148     if not all_thread_history:
0149         print("Error: No thread history found")
0150         print()
0151         print("Make sure you use the following parameters:")
0152         print("  jana:loglevel=debug")
0153         print("  jana:log:show_threadstamp=1")
0154         return
0155
0156     # Assign colors to processors
0157     processor_colors = {}
0158     #color_palette = ['#004E64', '#00A5CF', '#9FFFCB', '#25A18E', '#7AE582', '#FF69B4']
0159     color_palette = ['#004E64', '#00A5CF', '#25A18E', '#7AE582', '#FF69B4']
0160     color_index = 0
0161
0162     # Figure out drawing coordinate system
0163     overall_start_time = min(start for history in all_thread_history.values() for (start,_,_,_,_) in history)
0164     overall_end_time = max(end for history in all_thread_history.values() for (_,end,_,_,_) in history)
0165     thread_count = len(all_thread_history)
0166     width=1000
0167     x_scale = width/(overall_end_time-overall_start_time)
0168     thread_height=40
0169     thread_y_padding=20
0170     height=thread_count * thread_height + (thread_count+1) * thread_y_padding
0171
0172
0173     # Create the SVG drawing
0174     dwg = Drawing(width=width, height=height)
0175
0176     # Draw a rectangle for each processor run on each thread's timeline
0177     y_position = thread_y_padding
0178
0179     for barrier_start,barrier_end in barrier_history:
0180         rect_start = (barrier_start-overall_start_time)*x_scale
0181         if (barrier_end == barrier_start):
0182             rect_width=1
0183         else:
0184             rect_width = (barrier_end-barrier_start)*x_scale
0185
0186         dwg.add_rect(x=rect_start, y=0,
0187                      width=rect_width, height=height,
0188                      fill="red", stroke="none", stroke_width=1)
0189
0190     for thread_id, intervals in all_thread_history.items():
0191
0192         thread_id = int(thread_id)
0193         y_position = (thread_y_padding + thread_height) * (thread_id-1) + thread_y_padding
0194
0195         dwg.add_rect(x=0, y=y_position, width=1000, height=thread_height, stroke="lightgray", fill="lightgray")
0196         for start_time, end_time, processor_name, event_nr, result in intervals:
0197             # Calculate the position and width of the rectangle
0198             # Assign a unique color to each processor name
0199             if processor_name not in processor_colors:
0200                 processor_colors[processor_name] = color_palette[color_index % len(color_palette)]
0201                 color_index += 1
0202
0203             # Draw the rectangle
0204             rect_start = (start_time-overall_start_time)*x_scale
0205             if (end_time == start_time):
0206                 rect_width=1
0207             else:
0208                 rect_width = (end_time-start_time)*x_scale
0209
0210             rect_stroke_color = "black"
0211             if (result == "ComeBackLater" and event_nr is None):
0212                 rect_stroke_color = "gray"
0213
0214
0215             mouseover = "Arrow: " + processor_name + "\nEvent nr: " + str(event_nr) + "\nResult: " + result + "\nTime: "+ str(end_time-start_time) + "ms"
0216
0217             dwg.add_rect(x=rect_start, y=y_position,
0218                          width=rect_width, height=thread_height,
0219                          fill=processor_colors[processor_name],
0220                          stroke=rect_stroke_color, stroke_width=1,
0221                          mouseover_text=mouseover)
0222
0223             if (event_nr is not None):
0224                 dwg.add_text(str(event_nr), x=rect_start+1, y=y_position+thread_height-1, fill="white", font_size=8)
0225
0226
0227     for thread_id, intervals in region_history.items():
0228
0229         thread_id = int(thread_id)
0230         y_position = (thread_y_padding + thread_height) * (thread_id-1) + thread_y_padding
0231
0232         for start_time, end_time, region_name, event_nr in intervals:
0233             # Calculate the position and width of the rectangle
0234             # Assign a unique color to each processor name
0235             if region_name not in processor_colors:
0236                 processor_colors[region_name] = color_palette[color_index % len(color_palette)]
0237                 color_index += 1
0238
0239             # Draw the rectangle
0240             rect_start = (start_time-overall_start_time)*x_scale
0241             if (end_time == start_time):
0242                 rect_width=1
0243             else:
0244                 rect_width = (end_time-start_time)*x_scale
0245
0246             rect_stroke_color = "black"
0247
0248             mouseover = "Region: " + region_name + "\nEvent nr: " + str(event_nr) + "\nTime: "+ str(end_time-start_time) + "ms"
0249
0250             dwg.add_rect(x=rect_start, y=y_position+2,
0251                          width=rect_width, height=thread_height-12,
0252                          fill=processor_colors[region_name],
0253                          stroke=rect_stroke_color, stroke_width=1,
0254                          mouseover_text=mouseover)
0255
0256             if (event_nr is not None):
0257                 dwg.add_text(str(event_nr), x=rect_start+1, y=y_position+thread_height-12, fill="white", font_size=8)
0258
0259
0260     # Save the SVG file
0261     dwg.write(output_filename)
0262
0263
0264
0265 if __name__ == "__main__":
0266
0267     if len(sys.argv) == 1:
0268         input_filename = "log.txt"
0269         output_filename = "timeline.svg"
0270     elif len(sys.argv) == 3:
0271         input_filename = sys.argv[1]
0272         output_filename = sys.argv[2]
0273     else:
0274         print("Error: Wrong number of args")
0275         print("Usage: python jana-plot-utilization.py INPUTFILE OUTPUTFILE")
0276         sys.exit(1)
0277
0278     thread_history,region_history,barrier_history = parse_logfile(input_filename)
0279     #thread_history = {
0280     #    1103:[(0,1,"a"), (2,5,"b"), (6,8,"a")],
0281     #    219:[(0,3,"b"), (3,6,"c"), (9,10,"d")],
0282     #    3:[(2,7,"a")]
0283     #}
0284     create_svg(output_filename, thread_history, region_history, barrier_history)
0285
0286