def process_group_items( self, arg_ofile, arg_items ):
# Msg.trace("PerformanceSummaryItem::process_group_items")
my_grp_count = 0
my_grp_elapsed = 0
try:
for my_item in arg_items:
my_item_elapsed = my_item.force_end - my_item.force_start
my_item_count = my_item.total
my_grp_elapsed += my_item_elapsed
my_grp_count += my_item_count
my_line = "\nTask: %s, Instructions: %d, Elapsed: %0.3f\n" % ( my_item.task_id, my_item_count, my_item_elapsed )
arg_ofile.write( my_line )
# Msg.dbg( my_line )
#end: for my_task in my_group["tasks"]:
except Exception as arg_ex:
Msg.error_trace()
Msg.err( "Error Processing Summary, Reason: %s" % ( str( arg_ex ) ))
return my_grp_count, my_grp_elapsed
def load(self, arg_queue_item):
try:
# my_usr_lbl = Msg.set_label( "user", "SUMMARY_ITEM" )
self.load_process_info(arg_queue_item.process_info)
# Msg.lout( self, "user", "Summary Item(load_process_info)" )
self.load_task_info()
# Msg.lout( self, "user", "Summary Item(load_task_info)" )
self.load_process_log()
# Msg.lout( self, "user", "Summary Item(load_process_log)" )
self.load_force_log()
# Msg.lout( self, "user", "Summary Item(load_force_log)" )
self.load_force_elog()
# Msg.lout( self, "user", "Summary Item(load_force_elog)" )
self.prepare()
self.report()
# Msg.set_label( "user", my_usr_lbl )
except Exception as arg_ex:
Msg.error_trace()
Msg.err(str(arg_ex))
except:
Msg.error_trace()
def process_summary( self, sum_level = SummaryLevel.Fail ):
my_file_name = "%sperformance_summary.log" % ( PathUtils().include_trailing_path_delimiter( self.summary_dir ))
Msg.dbg( "Master Log File: %s" % ( my_file_name ))
my_utcdt = DateTime.UTCNow()
my_ofile = None
try:
# First try to open file
with open( my_file_name, "w" ) as my_ofile:
my_ofile.write( "Date: %s\n" % ( DateTime.DateAsStr( my_utcdt )))
my_ofile.write( "Time: %s\n" % ( DateTime.TimeAsStr( my_utcdt )))
self.process_errors( my_ofile )
my_total_count, my_total_elapsed = self.process_groups( my_ofile )
Msg.blank( "info" )
my_line = "Total Instructions Generated: %3d\n" % ( my_total_count )
my_line += "Total Elapsed Time: %0.3f\n" % ( my_total_elapsed )
my_line += "Overall Instructions per Second: %0.3f\n" % ( SysUtils.ifthen( bool( my_total_elapsed ), my_total_count / my_total_elapsed, 0 ))
Msg.info( my_line )
my_ofile.write( my_line )
except Exception as arg_ex:
Msg.error_trace()
Msg.err( "Error Processing Summary, " + str( arg_ex ) )
finally:
my_ofile.close()
def process_groups( self, arg_ofile ):
my_total_count = 0
my_total_elapsed = 0
my_groups = self.groups.task_groups();
# Msg.trace("PerformanceSummaryItem::process_groups")
for my_group, my_items in my_groups.items():
try:
my_str = "\nBegin Group: %s\n" % ( my_group )
arg_ofile.write( my_str )
Msg.blank( "info" )
Msg.info( my_str )
my_grp_count, my_grp_elapsed = self.process_group_items( arg_ofile, my_items )
my_total_count += my_grp_count
my_total_elapsed += my_grp_elapsed
my_line = "\nGroup Instructions: %3d\n" % ( my_grp_count )
my_line += "Group Elapsed Time: %0.3f\n" % ( my_grp_elapsed )
my_line += "Group Instructions per Second: %0.3f\n" % ( SysUtils.ifthen( bool( my_grp_elapsed ), my_grp_count / my_grp_elapsed, 0 ))
my_line += "End Group: %s\n" % ( my_group )
Msg.info( my_line )
arg_ofile.write( my_line )
except Exception as arg_ex:
Msg.error_trace()
Msg.err( "Unable to process, Group: %s, Reason: %s" % ( my_group, type( arg_ex )))
return my_total_count, my_total_elapsed
def run(self):
# Block on process queue while we have threads running and stuff to do
# == Replaced ==>> while True:
# == Replaced ==>> # Pop off the top of the process queue (should block if the queue is empty)
# == Replaced ==>> try:
# == Replaced ==>> next_item = self.summary_queue.dequeue(0)
# == Replaced ==>> except TimeoutError:
# == Replaced ==>> if (workers_done_event.isSet()):
# == Replaced ==>> summary_done_event.Signal()
# == Replaced ==>> return
# == Replaced ==>> else:
# == Replaced ==>> self.HeartBeat()
# == Replaced ==>> continue
# == Replaced ==>> my_item = self.summary.create_summary_item()
# == Replaced ==>> my_item.load( next_item )
# == Replaced ==>> self.summary.commit_item( my_item )
# == Replaced ==>> next_item = None
try:
while True: #not workers_done_event.isSet():
# Pop off the top of the process queue (should block if the queue is empty)
try:
# my_item = self.summary.create_summary_item()
# my_qitem = self.summary_queue.dequeue(0)
# my_item.load( my_qitem )
# self.summary.commit_item( my_item )
# my_qitem = None
# my_qitem = self.summary_queue.dequeue(0)
my_qitem = self.summary_queue.dequeue(0)
if isinstance(my_qitem, SummaryErrorQueueItem):
Msg.user(str(my_qitem.error_info), "SUMMARY_ERROR")
my_eitem = SummaryErrorItem()
my_eitem.load(my_qitem)
self.summary.commit_error_item(my_eitem)
else:
my_item = self.summary.create_summary_item()
my_item.load(my_qitem)
self.summary.commit_item(my_item)
my_qitem = None
except TimeoutError as arg_ex:
# {{{TODO}}} Implement proper heartbeat
# Msg.dbg( str( arg_ex ) )
if (workers_done_event.isSet()):
break
else:
self.HeartBeat()
continue
except Exception as arg_ex:
Msg.error_trace()
Msg.err(str(arg_ex))
raise
except:
Msg.error_trace()
raise
finally:
summary_done_event.Signal()
def load_iss_result(self, arg_dict):
# Msg.lout( arg_dict, "user", "ISS Results Dictionary ... " )
self.iss_log = arg_dict["iss-log"]
try:
self.iss_retcode = int(arg_dict["iss-retcode"])
except:
self.iss_retcode = -1
Msg.err("ISS Return Code in unrecognizable format")
def process_task_list(self):
for my_task_file in self.task_list:
# Msg.dbg( "Process Task File: %s" % ( my_task_file ))
my_curdir = PathUtils.current_dir()
try:
# self.process_task_file( my_task_file )
self.process_task_file(my_task_file)
except Exception as arg_ex:
Msg.error_trace()
Msg.err(str(arg_ex))
Msg.blank()
finally:
PathUtils.chdir(my_curdir)
def process(self):
# Msg.dbg( "TaskController::process()")
for my_ndx in range(0, self.ctrl_item.iterations):
try:
# my_usr_lbl = Msg.set_label( "user", "TASK-ITERATION" )
# Msg.user( "Executing Iteration #%d of %d Task: %s " % ( my_ndx + 1, self.ctrl_item.iterations, self.ctrl_item.fctrl_name ))
self.process_task_list()
except Exception as arg_ex:
# pass
Msg.error_trace()
Msg.err(str(arg_ex))
Msg.blank()
finally:
pass
def load(self, arg_ctrl_item ):
super().load( arg_ctrl_item )
# Msg.dbg( "FileController::load()" )
self.parent_fctrl = self.ctrl_item.file_path()
# Msg.dbg( "File Path: %s" % ( self.parent_fctrl ))
#my_content = open( self.parent_fctrl ).read()
# Msg.dbg( "\n" + my_content )
try:
my_content = open( self.parent_fctrl ).read()
except Exception as arg_ex:
Msg.err( "Message: %s, Control File Path: %s" % ( str( arg_ex ), self.parent_fctrl ))
my_err_queue_item = SummaryErrorQueueItem( { "error" : arg_ex
, "message": "Control File Not Found ..."
, "path" : self.ctrl_item.file_path()
, "type" : str( type( arg_ex ))
} )
self.ctrl_item.summary().queue.enqueue( my_err_queue_item )
return False
finally:
pass
try:
my_glb, my_loc = SysUtils.exec_content( my_content )
except Exception as arg_ex:
my_exc_type, my_exc_val, my_exc_tb = sys.exc_info()
my_ex = arg_ex
Msg.err( "Message: %s, Control File Path: %s" % ( str( arg_ex ), self.parent_fctrl))
Msg.blank()
my_err_queue_item = SummaryErrorQueueItem( { "error" : arg_ex
, "message": "Control File not processed..."
, "path" : self.ctrl_item.file_path()
, "type" : str( my_exc_type )
} )
self.ctrl_item.summary().queue.enqueue( my_err_queue_item )
return False
finally:
pass
self.fcontrol = my_loc["control_items"]
return True
def load_process_log(self):
self.force_cmd = None
self.force_elog = None
self.force_log = None
self.force_retcode = None
self.force_stderr = None
self.force_stdout = None
self.force_level = SummaryLevel.Any
self.force_start = 0.00
self.force_end = 0.00
self.iss_cmd = None
self.iss_log = None
self.iss_retcode = None
self.max_instr = None
self.min_instr = None
# Msg.fout( self.process_log, "dbg" )
with open(self.process_log, "r") as my_flog:
try:
for my_line in my_flog:
Msg.dbg("Load: %s" % my_line)
self.load_process_line(my_line)
except Exception as arg_ex:
Msg.error_trace(arg_ex)
Msg.err(str(arg_ex))
finally:
my_flog.close()
# here is the lowdown, if a generate line exists in the process log then a Result line must also exists,
if (self.detail_flags & SummaryDetail.ForceCmd
) and not (self.detail_flags & SummaryDetail.ForceResult):
self.load_gen_result({
"force-retcode": self.process_result[0],
"force-stdout": self.process_result[2],
"force-stderr": self.process_result[2],
"force_start": self.process_result[3],
"force_end": self.process_result[4]
})
elif (self.detail_flags & SummaryDetail.IssCmd
) and not (self.detail_flags & SummaryDetail.IssResult):
self.load_iss_result({
"iss-retcode": self.process_result[0],
"iss-log": None
})
def write_control_file(self, arg_frun_file, arg_content):
#arg_filename = "_def_frun.py"
with open(arg_frun_file, "w") as my_ofile:
try:
return (my_ofile.write(arg_content) > 0)
except Exception as arg_ex:
Msg.error_trace()
Msg.err("Error Writing Control File, " + str(arg_ex))
# reraise exception to prevent creating tasks in queue if the control file cannot be written
finally:
my_ofile.close()
return False
def exec_iss(self, arg_task_name):
# Msg.dbg( "ExecuteController::exec_iss( %s )" % ( arg_task_name ) )
# build rest of command for iss
my_elf = "%s.Default.ELF" % (arg_task_name)
# Msg.dbg( "Looking For: %s" % ( my_elf ))
my_elf = SysUtils.ifthen(PathUtils.check_file(my_elf), " %s" % my_elf,
"")
# Msg.dbg( "Using ELF: %s" % ( my_elf ))
my_elfns = "%s.Secondary.ELF" % (arg_task_name)
# Msg.dbg( "Looking For: %s" % ( my_elfns ))
my_elfns = SysUtils.ifthen(PathUtils.check_file(my_elfns),
" %s" % my_elfns, "")
my_cmd = self.sim_cmd % (my_elf, my_elfns)
try:
# execute the simulation
Msg.info("ISSCommand = " + str({"iss-command": my_cmd}))
my_log = self.sim_log
my_elog = self.sim_log
#my_ret_code = int( SysUtils.exec_cmd( my_cmd ) )
my_result = SysUtils.exec_process(my_cmd, my_log, my_elog,
self.ctrl_item.timeout, True)
my_ret_code = int(my_result[0])
my_std_out = str(my_result[1])
my_std_err = str(my_result[2])
my_start = str(my_result[3])
my_end = str(my_result[4])
Msg.info("ISSResult = " + str({
"iss-retcode": my_ret_code,
"iss-log": self.sim_log,
"iss-stdout": my_std_out,
"iss-stderr": my_std_err,
"iss-start": my_start,
"iss-end": my_end
}))
except Exception as arg_ex:
Msg.error_trace("ISS Execute Failure")
Msg.err("ISS did not properly execute, Reason: %s" % (str(arg_ex)))
return False
return True
def load_gen_result(self, arg_dict):
# Msg.lout( arg_dict, "dbg", "Generate Results Dictionary ... " )
try:
self.force_retcode = int(str(arg_dict["force-retcode"]).strip())
except:
self.force_retcode = -1
Msg.err("Generate Return Code in unrecognizable format")
self.force_stdout = arg_dict["force-stdout"]
self.force_stderr = arg_dict["force-stderr"]
if SysUtils.failed(self.force_retcode):
self.force_level = SummaryLevel.Fail
self.force_start = float(arg_dict.get("force-start", 0.00))
self.force_end = float(arg_dict.get("force-end", 0.00))
def process_task(self, arg_task_file):
try:
# get the subdirectory index
my_ndx = int(PathUtils.next_subdir())
# update the user label and send iteration message to the screen if user is active
# my_usr_lbl = Msg.set_label( "user", "TEST-ITERATION" )
# Msg.user( "Executing Iteration #%d of Test File: %s" % ( my_ndx + 1, arg_task_file ))
# Msg.set_label( "user", my_usr_lbl )
# create subdirectory and change into it
PathUtils.chdir("%05d" % my_ndx, True)
# save the task template file name with path to the control item
self.ctrl_item.fname = arg_task_file
# write out the control file
# if the write was successful then enqueue the new control file name with real path
my_ctrl_file = "%s_def_frun.py" % (
PathUtils.include_trailing_path_delimiter(
PathUtils.current_dir()))
PathUtils.touch("%sSTARTED" %
PathUtils.include_trailing_path_delimiter(
PathUtils.current_dir()))
my_content = self.prepare(arg_task_file)
if self.write_control_file(my_ctrl_file, my_content):
# my_queue_item = ProcessQueueItem( my_ctrl_file, self.ctrl_item.parent_fctrl, self.ctrl_item.fctrl_item, self.ctrl_item.group, my_content )
my_queue_item = ProcessQueueItem(
my_ctrl_file, self.ctrl_item, my_content
) # self.parent_fctrl, self.ctrl_item.fctrl_item, self.ctrl_item.group)
self.ctrl_item.parent_data.process_queue.enqueue(my_queue_item)
except Exception as arg_ex:
Msg.error_trace()
Msg.err(str(arg_ex))
# reraise to prevent adding to summary instance
raise
finally:
PathUtils.chdir("..")
def instruction_counts( self ):
my_lines = None
my_glog = "%s%s" % ( PathUtils.include_trailing_path_delimiter( self.work_dir ), self.force_log )
Msg.user("Path: %s" % my_glog)
with open( my_glog, "r" ) as my_log:
my_lines = my_log.readlines()
Msg.dbg( "Line %d: %s" % ( len( my_lines ), my_lines[-1]))
my_log.close()
try:
my_results = [ my_tmp for my_tmp in my_lines if re.search( ' Instructions Generated', my_tmp )]
Msg.lout( my_results, "dbg" )
if not my_results:
raise Exception( "Instruction Count Not Found in \"gen.log\"" )
# ok there are instruction counts located
for my_line in my_results:
my_line = my_line.strip()
# find the instruction type (Total, Default, Secondary)
my_lpos = my_line.find(']')
my_rpos = my_line.find( "Instr" )
my_type = PerformanceInstructionType.instruction_type(( my_line[my_lpos + 1 : my_rpos - 1 ]).strip())
# get the count for this instruction type
my_lpos = my_line.find( ':' )
my_count = int( my_line[my_lpos+2:].strip())
if my_type == PerformanceInstructionType.Total:
self.count = my_count
elif my_type == PerformanceInstructionType.Secondary:
self.secondary = my_count
elif my_type == PerformanceInstructionType.Default:
self.default = my_count
except ValueError:
Msg.error_trace()
Msg.err( "Unable to extract instruction count from %s" % ( int( my_lines[-1] )))
return 0
def process(self):
# Msg.dbg( "FileController::process()" )
# Msg.dbg( "FileController Contents: \n\"" + str( self.fcontrol ) + "\n" )
try:
# Msg.lout( my_options["work-dir"], MsgLevel.dbg, "Work Director Stack" )
# a control file may iterate through to completion according to the amount set in num_runs
for my_ndx in range( self.ctrl_item.iterations ):
# my_usr_lbl = Msg.set_label( "user", "FILE-ITERATION" )
# Msg.user( "Executing %d of %d Iterations, Control File: %s" % ( my_ndx + 1, self.ctrl_item.iterations, self.ctrl_item.file_path() ))
# Msg.set_label( "user", my_usr_lbl )
try:
my_item_ndx = 0
# each item in the control set exists as a dictionary
for my_item_dict in self.fcontrol:
try:
my_item_ndx += 1
my_usr_lbl = Msg.set_label( "user", "CTRL-FILE" )
Msg.blank( "user" )
Msg.user( "Processing Line: %s" % (str( my_item_dict )))
my_ctrl_item = ControlItem()
my_ctrl_item.parent_fctrl = self.parent_fctrl
my_ctrl_item.fctrl_item = str( my_item_dict )
my_item_dict[CtrlItmKeys.parent_vals], my_parent_data = self.ctrl_item.values()
Msg.lout( my_parent_data, "user", "Result Parent Data" )
Msg.lout( my_item_dict , "user", "Result Item Dictionary" )
Msg.set_label( "user", my_usr_lbl )
# Msg.user( "Processing Updated Line: %s" % (str( my_item_dict )), "CTRL-FILE" )
# Msg.user( str( my_parent_data.data() ), "CTRL-FILE" )
my_ctrl_item.load( my_item_dict, my_parent_data )
my_item_type = my_ctrl_item.item_type()
my_controller = None
if my_item_type == ControlItemType.TaskItem:
# Msg.dbg( "\nControl Item is a Control Task ..." )
my_controller = TaskController()
elif my_item_type == ControlItemType.FileItem:
# Msg.dbg( "\nControl Item is a Control File ..." )
my_controller = FileController()
else:
raise Exception( "\"" + my_fctrl_name + "\": Unknown Item Type ...\nUnable to Process ... " )
# Whew! everything is set up and ready to rock and roll, let the dogs out
# my_controller.load( my_ctrl_item )
# my_controller.process()
if my_controller.load( my_ctrl_item ):
my_controller.process()
# my_controller.load( my_ctrl_item )
# my_controller.process()
# Msg.dbg( "%s: Controller Creation Complete" % ( my_ctrl_item.fctrl_name ))
except TypeError as arg_ex:
Msg.err( str( arg_ex ))
my_err_queue_item = SummaryErrorQueueItem( { "error" : "Item #%s Contains an Invalid Type" % ( str( my_item_ndx ))
, "message": arg_ex
, "path" : self.ctrl_item.file_path()
, "type" : str( type( arg_ex ))
} )
self.ctrl_item.summary().queue.enqueue( my_err_queue_item )
Msg.blank()
except FileNotFoundError as arg_ex:
Msg.err( str( arg_ex ))
my_err_queue_item = SummaryErrorQueueItem( { "error" : arg_ex
, "message": "Control File Not Found ..."
, "path" : self.ctrl_item.file_path()
, "type" : str( type( arg_ex ))
} )
self.ctrl_item.summary().queue.enqueue( my_err_queue_item )
Msg.blank()
except Exception as arg_ex:
Msg.error_trace( str(arg_ex) )
Msg.err( str(arg_ex))
Msg.blank()
finally:
my_controller = None
my_item_dict = None
except Exception as arg_ex:
Msg.error_trace( "[ERROR] - " + str(arg_ex) )
Msg.err( str(arg_ex))
finally:
pass
finally:
pass
# Msg.dbg()
return True
Msg.dbg("Test Completed ....\n")
Msg.blank()
sys.exit(40)
except getopt.GetoptError as arg_ex:
from force_init import force_usage
Msg.error_trace("[ERROR] - " + str(arg_ex))
force_usage(UsageStr)
sys.exit(41)
except Exception as arg_ex:
from force_init import force_usage
Msg.err("[ERROR] - An Unhandled Error has Occurred during run of " +
str(sys.argv[0]))
traceback.print_exc(file=sys.stdout)
Msg.error_trace(str(arg_ex))
force_usage(UsageStr)
sys.exit(42)
finally:
if not my_pwd is None:
# Msg.dbg( "Restoring Original Directory: " + my_pwd )
PathUtils.chdir(my_pwd)
Msg.dbg("Returned To: %s" % (PathUtils.current_dir()))
Msg.info("Done with Unit Test of Regression")
def load_force_log(self, arg_seed_only=False):
self.default = None
self.secondary = None
self.total = None
self.seed = None
self.task_path = PathUtils.include_trailing_path_delimiter(
self.work_dir)
my_glog = "%s%s" % (self.task_path, self.force_log)
Msg.dbg("Path: %s" % my_glog)
# Msg.user( "Opening Generator Log File: %s" % ( my_glog ))
with open(my_glog, "r") as my_flog:
try:
for my_line in my_flog:
if SysUtils.found(
my_line.find("Secondary Instructions Generated")):
# my_secondary = my_line.replace( "[notice]Secondary Instructions Generated:", "" ).strip()
# self.secondary = int( my_secondary )
my_lpos = my_line.find(':')
my_count = int(my_line[my_lpos + 2:].strip())
# Msg.user( "Secondary Instructions: %d" % ( my_count ))
self.secondary = my_count
elif SysUtils.found(
my_line.find("Default Instructions Generated")):
# my_pos = my_line.find( ":" ) + 2
# my_default = my_line[ my_pos: ].strip()
# get the count for this instruction type
my_lpos = my_line.find(':')
my_count = int(my_line[my_lpos + 2:].strip())
# Msg.user( "Default Instructions: %d" % ( my_count ))
self.default = my_count
# my_default = my_line.replace( "[notice]Default Instructions Generated:", "" ).strip()
# self.default = int( my_default )
if SysUtils.found(
my_line.find("Total Instructions Generated")):
self.total = int(
my_line.replace(
"[notice]Total Instructions Generated: ",
"").strip())
my_lpos = my_line.find(':')
my_count = int(my_line[my_lpos + 2:].strip())
# Msg.user( "Total Instructions: %d" % ( my_count ))
self.total = my_count
if SysUtils.found(my_line.find("Initial seed")):
self.seed = my_line.replace("[notice]", "").replace(
"Initial seed = ", "").strip()
# Msg.dbg( "Seed: %s" % ( self.seed ))
# for simulation only the seed is needed
if arg_seed_only:
break
if not (self.seed is None or self.total is None
or self.secondary is None or self.default is None):
break
except Exception as arg_ex:
# NOTE: Determine the possible errors and handle accordingly, for now just keep processing
Msg.error_trace()
Msg.err(str(arg_ex))
finally:
my_flog.close()
