Tracing rules

SG246614

The following predicates can be used to create logging and tracing entries in rules:

• set_detailed_debugging  This writes rule trace information for predicates to the rule trace file. The predicate can be run from any rule.
• trace_it  This enables tracing of user-defined predicates.
• log_error This generates error messages to assist in rule development. It should be run from within a predicate that has been created to help to debug rules. The more recent predicates provided by Tivoli have this predicate already embedded. Use the predicates tell_err or set_log_error_source to set up the logging location.

For more information about the predicates refer to the IBM Tivoli Enterprise Console Rule Builder's Guide Version 3.8, GC32-0669. Tracing rules

To trace rules, you must first specify a trace file using the wsetesvrcfg -t command or the Server Parameters window (see the IBM Tivoli Enterprise Console Command and Task Reference for more information.)

Next, compile the rule base with tracing enabled. This can be done from the command line with the

wrb -comprules -trace

command, with a trace directive specified in a rule or rule set, or from the rule builder by selecting Trace Rules in the Compile Rule Base dialog. When compiling is completed, load the rule base. Ensure you select Trace Rules in the Event Server Parameters dialog before stopping and restarting the event server to begin logging of the trace output.

When they run, rules generate trace output in a log file. You can examine the trace file to analyze and debug rule execution. The name and location of the trace file is set in the Event Server Parameters dialog.

The default trace file is /tmp/rules.trace. The tail -f command is useful for viewing the trace file as events are received.

Trace granularity

The following levels of granularity are supported for rule tracing:

• All rules All rules within a rule base are traced when tracing is enabled by the wrb -comprules -trace command or by selecting the Trace Rules option when compiling a rule base with the rule builder.
• Rule set A particular rule set is traced by inserting a trace directive into the rule set. Insert it at the top before the first rule.
• Rule A particular rule is traced by inserting a trace directive into the rule. Insert it before the rule's event filter.

Tracing a rule set

To trace a rule set, insert the trace directive into the rule set. Insert it at the top before the first rule. The following example shows how to enable tracing in a rule set:

directive: trace    % Start trace.

rule: rule1: (
...
).                      % End rule1.

rule: rule2: (
...
).                      % End rule2.

rule: rule3: (
...
).                      % End rule3. 
                        % End rule set.
                        % End trace.

Tracing a rule

To trace a particular rule, insert the trace directive into the rule. Insert it before the rule's event filter. The following example shows how to enable tracing for a particular rule:

rule: test_rule: (
   directive: trace,
   event: _evt of_class within [ 'NT_NAV' ] where [ ],

   reception_action: action0:(
      drop_received_event
   )
).

Trace information

Trace information is written to the trace file for the following:

• Rules. When a rule is entered and exited. Only a rule whose event filter matches the event under analysis is traced.
• Attribute conditions. When an attribute condition of an event filter is entered and exited.
• Actions. When a rule action is entered and exited.
• Rule language predicates. When entering and exiting a rule language predicate, and when a predicate fails.
• Prolog predicates When a predicate written in Prolog within a rule action is entered and exited. Prolog predicate tracing is limited to one depth level; nested Prolog calls are not traced. (To trace nested calls, include the directive set_detailed_debugging(on) in the startup rule of the rule set.)

Rule tracing example

The following rule illustrates rule debugging. Assume that tracing is enabled and the rule is contained in the rule set my_first_set:

rule: my_first_rule: (

  description: 'Simplerule',
    event: _ev of_class 'HIGH_CPU_USAGE'
      where [usage: _usage,
             hostname: equals 'my_server'],

    action: auto_ack: (
       set_event_status(_ev, 'ACK'),
       set_event_administrator(_ev, 'john')
    ),

    action: page_administrator: (
      exec_program(_ev,
                   send_cpu_usage_to_pager,
                   'john my_server %d',
                   _usage],
                   'NO'
      )
  )
).

Tracing a rule event filter

The following trace line indicates that the my_first_set rule set has been entered:

[117]=> rule set my_first_set

The following trace line indicates that the rule my_first_rule has been entered:

[118] -> rule my_first_rule
event : 0x2c0b88 of_class HIGH_CPU_USAGE

The following trace lines indicate that the attribute conditions of the rule's event filter are being checked. These trace lines indicate that the event satisfies the attribute conditions:

[119] call condition
[120] call usage: _125
[121] exit usage: 95
[122] call hostname: _126
[123] exit hostname: my_server
[124] call hostname: my_server equals my_server
[125] exit hostname: my_server equals my_server
[126] exit condition

Lines 120-123 indicate that the value of two attributes are being retrieved (usage and hostname), while lines 124 and 125 indicate that a retrieved attribute value for hostname is being compared to a literal value (my_server) for equality.

