RL3 Profiling

An RL3 Profiler is a tool that enables to perform RL3 program analysis (e.g. running time or predicate calls) and build reports (flat, tree, calls) based on the created profiles.

Running a profiler

To run RL3 in data collection mode for profiling purposes, set up the environment variable:

RL3_PROFILING=categories

where:

categories - are one or more categories (separated by ',') from the following list:

all - for all categories

annotation - for annotations

matcher - for matchers

pattern - for patterns

predicate - for predicates

rule - for rules

transform - for transformations

Building profiles

In time of running an RL3 Profiler, rl3.MMMMMM.NNNNNN.prof files are created where:

MMMMMM - defines the name of the downloaded configuration;

NNNNNN - is an identifier of the RL3 Engine copy.

Files contain data on each rule or predicate call including:

• call nesting level;
• file path and name, code line number;
• execution time;
• code line statement.

An example of such a file can be found below:

2	phase2/about.rl3: 77:	0.000012636 sec #	match raw_url {p_raw_url_strong_about}
1	phase2/about.rl3: 74:	0.000013828 sec #	rule
3	../common_predicates.rl3: 140:	0.000000715 sec #	each i in ltexts_from_index on {LINE}

Building reports

To build reports, use the rl3p util on profiles:

rl3p --format=format rl3.MMMMMM.NNNNNN.prof

where:

format - defines the report type:

calls - a report on predicate calls

flat - report with items grouped by nesting level

tree - hierarchical report

'Calls' report

The report may contain such data:

• total execution time for all calls of a specified statement;
• total call count for a specified statement;
• statement execution time to total runtime ratio;
• statement definition.

An example of such a report can be found below:

0.168867562 sec	390 times	0.07%	# {matched_by_ref_strong}
0.104321456 sec	238 times	0.04%	# {matched_by_ref_weak}
0.093095527 sec	1255 times	0.04%	# match title {p_title_strong}

'Flat' report

The report may contain such data:

• call nesting level;
• file path and name, code line number;
• total execution time for all calls of a specified statement;
• total call count for a specified statement;
• statement execution time to total runtime ratio;
• statement definition.

An example of such a report can be found below:

1	phase2/contact.rl3: 177:	0.209418535 sec	67 times	0.16%	#	rule
1	phase2/management.rl3: 340:	0.094840047 sec	67 times	0.07%	#	rule
1	phase2/management.rl3: 314:	0.091352465 sec	67 times	0.07%	#	rule
2	phase2/contact.rl3: 190:	0.099794627 sec	64 times	0.07%	#	{matched_by_ref_strong}
2	phase2/management.rl3: 349:	0.085370302 sec	61 times	0.06%	#	{matched_by_ref_weak}
2	phase2/management.rl3: 327:	0.066157339 sec	61 times	0.05%	#	{matched_by_ref_strong}
3	../common_predicates.rl3: 83:	0.092111346 sec	1054 times	0.13%	#	{at_least_one_ltext_is {tl_specific_strong}}
3	../common_predicates.rl3: 157:	0.056220277 sec	1054 times	0.08%	#	match url {UD}{url_specific_strong}({UD}|$)
3	../common_predicates.rl3: 79:	0.047319038 sec	2063 times	0.06%	#	each i in ltexts on {LINE}

'Tree' report

The report may contain such data:

• call nesting level;
• file path and name, code line number;
• total execution time for all calls of a specified statement;
• total call count for a specified statement;
• statement execution time to total runtime ratio;
• statement definition.

An example of such a report can be found below:

1	phase2/contact.rl3: 177:	0.209418535 sec	67 times	0.16%	#	rule
2	phase2/contact.rl3: 190:	0.099794627 sec	64 times	0.48%	#	{matched_by_ref_strong}
3	phase2/contact.rl3: 131:	0.035196545 sec	64 times	0.35%	#	match url {p_url_weak_contact}
3	phase2/contact.rl3: 132:	0.022032261 sec	64 times	0.22%	#	match title {p_title_strong}
3	phase2/contact.rl3: 144:	0.011456732 sec	58 times	0.12%	#	{all_lpaths_are ({lpath_weak}|{lpath_strong})}
4	../common_predicates.rl3: 130:	0.011424540 sec	58 times	1.00%	#	each i in lpaths on {LINE}
3	phase2/contact.rl3: 130:	0.007327790 sec	64 times	0.07%	#	{all_mf_lpaths_are {lpath_strong}}