cleaned logs and added performance data for analysis

integration/code/pn_interface.alc

@@ -260,13 +260,10 @@ Element function transf_vf2(SearchState: Element, transf_m : Element, host_m : E
 
 	//feasability checks
 	if (list_len(SearchState["N_pattern_out"]) > list_len(SearchState["N_host_out"])):
-		log("not feasible1")
 		return SearchState
 	if (list_len(SearchState["N_pattern_in"]) > list_len(SearchState["N_host_in"])):
-		log("not feasible2")
 		return SearchState
 	if (list_len(SearchState["V_pattern"]) > list_len(SearchState["V_host"])):
-		log("not feasible3")
 		return SearchState
 
 	//initialise some variables
@@ -324,6 +321,10 @@ Element function transf_vf2(SearchState: Element, transf_m : Element, host_m : E
 // given a pattern, this function will return all matches in a model
 Element function tf_matchAll(tf_ma_transformation: Element, tf_ma_pattern : Element, tf_ma_model: Element ):
 	
+	//timing info
+	Integer starttime
+	starttime = current_time()
+	
 	//find all nodes in the pattern
 	
 	Element tf_ma_metamodelTransf //transformation metamodel
@@ -366,10 +367,18 @@ Element function tf_matchAll(tf_ma_transformation: Element, tf_ma_pattern : Elem
 	//call vf2 for the matching
 	
 	SearchState = transf_vf2(SearchState, tf_ma_transformation, tf_ma_model)
+	
+	//timing info
+	log(string_join("matching took ", cast_i2s( current_time() - starttime)))
 
 	return SearchState["matches"]
 
 Element function mergeLHSNAC(tf_er_lhs : Element, tf_er_nac: Element):
+	
+	//timing info
+	Integer starttime
+	starttime = current_time()
+	
 	Element final_matches
 	final_matches = create_node()
 	Element lhs_match
@@ -398,6 +407,10 @@ Element function mergeLHSNAC(tf_er_lhs : Element, tf_er_nac: Element):
 				return create_node()
 		if (allow_match):
 			list_append(final_matches, lhs_match)
+	
+	//timing info
+	log(string_join("merging LHS with NAC took ", cast_i2s( current_time() - starttime)))
+	
 	return final_matches
 
 Element function extractPivots(final_matches : Element, tf_er_transformation : Element, tf_er_model : Element):
@@ -426,13 +439,18 @@ Element function extractPivots(final_matches : Element, tf_er_transformation : E
 	return 0
 
 Element function cast_set2list(sset:Element):
-	Element rreturnlist
+	Element rreturnlist //this name must be made weird, otherwise compilation error
 	rreturnlist = create_node()
 	while (read_nr_out(sset) > 0):
 		list_append(rreturnlist, set_pop(sset))
 	return rreturnlist
 	
 Element function rhs_rewrite(final_matches : Element,plabel_to_rhsnode:Element, tf_er_transformation:Element, tf_er_model:Element ):
+	
+	//timing info
+	Integer starttime
+	starttime = current_time()
+	
 	//loop over all matches
 	Element rhs_plabels
 	Element rhs_plabel
@@ -493,6 +511,9 @@ Element function rhs_rewrite(final_matches : Element,plabel_to_rhsnode:Element,
 						list_delete(rhs_plabels,index)
 					else:
 						index = index + 1
+	
+	//timing info
+	log(string_join("rewriting took ", cast_i2s( current_time() - starttime)))
 
 	return 0
 	
@@ -663,23 +684,24 @@ Element function executeRuleBlock(transformation_model : Element,hostmodel:Eleme
 	Boolean succes
 	succes = False
 	Element Rule
+	Integer curtime
+	curtime = current_time()
 	if (typename == "RuleBlockRoot"):
 		// do nothing
-		log("= startinging transformation")
 		succes = True
 	elif (typename == "ARule"):
-		log("= running ARule")
+		//run Arule
 		Rule = read_edge_dst(set_pop(allOutgoingAssociationInstances(transformation_model, ruleblock, transformation_model["metamodel"]["model"]["getrule"])))
-		log(getName(transformation_model, Rule))
 		succes = tf_executeARule(transformation_model, Rule, hostmodel)
 	elif (typename == "FRule"):
-		log("= running FRule")
+		//run Frule
 		Rule = read_edge_dst(set_pop(allOutgoingAssociationInstances(transformation_model, ruleblock, transformation_model["metamodel"]["model"]["getrule"])))
-		log(getName(transformation_model, Rule))
 		succes = tf_executeFRule(transformation_model, Rule, hostmodel)
 	else:
 		log("RuleType is not supported yet")
 	
+	log(string_join(string_join(string_join("= running RuleBlock: ",getName(transformation_model, Rule)), " took "),cast_i2s(current_time() - curtime)))
+	
 	//Return the next
 	Element next
 	if succes: 
@@ -1500,22 +1522,29 @@ Element function initial_prompt():
 Void function main():
 	//initial_prompt()
 	log("==========================================================================")
-	log("=== creating metamodels")
+	Integer init_time
+	init_time = current_time()
 	Element root
 	root = create_metamodels()
-	log("=== load instantiation of transformation metamodel")
+	log(string_join("metamodel creation took ", cast_i2s(current_time() - init_time)))
+	init_time = current_time()
 	Element transf
 	transf = petrinet_transformation(root)
-	log("=== load test1")
+	log(string_join("transform model creation took ", cast_i2s(current_time() - init_time)))
+	init_time = current_time()
 	Element test1
 	test1 = test_simple_petrinet1(root)
-	log("=== check conformance of transformation")
+	log(string_join("simple petrinet model creation took ", cast_i2s(current_time() - init_time)))
+	init_time = current_time()
 	log(conformance_scd(transf))
-	log("=== run transform")
+	log(string_join("transformation conformance checking took ", cast_i2s(current_time() - init_time)))
+	init_time = current_time()
 	tf_transform(transf, test1)
-	log("=== printing some places")
+	log(string_join("transformation execution took ", cast_i2s(current_time() - init_time)))
+	init_time = current_time()
+	
+	log("==========================================================================")
 	printNode(test1, test1["model"]["p1"])
 	printNode(test1, test1["model"]["p2"])
 	log("=== done")
-	log("==========================================================================")
 	return