Variables are traced by their assigned internal number, not their name. The internal number is preceded by an underscore character (_). A variable is always used when retrieving an attribute value, even if you don't store the value in a named variable.

The following trace lines indicate that a HIGH_CPU_USAGE event for a host other than my_server (another_host) was received. This event did not match the attribute conditions specified in the event filter:

[119] call condition
[120] call usage: _125
[121] exit usage: 95
[122] call hostname: _126
[123] exit hostname: another_host
[124] call hostname: another_host equals my_server
[125] fail hostname: another_host equals my_server
[126] fail condition

When a failure occurs, no further attribute condition testing is performed, and thus no further tracing of attribute conditions occurs for this rule.

Tracing rule actions

If an event satisfies all of the conditions specified in the event filter, the rule actions are run and traced. Actions are traced at the following two levels:

• Tracing is performed when entering or exiting an action.
• Tracing is performed when entering or exiting a predicate or an event filter in a predicate.

The following is an example of the trace file output for two actions (auto_ack and page_administrator). The auto_ack action contains two predicates (set_event_status and set_event_administrator). The page_administrator action contains the exec_program predicate.

[127] call action auto_ack
[128] call set_event_status(0x2c0b88, ACK)
[129] exit set_event_status(0x2c0b88, ACK)
[130] call set_event_administrator(0x2c0b88, john)
[131] exit set_event_administrator(0x2c0b88, john)
[132] exit action auto_ack
[133] call action page_administrator
[134] call exec_program(0x2c0b88, send_cpu_usage_to_pager,
'john my_server %d',[95],NO)
[135] exit exec_program(0x2c0b88, send_cpu_usage_to_pager,
'john my_server %d',[95],NO)
[136] exit action page_administrator

As mentioned previously, variables are initially traced by their assigned internal number, not by their name. Once a variable has received a value, the value is used instead of the number (see trace line 134, which shows the value of my_server used instead of _126).

If a predicate called from within an action fails, the failure is reported in the trace file output and any remaining predicates in the action are not traced, because they are not run. A predicate can fail for any number of reasons, one of the more common being incorrect argument values.

Tracing multiple solution event filters in predicates

When a redo request is performed on a rule that contains an action that searches the event cache for all duplicates or all occurrences of an event, possible additional solutions are examined. If the event satisfies the event filter criteria of the predicate, a new solution for the event results.

If the action failed, it indicates that no other possibility successfully exited, that no other event satisfying the event filter criteria for the predicate was found, or that the predicate call failed.

The following action is the basis for the information that follows:

action: (
  all_instances(event: _nfs_ev of_class
                'NFS_SERVER_NOT_RESPONDING'
    where [server: equals 'Pascal' ]),

  set_event_status (nfs_ev, 'CLOSED')
)

Assume two NFS_SERVER_NOT_RESPONDING events for the server Pascal had were received and are in the event cache.

Lines 139 through 144 contain the trace information for the first event found by the all_instances predicate:

[139] call reception_action action_1
[140] call all_instances(event : _366 of_class
NFS_SERVER_NOT_RESPONDING where [server:equals
Pascal],0x2c0b88-600-600)
[141] exit all_instances(event : 0x2c0ae0 of_class
NFS_SERVER_NOT_RESPONDING where [server:equals
Pascal],0x2c0b88-600-600)
[142] call set_event_status(0x2c0ae0, CLOSED)
[143] exit set_event_status(0x2c0ae0, CLOSED)
[144] exit reception_action action_1

Lines 145 through 150 contain the trace information for the second event found by the all_instances predicate:

[145] redo reception_action action_1
[146] redo all_instances
[147] exit all_instances(event : 0x2eabf0 of_class
NFS_SERVER_NOT_RESPONDING where [server:equals \
Pascal],0x2c0b88-600-600)
[148] call set_event_status(0x2c0ae0, CLOSED)
[149] exit set_event_status(0x2cae0, CLOSED)
[150] exit reception_action action_1

Lines 151 through 154 contain the trace information generated when no additional events are found by the all_instances predicate:

[151] redo reception_action action_1
[152] redo all_instances
[153] fail all_instances(event : _366 of_class 
NFS_SERVER_NOT_RESPONDING where [server:equals 
Pascal],0x2c0b88-600-600)
[154] fail reception_action action_1

Profiling rules

Profiling generates a report that contains rule execution information. You can profile an entire rule base, rule sets, or particular rules. A report contains the following information for each rule being profiled:

• The amount of time (in seconds) spent by the rule to process the last event that triggered the rule
• The number of events processed by the rule
• The amount of time (in seconds) all events spent in the rule for processing
• The throughput of events for the rule, expressed as the number of events per second

The following figure shows an example of a profile report with one rule profiled:

