FD.io VPP  v18.01.2-1-g9b554f3
Vector Packet Processing
unix-kelog.c
Go to the documentation of this file.
1 /*
2  Copyright (c) 2010 Cisco and/or its affiliates.
3 
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at:
7  *
8  * http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15 */
16 
17 #include <vppinfra/error.h>
18 #include <vppinfra/unix.h>
19 #include <vppinfra/elog.h>
20 #include <vppinfra/format.h>
21 #include <vppinfra/os.h>
22 
23 #include <sys/types.h>
24 #include <sys/stat.h>
25 #include <fcntl.h>
26 #include <time.h>
27 
28 typedef enum
29 {
30  RUNNING = 0,
33 
34 typedef struct
35 {
37  u8 *task;
42 
43 void
44 kelog_init (elog_main_t * em, char *kernel_tracer, u32 n_events)
45 {
46  int enable_fd, current_tracer_fd, data_fd;
47  int len;
48  struct timespec ts, ts2;
49  char *trace_enable = "/debug/tracing/tracing_enabled";
50  char *current_tracer = "/debug/tracing/current_tracer";
51  char *trace_data = "/debug/tracing/trace";
52  f64 realtime, monotonic;
53  f64 freq, secs_per_clock;
54 
55  ASSERT (kernel_tracer);
56 
57  /*$$$$ fixme */
58  n_events = 1 << 18;
59 
60  /* init first so we won't hurt ourselves if we bail */
61  elog_init (em, n_events);
62 
63  enable_fd = open (trace_enable, O_RDWR);
64  if (enable_fd < 0)
65  {
66  clib_warning ("Couldn't open %s", trace_enable);
67  return;
68  }
69  /* disable kernel tracing */
70  if (write (enable_fd, "0\n", 2) != 2)
71  {
72  clib_unix_warning ("disable tracing");
73  close (enable_fd);
74  return;
75  }
76 
77  /*
78  * open + clear the data buffer.
79  * see .../linux/kernel/trace/trace.c:tracing_open()
80  */
81  data_fd = open (trace_data, O_RDWR | O_TRUNC);
82  if (data_fd < 0)
83  {
84  clib_warning ("Couldn't open+clear %s", trace_data);
85  return;
86  }
87  close (data_fd);
88 
89  /* configure tracing */
90  current_tracer_fd = open (current_tracer, O_RDWR);
91 
92  if (current_tracer_fd < 0)
93  {
94  clib_warning ("Couldn't open %s", current_tracer);
95  close (enable_fd);
96  return;
97  }
98 
99  len = strlen (kernel_tracer);
100 
101  if (write (current_tracer_fd, kernel_tracer, len) != len)
102  {
103  clib_unix_warning ("configure trace");
104  close (current_tracer_fd);
105  close (enable_fd);
106  return;
107  }
108 
109  close (current_tracer_fd);
110 
111  /*
112  * The kernel event log uses CLOCK_MONOTONIC timestamps,
113  * not CLOCK_REALTIME timestamps. These differ by a constant
114  * but the constant is not available in user mode.
115  * This estimate will be off by one syscall round-trip.
116  */
117  clib_time_init (&em->cpu_timer);
119  syscall (SYS_clock_gettime, CLOCK_MONOTONIC, &ts);
120 
121  /* enable kernel tracing */
122  if (write (enable_fd, "1\n", 2) != 2)
123  {
124  clib_unix_warning ("enable tracing");
125  close (enable_fd);
126  return;
127  }
128 
129  close (enable_fd);
130 }
131 
132 
133 u8 *
134 format_sched_event (u8 * s, va_list * va)
135 {
136  sched_event_t *e = va_arg (*va, sched_event_t *);
137 
138  s = format (s, "cpu %d task %10s type %s timestamp %12.6f\n",
139  e->cpu, e->task, e->type ? "WAKEUP " : "RUNNING", e->timestamp);
140 
141  return s;
142 }
143 
145 parse_sched_switch_trace (u8 * tdata, u32 * index)
146 {
147  u8 *cp = tdata + *index;
148  u8 *limit = tdata + vec_len (tdata);
149  int colons;
150  static sched_event_t event;
151  sched_event_t *e = &event;
152  static u8 *task_name;
153  u32 secs, usecs;
154  int i;
155 
156 again:
157  /* eat leading w/s */
158  while (cp < limit && (*cp == ' ' && *cp == '\t'))
159  cp++;
160  if (cp == limit)
161  return 0;
162 
163  /* header line */
164  if (*cp == '#')
165  {
166  while (cp < limit && (*cp != '\n'))
167  cp++;
168  if (*cp == '\n')
169  {
170  cp++;
171  goto again;
172  }
173  clib_warning ("bugger 0");
174  return 0;
175  }
176 
177  while (cp < limit && *cp != ']')
178  cp++;
179 
180  if (*cp == 0)
181  return 0;
182 
183  if (*cp != ']')
184  {
185  clib_warning ("bugger 0.1");
186  return 0;
187  }
188 
189  cp++;
190  while (cp < limit && (*cp == ' ' && *cp == '\t'))
191  cp++;
192  if (cp == limit)
193  {
194  clib_warning ("bugger 0.2");
195  return 0;
196  }
197 
198  secs = atoi (cp);
199 
200  while (cp < limit && (*cp != '.'))
201  cp++;
202 
203  if (cp == limit)
204  {
205  clib_warning ("bugger 0.3");
206  return 0;
207  }
208 
209  cp++;
210 
211  usecs = atoi (cp);
212 
213  e->timestamp = ((f64) secs) + ((f64) usecs) * 1e-6;
214 
215  /* eat up to third colon */
216  for (i = 0; i < 3; i++)
217  {
218  while (cp < limit && *cp != ':')
219  cp++;
220  cp++;
221  }
222  --cp;
223  if (*cp != ':')
224  {
225  clib_warning ("bugger 1");
226  return 0;
227  }
228  /* aim at '>' (switch-to) / '+' (wakeup) */
229  cp += 5;
230  if (cp >= limit)
231  {
232  clib_warning ("bugger 2");
233  return 0;
234  }
235  if (*cp == '>')
236  e->type = RUNNING;
237  else if (*cp == '+')
238  e->type = WAKEUP;
239  else
240  {
241  clib_warning ("bugger 3");
242  return 0;
243  }
244 
245  cp += 3;
246  if (cp >= limit)
247  {
248  clib_warning ("bugger 4");
249  return 0;
250  }
251 
252  e->cpu = atoi (cp);
253  cp += 4;
254 
255  if (cp >= limit)
256  {
257  clib_warning ("bugger 4");
258  return 0;
259  }
260  while (cp < limit && (*cp == ' ' || *cp == '\t'))
261  cp++;
262 
263  e->pid = atoi (cp);
264 
265  for (i = 0; i < 2; i++)
266  {
267  while (cp < limit && *cp != ':')
268  cp++;
269  cp++;
270  }
271  --cp;
272  if (*cp != ':')
273  {
274  clib_warning ("bugger 5");
275  return 0;
276  }
277 
278  cp += 3;
279  if (cp >= limit)
280  {
281  clib_warning ("bugger 6");
282  return 0;
283  }
284  while (cp < limit && (*cp != ' ' && *cp != '\n'))
285  {
286  vec_add1 (task_name, *cp);
287  cp++;
288  }
289  vec_add1 (task_name, 0);
290  /* _vec_len() = 0 in caller */
291  e->task = task_name;
292 
293  if (cp < limit)
294  cp++;
295 
296  *index = cp - tdata;
297  return e;
298 }
299 
300 static u32
301 elog_id_for_pid (elog_main_t * em, u8 * name, u32 pid)
302 {
303  uword *p, r;
304  mhash_t *h = &em->string_table_hash;
305 
306  if (!em->string_table_hash.hash)
307  mhash_init (h, sizeof (uword), sizeof (pid));
308 
309  p = mhash_get (h, &pid);
310  if (p)
311  return p[0];
312  r = elog_string (em, "%s(%d)", name, pid);
313  mhash_set (h, &pid, r, /* old_value */ 0);
314  return r;
315 }
316 
317 void
319 {
320  int enable_fd, data_fd;
321  char *trace_enable = "/debug/tracing/tracing_enabled";
322  char *trace_data = "/debug/tracing/trace";
323  u8 *data = 0;
324  u8 *dp;
325  int bytes, total_bytes;
326  u32 pos;
327  sched_event_t *evt;
328  u64 nsec_to_add;
329  u32 index;
330  f64 clocks_per_sec;
331 
332  enable_fd = open (trace_enable, O_RDWR);
333  if (enable_fd < 0)
334  {
335  clib_warning ("Couldn't open %s", trace_enable);
336  return;
337  }
338  /* disable kernel tracing */
339  if (write (enable_fd, "0\n", 2) != 2)
340  {
341  clib_unix_warning ("disable tracing");
342  close (enable_fd);
343  return;
344  }
345  close (enable_fd);
346 
347  /* Read the trace data */
348  data_fd = open (trace_data, O_RDWR);
349  if (data_fd < 0)
350  {
351  clib_warning ("Couldn't open %s", trace_data);
352  return;
353  }
354 
355  /*
356  * Extract trace into a vector. Note that seq_printf() [kernel]
357  * is not guaranteed to produce 4096 bytes at a time.
358  */
359  vec_validate (data, 4095);
360  total_bytes = 0;
361  pos = 0;
362  while (1)
363  {
364  bytes = read (data_fd, data + pos, 4096);
365  if (bytes <= 0)
366  break;
367 
368  total_bytes += bytes;
369  _vec_len (data) = total_bytes;
370 
371  pos = vec_len (data);
372  vec_validate (data, vec_len (data) + 4095);
373  }
374  vec_add1 (data, 0);
375 
376  /* Synthesize events */
377  em->is_enabled = 1;
378 
379  index = 0;
380  while ((evt = parse_sched_switch_trace (data, &index)))
381  {
382  u64 fake_cpu_clock;
383 
384  fake_cpu_clock = evt->timestamp * em->cpu_timer.clocks_per_second;
385  {
386  ELOG_TYPE_DECLARE (e) =
387  {
388  .format = "%d: %s %s",.format_args = "i4T4t4",.n_enum_strings =
389  2,.enum_strings =
390  {
391  "running", "wakeup",}
392  ,};
393  struct
394  {
395  u32 cpu, string_table_offset, which;
396  } *ed;
397 
398  ed = elog_event_data_not_inline (em, &__ELOG_TYPE_VAR (e),
399  &em->default_track, fake_cpu_clock);
400  ed->cpu = evt->cpu;
401  ed->string_table_offset = elog_id_for_pid (em, evt->task, evt->pid);
402  ed->which = evt->type;
403  }
404  _vec_len (evt->task) = 0;
405  }
406  em->is_enabled = 0;
407 }
408 
409 /*
410  * fd.io coding-style-patch-verification: ON
411  *
412  * Local Variables:
413  * eval: (c-set-style "gnu")
414  * End:
415  */
#define vec_validate(V, I)
Make sure vector is long enough for given index (no header, unspecified alignment) ...
Definition: vec.h:432
Definition: mhash.h:46
u8 * format_sched_event(u8 *s, va_list *va)
Definition: unix-kelog.c:134
sll srl srl sll sra u16x4 i
Definition: vector_sse2.h:337
elog_time_stamp_t init_time
Timestamps.
Definition: elog.h:169
f64 clocks_per_second
Definition: time.h:53
#define vec_add1(V, E)
Add 1 element to end of vector (unspecified alignment).
Definition: vec.h:518
void kelog_collect_sched_switch_trace(elog_main_t *em)
Definition: unix-kelog.c:318
u8 * format(u8 *s, const char *fmt,...)
Definition: format.c:419
static u32 elog_id_for_pid(elog_main_t *em, u8 *name, u32 pid)
Definition: unix-kelog.c:301
static void * elog_event_data_not_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Allocate an event to be filled in by the caller, non-inline.
Definition: elog.h:348
sched_event_type_t
Definition: unix-kelog.c:28
void elog_init(elog_main_t *em, u32 n_events)
Definition: elog.c:466
unsigned long u64
Definition: types.h:89
void kelog_init(elog_main_t *em, char *kernel_tracer, u32 n_events)
Definition: unix-kelog.c:44
sched_event_t * parse_sched_switch_trace(u8 *tdata, u32 *index)
Definition: unix-kelog.c:145
static uword mhash_set(mhash_t *h, void *key, uword new_value, uword *old_value)
Definition: mhash.h:117
void clib_time_init(clib_time_t *c)
Definition: time.c:175
The fine-grained event logger allows lightweight, thread-safe event logging at minimum cost...
void mhash_init(mhash_t *h, uword n_value_bytes, uword n_key_bytes)
Definition: mhash.c:168
vec_header_t h
Definition: buffer.c:282
#define clib_warning(format, args...)
Definition: error.h:59
#define ELOG_TYPE_DECLARE(f)
Definition: elog.h:439
#define ASSERT(truth)
unsigned int u32
Definition: types.h:88
static uword * mhash_get(mhash_t *h, const void *key)
Definition: mhash.h:110
u64 cpu
CPU cycle counter.
Definition: elog.h:125
clib_time_t cpu_timer
Place holder for CPU clock frequency.
Definition: elog.h:166
u64 uword
Definition: types.h:112
u32 elog_string(elog_main_t *em, char *fmt,...)
add a string to the event-log string table
Definition: elog.c:534
#define vec_len(v)
Number of elements in vector (rvalue-only, NULL tolerant)
double f64
Definition: types.h:142
unsigned char u8
Definition: types.h:56
#define clib_unix_warning(format, args...)
Definition: error.h:68
sched_event_type_t type
Definition: unix-kelog.c:40
u64 init_cpu_time
Definition: time.h:60
elog_track_t default_track
Default track.
Definition: elog.h:163