This page describes console output format of Polygraph clients and servers. Individual errors, warnings, and other run-time messages are explained elsewhere.

This documentation has been synchronized with Poly 2.1.0.

Polygraph sends status and error messages to the console. Console output can be redirected into a file using the --console option. The amount of information is controoled using the --verb_lvl option.

All messages that can go to the console (they may or may not be addmitted based on the current verbosity level) are also logged.

Request and reply dumps are not send to the console but are rather printed to the standard output stream. Errors that are not caught by polygraph are dumped to the standard error stream. Standard streams are also redirected, but are not logged. This behavior may change in the future versions of Polygraph.

Exsessive printing to the Console during a production test is a bad idea as it is likely to affect performance.

There are more console messages than is described on this page. Hopefully, most messages that are left out are self-explanatory. Please let us know if some message requires further documentation.

Below is a copy of client console output with some lines snipped. A letter-link on the left points to the description of the corresponding output section. Note that a high verbosity level is required to get all the output presented here.

pail> ./polyclt --config /tmp/my-simple.pg --verb_lvl 5 ...

000.00| Command: ./polyclt --config /tmp/simple.pg --verb_lvl 5 ...
000.00| Configuration:
	version:            2.1.H
	host_type:          i386-unknown-freebsd3.1
	verb_lvl:           5
	prn_reqs:           off
...
	proxy:              10.0.1.253:3128
	ports:              <none>
	ign_false_hits:     on
	prn_false_misses:   off

000.00| Phases:
     phase load_beg load_end     goal		 flags
      dflt     1.00     1.00 <none>

000.00| FDs: 12288 out of 12288 FDs can be used; safeguard limit: 11906
000.00| run-id: 01801f37.045eced8:00000004 pid: 52952
000.00| current time: Thu, 16 Sep 1999 22:04:52 GMT
000.00| waiting for traffic

000.01| agent `R101' starting on 10.0.0.1
000.09| i-dflt     23   4.52    196   0.00   0   1
000.17| i-dflt     48   5.00    199   0.00   0   1
000.25| i-dflt     73   5.00    199   0.00   0   1
000.34| i-dflt     98   5.00    198   0.00   0   1
000.42| i-dflt    125   5.40    185   0.00   0   1
...
001.92| i-dflt    649   5.60    178   0.00   0   1
002.00| i-dflt    677   5.60    178   0.00   0   1
002.09| i-dflt    704   5.40    185   0.00   0   1
002.11| Connection.cc:183: error: 1/1 (60) Operation timed out
002.17| i-dflt    730   5.20    198   0.00   1   1
002.25| i-dflt    754   4.80    200   0.00   0   1

^Cgot shutdown signal (2)
002.26| noticed shutdown signal (2)
002.26| got 755 xactions and 1 errors
002.26| shutdown reason: got shutdown signal

Most lines are prefixed with a timestamp (minutes since experiment start). Note that polygraph may not update its internal clock before printing a line so timestamps are approximate.

Section A

Polyclt output starts with Section A. The first section includes the repeat of the command line used to start polygraph and the dump of all option values for the current run.

If an option is explicitly given on the command line, the command line value will usually be honored and preserved. Other options will have their default values. Note that some defaults depend on other options.

The configuration dump at the beginning of a run does not define Polygraph behavior completely because most workload specs are in the configuration file. Given the same configuration file and the same options, Polygraph will produce the same kind of traffic. Note, however, that the same traffic may produce different results depending on the past history (e.g., a proxy used up all free disk space at the end of the previous run). Also, system imposed limits may affect Polygraph behavior.

After the options dump, Polygraph reports execution schedule using phases. For each phase, its name, load levels, ``goal'', and special flags are printed. In our case, we had a single and very simple default phase with constant (maximum) load level and no goal or flags.

After the phases schedule, Polygraph dumps some system limits:

• first 12288 FDs: Available number of FDs as reported by the setrlimit(RLIMIT_NOFILE) system call. Polygraph attempts to set current (soft) limit to maximum (hard) limit and then reports how many file descriptors OS allowed us to use.

• second 12288 FDs: Maximum number of FDs as reported by the getrlimit(RLIMIT_NOFILE) system call. If this value is higher than available number of FDs, then OS did not allow Polygraph to raise current (soft) limit hight enough.

• safeguard limit: Approximate number of FDs that Polygraph will allow itself to use. See the --fd_limit option for details.

At the bottom of Section A, Polygraph prints run id, process id, and current time. The run id is meant to be unique across all executions of Polygraph within a few years.

Section B

Section B represents run-time statistics. Run-time stats are usually printed in a table-like form. We describe the columns of that table in a separate section below.

Section B also contains an error message. The format for error messages is described below in a separate section.

Section C

Finally, Section C contains some statistics for the entire run. The output also includes the reason for run termination.

(1)    (2) (3)    (4)    (5)    (6)    (7)  (8) (9)
000.09| i-dflt     23   4.52    196   0.00   0   1
000.17| i-dflt     48   5.00    199   0.00   0   1
000.25| i-dflt     73   5.00    199   0.00   0   1
000.34| i-dflt     98   5.00    198   0.00   0   1
000.42| i-dflt    125   5.40    185   0.00   0   1

Here is a brief explanation for each column of the run-time stats output.

1. Minutes since start
2. "i-" and "p-" stand for Interval and Phase Stats
3. phase name
4. number of replies received so far (across all phases)
5. reply rate (replies per second)
6. mean response time in milliseconds (Poly 2.x and up);
   (this column is not present in earlier Polygraph versions)
7. hit ratio in percents (client side);
   nothing interesting on the server side yet
8. number of transaction errors during that interval or phase
   (note: not all errors are transaction errors)
9. number of open sockets, including UDP and other housekeeping sockets if any;
   this number is usually close to the number of pending transactions;
   (Interval Stats only!)

Individual errors, warnings, and other run-time messages are explained elsewhere.

Polygraph counts all errors it detects. However, Poly uses an exponential back-off algorithm when reporting errors on the console. Typically, only the following error occurrences will appear on a console: 1-st, 2-nd, 3-rd, 7-th, 15-th, ...

  (1)               (2)          (3/4) (5)            (6)
002.11| Connection.cc:183: error: 1/1 (60) Operation timed out

An explanation for each column of a typical run-time error output follows.

1. Timestamp.
2. Source code location if available.
3. Number of errors of this type so far.
4. Total number of errors so far.
5. Error code. The code corresponds to the errno value on your machine. Error codes above 255 are custom errors detected by Polygraph rather than by OS (e.g., ``false hit'' or ``foreign reply'').
6. Short textual description of the error.

In some cases, Polygraph may decide to print more than one line per error to provide a longer, more detailed description.

N.B. To be honest, we faked the error message for the purpose of showing at least some errors. If we put some stats in the example out of sync, please let us know.

Server console output is pretty much the same as the client output described above. With the following exceptions:

• Hit ratios are not measured and hence, not reported on the server side. The i- and p- lines have -1.00 in the hit ratio field for now.