============================================
              Timing Summary
--------------------------------------------
test_rls:
  Time for last Event: 7.000000000000001e-02
  Event Count:         2
  Total Time:          4.799999999999998e-01
  Events per second:   4.166666666666669e+00
--------------------------------------------
--------------------------------------------
============================================

To profile rules, you must compile the rule base with profiling enabled. This can be done from the command line with the wrb -comprules -profile command or with the profile directive specified in a rule set or rule.

After recompiling the rule base with profiling enabled, stop and restart the event server to begin the profiling. The profile report is appended to the $DBDIR/tec/profile file when you shut down the event server. Because a profile report is always appended to the same file it can become quite large if you never delete it or delete entries within it, so check it periodically.

Profile granularity

The following levels of granularity are supported for rule profiling:

All rules

All rules within a rule base are profiled when profiling is enabled by the wrb -comprules -profile command.

Rule set

A particular rule set is profiled by inserting a profile directive into the rule set, at the top before the first rule.

Rule

A particular rule is profiled by inserting a profile directive into the rule, before the rule's event filter.

Profiling a rule set

To profile an entire rule set, insert the directive before the first rule in the rule set. The following example shows how to enable profiling in a rule set:

directive: profile   % Start profiling.

rule: rule1: (
...
).                      % End rule1.

rule: rule2: (
...
).                      % End rule2.


rule: rule3: (
...
).                      % End rule3.
                        % End rule set.
                        % End profiling.

Profiling a rule

To profile a particular rule, insert the profile directive into the rule, before the rule's event filter. To suppress profiling of a particular rule, insert the profile_off directive at the same location. The following example shows how to enable profiling for a particular rule:

rule: test_rule: (
  directive: profile,
  event: _evt of_class within [ 'NT_NAV' ] where [ ],

  reception_action: action0:(
    drop_received_event
  )
).

Measuring event processing performance

You can measure event processing performance on the event server by generating a report of event arrival and processing during a user-defined sample period. This report also includes the overall count of events received and processed. You can also specify a time interval to be used for periodically calculating throughput during the sample period.

Events received by the event server are inserted into the reception log with a state of QUEUED. When processing by the event server is complete, the state of the event in the reception log is updated to PROCESSED. To create a report of this processing activity, add the following two parameters to the .tec_config configuration file:

tec_benchmark_report_period=report_period
tec_benchmark_sample_period=sample_period

where report_period is an integer specifying the rate at which processing rates are printed, and sample_period is an integer specifying the time window for which event arrival and processing rates are computed. After you add these parameters, stop and restart the event server.

If either of these parameters is specified in the configuration file, the output is printed to the tec_reception trace file. The following example shows the output produced (with time stamps removed):

===================================================
         Event Throughput Statistics
===================================================
Reporting Interval is 2 seconds 

Sample    Interval is 60 seconds 

Actual Period           8 seconds

Events Received:        592 

Event  Arrival Rate:    74.000000 events/second

Events Processed:       700 

Event  Processing Rate: 87.500000 events/second

 ------------------------------------------------
Total Events Waiting:   0 

Total Events Received:  6604 

Total Events Processed: 5666 

Processing Backlog: 938

The output is displayed in two sections. The first section displays the following information:

• The reporting and sample intervals specified in the configuration file
• The current cumulative time within the sample period
• The count of events received and the arrival rate
• The count of events processed and the processing rate (this is the event server processing throughput, in events per second)

The second section shows event-related statistics computed since the server was started, including the number of received, processed, and waiting events, as well as the current server backlog. (The backlog is the difference between the received and processed events.)

Recommended links

• TEC Rule Tracing (Part 1)
  This is the first part of a three part tip which takes a closer look at Rule Tracing. This tip describes how you can generate your own trace messages to help debug your rules
• TEC Rule Tracing (Part 2)
  This is the second part of a three part tip which takes a closer look at Rule Tracing. This tip describes how you can dynamically turn on and off tracing within your rulebase without having to perform a restart.
• TEC Rule Tracing (Part 3)
  This is the final part of a three part tip which takes a closer look at Rule Tracing. This tip describes how you can trace particular rules or actions within a rule base, thus allowing you to trace only the rules that you're currently developing.

Etc

Society

Groupthink : Two Party System as Polyarchy : Corruption of Regulators : Bureaucracies : Understanding Micromanagers and Control Freaks : Toxic Managers :   Harvard Mafia : Diplomatic Communication : Surviving a Bad Performance Review : Insufficient Retirement Funds as Immanent Problem of Neoliberal Regime : PseudoScience : Who Rules America : Neoliberalism  : The Iron Law of Oligarchy : Libertarian Philosophy

Quotes

