Viewing VU Event Logs

The Eggplant Performance Test Controller VU event log contains information about the progress of each virtual user (VU). Every VU has its own event log, which you can view in real-time (unless event logging is disabled in Eggplant Performance Studio). Most Virtual User API methods output some information to this log, and you can write to it directly from within a script using the writeMessage() method.

Reading the Log

You open a VU event log in Test Controller's main window just like you would any table or chart. To open the event log viewer for a specific VU, navigate to the VU in the Current test runs section of the left sidebar, then double-click the VU (or right-click the VU and select Open).

The virtual user event log viewer in Eggplant Performance Test Controller

Following is an explanation of how to read logs in the event log viewer, by column:

• Time: The elapsed time since the test run started. Every entry written to the event log is labeled with a timestamp that specifies when the engine encountered the event, so you can tell how far into the test run the event occurred. This is written to the nearest millisecond in the format HH:MM:SS:MSS.
• Type: Events are grouped according to their log type. Following is a list of common groups. See Common Groups and Events below for more information about each of them.
  • Test initialization & progression
  • Transactions
  • Timings
  • VU status & information
  • Check / progress point
• ID: Information specific to the event type.
• Info: Detailed information about the event.
• Thread ID: Indicates whether events were written by the main script or a background script.

Log Filtering Options

The event log viewer lets you filter the information you see in the log. Click the Filter button to see several filter options for you to choose from:

• Default - shows the most common log entries
• All - shows all entries in the log
• Custom - individually select or deselect the entry types to show in the log:
  • Transactions
  • Timings
  • Requests
  • Errors
  • Warnings
  • Messages
  • Metrics
  • Progress Points

Common Log Groups and Events

Following is a list of common log type groups and their events.

note

References to API methods vary depending on the script language used; use the tabs below to toggle between them.

Java

Test initialization and progression

Type	Description	ID	Info
Start	The time of test run initialization. This event is written in all logs. A VU will be in a Pending state until the Start activity event. The Pending state between Start and Start activity is usually because of VU "ramp up" or group start delay.	Empty	Empty
Start activity	When the VU progresses from a Pending to a Running state and begins script code execution.	Empty	Empty
Current script	The start of script execution - usually several scripts are executed within a workflow. If the VU is in the iterated section of a workflow, the Info column contains the iteration number (starting at zero).	Script name	Iteration number, or empty
End Activity	When the VU progresses from a Running to a Completed state.	Empty	Empty
End	Test run completion. If the VU is in the In Error state, the ID column will contain Fail. This can be caused by unhandled errors in the script, maximum failed iterations exceeded, or by passing false to exitVU().	Pass or Fail	Completed, Error, or a string passed to exitVU()

note

The exitVU() method can be useful to make a Virtual User finish early. By default it writes Pass and Completed to the log, but you can pass parameters to cause the VU to write Fail and be in the In Error state, and/or to write your own message in the Info column.

Transactions

All the Virtual User methods dealing with transactions take a transaction identifier (id) as a parameter - this appears in the ID column of the VU event log. The id passed to the startTransaction() method must match the id passed to any subsequent methods which affect that transaction, e.g. suspendTransaction() or endTransaction().

info

The transaction identifier is also commonly referred to as the transaction name.

Some methods may also take a tag parameter - this appears in the Info column of the VU event log and doesn't have to match.

Type	Description	ID	Info
Start transaction	Written when startTransaction() is called in the VU script.	Transaction identifier	Tag (optional)
Suspend transaction	suspendTransaction() can be used to exclude lengthy processing operations from being recorded in transaction timings.	Transaction identifier	Empty
Resume transaction	resumeTransaction() restarts timing after it has been suspended.	Transaction identifier	Empty
End transaction	The transaction end time is written when endTransaction() is called in the VU script. The difference between the times (minus any suspended time) is calculated as the transaction response time, or duration.	Transaction identifier	Tag (optional)
Fail transaction	Used to exclude a transaction from analysis or increase the failed transaction count for a VU group. This happens when calling failTransaction() or by setting the bool pass parameter of endTransaction() to false. This is particularly useful when there is a necessity to work with nested/overlapping transactions for applications that use asynchronous messaging.	Transaction identifier	Tag (optional)

Timings

All the Virtual User methods dealing with timings take a timing identifier_ (id) as a parameter - this appears in the ID column of the VU event log. The id passed to the startTiming() method must match the id passed to any subsequent methods which affect that timing, e.g. endTiming().

info

The timing identifier is also commonly referred to as the timing name.

Type	Description	ID	Info
Start timing	Written when startTiming() is called in the VU script. Some VU types write additional timings, most notably the Web VU types which may write timings for each HTTP request.	Timing identifier	Empty
End timing	The timing end time is written when endTiming() is called in the VU script. The difference between the times is calculated as the timing duration.	Timing identifier	Empty
Fail timing	Used to exclude a timing from analysis. This happens when calling failTiming() in the VU script.	Timing identifier	Empty

VU status and information

