Difference between revisions of "VPP/elog"

Revision as of 13:42, 25 May 2016

Introduction

The vppinfra event logger provides very lightweight (sub-100ns), precisely time-stamped event-logging services. 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.

Examples

A typical event definition and a related log entry creation sequence looks like this:

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 vppinfra event logger provides a couple of interesting additions. The “t4” format shown below pretty-prints one of the enumerated values:

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.

Format details

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

Using the event logger in the vpp engine

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:

vpp# clear event-logger
vpp# save event-logger <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.

Finding the required elog_main_t

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 use &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.

Worker-thread tracks

Each worker thread has its own pre-populated elog "trace" or "track". See the g2 viewer writeup for a picture of how multiple traces / tracks will be shown there.

Here's how to log an event to the current worker thread's trace / track:

vlib_worker_thread_t * w = vlib_worker_threads + vm->cpu_index;

d = ELOG_TRACK_DATA (&vlib_global_main.elog_main, e, w->elog_track);

Of course, you can create as many tracks as you need for visualization purposes. The g2 viewer supports at least O(1e3) tracks; the main limit turns out to be the user's ability to understand data displayed on an arbitrary number of tracks. Use the elog_register_track(...) API to create tracks.

String Table Manipulation

Here's a hash-table plus elog string table optimization scheme, suitable for optimizing the size of the event-log string table. It's reasonably common when logging arbitrarily-formatted strings to discover that there are thousands of instances of perhaps ten strings. Although the scheme shown here won't reduce the runtime involved to zero, it can be very helpful in reducing both time and space required to log arbitrary strings:

static u32 elog_id_for_string (my_main_t * m, u8 *string)
{
    uword * p, r;
    uword * h = m->elog_id_for_string;
    u8 *name_copy;

    if (! h)
        h = m->elog_id_for_string
            = hash_create_string (0, sizeof (uword));

    p = hash_get_mem (h, string);
    if (p)
        return p[0];
    r = elog_string (m->elog_main, "%s", string);
 
    name_copy = format (0, "%s%c", string, 0);
 
    hash_set_mem (h, string, r);
    m->elog_id_for_string = h;

    return r;
}

   if (EVENT_LOGGING > 0) {
       ELOG_TYPE_DECLARE (e) = {
           .format = "arbitrary string: %s",
           .format_args = "T4",
       };
       struct { u32 s_id; } * ed;
       ed = ELOG_DATA (m->elog_main, e);
       ed->s_id = elog_id_for_string (m, <arbitrary-string>);
     }

Dbarach (talk) 17:13, 29 February 2016 (UTC)

Dave Barach's slides at FD.io DevBoot April 2016 San Jose