War and Peace : Skeptical Finance : John Kenneth Galbraith :Talleyrand : Oscar Wilde : Otto Von Bismarck : Keynes : George Carlin : Skeptics : Propaganda  : SE quotes : Language Design and Programming Quotes : Random IT-related quotes :  Somerset Maugham : Marcus Aurelius : Kurt Vonnegut : Eric Hoffer : Winston Churchill : Napoleon Bonaparte : Ambrose Bierce :  Bernard Shaw : Mark Twain Quotes

Bulletin:

Vol 25, No.12 (December, 2013) Rational Fools vs. Efficient Crooks The efficient markets hypothesis : Political Skeptic Bulletin, 2013 : Unemployment Bulletin, 2010 :  Vol 23, No.10 (October, 2011) An observation about corporate security departments : Slightly Skeptical Euromaydan Chronicles, June 2014 : Greenspan legacy bulletin, 2008 : Vol 25, No.10 (October, 2013) Cryptolocker Trojan (Win32/Crilock.A) : Vol 25, No.08 (August, 2013) Cloud providers as intelligence collection hubs : Financial Humor Bulletin, 2010 : Inequality Bulletin, 2009 : Financial Humor Bulletin, 2008 : Copyleft Problems Bulletin, 2004 : Financial Humor Bulletin, 2011 : Energy Bulletin, 2010 : Malware Protection Bulletin, 2010 : Vol 26, No.1 (January, 2013) Object-Oriented Cult : Political Skeptic Bulletin, 2011 : Vol 23, No.11 (November, 2011) Softpanorama classification of sysadmin horror stories : Vol 25, No.05 (May, 2013) Corporate bullshit as a communication method  : Vol 25, No.06 (June, 2013) A Note on the Relationship of Brooks Law and Conway Law

History:

Fifty glorious years (1950-2000): the triumph of the US computer engineering : Donald Knuth : TAoCP and its Influence of Computer Science : Richard Stallman : Linus Torvalds  : Larry Wall  : John K. Ousterhout : CTSS : Multix OS Unix History : Unix shell history : VI editor : History of pipes concept : Solaris : MS DOS :  Programming Languages History : PL/1 : Simula 67 : C : History of GCC development :  Scripting Languages : Perl history   : OS History : Mail : DNS : SSH : CPU Instruction Sets : SPARC systems 1987-2006 : Norton Commander : Norton Utilities : Norton Ghost : Frontpage history : Malware Defense History : GNU Screen : OSS early history

Classic books:

The Peter Principle : Parkinson Law : 1984 : The Mythical Man-Month :  How to Solve It by George Polya : The Art of Computer Programming : The Elements of Programming Style : The Unix Hater’s Handbook : The Jargon file : The True Believer : Programming Pearls : The Good Soldier Svejk : The Power Elite

Most popular humor pages:

Manifest of the Softpanorama IT Slacker Society : Ten Commandments of the IT Slackers Society : Computer Humor Collection : BSD Logo Story : The Cuckoo's Egg : IT Slang : C++ Humor : ARE YOU A BBS ADDICT? : The Perl Purity Test : Object oriented programmers of all nations : Financial Humor : Financial Humor Bulletin, 2008 : Financial Humor Bulletin, 2010 : The Most Comprehensive Collection of Editor-related Humor : Programming Language Humor : Goldman Sachs related humor : Greenspan humor : C Humor : Scripting Humor : Real Programmers Humor : Web Humor : GPL-related Humor : OFM Humor : Politically Incorrect Humor : IDS Humor : "Linux Sucks" Humor : Russian Musical Humor : Best Russian Programmer Humor : Microsoft plans to buy Catholic Church : Richard Stallman Related Humor : Admin Humor : Perl-related Humor : Linus Torvalds Related humor : PseudoScience Related Humor : Networking Humor : Shell Humor : Financial Humor Bulletin, 2011 : Financial Humor Bulletin, 2012 : Financial Humor Bulletin, 2013 : Java Humor : Software Engineering Humor : Sun Solaris Related Humor : Education Humor : IBM Humor : Assembler-related Humor : VIM Humor : Computer Viruses Humor : Bright tomorrow is rescheduled to a day after tomorrow : Classic Computer Humor

The Last but not Least Technology is dominated by two types of people: those who understand what they do not manage and those who manage what they do not understand ~Archibald Putt. Ph.D

The statements, views and opinions presented on this web page are those of the author (or referenced source) and are not endorsed by, nor do they necessarily reflect, the opinions of the Softpanorama society. We do not warrant the correctness of the information provided or its fitness for any purpose. The site uses AdSense so you need to be aware of Google privacy policy. You you do not want to be tracked by Google please disable Javascript for this site. This site is perfectly usable without Javascript.

Last modified: March 12, 2019