Type	Description	ID	Info
Error	Logged in the following circumstances: Calling error() in the VU script Unhandled exceptions within VU script code Using the error action type ACT_ERROR in the various verification methods of WebBrowserUserScript	Empty	Error message
Warning	Logged in the following circumstances: Calling warn() in the VU script 404 Not Found status codes received by Web VUs Using the warning action type ACT_WARNING in the various verification methods of WebBrowserUserScript	Empty	Warning message
Message	Logged by calling writeMessage() in the VU script. Various other information messages from Test Controller and the injector/engine may appear in the VU event log.	Empty	Info message

Progress points

In Test Controller and Analyzer it is possible to see the number of progress points passed/failed per VU, per VU group and for the test as a whole. The Virtual Users table in Test Controller also shows, for each Virtual User, the most recent progress point whether passed or failed.

Type	Description	ID	Info
Pass	Written when setProgressPoint() is called with the pass parameter set to true	Progress point name	info parameter to setProgressPoint(), or empty
Fail	Written when setProgressPoint() is called with the pass parameter set to false	Progress point name	info parameter to setProgressPoint(), or empty

C#

Test initialization and progression

Type	Description	ID	Info
Start	The time of test run initialization. This event is written in all logs. A VU will be in a Pending state until the Start activity event. The Pending state between Start and Start activity is usually because of VU "ramp up" or group start delay.	Empty	Empty
Start activity	When the VU progresses from a Pending to a Running state and begins script code execution.	Empty	Empty
Current script	The start of script execution - usually several scripts are executed within a workflow. If the VU is in the iterated section of a workflow, the Info column contains the iteration number (starting at zero).	Script name	Iteration number, or empty
End Activity	When the VU progresses from a Running to a Completed state.	Empty	Empty
End	Test run completion. If the VU is in the In Error state, the ID column will contain Fail. This can be caused by unhandled errors in the script, maximum failed iterations exceeded, or by passing false to ExitVU().	Pass or Fail	Completed, Error, or a string passed to ExitVU()

note

The ExitVU() method can be useful to make a Virtual User finish early. By default it writes Pass and Completed to the log, but you can pass parameters to cause the VU to write Fail and be in the In Error state, and/or to write your own message in the Info column.

Transactions

All the Virtual User methods dealing with transactions take a transaction identifier (id) as a parameter - this appears in the ID column of the VU event log. The id passed to the StartTransaction() method must match the id passed to any subsequent methods which affect that transaction, e.g. SuspendTransaction() or EndTransaction().

info

The transaction identifier is also commonly referred to as the transaction name.

Some methods may also take a tag parameter - this appears in the Info column of the VU event log and doesn't have to match.

Type	Description	ID	Info
Start transaction	Written when StartTransaction() is called in the VU script.	Transaction identifier	Tag (optional)
Suspend transaction	SuspendTransaction() can be used to exclude lengthy processing operations from being recorded in transaction timings.	Transaction identifier	Empty
Resume transaction	ResumeTransaction() restarts timing after it has been suspended.	Transaction identifier	Empty
End transaction	The transaction end time is written when EndTransaction() is called in the VU script. The difference between the times (minus any suspended time) is calculated as the transaction response time, or duration.	Transaction identifier	Tag (optional)
Fail transaction	Used to exclude a transaction from analysis or increase the failed transaction count for a VU group. This happens when calling FailTransaction() or by setting the bool pass parameter of EndTransaction() to false. This is particularly useful when there is a necessity to work with nested/overlapping transactions for applications that use asynchronous messaging.	Transaction identifier	Tag (optional)

Timings

All the Virtual User methods dealing with timings take a timing identifier_ (id) as a parameter - this appears in the ID column of the VU event log. The id passed to the StartTiming() method must match the id passed to any subsequent methods which affect that timing, e.g. endTiming().

info

The timing identifier is also commonly referred to as the timing name.

Type	Description	ID	Info
Start timing	Written when StartTiming() is called in the VU script. Some VU types write additional timings, most notably the Web VU types which may write timings for each HTTP request.	Timing identifier	Empty
End timing	The timing end time is written when EndTiming() is called in the VU script. The difference between the times is calculated as the timing duration.	Timing identifier	Empty
Fail timing	Used to exclude a timing from analysis. This happens when calling FailTiming() in the VU script.	Timing identifier	Empty

VU status and information

Type	Description	ID	Info
Error	Logged in the following circumstances: Calling Error() in the VU script Unhandled exceptions within VU script code Using the error action type ACT_ERROR in the various verification methods of WebBrowserUserScript	Empty	Error message
Warning	Logged in the following circumstances: Calling Warn() in the VU script 404 Not Found status codes received by Web VUs Using the warning action type ACT_WARNING in the various verification methods of WebBrowserUserScript	Empty	Warning message
Message	Logged by calling WriteMessage() in the VU script. Various other information messages from Test Controller and the injector/engine may appear in the VU event log.	Empty	Info message

Progress points

In Test Controller and Analyzer it is possible to see the number of progress points passed/failed per VU, per VU group and for the test as a whole. The Virtual Users table in Test Controller also shows, for each Virtual User, the most recent progress point whether passed or failed.

Type	Description	ID	Info
Pass	Written when SetProgressPoint() is called with the pass parameter set to true	Progress point name	info parameter to SetProgressPoint(), or empty
Fail	Written when SetProgressPoint() is called with the pass parameter set to false	Progress point name	info parameter to SetProgressPoint(), or empty