2ba9dcf408
Change-Id: I3de038439bf0ab5755777c0f4930aec0514f5b63 Signed-off-by: John DeNisco <jdenisco@cisco.com>
294 lines
11 KiB
ReStructuredText
294 lines
11 KiB
ReStructuredText
.. _eventviewer:
|
||
|
||
Event-logger
|
||
============
|
||
|
||
The vppinfra event logger provides very lightweight (sub-100ns)
|
||
precisely time-stamped event-logging services. See
|
||
./src/vppinfra/{elog.c, elog.h}
|
||
|
||
Serialization support makes it easy to save and ultimately to combine a
|
||
set of event logs. In a distributed system running NTP over a local LAN,
|
||
we find that event logs collected from multiple system elements can be
|
||
combined with a temporal uncertainty no worse than 50us.
|
||
|
||
A typical event definition and logging call looks like this:
|
||
|
||
.. code-block:: c
|
||
|
||
ELOG_TYPE_DECLARE (e) =
|
||
{
|
||
.format = "tx-msg: stream %d local seq %d attempt %d",
|
||
.format_args = "i4i4i4",
|
||
};
|
||
struct { u32 stream_id, local_sequence, retry_count; } * ed;
|
||
ed = ELOG_DATA (m->elog_main, e);
|
||
ed->stream_id = stream_id;
|
||
ed->local_sequence = local_sequence;
|
||
ed->retry_count = retry_count;
|
||
|
||
The ELOG\_DATA macro returns a pointer to 20 bytes worth of arbitrary
|
||
event data, to be formatted (offline, not at runtime) as described by
|
||
format\_args. Aside from obvious integer formats, the CLIB event logger
|
||
provides a couple of interesting additions. The "t4" format
|
||
pretty-prints enumerated values:
|
||
|
||
.. code-block:: c
|
||
|
||
ELOG_TYPE_DECLARE (e) =
|
||
{
|
||
.format = "get_or_create: %s",
|
||
.format_args = "t4",
|
||
.n_enum_strings = 2,
|
||
.enum_strings = { "old", "new", },
|
||
};
|
||
|
||
The "t" format specifier indicates that the corresponding datum is an
|
||
index in the event's set of enumerated strings, as shown in the previous
|
||
event type definition.
|
||
|
||
The “T” format specifier indicates that the corresponding datum is an
|
||
index in the event log’s string heap. This allows the programmer to emit
|
||
arbitrary formatted strings. One often combines this facility with a
|
||
hash table to keep the event-log string heap from growing arbitrarily
|
||
large.
|
||
|
||
Noting the 20-octet limit per-log-entry data field, the event log
|
||
formatter supports arbitrary combinations of these data types. As in:
|
||
the ".format" field may contain one or more instances of the following:
|
||
|
||
- i1 - 8-bit unsigned integer
|
||
- i2 - 16-bit unsigned integer
|
||
- i4 - 32-bit unsigned integer
|
||
- i8 - 64-bit unsigned integer
|
||
- f4 - float
|
||
- f8 - double
|
||
- s - NULL-terminated string - be careful
|
||
- sN - N-byte character array
|
||
- t1,2,4 - per-event enumeration ID
|
||
- T4 - Event-log string table offset
|
||
|
||
The vpp engine event log is thread-safe, and is shared by all threads.
|
||
Take care not to serialize the computation. Although the event-logger is
|
||
about as fast as practicable, it's not appropriate for per-packet use in
|
||
hard-core data plane code. It's most appropriate for capturing rare
|
||
events - link up-down events, specific control-plane events and so
|
||
forth.
|
||
|
||
The vpp engine has several debug CLI commands for manipulating its event
|
||
log:
|
||
|
||
.. code-block:: console
|
||
|
||
vpp# event-logger clear
|
||
vpp# event-logger save <filename> # for security, writes into /tmp/<filename>.
|
||
# <filename> must not contain '.' or '/' characters
|
||
vpp# show event-logger [all] [<nnn>] # display the event log
|
||
# by default, the last 250 entries
|
||
|
||
The event log defaults to 128K entries. The command-line argument "...
|
||
vlib { elog-events nnn } ..." configures the size of the event log.
|
||
|
||
As described above, the vpp engine event log is thread-safe and shared.
|
||
To avoid confusing non-appearance of events logged by worker threads,
|
||
make sure to code vlib\_global\_main.elog\_main - instead of
|
||
vm->elog\_main. The latter form is correct in the main thread, but
|
||
will almost certainly produce bad results in worker threads.
|
||
|
||
G2 graphical event viewer
|
||
==========================
|
||
|
||
The G2 graphical event viewer can display serialized vppinfra event logs
|
||
directly, or via the c2cpel tool. G2 is a fine-grained event-log viewer. It's
|
||
highly scalable, supporting O(1e7 events) and O(1e3 discrete display "tracks").
|
||
G2 displays binary data generated by the vppinfra "elog.[ch]" logger component,
|
||
and also supports the CPEL file format, as described in this section.
|
||
|
||
Building
|
||
--------------
|
||
|
||
.. code-block:: console
|
||
|
||
$ cd build-root
|
||
$ make g2-install
|
||
$ ./install-native/g2/bin/g2 --help
|
||
g2 [--ticks-per-us <value>][--cpel-input <filename>] [--clib-input <filename]>
|
||
G2 (x86_64 GNU/Linux) major version 3.0
|
||
Built Wed Feb 3 10:58:12 EST 2016
|
||
|
||
Setting the Display Preferences
|
||
------------------------------------------------
|
||
|
||
The file $<*HOMEDIR*>/.g2 contains display preferences, which can be overridden.
|
||
Simply un-comment one of the stanzas shown below, or experiment as desired.
|
||
|
||
.. code-block:: c
|
||
|
||
/*
|
||
* Property / parameter settings for G2
|
||
*
|
||
* Setting for a 1024x768 display:
|
||
* event_selector_lines=20
|
||
* drawbox_height=800
|
||
* drawbox_width=600
|
||
*
|
||
* new mac w/ no monitor:
|
||
* event_selector_lines=20
|
||
* drawbox_height=1200
|
||
* drawbox_width=700
|
||
*
|
||
* 1600x1200:
|
||
* drawbox_width=1200
|
||
* drawbox_height=1000
|
||
* event_selector_lines=25
|
||
*
|
||
* for making screenshots on a Macbook Pro
|
||
* drawbox_width=1200
|
||
* drawbox_height=600
|
||
* event_selector_lines=20
|
||
*/
|
||
|
||
Screen Taxonomy
|
||
----------------------------
|
||
|
||
Here is an annotated G2 viewer screenshot, corresponding to activity during BGP
|
||
prefix download. This data was captured on a Cisco IOS-XR system:
|
||
|
||
.. figure:: /_images/g21.jpg
|
||
:scale: 75%
|
||
|
||
|
||
The viewer has two main scrollbars: the horizontal axis scrollbar shifts the main
|
||
drawing area in time; the vertical axis changes the set of visible process traces.
|
||
The zoomin / zoomout operators change the time scale.
|
||
|
||
The event selector PolyCheckMenu changes the set of displayed events.
|
||
Using these tools -- and some patience -- you can understand a given event log.
|
||
|
||
Mouse Gestures
|
||
-------------------------
|
||
|
||
G2 has three fairly sophisticated mouse gesture interfaces, which are worth describing
|
||
in detail. First, a left mouse click on a display event pops up a per-event detail box.
|
||
|
||
.. figure:: /_images/g22.jpg
|
||
:scale: 75%
|
||
|
||
A left mouse click on an event detail box closes it.
|
||
To zoom to a region of the display, press and hold the left mouse button, then drag
|
||
right or left until the zoom-fence pair appears:
|
||
|
||
.. figure:: /_images/g23.jpg
|
||
:scale: 75%
|
||
|
||
When the zoom operation completes, the display is as follows:
|
||
|
||
.. figure:: /_images/g24.jpg
|
||
|
||
A click on any of the figures will show them at full resolution, right-click will open figures in new tabs,
|
||
|
||
Time Ruler
|
||
------------------
|
||
|
||
To use a time ruler, press and hold the right mouse button; drag right or left
|
||
until the ruler measures the region of interest. If the time axis scale is coarse,
|
||
event boxes can have significant width in time, so use a "reference point" in
|
||
each event box when using the time ruler.
|
||
|
||
.. figure:: /_images/g25.jpg
|
||
:scale: 75%
|
||
|
||
Event Selection
|
||
-------------------------
|
||
|
||
Changing the Event Selector setup controls the set of points displayed in an
|
||
obvious way. Here, we suppress all events except "this thread is now running on the CPU":
|
||
|
||
.. figure:: /_images/g26.jpg
|
||
:scale: 75%
|
||
|
||
Same setup, with all events displayed:
|
||
|
||
.. figure:: /_images/g27.jpg
|
||
:scale: 75%
|
||
|
||
Note that event detail boxes previously shown, but suppressed due to deselection
|
||
of the event code will reappear when one reselects the event code. In the example
|
||
above, the "THREAD/THREADY pid:491720 tid:12" detail box appears in this fashion.
|
||
|
||
Snapshot Ring
|
||
-----------------------
|
||
|
||
Three buttons in lower left-hand corner of the g2 main window control the snapshot
|
||
ring. Snapshots are simply saved views: maneuver the viewer into an "interesting"
|
||
configuration, then press the "Snap" button to add a snapshot to the ring.
|
||
|
||
Click **Next** to restore the next available snapshot. The **Del** button deletes the current snapshot.
|
||
|
||
See the hotkey section below for access to a quick and easy method to save and
|
||
restore the snapshot ring. Eventually we may add a safe/portable/supported mechanism
|
||
to save/restore the snapshot ring from CPEL and vppinfra event log files.
|
||
|
||
Chasing Events
|
||
------------------------
|
||
|
||
Event chasing sorts the trace axis by occurrence of the last selected event. For
|
||
example, if one selects an event which means "thread running on the CPU" the first
|
||
N displayed traces will be the first M threads to run (N <= M; a thread may run
|
||
more than once. This feature addresses analytic problems caused by the finite size of the drawing area.
|
||
|
||
In standard (NoChaseEvent) mode, it looks like only BGP threads 5 and 9 are active:
|
||
|
||
.. figure:: /_images/g28.jpg
|
||
:scale: 75%
|
||
|
||
After pressing the ChaseEvent button, we see a different picture:
|
||
|
||
.. figure:: /_images/g29.jpg
|
||
:scale: 75%
|
||
|
||
Burying Boring Tracks
|
||
-----------------------------------
|
||
|
||
The sequence <ctrl><left-mouse-click> moves the track under the mouse to the end
|
||
of the set of tracks, effectively burying it. The sequence <shift><left-mouse-click>
|
||
moves the track under the mouse to the beginning of the set of tracks. The latter
|
||
function probably isn't precisely right--I think we may eventually provide an "undo"
|
||
stack to provide precise thread exhumation.
|
||
|
||
Summary Mode
|
||
-------------------------
|
||
|
||
Summary mode declutters the screen by rendering events as short vertical line
|
||
segments instead of numbered boxes. Event detail display is unaffected. G2 starts
|
||
in summary mode, zoomed out sufficiently for all events in the trace to be displayed.
|
||
Given a large number of events, summary mode reduces initial screen-paint time to a
|
||
tolerable value. Once you've zoomed in sufficiently, type "e" - enter event mode,
|
||
to enable boxed numeric event display.
|
||
|
||
Hotkeys
|
||
-------------
|
||
|
||
G2 supports the following hotkey actions, supposedly (circa 1996) Quake-like
|
||
according to the feature's original author:
|
||
|
||
+----------------------+--------------------------------------------------------+
|
||
| Key | Function |
|
||
+======================+========================================================+
|
||
| w | Zoom-in |
|
||
+----------------------+--------------------------------------------------------+
|
||
| s | Zoom-out |
|
||
+----------------------+--------------------------------------------------------+
|
||
| a | Scroll Left |
|
||
+----------------------+--------------------------------------------------------+
|
||
| d | Scroll Right |
|
||
+----------------------+--------------------------------------------------------+
|
||
| e | Toggle between event and summary-event mode |
|
||
+----------------------+--------------------------------------------------------+
|
||
| p | Put (write) snapshot ring to snapshots.g2 |
|
||
+----------------------+--------------------------------------------------------+
|
||
| l | Load (read) snapshot ring from snapshots.g2 |
|
||
+----------------------+--------------------------------------------------------+
|
||
| <ctrl>-q | quit |
|
||
+----------------------+--------------------------------------------------------+
|