diff options
Diffstat (limited to 'docs/developer/corefeatures/eventviewer.rst')
| -rw-r--r-- | docs/developer/corefeatures/eventviewer.rst | 286 |
1 files changed, 286 insertions, 0 deletions
diff --git a/docs/developer/corefeatures/eventviewer.rst b/docs/developer/corefeatures/eventviewer.rst new file mode 100644 index 00000000000..21d5fa95275 --- /dev/null +++ b/docs/developer/corefeatures/eventviewer.rst @@ -0,0 +1,286 @@ +.. _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 G2 +~~~~~~~~~~~ + +This link describes :ref:`how to build G2 <building-g2>` + +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 | ++----------------------+--------------------------------------------------------+ |