docs/gettingstarted/developers/eventviewer.rst

   1 .. _eventviewer:
   2
   3 Event-logger
   4 ============
   5
   6 The vppinfra event logger provides very lightweight (sub-100ns)
   7 precisely time-stamped event-logging services. See
   8 ./src/vppinfra/{elog.c, elog.h}
   9
  10 Serialization support makes it easy to save and ultimately to combine a
  11 set of event logs. In a distributed system running NTP over a local LAN,
  12 we find that event logs collected from multiple system elements can be
  13 combined with a temporal uncertainty no worse than 50us.
  14
  15 A typical event definition and logging call looks like this:
  16
  17 .. code-block:: c
  18
  19     ELOG_TYPE_DECLARE (e) =
  20     {
  21       .format = "tx-msg: stream %d local seq %d attempt %d",
  22       .format_args = "i4i4i4",
  23     };
  24     struct { u32 stream_id, local_sequence, retry_count; } * ed;
  25     ed = ELOG_DATA (m->elog_main, e);
  26     ed->stream_id = stream_id;
  27     ed->local_sequence = local_sequence;
  28     ed->retry_count = retry_count;
  29
  30 The ELOG\_DATA macro returns a pointer to 20 bytes worth of arbitrary
  31 event data, to be formatted (offline, not at runtime) as described by
  32 format\_args. Aside from obvious integer formats, the CLIB event logger
  33 provides a couple of interesting additions. The "t4" format
  34 pretty-prints enumerated values:
  35
  36 .. code-block:: c
  37
  38     ELOG_TYPE_DECLARE (e) =
  39     {
  40       .format = "get_or_create: %s",
  41       .format_args = "t4",
  42       .n_enum_strings = 2,
  43       .enum_strings = { "old", "new", },
  44     };
  45
  46 The "t" format specifier indicates that the corresponding datum is an
  47 index in the event's set of enumerated strings, as shown in the previous
  48 event type definition.
  49
  50 The “T” format specifier indicates that the corresponding datum is an
  51 index in the event log’s string heap. This allows the programmer to emit
  52 arbitrary formatted strings. One often combines this facility with a
  53 hash table to keep the event-log string heap from growing arbitrarily
  54 large.
  55
  56 Noting the 20-octet limit per-log-entry data field, the event log
  57 formatter supports arbitrary combinations of these data types. As in:
  58 the ".format" field may contain one or more instances of the following:
  59
  60 -   i1 - 8-bit unsigned integer
  61 -   i2 - 16-bit unsigned integer
  62 -   i4 - 32-bit unsigned integer
  63 -   i8 - 64-bit unsigned integer
  64 -   f4 - float
  65 -   f8 - double
  66 -   s - NULL-terminated string - be careful
  67 -   sN - N-byte character array
  68 -   t1,2,4 - per-event enumeration ID
  69 -   T4 - Event-log string table offset
  70
  71 The vpp engine event log is thread-safe, and is shared by all threads.
  72 Take care not to serialize the computation. Although the event-logger is
  73 about as fast as practicable, it's not appropriate for per-packet use in
  74 hard-core data plane code. It's most appropriate for capturing rare
  75 events - link up-down events, specific control-plane events and so
  76 forth.
  77
  78 The vpp engine has several debug CLI commands for manipulating its event
  79 log:
  80
  81 .. code-block:: console
  82
  83     vpp# event-logger clear
  84     vpp# event-logger save <filename> # for security, writes into /tmp/<filename>.
  85                                       # <filename> must not contain '.' or '/' characters
  86     vpp# show event-logger [all] [<nnn>] # display the event log
  87                                        # by default, the last 250 entries
  88
  89 The event log defaults to 128K entries. The command-line argument "...
  90 vlib { elog-events nnn } ..." configures the size of the event log.
  91
  92 As described above, the vpp engine event log is thread-safe and shared.
  93 To avoid confusing non-appearance of events logged by worker threads,
  94 make sure to code vlib\_global\_main.elog\_main - instead of
  95 vm->elog\_main. The latter form is correct in the main thread, but
  96 will almost certainly produce bad results in worker threads.
  97
  98 G2 graphical event viewer
  99 ==========================
 100
 101 The G2 graphical event viewer can display serialized vppinfra event logs
 102 directly, or via the c2cpel tool. G2 is a fine-grained event-log viewer. It's
 103 highly scalable, supporting O(1e7 events) and O(1e3 discrete display "tracks").
 104 G2 displays binary data generated by the vppinfra "elog.[ch]" logger component,
 105 and also supports the CPEL file format, as described in this section.
 106
 107 Building
 108 --------------
 109
 110 .. code-block:: console
 111
 112    $ cd build-root
 113    $ make g2-install
 114    $ ./install-native/g2/bin/g2 --help
 115    g2 [--ticks-per-us <value>][--cpel-input <filename>] [--clib-input <filename]>
 116    G2 (x86_64 GNU/Linux) major version 3.0
 117    Built Wed Feb  3 10:58:12 EST 2016
 118
 119 Setting the Display Preferences
 120 ------------------------------------------------
 121
 122 The file $<*HOMEDIR*>/.g2 contains display preferences, which can be overridden.
 123 Simply un-comment one of the stanzas shown below, or experiment as desired.
 124
 125 .. code-block:: c
 126
 127     /*
 128      * Property / parameter settings for G2
 129      *
 130      * Setting for a 1024x768 display:
 131      * event_selector_lines=20
 132      * drawbox_height=800
 133      * drawbox_width=600
 134      *
 135      * new mac w/ no monitor:
 136      * event_selector_lines=20
 137      * drawbox_height=1200
 138      * drawbox_width=700
 139      *
 140      * 1600x1200:
 141      * drawbox_width=1200
 142      * drawbox_height=1000
 143      * event_selector_lines=25
 144      *
 145      * for making screenshots on a Macbook Pro
 146      * drawbox_width=1200
 147      * drawbox_height=600
 148      * event_selector_lines=20
 149      */
 150
 151 Screen Taxonomy
 152 ----------------------------
 153
 154 Here is an annotated G2 viewer screenshot, corresponding to activity during BGP
 155 prefix download. This data was captured on a Cisco IOS-XR system:
 156
 157 .. figure:: /_images/g21.jpg
 158    :scale: 75%
 159
 160
 161 The viewer has two main scrollbars: the horizontal axis scrollbar shifts the main
 162 drawing area in time; the vertical axis changes the set of visible process traces.
 163 The zoomin / zoomout operators change the time scale.
 164
 165 The event selector PolyCheckMenu changes the set of displayed events.
 166 Using these tools -- and some patience -- you can understand a given event log.
 167
 168 Mouse Gestures
 169 -------------------------
 170
 171 G2 has three fairly sophisticated mouse gesture interfaces, which are worth describing
 172 in detail. First, a left mouse click on a display event pops up a per-event detail box.
 173
 174 .. figure:: /_images/g22.jpg
 175    :scale: 75%
 176
 177 A left mouse click on an event detail box closes it.
 178 To zoom to a region of the display, press and hold the left mouse button, then drag
 179 right or left until the zoom-fence pair appears:
 180
 181 .. figure:: /_images/g23.jpg
 182    :scale: 75%
 183
 184 When the zoom operation completes, the display is as follows:
 185
 186 .. figure:: /_images/g24.jpg
 187
 188 A click on any of the figures will show them at full resolution, right-click will open figures in new tabs,
 189
 190 Time Ruler
 191 ------------------
 192
 193 To use a time ruler, press and hold the right mouse button; drag right or left
 194 until the ruler measures the region of interest. If the time axis scale is coarse,
 195 event boxes can have significant width in time, so use a "reference point" in
 196 each event box when using the time ruler.
 197
 198 .. figure:: /_images/g25.jpg
 199    :scale: 75%
 200
 201 Event Selection
 202 -------------------------
 203
 204 Changing the Event Selector setup controls the set of points displayed in an
 205 obvious way. Here, we suppress all events except "this thread is now running on the CPU":
 206
 207 .. figure:: /_images/g26.jpg
 208    :scale: 75%
 209
 210 Same setup, with all events displayed:
 211
 212 .. figure:: /_images/g27.jpg
 213    :scale: 75%
 214
 215 Note that event detail boxes previously shown, but suppressed due to deselection
 216 of the event code will reappear when one reselects the event code. In the example
 217 above, the "THREAD/THREADY pid:491720 tid:12" detail box appears in this fashion.
 218
 219 Snapshot Ring
 220 -----------------------
 221
 222 Three buttons in lower left-hand corner of the g2 main window control the snapshot
 223 ring. Snapshots are simply saved views: maneuver the viewer into an "interesting"
 224 configuration, then press the "Snap" button to add a snapshot to the ring.
 225
 226 Click **Next** to restore the next available snapshot. The **Del** button deletes the current snapshot.
 227
 228 See the hotkey section below for access to a quick and easy method to save and
 229 restore the snapshot ring. Eventually we may add a safe/portable/supported mechanism
 230 to save/restore the snapshot ring from CPEL and vppinfra event log files.
 231
 232 Chasing Events
 233 ------------------------
 234
 235 Event chasing sorts the trace axis by occurrence of the last selected event. For
 236 example, if one selects an event which means "thread running on the CPU" the first
 237 N displayed traces will be the first M threads to run (N <= M; a thread may run
 238 more than once. This feature addresses analytic problems caused by the finite size of the drawing area.
 239
 240 In standard (NoChaseEvent) mode, it looks like only BGP threads 5 and 9 are active:
 241
 242 .. figure:: /_images/g28.jpg
 243    :scale: 75%
 244
 245 After pressing the ChaseEvent button, we see a different picture:
 246
 247 .. figure:: /_images/g29.jpg
 248    :scale: 75%
 249
 250 Burying Boring Tracks
 251 -----------------------------------
 252
 253 The sequence <ctrl><left-mouse-click> moves the track under the mouse to the end
 254 of the set of tracks, effectively burying it. The sequence <shift><left-mouse-click>
 255 moves the track under the mouse to the beginning of the set of tracks. The latter
 256 function probably isn't precisely right--I think we may eventually provide an "undo"
 257 stack to provide precise thread exhumation.
 258
 259 Summary Mode
 260 -------------------------
 261
 262 Summary mode declutters the screen by rendering events as short vertical line
 263 segments instead of numbered boxes. Event detail display is unaffected. G2 starts
 264 in summary mode, zoomed out sufficiently for all events in the trace to be displayed.
 265 Given a large number of events, summary mode reduces initial screen-paint time to a
 266 tolerable value. Once you've zoomed in sufficiently, type "e" - enter event mode,
 267 to enable boxed numeric event display.
 268
 269 Hotkeys
 270 -------------
 271
 272 G2 supports the following hotkey actions, supposedly (circa 1996) Quake-like
 273 according to the feature's original author:
 274
 275 +----------------------+--------------------------------------------------------+
 276 | Key                  | Function                                               |
 277 +======================+========================================================+
 278 | w                    | Zoom-in                                                |
 279 +----------------------+--------------------------------------------------------+
 280 | s                    | Zoom-out                                               |
 281 +----------------------+--------------------------------------------------------+
 282 | a                    | Scroll Left                                            |
 283 +----------------------+--------------------------------------------------------+
 284 | d                    | Scroll Right                                           |
 285 +----------------------+--------------------------------------------------------+
 286 | e                    | Toggle between event and summary-event mode            |
 287 +----------------------+--------------------------------------------------------+
 288 | p                    | Put (write) snapshot ring to snapshots.g2              |
 289 +----------------------+--------------------------------------------------------+
 290 | l                    | Load (read) snapshot ring from snapshots.g2            |
 291 +----------------------+--------------------------------------------------------+
 292 | <ctrl>-q             | quit                                                   |
 293 +----------------------+--------------------------------------------------------+