Previous | Contents | Index |
Once you have used the Event Logger, you will find that it generates a large volume of information to be analyzed. Discard any unneeded log files, since the Event Logger will continue to record information in the files, enlarging them until the disk is full.
To help reduce the generation of unwanted information, you can use the -trace options to enable event logging on only a subset of events. That is, rather than specifying the all option, specify only calls or only context_handles. The subset you specify will depend on the part of your application you are debugging. Because the -trace option provides logging control on a per-compilation basis, the interface must be rebuilt to enable or disable logging of different event types. The -trace options offer the ability to select different event types for the various IDL interfaces that may make up a single application.
You can use the -trace option to request logging of a single type of event, such as errors, with a command similar to the following:
$ idl binopwk.idl -trace errors |
You can also use the -trace option to request logging of multiple event types, such as errors and calls as shown below:
$ idl binopwk.idl -trace errors -trace calls |
This command enables the Event Logger, specifying error and call event logging.
To enable event logging to trace the execution of RPC calls within a process, perform the following steps:
$ idl binopwk.idl -trace all |
$ RPC_LOG_FILE == "server.log" |
$ RPC_LOG_FILE == "" |
$ RPC_LOG_FILE == "client.log" |
$ RPC_LOG_FILE == "" |
Now you can invoke the client and server processes. The event log will
be recorded in the specified file or displayed on your screen when you
execute the application.
17.2.3 Combining Event Logs
Although event logs are generated locally for each process, you can combine event log files to provide a broader view of application execution.
Note that this section does not give examples of each step in the application development process.
The syntax of a merge command is as follows:
$ merge server-filename.log, client-filename. log client_and_server-filename.log |
If two events have the same timestamp, you receive a warning message after the merge is completed.
The following example illustrates how to merge logs from two different systems:
$ idl fpe_server.idl -trace calls -trace errors $ RPC_LOG_FILE == "server.log" $ server |
$ idl fpe_client.idl -trace calls -trace errors $ RPC_LOG_FILE == "client.log" $ client |
1993-03-03:20:37.170-5:00I0.121 murp:17924/15 fpe.setup log_start <DATA> 1993-03-03:20:37.170-5:00I0.121 murp:17924/15 RPC LogMgrlistening <DATA> 1993-03-03:20:37.180-5:00I0.121 murp:17924/15 fpe.setup activate <DATA> 1993-03-03:20:37.180-5:00I0.121 murp:17924/15 fpe.setup terminate <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 fpe.float <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 transmit_fault <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 fpe.float terminate <DATA> |
1993-03-03:20:37.850-5:00I0.121 ifdef:28168/1 fpe.stup log_start <DATA> 1993-03-03:20:37.880-5:00I0.121 ifdef:28168/1 fpe.stup call_start <DATA> 1993-03-03:20:37.190-5:00I0.121 ifdef:28168/1 fpe.stup call_end <DATA> 1993-03-03:20:37.190-5:00I0.121 ifdef:28168/1 fpe.flt call_start <DATA> 1993-03-03:20:37.210-5:00I0.121 ifdef:28168/1 receive_fault <DATA> 1993-03-03:20:37.210-5:00I0.121 ifdef:28168/1 call_failure <DATA> |
$ merge server.log,client.log client_and_server.log |
1993-03-03:20:37.850-5:00I0.121 ifdef:28168/1 fpe.setup log_start <DATA> 1993-03-03:20:37.880-5:00I0.121 ifdef:28168/1 fpe.setup call_start<DATA> 1993-03-03:20:37.170-5:00I0.121 murp:17924/15 fpe.setup log_start <DATA> 1993-03-03:20:37.170-5:00I0.121 murp:17924/15 RPC LogMgrlistening <DATA> 1993-03-03:20:37.180-5:00I0.121 murp:17924/15 fpe.setup terminate <DATA> 1993-03-03:20:37.190-5:00I0.121 ifdef:28168/1 fpe.setup call_end <DATA> 1993-03-03:20:37.190-5:00I0.121 ifdef:28168/1 fpe.float call_start<DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 fpe.float activate <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 fpe.float exception <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 transmit_fault <DATA> 1993-03-03:20:37.200-5:00I0.121 murp:17924/15 fpe.float terminate <DATA> 1993-03-03:20:37.210-5:00I0.121 ifdef:28168/1 receive_fault <DATA> 1993-03-03:20:37.210-5:00I0.121 ifdef:28168/1 call_failure <DATA> |
For the merged output to be accurate, the system clocks on all hosts on which event logs are generated must be closely synchronized. The Distributed Time Service (DTS) component of Digital's DCE provides such a service. Once the clocks are synchronized, the ordering of events in a merged log file is valid only if the difference between timestamps made on different machines is greater than the inaccuracy field in those timestamps. (See the DTS documentation for more information about timestamps.)
In the preceding client_and_server.log file example, consider the event with the timestamp 1993-03-03:20:37:03.180-5:00I0.121 and the event that follows it (these two event lines are separated from the rest of the log by a blank line before and after). Note that the timestamps indicate that the terminate event precedes the call_end event.
However, you cannot determine this sequence of events by comparing
timestamps because the inaccuracy value at the end of the timestamp is
greater than the difference between the timestamps. That is, the
difference in time between these events is only 10 milliseconds (the
difference between 180 and 190 milliseconds). However, the inaccuracy
in the timestamps is 121 milliseconds (I0.121). Therefore, the log is
not a definitive indicator of which event occurred first. Because of
the simplicity of the example and the single thread of control, you can
assume that the terminate event preceded the call_end
event.
17.2.4 Disabling Event Logging
To disable event logging, compile your interface without specifying the -trace option. For example:
$ idl binopwk.idl |
In addition to the -trace options, the Event Logger offers two other methods for controlling information in the event log. Each facility is advantageous in different circumstances, depending on the type of processes with which you are working and the type of events you need to log. The two methods are as follows:
The following sections provide detailed descriptions of how to use each
of these methods to control the type of events logged.
17.3.1 Controlling Logged Events with a Symbol
One way to control the type of events logged is by assigning the symbol RPC_EVENTS. This method is ideal for an application that contains a single RPC interface because a symbol provides control at the process level, rather than at the interface-by-interface level. However, to enable the symbol you must first stop the client or server process.
To use symbols to control event logging, first use the IDL -trace option in your idl compile command and then assign the log file with RPC_LOG_FILE. You can then use the symbol RPC_EVENTS to reduce the number of events currently being logged. That is, if you used the -trace errors option to request error event logging, you can subsequently use only the symbol to request logging of errors or none. You cannot use the symbol to increase the number of event types to be logged. To do this, you must recompile the interface with the required -trace options.
The value of RPC_EVENTS is a list of event types separated by commas. The list identifies the event types to be monitored. Valid values are the same as those for -trace (except log_manager). These values are all, none, calls, context, errors, and misc.
An example command line follows:
$ RPC_EVENTS == "calls,errors" |
If the symbol RPC_EVENTS was not assigned, then by default all of the
events specified with the -trace option are written into the
event log.
17.3.2 Controlling Logged Events with the RPC Log Manager
During application development, certain problems occur only after a server has executed some number of calls. Other problems may require more information than anticipated to debug. These problems can be addressed by enabling the RPC Log Manager in your application image. The Log Manager offers a command line interface (rpclm) for manipulating logging operations during application execution. When you use the rpclm command line interface, you need not rebuild your interface or stop and restart your server or client process to manipulate logging operations.
The rpclm command interface commands are shown in Table 17-4.
Command | Description |
---|---|
inquire | Inquire about the currently logged events and determine the name of the active log file. |
log | Specify additional events to log. Valid values are all, none, calls, context, errors, and misc. |
unlog | Disable logging of the specified event types. Valid values are all, none, calls, context, errors, and misc. |
file | Change the output device or file to which events are logged. |
quit | Terminate the rpclm session. |
help | Display a description of rpclm commands. |
Follow these steps to enable the RPC Log Manager to control event logging:
Only string bindings from a listening event can be used to invoke rpclm. |
The rpclm command interface allows you to control event logging parameters from your keyboard. You can use the command interface to reduce the events currently being logged as well as to manipulate logging operations. You can enable or disable logging of different event types (within the set selected with the -trace option), store event logging in a file or display it on the screen, inquire about the current event types being logged, and display the name of the current log file.
The following procedure illustrates how to use the Log Manager:
$ idl binopwk.idl -trace all -trace log_manager |
$ RPC_LOG_FILE == "client.log" |
<TIME> murp:17868/15 RPC LogMgr listening ncacn_ip_tcp:16.31.48[3820] |
$ rpclm "ncacn_ip_tcp:16.31.48.144[3820]" |
rpclm> unlog all Event types: Events logged to terminal rpclm> log calls Event types: call Events logged to terminal |
<TIME> murp:17868/15 RPC Log Mgr log_events none <TIME> murp:17868/15 RPC Log Mgr log_events calls |
The following example illustrates a command dialog between the user and rpclm. The dialog begins when the user specifies a string binding from a listening event to rpclm.
$ rpclm "ncacn_ip_tcp:cltdce[1821]" rpclm> help rpclm Commands: inquire - Display logged events and log filename log - Specify additional events to log unlog - Specify events that should no longer be logged file - Change file into which events are logged quit - Exit log manager rpclm> inquire Event Types: calls Events logged to terminal rpclm> log errors Event Types: calls errors Events logged to terminal rpclm> file server.log Event Types: calls errors Events logged to file 'server.log' rpclm> quit |
In this dialog, the user enters the help command to display the rpclm commands and command descriptions.
The user then enters the inquire command to display the types of events being logged and the log filename. In this example, errors are being logged to the screen.
The user enters the log calls command to specify that the Log Manager should start logging all events relating to calls, in addition to error events.
The user then enters the file command and specifies a filename. This command requests that rpclm change its output device from the terminal screen to a file named server.log.
The user then enters the quit command to terminate the
rpclm session.
17.4 Using the -trace Option, Symbols, and the Log Manager Together
This section describes a few different ways to use the -trace options, symbols, and the Log Manager together. When you are learning to use the Event Logger, one possible approach is to specify all-inclusive event logging with the -trace all IDL compilation option, and then examine the event log to get an understanding of typical output. You can then use the symbol RPC_EVENTS to log only those events needed, such as calls or errors.
In the case of a running process that you do not want to terminate, use a different method. First enable the Event Logger specifying logging of all events, and enable the Log Manager also, as follows:
$ idl filename -trace all -trace log_manager |
Set the event log to display on the screen, as follows:
$ RPC_LOG_FILE == "" |
Then, assign the RPC_EVENTS symbol so it will not log any event types, as follows:
$ RPC_EVENTS == "none" |
With these parameters set, the only event that will be displayed is the listening event once the first call is made to a server interface compiled with the -trace log_manager option. You can then obtain the string binding for the process and use it later, if needed. Once you start the process, if an error occurs, use the string binding to invoke the rpclm command interface and log the needed events. Any rpclm commands issued at this point will modify the RPC_EVENTS symbol assignment. For example, if you assign the symbol RPC_EVENTS to calls and then issue a command to rpclm to log errors, errors as well as calls will be logged.
Once you are familiar with Event Logger output, consider regularly using the command interface to enable or disable subsets of event types as needed.
This section provides an example of common tasks you may need to perform during event logging. In this particular example, a distributed server process provides a mathematical calculation service. The client process passes data to be calculated to the server process. This type of processing often generates exception events such as those in the example event log. That is, some operations are interrupted by floating point overflow and integer division by zero exceptions, as well as others. This example uses rpclm to control logging of a server process; however, rpclm can also be used to control event logging for a client process.
The following processes are shown in three windows: a server process window, a client process window, and an rpclm window.
$ idl server.calc -trace all -trace log_manager |
$ RPC_LOG_FILE == "" $ RPC_EVENTS == "none" $ server ncacn_ip_tcp |
<TIME> murp:17868/15 fpe.setup log_start none <TIME> murp:17868/15 RPC LogMgr listening ncacn_ip_tcp:16.31.48[3820] |
$ client ncacn_ip_tcp 16.31.48.86 [3123] PASS 1 |
$ rpclm "ncacn_ip_tcp:16.31.48.144[3820]" rpclm> inquire Event types: Events logged to terminal rpclm> log errors Event types: errors Events logged to terminal |
$ client ncacn_ip_tcp 16.31.48.86 [3123] PASS 2 |
<TIME> murp:17868/15 RPC Log Mgr log_events errors <TIME> murp:17868/15 fpe.flt_overflw exception Floating point overflow (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_overflow <TIME> murp:17868/15 fpe.flt_underflw exception Floating point underflow (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_underflow <TIME> murp:17868/15 fpe.flt_divbyzer exception Floating point/decimal divide by zero (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_div_by_zero <TIME> murp:17868/15 fpe.dble_overflw exception Floating point overflow (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_overflow <TIME> murp:17868/15 fpe.dble_underflw exception Floating point underflow (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_underflow <TIME> murp:17868/15 fpe.dble_divbyzer exception Floating point/decimal divide by zero (dce/thd) <TIME> murp:17868/15 transmit_fault rpc_s_fault_fp_div_by_zero |
rpclm> unlog all Event types: Events logged to terminal |
Previous | Next | Contents | Index |